执行计划变化导致CPU负载高的问题分析 (r8笔记第20天)

前几天碰到一个CPU负载较高的问题。从系统层面来看,情况不是很严重,但是从应用的角度来说,已经感觉到很慢了。因为前端的调用频率还是比较高。所以会把这个问题放大。 使用top -c查看了基本的服务器信息。可以看到负载大概在30%左右。IO wait不高。

top - 19:30:48 up 179 days,  4:54,  3 users,  load average: 4.43, 4.28, 4.14
Tasks: 669 total,   6 running, 661 sleeping,   0 stopped,   2 zombie
Cpu(s): 24.1%us,  3.4%sy,  0.0%ni, 69.0%id,  0.0%wa,  0.0%hi,  3.4%si,  0.0%st
Mem:  32949016k total, 32835380k used,   113636k free,   292028k buffers
Swap: 16771776k total,  4563936k used, 12207840k free, 25528396k cached

而首当其冲的几个进程都是CPU利用率100%

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+   COMMAND                  
 9014 oracle    18   0 16.1g 1.1g 1.1g R 100.0  3.5  13:01.09 oraclexxx  (LOCAL=NO)      
 9024 oracle    16   0 16.1g 1.5g 1.5g R 100.0  4.8  36:31.23 oraclexxx  (LOCAL=NO)      
 9100 oracle    17   0 16.1g 1.1g 1.1g R 100.0  3.4   8:34.87 oraclexxx  (LOCAL=NO)       
22975 root      15   0 13164 1568  812 R 100.0  0.0   0:00.04 top  -c                         

看看这几个进程在干嘛?发现都在执行相同的sql语句。 $sh showpid.sh 9014 SQL_ID SQL_TEXT ------------------------------ ------------------------------------------------------------ 5h92pf9xtbps4 UPDATE SWD_DRAWCN SET WEAPONLISTNO=:1,IP=:2, ROLE_NAME=:3, GROUP_ID=:4, SERVER_IP=:5, SERVER_NAME=:6, ROLE_GUID=:7, ROLE_LEVEL=:8, DRAWED='Y',DRAWDATE=sysdate,SN_GET=:9 WHERE ID=:10 AND CN=LOWER(:11) AND DRAW_TYPE=:12 PREV_SQL_ID SQL_TEXT ------------------------------ ------------------------------------------------------------ 5h92pf9xtbps4 UPDATE SWD_DRAWCN SET WEAPONLISTNO=:1,IP=:2, ROLE_NAME=:3, GROUP_ID=:4, SERVER_IP=:5, SERVER_NAME=:6, ROLE_GUID=:7, ROLE_LEVEL=:8, DRAWED='Y',DRAWDATE=sysdate,SN_GET=:9 WHERE ID=:10 AND CN=LOWER(:11) AND DRAW_TYPE=:12 所以看起来很有可能是sql语句导致的问题。从最近的快照里面的sql对应的db time使用情况可以看出,5h92pf9xtbps4竟然有三行内容。这个当然是从awr报告里面直接看不到的。 $ sh showsnapsql.sh 105206 Current Instance ~~~~~~~~~~~~~~~~ DBID DB_NAME INST_NUM INST_NAME ---------- --------- ---------- ---------------- 1720209052 XXX 1 xxx SNAP_ID SQL_ID EXECUTIONS_DELTA ELAPSED_TI PER_TOTAL ---------- ------------- ---------------- ---------- ---------- 105206 5h92pf9xtbps4 6783 6863s 96% 105206 5h92pf9xtbps4 0 6863s 96% 105206 5h92pf9xtbps4 47032 6863s 96% 所以初步感觉是执行计划发生了变化,如果从这个思路来看,这个问题似乎也能说得通了,为什么之前没有问题,现在有问题了。 我们来看看awr报告里面怎么说。

Elapsed Time (s)

CPU Time (s)

Executions

Elap per Exec (s)

% Total DB Time

SQL Id

SQL Module

SQL Text

12,605

12,605

113,557

0.11

96.90

5h92pf9xtbps4

xxxtest@BJ-YF-4-166 (TNS V1-V3)

UPDATE SWD_DRAWCN SET WEAPONLI...

当然这个语句可以看出这个语句还是有些问题。可以用coe的脚本看出,这个语句存在3个不同的执行计划,而且执行计划之间的差别看起来差别不是很大,但是在调用频繁的系统中,这个影响就会被放大。 SQL_ID: 5h92pf9xtbps4 PLAN_HASH_VALUE AVG_ET_SECS --------------- ----------- 2762405514 .037 889840933 .103 3278101387 .194 从awrsqrpt里面得到一些更具体的信息,可以看到第一个执行计划较好的语句在1个小时内执行次数近1万多次。而第二条执行频率高了很多10万多次,但是执行时间要低很多。第三个执行计划执行次数为0.

#

Plan Hash Value

Total Elapsed Time(ms)

Executions

1st Capture Snap ID

Last Capture Snap ID

1

3278101387

12,227,848

12,610

105205

105206

2

2762405514

377,370

100,947

105205

105206

3

889840933

0

0

105205

105206

所以针对这种情况,我把注意力放在了前两个执行计划上。 来看看语句的索引情况,对应的表有两个索引,一个字段建立在draw_type上,另外一个建立在类似id的字段CN上。这个表中的数据有1千万左右。 PLAN hash value为3278101387的执行计划为:

Id

Operation

Name

Rows

Bytes

