執行計劃變化導致CPU負載高的問題分析
前幾天碰到一個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報告裡面怎麼說。
當然這個語句可以看出這個語句還是有些問題。可以用coe的指令碼看出，這個語句存在3個不同的執行計劃，而且執行計劃之間的差別看起來差別不是很大，但是在呼叫頻繁的系統中，這個影響就會被放大。
SQL_ID: 5h92pf9xtbps4
PLAN_HASH_VALUE AVG_ET_SECS
--------------- -----------
2762405514 .037
889840933 .103
3278101387 .194
從awrsqrpt裡面得到一些更具體的資訊，可以看到第一個執行計劃較好的語句在1個小時內執行次數近1萬多次。而第二條執行頻率高了很多10萬多次，但是執行時間要低很多。第三個執行計劃執行次數為0.
所以針對這種情況，我把注意力放在了前兩個執行計劃上。
來看看語句的索引情況，對應的表有兩個索引，一個欄位建立在draw_type上，另外一個建立在類似id的欄位CN上。這個表中的資料有1千萬左右。
PLAN hash value為的執行計劃為：
而PLAN hash value為的執行計劃為：
看兩個執行計劃，貌似差別也不大。但是這種細微的差別的影響就導致了執行時間近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利用率降下來了。當然這種情況處理完之後，從業務的反饋已經正常了。
但是對於這個問題目前的方案還是一個臨時解決，還是需要持續改進。
使用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... |
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 |
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 |
| 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 |
為什麼之前有問題，現在沒有，如果檢視以前的執行情況，是肯定走了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/，如需轉載，請註明出處，否則將追究法律責任。
相關文章
- 執行計劃錯誤導致系統負載高負載
- RLM$SCHDNEGACTION 執行導致負載問題負載
- 執行計劃的偏差導致的效能問題
- 完美的執行計劃導致的效能問題
- 故障分析 | 大量短時程式導致 cpu 負載過高案例一則負載
- 執行計劃問題導致處理速度時快時慢的問題
- latch 相關效能問題診斷： latch: row cache objects等待事件導致CPU負載高Object事件負載
- 執行計劃中的COLLECTION ITERATOR PICKLER FETCH導致的效能問題
- ORACLE DML執行計劃頻繁變更導致業務響應極慢問題的處理Oracle
- 分析執行計劃優化SQLORACLE的執行計劃(轉)優化SQLOracle
- Nodejs mkdirP 模組導致CPU佔用高的問題NodeJS
- crontab導致CPU異常的問題分析及處理
- PostgreSQL執行計劃變化SQL
- 分析執行計劃最佳化SQLORACLE的執行計劃(轉)SQLOracle
- 一個執行計劃解析的小問題分析
- 執行計劃變化的處理
- cpu使用率低負載高，原因分析負載
- Grant許可權導致執行計劃失效
- PHP-FPM 導致負載過高的排查方法 善用PHP慢執行日誌slow logPHP負載
- 【RAC】處理因ons導致CPU使用率過高的問題
- 【優化】ORACLE執行計劃分析優化Oracle
- 利用 Arthas 精準定位 Java 應用 CPU 負載過高問題Java負載
- Dubbo Hession反序列化導致CPU佔用飆高用例分析
- 解決new Thread().Start導致高併發CPU 100%的問題thread
- ANALYZE導致的阻塞問題分析
- _optimizer_invalidation_periond導致收集統計資訊後執行計劃沒有改變
- 統計資訊不正確導致執行計劃的錯誤選擇
- autotrace 和explain plan for可能導致執行計劃錯誤AI
- 從業務角度分析奇怪的資料庫高負載問題資料庫負載
- mysql的執行計劃快取問題MySql快取
- 通過執行計劃中的CONCATENATION分析sql問題SQL
- 透過執行計劃中的CONCATENATION分析sql問題SQL
- Flume高可用負載均衡問題負載
- 11G的SORT GROUP BY NOSORT導致錯誤執行計劃
- SQL Server 2005遊標的行為變化導致的死鎖問題SQLServer
- zabbix修改LINUX的CPU負載監控問題Linux負載
- 一個高請求量負載設計問題負載
- WebMagic多執行緒導致註解失效問題Web執行緒