異常程式導致大量資源佔用

這是一個10.2.0.5 RAC for AIX環境，出問題的是節點2，節點1上目前正常。

登入主機，執行vmstat：

ERPDB2@/home/oracle>vmstat 2 10

System configuration: lcpu=14 mem=93183MB

kthr    memory              page              faults        cpu   
----- ----------- ------------------------ ------------ -----------
 r  b   avm   fre  re  pi  po  fr   sr  cy  in   sy  cs us sy id wa
 4  0 18761773 144324   0   0   0   0    0   0 654 15458 3714 29  1 70  0
 2  0 18762563 143534   0   0   0   0    0   0 1033 21523 4569 35  1 64  0
 2  0 18766475 139622   0   0   0   0    0   0 2463 33805 8193 35  3 58  3
 2  0 18767065 139032   0   0   0   0    0   0 3038 35103 10483 28  3 66  3
 3  0 18768118 137979   0   0   0   0    0   0 1782 30526 6418 38  2 57  2
 3  0 18768144 137953   0   0   0   0    0   0 2617 43525 8417 50  3 43  4
 4  0 18768173 137923   0   0   0   0    0   0 2695 57761 8819 43  4 50  2
 3  0 18768157 137939   0   0   0   0    0   0 2693 33832 7419 43  3 54  0
 3  0 18768681 137415   0   0   0   0    0   0 1048 25207 4581 46  2 52  0
 3  0 18767478 138617   0   0   0   0    0   0 950 34960 4568 49  2 48  1

系統中空閒記憶體不到平時的一半，CPU的IDLE比率也比平時要低一些。

透過ps –ef檢查oracle使用者程式：

ERPDB2@/home/oracle>ps -ef|grep ora
  oracle 131128      1   0   Jun 06      -  0:01 ora_reco_cnderpdb2
  oracle 135254      1   0   May 15      - 21:29 /u01/agent10g/perl/bin/perl /u01/agent10g/bin/emwd.pl agent /u01/agent10g/sysman/log/emagent.nohup
  oracle 143398      1   0   Jun 06      -  3:12 oraclecnderpdb2 (DESCRIPTION=(LOCAL=YES)(ADDRESS=(PROTOCOL=beq)))
  oracle 147644 225730   0   May 15      -  0:08 /u01/crs/bin/evmlogger.bin -o /u01/crs/evm/log/evmlogger.info -l /u01/crs/evm/log/evmlogger.log
  oracle 151692 209252   0   May 15      -  0:00 /bin/sh -c cd /u01/crs/log/p5b1/cssd/oclsomon; ulimit -c unlimited; /u01/crs/bin/oclsomon  || exit $?
  oracle 155674      1   0   Jun 06      - 29:12 ora_arc0_cnderpdb2
  oracle 163980      1   0   Jun 06      -  6:31 ora_pz99_cnderpdb2
  oracle 167972      1   0   Jun 06      - 38:23 ora_mmnl_cnderpdb2
  oracle 176168      1   0   Jun 06      -  6:58 ora_smon_cnderpdb2
  oracle 184522      1   3 09:04:57      -  0:04 oraclecnderpdb2 (LOCAL=NO)
  oracle 188568      1   0   Jun 06      - 170:28 ora_lms0_cnderpdb2
  oracle 196612      1   0 09:03:15      -  0:05 oraclecnderpdb2 (LOCAL=NO)
  oracle 204830      1   0 08:40:50      -  0:01 oraclecnderpdb2 (LOCAL=NO)
  oracle 213246      1   0   Jun 06      -  0:00 ora_q000_cnderpdb2
  oracle 229486      1   0 08:57:37      -  0:03 oraclecnderpdb2 (LOCAL=NO)
  oracle 245984      1   0 08:45:02      -  0:03 oraclecnderpdb2 (LOCAL=NO)
  oracle 249858      1   0 08:27:13      -  0:08 oraclecnderpdb2 (LOCAL=NO)
