详述一条SQL引发的高CPU故障处理过程 1. 问题背景 2. 问题分析过程 3. 问题结论 4. 解决方法
关注我们，下载更多资源
作者 | 刘娣，多年数据库服务经验、主要服务于移动经营商，具有丰富的数据库性能优化、故障处理经验，擅长SQL审核和性能优化。
研发反馈某核心业务数据库 dbtime 使用率相比昨天有了明显的波动。
从截图中可以看到9点到11点15分采样区间内dbtime波动明显，选取了11点到11点15分的awr报告分析。
2. 问题分析过程
2.1. 数据库负载对比
相比29号同时段awr报告，30号的数据库DBTime变化明显，可以看到Average Active Sessions由27.3变为114.4，变化非常明显。但是逻辑读、IOPS、事务量变化并不是很明显。
2.2. 查看top event
7月30日11点-11点15的awr区间内的TOP10的等待事件中，排名第一的DB CPU占比只有32.3%，加上排名第二的log file sync，总共也不过43%左右，TOP 10加在一起不超过50%。对于这种情况而言，应该是有大量的时间数据库没有计算到，常见的情况为时间消耗在CPU队列中。
从监控系统看到11点左右CPU使用率高达59%，虽然看起来CPU不到60%，但是考虑到这个值是30秒钟的平均值，很可能在短时间内出现CPU冲高，大量会话在CPU队列中等待的现象。 这是一套平均CPU使用率在20%以下的系统，基本可以推断是由于高CPU引起DBTIME波动，因此主要关注数据库中CPU排行第一的SQL，就是SQL_ID d1h5mbfv77au，对比其他时间段发现该SQL执行频率是平时的10多倍。
2.3. 定位SQL
2.3.1. SQL语义
SQL_ID：d1h5mbfv77au
select to_char(lengthb(endnum), 'FM000') || chr(0) num_length,
endnum,
beginnum,
region,
numtype
from tab t
where not exists (select 1
from tab a
where a.beginnum <= t.beginnum
and a.endnum >= t.endnum
and a.rowid <> t.rowid
and lengthb(a.beginnum) = lengthb(t.beginnum))
order by 1, 2, 3;
我们来看一下where条件的语义，是需要找到满足这样条件的2条记录，然后丢掉第二条，并且对于重复的数据全部去掉:
【第一条记录的初始号段<=第二条记录的初始号段
第一条记录的结束号段>=第二条记录的结束号段
不能是同一行并且初始号段的长度还要一样】
这个SQL有去重和去掉子号段的效果，构造出这样的两条数据，第二条的记录就是要被丢弃的：
我们选取表中不符合条件的几条记录来分析一下：
以下两条记录是重复的，需要全部丢弃掉；
以下两条记录初始号段hy00<hy_0，结束号段hyzz>hy_z，因此第二条记录就是要被丢弃的：
2.3.2. 表和索引统计信息
进一步看下表的基本统计信息，TAB表数据量5万左右：
2.3.3. 执行计划
执行计划中CPU主要消耗在hash join anti这步,对于这种子查询的SQL，可以强制子查询不展开走filter的执行计划，下面我们测试一下子查询不展开的执行计划：
filter的执行计划消耗了1000多万的逻辑读，执行时间5分钟左右，高逻辑读也会引发高CPU；
hash join anti的执行计划逻辑读756，执行计划5分钟左右，仅是对比这两个执行计划的话，还是hash join anti资源消耗更低。可是仍然有个疑问：hash join怎么会消耗这么高的cpu？
2.3.4. 回顾Hash连接
再解答这个疑问之前，我们先来回顾一下hash join连接：
Oracle7.3以后引入了hash join连接，这是一种在表连接的时候依靠hash运算得到关联结果集的表连接方法，只运行在CBO优化器中，hash join只能作用于等值连接，即使是hash反连接，Oracle实际上也是将其转化为等价的等值连接来处理。
Hash join的过程：
1、两个表做关联，根据where条件将过滤后的结果集计做A、B，假设关联列是A.ID=B.ID
2、取A中的每一条数据根据关联列ID列做两个hash运算 计做hashvalue1 hashvalue2
3、根据hashvalue1将A中的数据分作N个partition称作Ai和N个bucket(包含查询列、关联列、hashvalue2，如果Ai过大，需要将记录数最多的bucket写入temp)，同时Oracle会构建一个位图，用来标记Ai中所包含的每一个bucket是否有记录，如果Ai都在内存中，就不会启用位图过滤了。
4、读取B中的每一条记录并按照连接列ID做运算，计算出hashvalue1和hashvalue2，根据hashvalue1去Ai中寻找匹配的bucket并校验，如果在匹配的bucket中找到符合条件的记录就返回，如果找不到记录需要去访问步骤3中构造的位图，如果位图中显示该bucket在Ai中记录数大于0，那说明bucket对应的记录不在内存在磁盘，需要将B中对应的记录以partition的形式写回磁盘。
5、内存中的bucket对比结束后再对比temp中的，将temp里面的bucket里的数据根据hashvalue2重新分bucket然后匹配计算
2.3.5. 是否关联列上的函数运算消耗过多的CPU
上面SQL的关联列是【lengthb(a.beginnum) = lengthb(t.beginnum)】，我们知道在列上做运算是会消耗CPU资源的，所以开始猜测是因为对beginnum列做了运算导致消耗了非常多的CPU，我们先测试一下对列做函数运算是否会消耗大量的CPU资源：
test表的id列是没有索引的，以上两个语句走的都是全表扫描的执行计划，但是CPU时间和执行时间相差都非常大。这两个SQL的区别就是是否对id列做了运算。因此我们平时写SQL的时候，尽量避免在列上做运算，会消耗额外的系统资源。
那么我们这个SQL语句是否也是因为在关联列上做length运算导致消耗过多的cpu呢？我们继续测试对TAB表的beginnum字段做length运算，测试消耗的CPU资源是否非常大：
从上面测试结果可以看出加了length运算消耗了更多的CPU（30000-20000=10000ms），比起上面的hash join执行了5分多钟差距较大，由此可见在列上做运算的确会造成CPU资源的额外消耗，但是并不是我们这个SQL消耗CPU资源的主要原因，那么到底为什么hash join会消耗如此高的CPU呢？下面我们通过10104事件分析hash连接。
2.3.6. 10104分析为什么产生高CPU
我们知道hash join是发生在PGA中的，所以它是不消耗逻辑读的，因此上面讲的这个SQL消耗的逻辑读非常低这是能理解的，但是为什么hash join anti这一步消耗的CPU却非常高呢？
我们借助10104事件所产生的trc文件来观察一下目标SQL在做hash连接时的大致过程和一些统计信息（比如用了多少hash partition、多个hash bucket以及各个bucket中分别有多少条记录），10104事件在实际诊断hash连接的性能问题时非常有用，具体过程如下：
oradebug setmypid
oradebug event 10104 trace name context forever，level 1
set autot traceonly
oradebug tracefile_name
10104事件产生的trc文件部分内容如下：
从上面trc文件中
Number of in-memory partitions (may have changed): 8
Final number of hash buckets: 131072
Total buckets: 131072 Empty buckets: 131048 Non-empty buckets: 24
Total number of rows: 49379
Maximum number of rows in a bucket: 31356
Average number of rows in non-empty buckets: 2057.458252
Disabled bitmap filtering: filtered rows=0 minimum required=50 out of=1000
可以看出hash连接驱动结果集的行数为49379，共分配了8个hash partition，131072个hash bucket，其中有131048个空的bucket，真正存放结果集记录数的bucket有24个，包含最多的记录数的bucket所含的记录数是31356行，以及上述hash连接没有启用位图过滤。
2.3.7. 10046查看等待事件
我们继续再思考一下，在该SQL高并发执行的时候数据库有没有什么等待？我又生成了一份10046来继续分析这个问题，相关trc内容如下：
|
===================== PARSING IN CURSOR #11529215044982124440 len=431 dep=0 uid=49 oct=3 lid=0 tim=43008810081644 hv=3439201088 ad='c000000feda18a80' sqlid='c4s85nb6gw2u0' select to_char(lengthb(endnum), 'FM000') || chr(0) num_length, endnum, beginnum, region, numtype from tab t where not exists (select 1 from tab a where a.beginnum <= t.beginnum and a.endnum >= t.endnum and a.rowid <> t.rowid and lengthb(a.beginnum) = lengthb(t.beginnum)) order by 1, 2, 3 END OF STMT PARSE #11529215044982124440:c=0,e=5067,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=807524954,tim=43008810081640 EXEC #11529215044982124440:c=0,e=70,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=807524954,tim=43008810081938 WAIT #11529215044982124440: nam='SQL*Net message to client' ela= 2 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=43008810081974
然后在这里一直卡住没有继续生成trc内容，查看等待事件是 SQL*Net message to client sys@PUBDB>select event,status,sid from v$session where sql_id='c4s85nb6gw2u0'; 过了几分钟trc文件内容继续：
*** 2018-09-05 16:38:29.205 FETCH #11529215044982124440:c=367160000,e=368492595,p=0,cr=756,cu=0,mis=0,r=1,dep=0,og=1,plh=807524954,tim=43009178581250 WAIT #11529215044982124440: nam='SQL*Net message from client' ela= 863 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=43009178588631 WAIT #11529215044982124440: nam='SQL*Net message to client' ela= 2 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=43009178588735 FETCH #11529215044982124440:c=0,e=193,p=0,cr=0,cu=0,mis=0,r=100,dep=0,og=1,plh=807524954,tim=43009178588903 WAIT #11529215044982124440: nam='SQL*Net message from client' ela= 910 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=43009178589853 WAIT #11529215044982124440: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=43009178589884 FETCH #11529215044982124440:c=0,e=212,p=0,cr=0,cu=0,mis=0,r=100,dep=0,og=1,plh=807524954,tim=43009178590091 WAIT #11529215044982124440: nam='SQL*Net message from client' ela= 891 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=43009178591017 WAIT #11529215044982124440: nam='SQL*Net message to client' ela= 0 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=43009178591045 ...... |
将10046 trc文件格式化
|
Misses in library cache during parse: 1 Optimizer mode: ALL_ROWS Parsing user id: 49 Number of plan statistics captured: 2 |
从trc文件可以看到该SQL在执行过程中fetch了1014次，消耗的时间是743.88秒，花在cpu上的时间是741.62秒，消耗的一致性逻辑读是1512，fetch回的行数是101116行（对于select语句而言，有execute阶段，但是execute阶段的disk、query、current一般为0，都算在了fetch阶段）。 数据库对应的等待事件是【SQL*Net message to client和SQL*Net message from client】，下面解释一下这两个等待事件：
SQL*Net message from client
表示服务端等待着客户端发来请求，如果客户端一直没有向服务器端发送任何请求，那么在服务器端会话就会处于SQL*Net message from client等待事件
SQL*Net message to client
这个等待事件发生在一个服务器进程已经向客户端发送消息或数据并等待客户端回复的时候，这个等待事件通常被认为是一个网络等待事件，一般意味着网络瓶颈或不正确的TCP连接配置。但是它不能做为对网络延迟的准确评估或量化。
2.3.8. ASH报告查看SQL对应等待事件
生成该SQL的ash报告：
DB Time=所有前台会话等待的时间=CPU时间+IO时间+非空闲等待时间+在CPU队列中等待的时间。其中在CPU队列中等待的时间就是CPU Wait，在ASH中可以清楚的看到CPU +Wait for CPU，这个状态代表了一个会话正在使用CPU或者正在等待CPU来执行，是不算做Oracle的任何一种等待事件的。
故障时间段CPU的使用率最高达到59%，说明CPU资源并没有被耗尽，并不是因为CPU不足造成的等待。Oracle进程并不是一直持有CPU资源的，进程持有CPU一段时间后会释放CPU，然后进入CPU等待队列中，然后继续持有CPU或者其他IO资源，可以参照下面的图理解：’
3. 问题结论
到这里可以得出为什么上面的SQL执行很久都没有结束而且还造成了非常高的CPU：因为表中的数据length之后只有很少的distinct值，而表中绝大多数数据length之后的长度是一样的，因此造成单个hash bucket里面包含的记录数太多，大部分时间消耗在遍历bucket中所有的记录数，而这个扫描过程是需要CPU资源的；而因为hash join发生在PGA，所以不耗费逻辑读。
查询表中的数据验证：
所以length(beginnum)=11的bucket和length(beginnum)=13的bucket的两个桶需要内部做31356*31356+17185*17185次对比的，当然就会造成大量的CPU消耗。
4. 解决方法
这是一个刷新共享内存的SQL，同时会有几十个进程并发刷新，并发量一旦增加就会造成CPU波动明显，研发修改程序将原来的10分钟刷新一次改为半小时刷新一次，相当于控制了并发，问题得到缓解。
但是仅依靠降低并发只能暂时缓解这个问题，后续又跟研发商讨出以下解决方案：
1）新增一个表把不满足条件的结果集保存下来，并增加一个进程定期去更新该表(该表数据量较小，只有一千多条)，只有一个进程执行这个操作：
create table tab_child as
select *
from tab t
where exists (select 1
from tab a
where t.beginnum >= a.beginnum
and t.endnum <= a.endnum
and a.rowid <> t.rowid
and lengthb(a.beginnum) = lengthb(t.beginnum));
2）把子查询的表替换成上述新增的表，由于子查询的表数据量只有1000多条，hash连接的成本降低明显：
select to_char(lengthb(endnum), 'FM000') || chr(0) num_length,
endnum,
beginnum,
region,
numtype
from tab t
where not exists (select 1
from tab_child a
where a.beginnum <= t.beginnum
and a.endnum >= t.endnum
and lengthb(a.beginnum) = lengthb(t.beginnum))
order by 1, 2, 3;
就这个问题后续我又咨询了杨长老，他认为对于这种对自关联的SQL语句，使用分析函数改写会有非常好的效果，上面的这个SQL效率低是因为自关联的条件的选择度很差，需要靠不等条件来过滤数据，而分析函数避免了自关联，改写之后SQL变成了一个单表扫描，执行时间由5分多钟降为1.35秒，性能提升非常明显：
我们关注一下max(endnum) over(partition by lengthb(beginnum) order by beginnum, endnum desc) endnum这个分析函数，其ORDER BY语句中包含了beginnum，endnum desc，这说明这个max()函数获取的窗口范围是按照beginnum从小到大、endnum从大到小的排序，其实就是包含了原SQL语义中想要的beginnum最小+endnum最大的要求，然后我们通过row_number() over(partition by lengthb(beginnum), endnum order by beginnum) rn =1和count(*) over(partition by lengthb(beginnum), oldendnum, beginnum) cn=1去掉所有子号段和重复的数据，这样就保持了和原SQL同样的语义。
Oracle里的优化需要联系实际业务，有时候理解了业务场景的含义，对于我们优化SQL会有很大的帮助，上面的这则case就是根据业务含义进行了适当的改写，改写之后性能提升明显：
我们日常需要注意的是尽量避免在列上做运算，一个简单的id=1 和id+1=2，消耗的资源可能会相差很大；
如果遇到了自关联的SQL，分析函数是避免自关联的利器，可以尝试进行改写。
实际情况中并不是所有的问题SQL在数据库层面都有优化的方法，有些时候SQL就是没有条件没有办法进一步优化，这种情况下业务层面的调整、加并发或者控制执行频率都是可以考虑的方式。
原创：刘娣
资源下载
关注公众号：数据和云（OraNews）回复关键字获取
2018DTCC , 数据库大会PPT
2018DTC，2018 DTC 大会 PPT
DBALIFE ，“DBA 的一天”海报
DBA04 ，DBA 手记4 电子书
122ARCH ，Oracle 12.2体系结构图
2018OOW ，Oracle OpenWorld 资料
PRELECTION ，大讲堂讲师课程资料
近期文章Oracle研发总裁Thomas Kurian加盟Google Cloud
Oracle 18c新特性:动态 Container Map 增强 Application Container 灵活性
Oracle 18c新特性:Schema-Only 帐号提升应用管理安全性
Oracle 18c新特性:多租户舰队 CDB Fleet (含PPT)