今天看到一个报警信息，大体是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 | 7gwxpwru0czqw | JDBC Thin Client | select companyname from licens... |
| 694 | 686 | 23,024,521 | 0.00 | 6.41 | 7nkxbfnwgx93v | 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 | 7gwxpwru0czqw | JDBC Thin Client | select companyname from licens... |
| 23,024,521 | 0 | 0.00 | 0.00 | 0.00 | 7nkxbfnwgx93v | 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行，尽管这个表里有百万的数据。
所以从这些痕迹来看，这个问题是一个异常的状态，需要和开发人员协调，到底是数据问题还是调用的逻辑部分出了问题。