—-曾令军，云和恩墨南区交付技术经理

堵塞往往是一件可怕的事情，交通堵塞让人心烦意乱，水道堵塞城市就会臭气冲天，言路堵塞则是非难辨。数据库出现会话堵塞，则很可能造成系统业务中断，这对于DBA来说，是一个非常大的考验。幸运的是，Oracle数据库产品非常成熟，有完善的日志体系、运行数据跟踪记录、全面的数据字典，可以帮助我们在遇到问题时，有迹可循有据可查。在处理这类问题时，在千头万绪的会话和数据中，理清思路正本清源，从根本上治理堵塞的问题是最重要的，这也是本文想要阐述的一个核心观点：洞若观火–治堵之道在清源。

理论容易理解，却难于上手使用，实战才是最好的老师。我们从一个案例入手，将会话堵塞问题相关的数据库基础知识与实战方法嵌入其中，一起探寻治堵的乐趣。

1.观察：把问题说清楚

在我印象中，DBA都是很明事理的人，因为这个职业经常要干的一件事情就是：“把问题说清楚，把规矩讲明白”。这是一项软技能，不管是问题分析过程中与同行沟通，还是最后给领导汇报，清楚明白是基本的要求。关于会话堵塞要说清楚的几个问题：

1. 会话增长趋势是怎样的？
2. 有没有等待事件？
3. 服务器资源消耗情况怎样？
4. 对业务的影响范围多大？

1.1. 会话的增长趋势

进入案例，查询V$SYSMETRIC_HISTORY视图，可以得出每分钟内会话数的增长趋势：

select begin_time,trunc(value) from V$SYSMETRIC_HISTORY where metric_name='Average Active Sessions' and group_id=2 order by begin_time;

  从6月26日01：28分开始，节点1的活动会话数突增，从平常的10左右增加到近160个活动会话，持续到01：50分左右恢复正常。

1.2. 等待事件情况

查询v$active_session_history视图（数据保留时间有限，没有就查历史视图），分析问题开始时间段的等待事件情况：

select trunc(sample_time,'mi'),event,count(1) from dba_hist_active_sess_history

where SAMPLE_TIME>to_date('20180626 01:26:00','yyyymmdd hh24:mi:ss')

and SAMPLE_TIME<to_date('20180626 01:31:00','yyyymmdd hh24:mi:ss') and event is not null group by trunc(sample_time,'mi'),event having count(1)>2 order by 1,3;

数据库中的等待事件通常都会很多，哪些才是与问题有关的，甄别技巧有两个：

1. 哪些是新出现的等待事件
2. 哪些是数量越来越多的等待事件

比如上图，首先从1：28分，出现library cache lock等待事件，接着在1：29分出现cursor:pin S wait on X等待事件及library cache lock，然后在1：30分开始，等待阻塞就更加严重了，主要的表现还是library cache lock伴随着cursor: pin S wait on X。那么library cache lock就是需要重点分析的事件。

服务器的资源消耗情况、业务的影响范围，这两部分数据也是需要了解的，比较简单此处没有贴出。问题现象已经明白了：

1. 数据库1：28分开始出现会话阻塞，增长速度很快
2. 阻塞时伴随着严重的library cache lock等待事件

2.分析：找到源头是关键

阻塞问题有一个共同特点：最开始都是小规模的等待，然后不断有更多的会话产生级联等待。从第一部分的现象描述中，我们已经得出信息：01:28分，出现library cache lock等待事件。沿着这条线索，继续分析ASH视图数据：

在1：28分问题刚开始的阶段，等待library cache lock的SQL语句有：31m8x89zjtfxu、b0gj1rx574uhb、c0a2qqsna22ta及33c1zf5v6t8t3，其中两个会话执行33c1zf5v6t8t3是建索引的语句，另外三个，一个是查询，一个是插入、一个是update语句，这三个语句都是在进行解析操作，等待事件都是library cache lock。

