一次监控系统进程影响的业务响应的问题及解决

也是十一期间，业务反应出帐过程中某程序执行特别慢，怀疑是oracle数据库有问题，需要尽快处理，根据业务提供的相关信息，相关业务从wwzg3主机发起，业务主要使用了账本通知表www_BOOK_CHG_NOTIFY和短信表WWW.www_busi_sms。
提供了一个sql语句
select *
  from WWW.www_book_scheme_fee_0104 a,
       WWW.www_book_scheme_rec_0104 b,
       WWW.crm_user                 c
where a.so_nbr = b.so_nbr
   and a.wwwt_id = c.wwwt_id
   and a.after_month <= to_char(sysdate, 'yyyymm')
   and c.phone_id = b.phone_id
   and b.sts = 0

   and a.sts = 0;

1，登录数据库主机，发现主机资源充足，系统资源不存在瓶颈，CPU利用率只有40%
SQL> !sar -u 3 5

HP-UX wbdb1 B.11.31 U ia64    10/04/12

12:24:01    %usr    %sys    %wio   %idle
12:24:04      27       4       8      60
12:24:07      30       3       7      60
12:24:10      28       2       8      62
12:24:13      30       4      10      56
12:24:16      30       3      10      57

Average       29       3       9      59
2，开发提供的sql执行速度特别快，相关业务表唯一有点异常的sql执行计划如下,基本上都是全表扫描，但目前数据库中没有发现该语句正在运行
因此排除

PLAN_TABLE_OUTPUT
------------------------------------------------------------------------------------------------------------------------------------

---------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                         | Name                     | Rows  | Bytes |TempSpc| Cost (%CPU)| Pstart| Pstop |
---------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                  |                          |     1 |   430 |       | 87768   (1)|       |       |
|   1 |  TABLE wwwESS BY LOCAL INDEX ROWID| CRM_USER                 |     1 |    20 |       |    21   (0)|       |       |
|   2 |   NESTED LOOPS                    |                          |     1 |   430 |       | 87768   (1)|       |       |
|   3 |    HASH JOIN                      |                          |   385 |   154K|  2832K| 79678   (1)|       |       |
|   4 |     HASH JOIN                     |                          | 10999 |  2696K|   343M| 75513   (1)|       |       |
|   5 |      MERGE JOIN CARTESIAN         |                          |  5634K|   279M|       | 20348   (1)|       |       |
|   6 |       TABLE wwwESS FULL           | www_BOOK_SCHEME_COND     |  2189 | 32835 |       |    39   (0)|       |       |
|   7 |       BUFFER SORT                 |                          |  2574 | 95238 |       | 20309   (1)|       |       |
|   8 |        TABLE wwwESS FULL          | www_BOOK_SCHEME_SAP_MAP  |  2574 | 95238 |       |     9   (0)|       |       |
|   9 |      TABLE wwwESS FULL            | www_BOOK_SCHEME_REC_0104 |  2306K|   437M|       | 14986   (2)|       |       |
|  10 |     TABLE wwwESS FULL             | www_BOOK_SCHEME_FEE_0104 | 80636 |    12M|       |  3373   (2)|       |       |
|  11 |    PARTITION RANGE ALL            |                          |     1 |       |       |    20   (0)|     1 |    10 |
|  12 |     INDEX RANGE SCAN              | IDX_USER_PHONE           |     1 |       |       |    20   (0)|     1 |    10 |
---------------------------------------------------------------------------------------------------------------------------

3，数据库中的top 10 sql看，没有发现来自wwzg3主机的异常sql，基本上都来自wbzc4

awr本处省略
4，通过以上推断，数据库没有任何问题，于是转向查看运行相关进程的主机是否异常，果然问题不在数据库，在wwzg3主机资源利用率过高，系统利用率100%
    CPU利用率100%，被%sys消耗，
root@wwzg3[/]#sar -u 3 5

HP-UX wwzg3 B.11.31 U ia64    10/04/12

13:47:38    %usr    %sys    %wio   %idle
13:47:41      30      70       0       0
13:47:44      30      70       0       0
13:47:47      30      69       0       0
13:47:50      31      69       0       0
13:47:53      30      69       0       1

Average       30      69       0       0

5，262个idcp.sh进程正在运行
root@wwzg3[/]#ps -ef|grep idcp.sh|wc -l
262

    root 20282 10168  1 13:55:30 pts/17    0:00 grep 7675