.
.
.
  oracle 254624      1   0 08:40:50      -  0:22 oraclecnderpdb2 (LOCAL=NO)
  oracle 258610      1   0 09:00:18      -  0:01 oraclecnderpdb2 (LOCAL=NO)
  oracle 262670      1   0 09:03:58      -  0:05 oraclecnderpdb2 (LOCAL=NO)
  oracle 267004      1 104 13:44:29      - 927:49 oraclecnderpdb2 (LOCAL=NO)
  oracle 275192      1   0 08:51:19      -  0:01 oraclecnderpdb2 (LOCAL=NO)
  oracle 295508      1   0 09:02:51      -  0:01 oraclecnderpdb2 (LOCAL=NO)
  oracle 299676      1   0 08:48:07      -  0:53 oraclecnderpdb2 (LOCAL=NO)
.
.
.
  oracle 697136      1   0 08:14:58      -  0:02 oraclecnderpdb2 (LOCAL=NO)
  oracle 725768      1   0 08:09:49      -  0:10 oraclecnderpdb2 (LOCAL=NO)
  oracle 730046      1   0 08:17:20      -  0:14 oraclecnderpdb2 (LOCAL=NO)
  oracle 738172      1   0 08:03:46      -  0:18 oraclecnderpdb2 (LOCAL=NO)
  oracle 742256      1   0 08:16:20      -  0:05 oraclecnderpdb2 (LOCAL=NO)
  oracle 746320      1   0 08:11:00      -  0:14 oraclecnderpdb2 (LOCAL=NO)
  oracle 754448      1   0   Jul 05      -  4:34 oraclecnderpdb2 (LOCAL=NO)
  oracle 758660      1   0 08:19:12      -  0:13 oraclecnderpdb2 (LOCAL=NO)
  oracle 766894      1   0 14:14:16      -  0:39 oraclecnderpdb2 (LOCAL=NO)
  oracle 771046      1   0   Jul 05      - 12:45 oraclecnderpdb2 (LOCAL=NO)
  oracle 774984      1   0 07:54:22      -  0:03 oraclecnderpdb2 (LOCAL=NO)
  oracle 779134      1   0 08:20:44      -  2:36 oraclecnderpdb2 (LOCAL=NO)
  oracle 787356      1   0 13:51:39      -  0:50 oraclecnderpdb2 (LOCAL=NO)
  oracle 791516      1   0 07:56:18      -  0:55 oraclecnderpdb2 (LOCAL=NO)

檢查程式的時候發現一個程式267004佔用了100%的CPU，且CPU執行時間超過了900分鐘也就是15個小時，而這個程式並非Oracle的後臺程式，而是使用者程式。

登入資料庫檢查系統狀態，發現V$LOCK檢視中存在一個長時間持有鎖的會話：

ERPDB2@/home/oracle>sqlplus / as sysdba

SQL*Plus: Release 10.2.0.5.0 - Production on Wed Jul 6 09:13:44 2011

Copyright (c) 1982, 2010, Oracle.  All Rights Reserved.

Connected to:
Oracle Database 10g Enterprise Edition Release 10.2.0.5.0 - 64bit Production
With the Partitioning, Real Application Clusters, OLAP, Data Mining
and Real Application Testing options

SQL> set pages 100 lines 138
SQL> select * from v$lock where type not in ('MR', 'TO');

ADDR             KADDR             SID TY       ID1       ID2 LMODE REQUEST  CTIME   BLOCK
---------------- ---------------- ---- -- --------- --------- ----- ------- ------- ------
0700000C89595068 0700000C89595088 1093 XR         4         0     1       0       0      2
0700000C89595110 0700000C89595130 1083 XR         0         0     1       0 2543466      2
0700000C895951B8 0700000C895951D8 1093 CF         0         0     2       0 2543466      2
0700000C89595260 0700000C89595280 1094 RT         2         1     6       0 2543460      2
0700000C89595308 0700000C89595328 1093 RS        25         1     2       0 2543463      2
0700000C89595458 0700000C89595478 1094 RT         2         0     6       0 2543463      2
0700000C895955A8 0700000C895955C8 1096 DM         1         0     4       0 2543459      2
0700000C89595650 0700000C89595670 1096 PW         1         0     3       0 2543458      2
0700000C895956F8 0700000C89595718 1096 RT         2         2     6       0 2543460      2
0700000C89596790 0700000C895967B0 1092 TS        16         2     3       0 2543459      2
0700000C89596838 0700000C89596858 1093 KT      4839         0     4       0 2543459      2
0700000C895AF8D0 0700000C895AF8F0 1065 CU 672471248 117440522     6       0   56181      0