2.1. 等待事件说明

根据MOS 'library cache lock' Waits: Causes and Solutions (文档 ID 1952395.1) 文档描述我们得知，在对相关表进行DDL操作的时候，依赖于这个对象的游标会失效，导致大量的硬解析，存储过程、包或者视图失效进行重编译，而在编译的过程当中会加独占锁，而且SQL语句在解析的时候会申请library cache lock来锁定对象，如果相关对象在重编译、或者别的会话正在解析相同的语句，就获取不到锁资源，产生等待。

2.2. 等待事件与SQL

这个等待是与SQL解析有关，首先抓取到这些被阻塞的SQL语句文本（涉及到客户信息，只截取部分SQL）：

b0gj1rx574uhb

c0a2qqsna22ta

另外还有两个创建索引的会话33c1zf5v6t8t3，可以看出，这些SQL以及创建索引的操作都与H_KNS_TRAN有关

2.3. 数据库日志分析

结合上述两个部分的分析过程，library cache lock等待事件很可能是由于与H_KNS_TRAN有关的DDL语句引起，此时我们去检查数据库日志进行确认，是否存在与H_KNS_TRAN有关的DDL操作：

通过数据库日志，我们发现，在删除分区操作之后，数据库有提示索引失效的问题，并接下来还进行了split分区的操作。DDL操作必然会导致相关对象的游标失效，索引失效，进而出现大量的library cache lock等待事件。数据库做删除分区操作时，也会导致全局索引失效，这个问题在MOS文档Top Issues Encountered Regarding Split Partition (文档 ID 199623.1)有详细描述，除非split的分区表没有数据，否则SPLIT分区表的操作会导致新的分区索引失效。

  检查h_kns_tran表的索引情况，确实存在一个全局索引，而且这个全局索引每天晚上都会重建，但是由于这个索引用的并不多，而且表上还有另外一个PK主键索引，所以对系统的冲击并不大。

从这部分的分析可以得出，最根本的原因就是这些DDL操作，引起了数据库中大量的游标失效，以及索引失效，SQL需要重新硬解析，硬解析又引起了会话阻塞。但是问题来了，这些DDL操作的用途是做历史数据转移，从应用的角度来说，是不可缺少的。注意到当时处于凌晨，并发的业务量并不大。所以，还需要进一步分析阻塞的源头，以及硬解析的具体情况。

2.4. 阻塞源头分析

前面的内容都是准备阶段和分析的前奏，这部分进入了本文档最重要的环节：找源头。

第一步：找blocking_session

select sample_time,session_id,sql_id,sql_opname,event,blocking_session,blocking_session_serial# from dba_hist_active_sess_history

where SAMPLE_TIME>to_date('20180626 1:26:00','yyyymmdd hh24:mi:ss')

and SAMPLE_TIME<to_date('20180626 1:31:00','yyyymmdd hh24:mi:ss')

and event='library cache lock'

order by sample_time;

从时间线上分析，会话最早是在1:28:47秒出现阻塞，1:28:57秒这个时刻被阻塞的4个会话都是后续串连发生的。由该信息可以推断，会话3302是其他会话发生library cache lock的源头， 正在执行的语句为cc2zqqrwy84c1，这条语句也是涉及到对象H_KNS_TRAN这个视图。

第二步：分析blocking_session的运行轨迹

进一步分析该3302这个会话在问题26分到30分之间（时间范围略有放大，是为了确保开始时间的准确性）的执行情况：

select sample_time,session_id,session_serial#,sql_id,in_parse,in_hard_parse,event,p1,p2,p3,blocking_session from dba_hist_active_sess_history where session_id=3302 and session_serial#=41425 and SAMPLE_TIME>to_date('20180626 01:26:00','yyyymmdd hh24:mi:ss') and SAMPLE_TIME<to_date('20180626 01:31:00','yyyymmdd hh24:mi:ss')

order by sample_time;

