關於CPU使用率高的awr分析

dbhelper發表於2016-04-27
今天看到一個報警資訊，大體是CPU使用異常。

ZABBIX-監控系統:
------------------------------------
報警內容: CPU utilization is too high
------------------------------------
報警級別: PROBLEM
------------------------------------
監控專案: CPU idle time：55.17 %
------------------------------------
報警時間:2016.03.22-19:03:23

對於這個問題，看到CPU使用率過高，大體已經有了一些思路。但是還是需要一些論證。
首先檢視sar的情況，可以看出CPU的平均使用率在30~40%
06:55:01 PM       all     32.35      0.00      7.57      0.00     60.08
06:56:01 PM       all     31.78      0.00      7.55      0.00     60.67
06:57:01 PM       all     31.65      0.00      7.52      0.01     60.82
06:58:01 PM       all     31.42      0.00      7.48      0.00     61.10
06:59:01 PM       all     30.91      0.00      7.58      0.00     61.51
07:00:02 PM       all     31.13      0.00      7.62      0.00     61.25
07:01:01 PM       all     30.84      0.00      7.62      0.02     61.53
07:02:01 PM       all     31.86      0.00      7.83      0.11     60.19
07:03:01 PM       all     32.88      0.00      7.64      0.06     59.43
Average:          all     24.34      0.00      7.11      0.04     68.51
但是top的結果卻讓我有些奇怪。
top - 19:04:19 up 68 days, 22:47,  2 users,  load average: 4.47, 4.58, 4.47
Tasks: 284 total,  14 running, 269 sleeping,   0 stopped,   1 zombie
Cpu(s): 31.6% us,  3.9% sy,  0.0% ni, 60.5% id,  0.0% wa,  0.1% hi,  3.9% si
Mem:  16430192k total, 16283948k used,   146244k free,   123716k buffers
Swap: 33551744k total,   115632k used, 33436112k free, 13809040k cached
可以看到CPU的使用率雖高，但是IO卻幾乎沒有什麼消耗。
然後檢視部分的程式資訊，發現有部分的程式CPU使用率較高。這個時候看起來是一個全表掃描的機率偏大了。
  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND                                                                
28185 oracle    16   0 6282m 835m 829m S 82.6  5.2   5:01.48 oracletest (LOCAL=NO)                                                  
28237 oracle    16   0 6282m 832m 826m S 82.6  5.2   4:50.64 oracletest (LOCAL=NO)                                                  
28345 oracle    16   0 6283m 874m 867m R 82.6  5.5   3:54.84 oracletest (LOCAL=NO)                                                  
28425 oracle    16   0 6281m 689m 682m S 82.6  4.3   3:50.17 oracletest (LOCAL=NO)                                                  
28703 oracle    16   0 6281m 571m 565m S 82.6  3.6   2:06.54 oracletest (LOCAL=NO)  
然後繫結程式，檢視程式對應的session執行sql的情況，發現語句竟然是一句非常簡單的查詢。
PREV_SQL_ID                    SQL_TEXT
------------------------------ ------------------------------------------------------------
7gwxpwru0czqw                  select companyname from license   
執行計劃如何呢，確實是一個全表掃描。
Plan hash value: 2492423498
-----------------------------------------------------------------------------
| Id  | Operation         | Name    | Rows  | Bytes | Cost (%CPU)| Time     |
-----------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |         |       |       |     3 (100)|          |
|   1 |  TABLE ACCESS FULL| LICENSE |     1 |    29 |     3   (0)| 00:00:01 |
-----------------------------------------------------------------------------
但是這個時候的問題倒不是在於這個全表掃描了，關鍵就是這個表中目前只有1條資料。
為什麼會有這個CPU消耗較大的情況呢，目前來看，語句的執行頻率極高。

 Per Second Per Transaction
Redo size: 3,455.88 0.53
Logical reads: 54,200.78 8.32
Block changes: 17.89 0.00
Physical reads: 5.72 0.00
Physical writes: 1.25 0.00
User calls: 39,104.93 6.01
Parses: 13,033.74 2.00
Hard parses: 4.75 0.00
Sorts: 12.16 0.00
Logons: 0.07 0.00
Executes: 13,035.13 2.00
Transactions: 6,512.05  
如果看到這種情況，會發現目前的系統還是非常繁忙的，那麼主要在哪兒忙呢。可以看到rollback的比例非常高。
% Blocks changed per Read: 0.03 Recursive Call %: 25.04
Rollback per transaction %: 99.97 Rows per Sort: 2027.20
從這個也可以看出應該是應用的邏輯部分出了問題，或者資料問題導致的校驗失敗導致回滾。
這個時候檢視等待事件的情況如下。
Event Waits Time(s) Avg Wait(ms) % Total Call Time Wait Class
CPU time   10,839   100.1  
SQL*Net message to client 93,924,202 73 0 .7 Network
latch: cache buffers chains 79,297 8 0 .1 Concurrency
cursor: pin S 71,807 2 0 .0 Other
log file sync 7,136 1 0 .0 Commit
我們直接到sql的部分來看看。下面兩條語句的執行頻率極高，大概是1個小時2千多萬次的頻率。
Elapsed Time (s) CPU Time (s) Executions Elap per Exec (s) % Total DB Time SQL Id SQL Module SQL Text
1,470 1,414 23,451,700 0.00 13.57 JDBC Thin Client select companyname from licens...
694 686 23,024,521 0.00 6.41 JDBC Thin Client select supdepid from mdepart...
那麼怎麼看出語句存在問題呢。可以在executions部分找到一些痕跡。
Executions Rows Processed Rows per Exec CPU per Exec (s) Elap per Exec (s) SQL Id SQL Module SQL Text
23,451,700 23,440,315 1.00 0.00 0.00 JDBC Thin Client select companyname from licens...
23,024,521 0 0.00 0.00 0.00 JDBC Thin Client select supdepid from mdepart
第二條語句的執行頻率和第一條一樣都非常高，但是第二條語句的“Rows Processed"為0
如果檢視語句的buffer gets，就會發現是0
$ sh showsql.sh 7nkxbfnwgx93v
HASH_VALUE PLAN_HASH_VALUE DISK_READS BUFFER_GETS      SORTS EXECUTIONS   CPU_TIME ELAPSED_TIME_S WAIT_TIME_EACH
---------- --------------- ---------- ----------- ---------- ---------- ---------- -------------- --------------
 956212347      3350531500          0           0          0 1806030210         29              0              2
這是為什麼呢。因為語句是這樣的形式。
select supdepid from mdepartment where id =''
其中這個表的id列有非空約束，還有對應的id索引，這種情況下，直接會返回0行，儘管這個表裡有百萬的資料。
所以從這些痕跡來看，這個問題是一個異常的狀態，需要和開發人員協調，到底是資料問題還是呼叫的邏輯部分出了問題。



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

相關文章