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

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

原文发布于微信公众号 - 杨建荣的学习笔记(jianrong-notes)

原文发表时间:2016-03-22

本文参与腾讯云自媒体分享计划,欢迎正在阅读的你也加入,一起分享。

发表于

我来说两句

0 条评论
登录 后参与评论

相关文章

来自专栏乐沙弥的世界

Failed to upgrade Oracle Cluster Registry configuration(root.sh)

    最近在给客户基于Suse 11 sp3安装Oracle 10g RAC,在安装完clusterware执行/u01/app/crs/root.sh时收...

961
来自专栏JavaNew

Spring Boot实战:数据库操作

43615
来自专栏数据库新发现

使用Oracle Wrap工具加密你的代码

Last Updated: Monday, 2004-11-15 22:31 Eygle

1132
来自专栏aoho求索

Spring Boot集成MyBatis实现通用Mapper

关于MyBatis,大部分人都很熟悉。MyBatis 是一款优秀的持久层框架,它支持定制化 SQL、存储过程以及高级映射。MyBatis 避免了几乎所有的 JD...

5101
来自专栏乐沙弥的世界

mydumper安装及安装故障汇总

   mydumper是针对mysql数据库备份的一个轻量级第三方的开源工具,备份方式术语逻辑备份。它支持多线程,备份速度远高于原生态的mysqldump以及众...

1610
来自专栏蓝天

零停重启程序工具Huptime研究

零停重启目标程序,比如一个网络服务程序,不用丢失和中断任何消息实现重新启动,正在处理的消息也不会中断和丢失,重启的方法是给目标程序的进程发SIGHUP信号。...

881
来自专栏Bug生活2048

Spring Boot学习笔记(五)整合MyBatis实现数据库访问

这里主要依赖两个,一个是连接MySql的`mysql-connector-java`,还一个是SpringBoot整合MyBatis的核心依赖`mybatis-...

1022
来自专栏软件开发

Spring MVC 学习总结(十一)——IDEA+Maven+多模块实现SSM框架集成

与SSH(Struts/Spring/Hibernate/)一样,Spring+SpringMVC+MyBatis也有一个简称SSM,Spring实现业务对象管...

2902
来自专栏杨建荣的学习笔记

关于exp statistics的问题和简单测试(82天)

在数据导出的时候,可能会碰到EXP-00091: Exporting questionable statistics.的问题,有时候会让人有点摸不到头脑,不知道...

2288
来自专栏bboysoul

linux编译安装apache

wget http://mirrors.ustc.edu.cn/apache/httpd/httpd-2.4.25.tar.gz tar -zxvf http...

2853

扫码关注云+社区

领取腾讯云代金券