執行計劃變化導致CPU負載高的問題分析

dbhelper發表於2016-04-27
負載
前幾天碰到一個CPU負載較高的問題。從系統層面來看，情況不是很嚴重，但是從應用的角度來說，已經感覺到很慢了。因為前端的呼叫頻率還是比較高。所以會把這個問題放大。
使用top -c檢視了基本的伺服器資訊。可以看到負載大概在30%左右。IO wait不高。
top - 19:30:48 up 179 days,  4:54,  3 users,  load average: 4.43, 4.28, 4.14
Tasks: 669 total,   6 running, 661 sleeping,   0 stopped,   2 zombie
Cpu(s): 24.1%us,  3.4%sy,  0.0%ni, 69.0%id,  0.0%wa,  0.0%hi,  3.4%si,  0.0%st
Mem:  32949016k total, 32835380k used,   113636k free,   292028k buffers
Swap: 16771776k total,  4563936k used, 12207840k free, 25528396k cached
而首當其衝的幾個程式都是CPU利用率100%
  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND                                                                
 9014 oracle    18   0 16.1g 1.1g 1.1g R 100.0  3.5  13:01.09 oraclexxx (LOCAL=NO)                                                  
 9024 oracle    16   0 16.1g 1.5g 1.5g R 100.0  4.8  36:31.23 oraclexxx (LOCAL=NO)                                                  
 9100 oracle    17   0 16.1g 1.1g 1.1g R 100.0  3.4   8:34.87 oraclexxx (LOCAL=NO)                                                  
22975 root      15   0 13164 1568  812 R 100.0  0.0   0:00.04 top -c                                                                
看看這幾個程式在幹嘛？發現都在執行相同的sql語句。
$sh showpid.sh 9014
SQL_ID                         SQL_TEXT
------------------------------ ------------------------------------------------------------
5h92pf9xtbps4                  UPDATE SWD_DRAWCN SET WEAPONLISTNO=:1,IP=:2, ROLE_NAME=:3, G
                               ROUP_ID=:4, SERVER_IP=:5, SERVER_NAME=:6, ROLE_GUID=:7, ROLE
                               _LEVEL=:8, DRAWED='Y',DRAWDATE=sysdate,SN_GET=:9 WHERE ID=:1
                               0 AND CN=LOWER(:11) AND DRAW_TYPE=:12
PREV_SQL_ID                    SQL_TEXT
------------------------------ ------------------------------------------------------------
5h92pf9xtbps4                  UPDATE SWD_DRAWCN SET WEAPONLISTNO=:1,IP=:2, ROLE_NAME=:3, G
                               ROUP_ID=:4, SERVER_IP=:5, SERVER_NAME=:6, ROLE_GUID=:7, ROLE
                               _LEVEL=:8, DRAWED='Y',DRAWDATE=sysdate,SN_GET=:9 WHERE ID=:1
                               0 AND CN=LOWER(:11) AND DRAW_TYPE=:12
所以看起來很有可能是sql語句導致的問題。從最近的快照裡面的sql對應的db time使用情況可以看出，5h92pf9xtbps4竟然有三行內容。這個當然是從awr報告裡面直接看不到的。
$ sh showsnapsql.sh 105206
Current Instance
~~~~~~~~~~~~~~~~
      DBID DB_NAME     INST_NUM INST_NAME
---------- --------- ---------- ----------------
1720209052 XXX                1 xxx
   SNAP_ID SQL_ID        EXECUTIONS_DELTA ELAPSED_TI PER_TOTAL
---------- ------------- ---------------- ---------- ----------
    105206 5h92pf9xtbps4             6783 6863s      96%
    105206 5h92pf9xtbps4                0 6863s      96%
    105206 5h92pf9xtbps4            47032 6863s      96%
