关于CPU使用率高的awr分析

今天看到一个报警信息，大体是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行，尽管这个表里有百万的数据。
所以从这些痕迹来看，这个问题是一个异常的状态，需要和开发人员协调，到底是数据问题还是调用的逻辑部分出了问题。