从这个会话的执行情况及等待事件的轨迹数据，可以得到以下几点信息：

1. 01：28：47秒到01：29：47秒之间，该会话一直卡在cc2zqqrwy84c1这条SQL语句上，共持续了60多秒。
2. cc2zqqrwy84c1前60秒都处于In_hard_parse（硬解析）的状态，这两个字段很多人没有留意，其实对分析解析的问题非常有用。注意这个系统中设置了超时时间，如果交易60秒内不能完成，就会被强制回滚。所以从29:37秒，会话采样到的信息为读取1号system.dbf数据文件（p1参数），其实就是读了回滚段
3. 分析该SQL前60秒（硬解析过程中）的P1、P2参数，对应dba_extents视图的段信息：

select * from dba_extents where file_id=72 and (3521740 between block_id and block_id+blocks)

（结果图略）查询到的结果显示会话一直在读取H_KNS_TRAN这个表，从2017年的分区数据一直读到2018年的分区数据。

注意这里的等待事件是db file sequential read，数据文件单块读。问题来了，解析过程为什么会有单块读呢，而且是读表数据，不是索引或数据字典之类的数据？

第三步：推测最终的原因

大量表数据的单块读，只有一种情况，那就是数据动态采样。由于这条语句最终没有解析成功，从数据库中找出一条与该语句类似的SQL，通过下面这条SQL语句查询确认：

select * from table(dbms_xplan.display_awr('cc2zqqrwy84c1')); 

上图为模拟示例图，生成执行计划时，确实存在动态采样的情况，采样级别为level 4。同时检查数据库optimizer_dynamic_sampling参数，值也是4，也就是说引发阻塞的这60秒的时间，都是在对h_kns_tran表进行动态采样。而在这个采样的过程中，一直是持有该表上的解析相关的锁资源的，所以才引发了后面的大量library cache lock的等待。

2.5. 扩展知识

这里需要了解一个知识点，动态采样技术可以通过直接从需要分析的对象上收集数据块（采样）来获得CBO需要的统计信息，分成了11个级别，具体参考官方文档：Table 13-10 Dynamic Statistics Levels。Level 2是默认值，对所有的未分析表做分析，动态采样的数据块是默认数据块数为64；而Level 4采样的表包含满足Level 2和Level 3定义的表，同时还包括单表的谓词会引用另外的2个列或者更多的列。大多数SQL都会存在2个或更多列的谓词条件，所以这个范围是非常大的。如果数据库的动态采样级别设置为4，在稍微大点的表相关SQL进行硬解析的时候，很可能会触发动态采样，这在SQL执行频率特别高的OLTP系统中，是不恰当的。

总算找到了问题的根本原因，将动态采样级别降回到默认值之后，堵塞的问题就没有再发生了。找到根源，排除堵塞源头，是解决问题的关键。

3.总结：思路决定出路

不论是解决小的数据库问题，还是做大型的专项工作，思路起到了决定成败的作用。在运维工作过程中，这需要我们不断地总结和积累，把自己实战的经历、领悟到的技巧，转换成做实事的思路和经验。

对于这次问题来说，把问题说清楚并不难：

1. 最根本的原因是程序中存在对大表的DDL操作，引发了索引失效和游标失效
2. 索引失效和游标失效会引起SQL硬解析
3. SQL硬解析时发生了大表的动态采样，长时间持有锁资源，进而导致了会话阻塞现象的发生

更进一步，我们需要对这一类问题的处理思路做出总结：

1. 把问题说清楚，充分了解问题现象、时间范围、影响范围
2. 从源头入手，找到开始的时间，理清问题发生的脉络
3. 以时间为线索，重点分析阻塞会话的运行轨迹和ASH数据
4. 理论知识扎实，对看到的数据才具备敏感性
5. 充分利用MOS和官方文档等资料，协助分析，很多时候都是现学现用

更多精彩请关注“数据和云”公众号