root@wwzg3[/]#ps -ef|grep idcp.sh
    root 10315 10146  0 13:55:40 ?         0:00 /usr/bin/sh /home/patrol/IDCPCM/main/idcp.sh
    root  9848  9803 253 20:40:00 ?        25:36 /usr/bin/sh /home/patrol/IDCPCM/main/idcp.sh
    root 29251 29179 251 19:10:00 ?        30:05 /usr/bin/sh /home/patrol/IDCPCM/main/idcp.sh
    root 19055  3432  0 16:40:00 ?         0:00 sh -c  /home/patrol/IDCPCM/main/idcp.sh 1>/dev/null 2>/dev/null
    root 13603  3432  0 15:50:00 ?         0:00 sh -c  /home/patrol/IDCPCM/main/idcp.sh 1>/dev/null 2>/dev/null
    root 13384  3432  0 18:20:00 ?         0:00 sh -c  /home/patrol/IDCPCM/main/idcp.sh 1>/dev/null 2>/dev/null
    root 26541  3432  0 15:20:00 ?         0:00 sh -c  /home/patrol/IDCPCM/main/idcp.sh 1>/dev/null 2>/dev/null
    root 29340 29289 252 21:10:00 ?        24:36 /usr/bin/sh /home/patrol/IDCPCM/main/idcp.sh
    root 22296 22236 251 18:00:00 ?        34:44 /usr/bin/sh /home/patrol/IDCPCM/main/idcp.sh
    root 10677 10653 252 21:00:00 ?        23:38 /usr/bin/sh /home/patrol/IDCPCM/main/idcp.sh
    root 20122  3432  0 21:20:00 ?         0:00 sh -c  /home/patrol/IDCPCM/main/idcp.sh 1>/dev/null 2>/dev/null
    root 25174 25034 250 07:00:00 ?         6:48 /usr/bin/sh /home/patrol/IDCPCM/main/idcp.sh
    root  6585  6499 251 03:20:00 ?        11:50 /usr/bin/sh /home/patrol/IDCPCM/main/idcp.sh
    root 10206 10177  0 13:55:39 ?         0:00 /usr/bin/sh /home/patrol/IDCPCM/main/idcp.sh
    root 25419 25344 253 21:40:00 ?        21:52 /usr/bin/sh /home/patrol/IDCPCM/main/idcp.sh
    root 27135  3432  0 17:00:01 ?         0:00 sh -c  /home/patrol/IDCPCM/main/idcp.sh 1>/dev/null 2>/dev/null
    root 10347   944  0 13:55:40 ?         0:00 /usr/bin/sh /home/patrol/IDCPCM/main/idcp.sh
    root 10167 10166  0 13:55:39 ?         0:00 /usr/bin/sh /home/patrol/IDCPCM/main/idcp.sh
    root 25569  3432  0 18:30:00 ?         0:00 sh -c  /home/patrol/IDCPCM/main/idcp.sh 1>/dev/null 2>/dev/null
    root 10256  2025  0 13:55:40 ?         0:00 /usr/bin/sh /home/patrol/IDCPCM/main/idcp.sh
    root 29111 29082 252 20:50:00 ?        24:08 /usr/bin/sh /home/patrol/IDCPCM/main/idcp.sh
6，该进程每隔10分钟会起一个定时任务，但从上面的进程看，昨天开始运行的进程都还没有执行结束，异常原因未知
#BOMC
30 2 * * * /home/patrol/CM/up_bin/get_cm.sh 1>/dev/null 2>&1
0,10,20,30,40,50 * * * *  /home/patrol/IDCPCM/main/idcp.sh 1>/dev/null 2>/dev/null


7，kill 相关异常进程，为了防止问题再次发生，手工注释掉了该job的自动运行，系统恢复了正常
#BOMC
30 2 * * * /home/patrol/CM/up_bin/get_cm.sh 1>/dev/null 2>&1
#0,10,20,30,40,50 * * * *  /home/patrol/IDCPCM/main/idcp.sh 1>/dev/null 2>/dev/null

改进措施
 自动运行的监控脚本一直处于正常运行状态，很难定位具体异常的原因了。因此为了防止类似问题发生，对脚本程序进行了修改，增加了判断语句
 前一个调度如果还没有执行完，则强制退出脚本，重新执行，并添加了日志记录
 IDCPNUM=`ps -ef|grep idcp.sh|grep -v grep|wc -l|awk '{ print $1 }'`
if [ $IDCPNUM -ge 1 ]; then
ps -ef |grep  idcp.sh |awk '{system("kill -9 "$2)}'
sleep 10
cd $TMDR
rm PM*.txt
fi

总结：业务反应数据库慢，其实可能根本不是数据库的问题，要综合分析判断，本次问题其实就出在访问数据库的客户端所在的主机太忙。