今天看到一個報警資訊，大體是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
28345
oracle 16 0 6283m 874m 867m R 82.6 5.5 3:54.84 oracletest
28425
oracle 16 0 6281m 689m 682m S 82.6 4.3 3:50.17 oracletest
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
Physical writes:
1.25
User calls:
39,104.93
6.01
Parses:
13,033.74
2.00
Hard parses:
4.75
Sorts:
12.16
Logons:
0.07
Executes:
13,035.13
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
.7
Network
latch: cache buffers chains
79,297
8
.1
Concurrency
cursor: pin S
71,807
Other
log file sync
7,136
1
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
13.57
<a href="#7gwxpwru0czqw">7gwxpwru0czqw</a>
JDBC Thin Client
select companyname from licens...
694
686
23,024,521
6.41
<a href="#7nkxbfnwgx93v">7nkxbfnwgx93v</a>
select supdepid from mdepart...
那麼怎麼看出語句存在問題呢。可以在executions部分找到一些痕迹。
Rows Processed
Rows per Exec
CPU per Exec (s)
23,440,315
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行，盡管這個表裡有百萬的資料。
是以從這些痕迹來看，這個問題是一個異常的狀态，需要和開發人員協調，到底是資料問題還是調用的邏輯部分出了問題。
![Java小案例——随機數猜測随機數猜測[圖]](data:image/gif;base64,R0lGODlhAQABAIAAAP///wAAACwAAAAAAQABAAACAkQBADs=)