Cost (%CPU)

Time

0

UPDATE STATEMENT

62 (100)

1

UPDATE

SWD_DRAWCN

2

TABLE ACCESS BY INDEX ROWID

SWD_DRAWCN

1

111

62 (0)

00:00:01

3

INDEX RANGE SCAN

IND_DRAWCN_TYPE

8465

9 (0)

00:00:01

而PLAN hash value为2762405514的执行计划为:

Id

Operation

Name

Rows

Bytes

Cost (%CPU)

Time

0

UPDATE STATEMENT

48 (100)

1

UPDATE

SWD_DRAWCN

2

TABLE ACCESS BY INDEX ROWID

SWD_DRAWCN

1

123

48 (0)

00:00:01

3

INDEX RANGE SCAN

IND_SWD_DRAWCN_CN

891

2 (0)

00:00:01

看两个执行计划,貌似差别也不大。但是这种细微的差别的影响就导致了执行时间近40倍的差别。 为什么之前有问题,现在没有,如果查看以前的执行情况,是肯定走了CN的索引,而现在出现问题是走了TYPE的索引。 为什么执行计划发生了一些改变,还是和统计信息的情况和统计信息收集的一些规则有关。 那么这个问题基本已经有了方向,怎么修复呢。主要有两种思路,一种是重新收集统计信息,尽可能创建符合索引CN,TYPE, 第二种思路就是修改执行计划,让语句执行目前最优的执行计划,这个时候,sqlprofile就派上大的用处了。 打开coe脚本,把原来的outline部分修改为下面的形式

h := SYS.SQLPROF_ATTR(
q'[BEGIN_OUTLINE_DATA]',
q'[IGNORE_OPTIM_EMBEDDED_HINTS]',
q'[OPTIMIZER_FEATURES_ENABLE('10.2.0.4')]',
q'[OPT_PARAM('optimizer_index_cost_adj' 30)]',
q'[OPT_PARAM('optimizer_index_caching' 90)]',
q'[ALL_ROWS]',
q'[OUTLINE_LEAF(@"UPD$1")]',
q'[INDEX_RS_ASC(@"UPD$1" "SWD_DRAWCN"@"UPD$1" ("SWD_DRAWCN"."CN"))]',
q'[END_OUTLINE_DATA]');  

然后替换,回车以后马上查看top情况,发现问题马上缓解了下来, 等了几分钟,可以看到确实cpu利用率降下来了。当然这种情况处理完之后,从业务的反馈已经正常了。 但是对于这个问题目前的方案还是一个临时解决,还是需要持续改进。

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

原文发表时间:2016-02-25

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

发表于

我来说两句

0 条评论
登录 后参与评论

相关文章

来自专栏数据和云

追本溯源:Oracle 只读表空间的探索实践

作者简介 ? 胡中豪 云和恩墨西区交付工程师,多年一线 DBA 经验,曾服务于运营商、电网、政府行业、银行等行业客户;擅长数据库故障处理、性能优化、实施升级 本...

2913
来自专栏乐沙弥的世界

Oracle 角色、配置文件

增加或删除角色中的某一权限,被授予该角色的所有用户或角色自动地获得新增权限或删除旧的权限

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

关于dual表的破坏性测试(r3笔记第60天)

关于dual表的破坏性测试,既然是破坏性测试,就需要确定这个测试仅限于测试或者个人学习所用,可能有些sql看似极为简单,但是一旦运行就会导致整个业务系统崩溃。 ...

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

一个普通数据库用户所能查到的"意料之外"的信息(r2笔记98天)

有时候限于工作环境的情况,大多数开发人员只得到了一个权限收到限制的数据库用户。 可能你都不知道你所拥有的数据库用户都能查到哪些你想象不到的数据库信息,其实你知道...

3448
来自专栏沃趣科技

应用示例荟萃 | performance_schema全方位介绍(上)

经过前面6个篇幅的学习,相信大家对什么是performance_schema,已经初步形成了一个整体认识,但我想很多同行看完之前的文章之后可能还是一脸懵逼,今天...

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

不经意发现的dba_objects和dba_tables中的细节(r7笔记第56天)

今天有一个同学问我一个问题,因为白天比较忙也没有在意,在下班后坐地铁的时候抽空看了这个问题,感觉还是蛮有意思的。但是当时也没有任何答案,就准备自己回去好好实验一...

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

深度解析dba_segments和sys.seg$中的细节差异(上) (r5笔记第27天)

今天在查看系统空间使用情况的时候,发现一个细节的问题,自己死磕了一把,还是发现了不少有价值的东西。 事情的起因是我在使用脚本在某个环境中查看每个用户所占有的空间...

3598
来自专栏idba

死锁案例之四

一 前言 死锁,其实是一个很有意思也很有挑战的技术问题,大概每个DBA和部分开发同学都会在工作过程中遇见 。关于死锁我会持续写一个系列的案例分析,希望能够对想...

883
来自专栏乐沙弥的世界

RAC环境下的阻塞(blocking blocked)

      RAC环境下的阻塞不同于单实例情形,因为我们需要考虑到位于不同实例的session。也就是说之前查询的v$session,v$lock相应的应变化为...

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

ORA-01427问题的分析和解决(r6笔记第51天)

前几天开发的同事反馈一个问题,说前台系统报出了ORA错误,希望我们能看看是什么原因。 java.sql.SQLException: ORA-01427: sin...

2824

扫码关注云+社区

领取腾讯云代金券