执行计划变化导致CPU负载高的问题分析

前几天碰到一个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, G
                               ROUP_ID=:4, SERVER_IP=:5, SERVER_NAME=:6, ROLE_GUID=:7, ROLE
                               _LEVEL=:8, DRAWED='Y',DRAWDATE=sysdate,SN_GET=:9 WHERE ID=:1
                               0 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, G
                               ROUP_ID=:4, SERVER_IP=:5, SERVER_NAME=:6, ROLE_GUID=:7, ROLE
                               _LEVEL=:8, DRAWED='Y',DRAWDATE=sysdate,SN_GET=:9 WHERE ID=:1
                               0 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利用率降下来了。当然这种情况处理完之后,从业务的反馈已经正常了。
但是对于这个问题目前的方案还是一个临时解决,还是需要持续改进。

时间: 2024-11-03 07:18:08

执行计划变化导致CPU负载高的问题分析的相关文章

oracle 执行计划改变导致数据库负载过高解决办法

数据库主机负载 这里明显表现系统load 偏高,而且还在上升中:top的进程中,占用cpu都计划100% top - 16:25:39 up 123 days,  1:42,  4 users,  load average: 46.19, 45.08, 43.93 Tasks: 1469 total,  28 running, 1439 sleeping,   0 stopped,   2 zombie Cpu(s): 45.9%us,  1.1%sy,  0.0%ni, 47.1%id,  5

关于SQL执行计划错误导致临时表空间不足的问题_oracle

故障现象:临时表空间不足的问题已经报错过3次,客户也烦了,前两次都是同事添加5G的数据文件,目前已经达到40G,占用临时表空间主要是distinct 和group by 以及Union all 表数据量在200W左右,也不至于把40G的临时表空间撑爆. 原因分析:既然排序用不了这么多临时表空间应该是别的原因造成. 从包含故障时间段的AWR报告中可以看出这一阶段DBtime蛮高的,并且sql execute elapsed time 竟然占到了99.43%,可以断定是SQL语句引起的. 通过TOP

[20131121]奇怪的执行计划变化.txt

[20131121]奇怪的执行计划变化.txt SCOTT@test> @verBANNER--------------------------------------------------------------------------------Oracle Database 11g Enterprise Edition Release 11.2.0.3.0 - 64bit Production create table t pctfree 99 as select rownum id,l

关于执行计划中的%CPU的含义

今天突然想起前段时间学习的一篇博客,是oaktable的Charles Hooper所写,链接为: https://hoopercharles.wordpress.com/2010/02/19/what-is-the-meaning-of-the-cpu-column-in-an-explain-plan/ 自己也趁机消化了一下.对于执行计划中的 列Cost (%CPU),其中的%CPU的含义很少有人能够说得清楚,于是Charles Hooper写了上面的文章来解释. 对于执行计划的信息都会放入

一条SQL语句的执行计划变化探究

最近有个同事碰到一个问题,想让我给点思路.我大体了解了一下,是一个系统目前在做压力测试,但是经业务反馈发现某个环节的处理时间有些长,排查了一圈,最后这件事情就落在了DB这边,希望DB能够给点意见,是否存在一些性能瓶颈.     我们从开发同学那里得到的一个基本的SQL语句,根据关键字从v$sql中做了提取,发现对应的SQL语句的执行时间还是OK的. 得到的SQL语句如下:SQL_ID        SQL_FULLTEXT ------------- ----------------------

一条SQL语句的执行计划变化探究(r10笔记第9天)

继续上次分析的一个问题,一个简单的SQL语句执行计划有些奇怪,明明可以走唯一性索引但是却走了另外一个索引. 当然了,最后逐步定位,发现是在直方图的地方有一些差别.取消直方图之后,执行计划立刻恢复了正常. 当然问题来了,这个是为什么呢,收集统计信息中的auto选项是什么含义呢.为什么两个数据类型一样的(varchar2(64))的列,境遇却大大不同. 我们来看看一些统计信息的数据. 为了跟进一步验证数据的分布律和选取代价,我们查询它的直方图信息. SQL>   select to_char(end

关于CPU使用率高的awr分析

今天看到一个报警信息,大体是CPU使用异常. ZABBIX-监控系统: ------------------------------------报警内容: CPU utilization is too high ------------------------------------报警级别: PROBLEM ------------------------------------监控项目: CPU idle time:55.17 % ------------------------------

Mysql数据库导致CPU很高的问题解决

服务器环境 Liunx AS4 + PHP5 + Mysql5 + Apache 2 实用TOP 命令查询系统性能的时候发现CPU经常到达100% 开始以为是DDOS攻击--加装了防火墙(没起作用) 又开始从liunx系统查找是不是系统问题,(也没起作用) 偶尔从网络上发现一篇文章,有人也类似遇到了这样的问题,但并没指出具体解决方案, 不过提醒了我,不是系统问题就是程序问题! 这次我开始从新过滤PHP代码,偶尔发现很多兄弟写的代码只有"常"连接,竟然没有Close! 我把所以的页面都加

java程序启动时cpu和负载高探索

这两天协助运维定位1个监控程序CPU占用率达到150%的问题,过程曲折,结论简单,很有意思:) 首先我们来看一下cpu高时候截图: 可以看到红色框中的监控程序CPU占用率都很高,但其实这些监控程序的实现很简单:发送1个http请求,收到响应后简单判断一下响应码,然后打印监控结果,打印完成就退出了.每次监控都会重新由daemon程序拉起运行. 这么简单的业务占用这么高的cpu,怎么感觉都不太可能,于是拿到监控程序的源码开始定位. 第一个想到的是VisualVm.JConsole等工具,但由于程序很