12 rows selected.

其中SID為1065的會話持有了鎖達到了56181秒，根據TYPE型別，這個一個和CURSOR有關的鎖，檢查會話和程式資訊：

SQL> select sid, event, program
2 from v$session
3 where paddr in
4 (select addr
5 from v$process
6 where spid = 267004);

SID EVENT                              PROGRAM
---------- ----------------------------------- -------------------
      1065 SQL*Net more data from client

SQL> select sid, event, seconds_in_wait from v$session where sid = 1065;

SID EVENT                          SECONDS_IN_WAIT
---------- ------------------------------ ---------------
      1065 SQL*Net more data from client  56645

SQL> select sql_text
2 from v$sqltext_with_newlines
3 where sql_id =
4 (select sql_id
5 from v$session
6 where sid = 1065)
7 order by piece;

SQL_TEXT
----------------------------------------------------------------
select ' ' year,' ' month, '201103' yearmonth,'2011.03.31' vdate
,vtype,vno,ino,expl,0 vdc,acode,substr(acode,1,4) acode2 ,bco
de,substr(bcode,1,5) bcode2,ccode,dcode,ecode,gcode,substr(gcode
,1,7) gcode2,hcode,icode ,scode,max(vhtype) vhtype,fcode,rerate
,(case when substr(acode,1,4) in ('1125','1132','1152','2122',
'2132') then null else uerate end) uerate ,sum(rmbdebit) rmbdeb
it ,sum(rmbcredit) rmbcredit ,sum(rmb) rmb ,sum(fcydebit) fcy
debit ,sum(fcycredit) fcycredit ,sum(fcy) fcy ,(case when sub
str(acode,1,4) in ('1125','1132','1152','2122','2132') then null
else sum(usddebit) end) usddebit ,(case when substr(acode,1,4)
in ('1125','1132','1152','2122','2132') then null else sum(usdc
redit) end) usdcredit ,(case when substr(acode,1,4) in ('1125',
'1132','1152','2122','2132') then null else sum(usd) end) usd ,
sum(qtydebit) qtydebit ,sum(qtycredit) qtycredit ,sum(qty) qty
,'' lxzl ,'' vprepare , 0 vno2 from ( select to_char(year)
year,to_char(month) month,' ' vdate ,substr(ta.bcode,2,4) vtyp
e,' ' vno,0 ino,'???' expl,tb.dc vdc,ta.acode ,ta.bcode,ccod
e,dcode,ecode,hcode,icode,gcode,scode,' ' vhtype,fcode ,(case w
hen nvl(fcybalance,0)=0 then 0 else nvl(rmbbalance,0)/nvl(fcybal
ance,0) end) rerate ,(case when nvl(fcybalance,0) = 0 then 0
else nvl(usdbalance,0)/nvl(fcybalance,0) end) uerate ,0 rmbde
bit ,0 rmbcredit ,(nvl(rmbbalance,0)*tb.dc) rmb ,0 fcydebit
,0 fcycredit ,nvl(fcybalance,0)*tb.dc fcy ,0 usddebit ,0 usd
credit ,(nvl(usdbalance,0)*tb.dc) usd ,0 qtydebit ,0 qtycredi
t ,(nvl(qtybalance,0)*tb.dc) qty ,'' lxzl ,'' vprepare , 0 v
no2 from balance ta left outer join acode tb on ta.acode=tb.a
code where ( (year=2011 and month =3) ) and ((bcode='9100601
2209' and bitand(flag1,4)=4) or (bcode='91006012185' and bitand(
flag1,4)=4) or (bcode='91006011950' and bitand(flag1,4)=4) or (b
code='91006011936' and bitand(flag1,4)=4) or (bcode='91006011427
' and bitand(flag1,4)=4) or (bcode='90006011950' and bitand(flag
1,4)=4) or (bcode='90006011936' and bitand(flag1,4)=4) or (bcode
.
.
.
bcode like '01391%' or bcode like '91006%' or bcode like '02506%
' or bcode like '02306%' or bcode like '01399%' or bcode like '0
1396%' or bcode like '01387%' or bcode like '10006%' or bcode li
ke '02006%' or bcode like '01389%' or bcode like '01206%' or bco
de like '90006%' or bcode like '03006%' or bcode like '01394%' o
r bcode like '01393%' or bcode like '05006%' or bcode like '0138
6%' or bcode like '01306%') and ( bcode like '01306%' or bcode
like '01306%' or bcode like '04006%') and (ecode like '006013
060101%' or ecode like '006013060134%' or ecode like '0060400601
01%') and (ta.acode like '1243%') and (gcode like '140201500
7%') and 1=1

991 rows selected.

SQL> select sid, username, status from v$session where sid = 1065;

SID USERNAME                       STATUS
---------- ------------------------------ --------
      1065 CNDERP                         ACTIVE

以前碰到過類似的情況，不過等待事件是SQL*Net more data to client，而且會話狀態也是ACTIVE，現象同樣是單個程式佔用了100%的CPU，且一直處於執行狀態。以前碰到的問題應該是網路閃斷造成了通訊異常所致。

而今天碰到的這個問題，應該和上面這個異常複雜的SQL有關。很可能Oracle在分析這個SQL的時候碰到了異常，因此一直處於SQL*Net more data from client的等待狀態，這個SQL的大小已經接近64K了，如果在分析的過程中碰到了什麼bug也並不奇怪。

這個程式屬於使用者程式，因此中止對於系統並沒有影響，直接利用kill -9殺掉作業系統上的程式：

ERPDB2@/home/oracle>kill -9 267004
ERPDB2@/home/oracle>ps -ef|grep 267004
  oracle 365340 529208   0 09:28:49  pts/1  0:00 grep 267004
ERPDB2@/home/oracle>vmstat 2 10

System configuration: lcpu=14 mem=93183MB

kthr    memory              page              faults        cpu   
----- ----------- ------------------------ ------------ -----------
 r  b   avm   fre  re  pi  po  fr   sr  cy  in   sy  cs us sy id wa
 2  0 15894079 2907698   0  10   0   0    0   0 1534 176158 6008 13  4 80  3
 1  0 15891796 2909960   0   9   0   0    0   0 1137 18452 4937 11  2 85  2
 2  0 15894685 2907066   0   2   0   0    0   0 1921 25201 6747 16  2 77  6
 1  0 15892077 2909667   0   3   0   0    0   0 953 115275 4685 19  3 74  5
 1  0 15892618 2909115   0   4   0   0    0   0 403 8784 3394 17  1 82  0
 2  0 15894081 2907652   0   0   0   0    0   0 1193 19291 5034 29  1 69  0
 4  0 15911090 2890642   0   0   0   0    0   0 2814 36575 8361 39  2 58  0
 4  0 15921801 2879931   0   0   0   0    0   0 2941 41975 8528 52  3 45  0
 4  0 15933411 2868320   0   0   0   0    0   0 1358 32741 5073 56  2 41  0
 3  0 15941350 2860381   0   0   0   0    0   0 793 26134 4077 52  1 46  0

可以看到，殺掉問題會話後，系統空閒記憶體恢復正常，CPU的總體IDLE也有所提升。雖然這個問題解決了，但是如果這種複雜的SQL經常出現的話，那麼再次碰到類似的問題也只是時間的問題。