所以初步感覺是執行計劃發生了變化，如果從這個思路來看，這個問題似乎也能說得通了，為什麼之前沒有問題，現在有問題了。
我們來看看awr報告裡面怎麼說。
Elapsed Time (s) CPU Time (s) Executions Elap per Exec (s) % Total DB Time SQL Id SQL Module SQL Text
12,605 12,605 113,557 0.11 96.90 xxxtest@BJ-YF-4-166 (TNS V1-V3) UPDATE SWD_DRAWCN SET WEAPONLI...
當然這個語句可以看出這個語句還是有些問題。可以用coe的指令碼看出，這個語句存在3個不同的執行計劃，而且執行計劃之間的差別看起來差別不是很大，但是在呼叫頻繁的系統中，這個影響就會被放大。
SQL_ID: 5h92pf9xtbps4
PLAN_HASH_VALUE AVG_ET_SECS
--------------- -----------
     2762405514        .037
      889840933        .103
     3278101387        .194
從awrsqrpt裡面得到一些更具體的資訊，可以看到第一個執行計劃較好的語句在1個小時內執行次數近1萬多次。而第二條執行頻率高了很多10萬多次，但是執行時間要低很多。第三個執行計劃執行次數為0.

# Plan Hash Value Total Elapsed Time(ms) Executions 1st Capture Snap ID Last Capture Snap ID
12,227,848 12,610 105205 105206
377,370 100,947 105205 105206
0 0 105205 105206
所以針對這種情況，我把注意力放在了前兩個執行計劃上。 來看看語句的索引情況，對應的表有兩個索引，一個欄位建立在draw_type上，另外一個建立在類似id的欄位CN上。這個表中的資料有1千萬左右。
PLAN hash value為的執行計劃為：
Id Operation Name Rows Bytes Cost (%CPU) Time
0 UPDATE STATEMENT       62 (100)  
1    UPDATE SWD_DRAWCN        
2      TABLE ACCESS BY INDEX ROWID SWD_DRAWCN 1 111 62 (0) 00:00:01
3        INDEX RANGE SCAN IND_DRAWCN_TYPE 8465   9 (0) 00:00:01
而PLAN hash value為的執行計劃為：
Id Operation Name Rows Bytes Cost (%CPU) Time
0 UPDATE STATEMENT       48 (100)  
1    UPDATE SWD_DRAWCN        
2      TABLE ACCESS BY INDEX ROWID SWD_DRAWCN 1 123 48 (0) 00:00:01
3        INDEX RANGE SCAN IND_SWD_DRAWCN_CN 891   2 (0) 00:00:01
看兩個執行計劃，貌似差別也不大。但是這種細微的差別的影響就導致了執行時間近40倍的差別。
為什麼之前有問題，現在沒有，如果檢視以前的執行情況，是肯定走了CN的索引，而現在出現問題是走了TYPE的索引。
為什麼執行計劃發生了一些改變，還是和統計資訊的情況和統計資訊收集的一些規則有關。
那麼這個問題基本已經有了方向，怎麼修復呢。主要有兩種思路，一種是重新收集統計資訊，儘可能建立符合索引CN,TYPE, 第二種思路就是修改執行計劃，讓語句執行目前最優的執行計劃，這個時候，sqlprofile就派上大的用處了。
開啟coe指令碼，把原來的outline部分修改為下面的形式
h := SYS.SQLPROF_ATTR(
q'[BEGIN_OUTLINE_DATA]',
q'[IGNORE_OPTIM_EMBEDDED_HINTS]',
q'[OPTIMIZER_FEATURES_ENABLE('10.2.0.4')]',
q'[OPT_PARAM('optimizer_index_cost_adj' 30)]',
q'[OPT_PARAM('optimizer_index_caching' 90)]',
q'[ALL_ROWS]',
q'[OUTLINE_LEAF(@"UPD$1")]',
q'[INDEX_RS_ASC(@"UPD$1" "SWD_DRAWCN"@"UPD$1" ("SWD_DRAWCN"."CN"))]',
q'[END_OUTLINE_DATA]'); 
然後替換，回車以後馬上檢視top情況，發現問題馬上緩解了下來，
等了幾分鐘，可以看到確實cpu利用率降下來了。當然這種情況處理完之後，從業務的反饋已經正常了。
但是對於這個問題目前的方案還是一個臨時解決，還是需要持續改進。


來自 “ ITPUB部落格 ” ，連結：http://blog.itpub.net/8494287/viewspace-2089587/，如需轉載，請註明出處，否則將追究法律責任。

相關文章