前往小程序,Get更优阅读体验!
立即前往
首页
学习
活动
专区
工具
TVP
发布
社区首页 >专栏 >关于CPU使用率高的awr分析(r8笔记第46天)

关于CPU使用率高的awr分析(r8笔记第46天)

作者头像
jeanron100
发布2018-03-19 15:12:06
8760
发布2018-03-19 15:12:06
举报
文章被收录于专栏:杨建荣的学习笔记

今天看到一个报警信息,大体是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

代码语言:javascript
复制
$ 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行,尽管这个表里有百万的数据。 所以从这些痕迹来看,这个问题是一个异常的状态,需要和开发人员协调,到底是数据问题还是调用的逻辑部分出了问题。

本文参与 腾讯云自媒体同步曝光计划,分享自微信公众号。
原始发表:2016-03-22,如有侵权请联系 cloudcommunity@tencent.com 删除

本文分享自 杨建荣的学习笔记 微信公众号,前往查看

如有侵权,请联系 cloudcommunity@tencent.com 删除。

本文参与 腾讯云自媒体同步曝光计划  ,欢迎热爱写作的你一起参与!

评论
登录后参与评论
0 条评论
热度
最新
推荐阅读
领券
问题归档专栏文章快讯文章归档关键词归档开发者手册归档开发者手册 Section 归档