一次Oracle bug的故障排查过程思考

问题现象：

一套十几个TPS的系统被执行2分钟(00:30-00:32)的夜维(删除历史过期的数据)搞挂了。

初步分析：

通过应用日志，定位到应用处理都卡在了一条SQL语句上，这个SQL要更新一个包含4个CLOB列的表，有的update操作执行时间超过了10秒，形如，

update A set a=:1, b=:2, c=:3 ... where id=:10 and update_time=:11;

通过夜维日志，定位到在应用出现卡顿的时间内，夜维正在执行删除这张A表的操作，SQL中会接受删除日期和一次删除的条数作为参数，分别是90和10000，表示一次删除10000条90天以前的历史数据(一天大约20万)，日志记录了一次删除10000条的用时，都在6-10秒内，和前几日的执行时间相比，基本一致，并未出现异常，

delete from A where update_time <= trunc(sysdate) - :1 and rownum <= :2

通过操作系统oswtop监控的信息，发现故障期间，数据库服务器的CPU idle曾降低到0%，正常时间段内，CPU idle通常是80%-90%，所以故障期间，应该是什么操作，极度消耗CPU。

通过数据库AWR，看到resmgr:cpu quantum排在榜首，

在故障时间段内，看到业务的update和夜维的delete操作等待事件的信息，尤其update操作，等待的就是resmgr:cpu quantum，

这个等待事件，参考了eygle的文章(https://www.eygle.com/archives/2011/07/events_resmgr_cpu_quantum.html)，提示这个问题是和资源管理相关的，如果启用资源管理计划，就可能遇到这个问题。如果确认性能受到了资源管理期的影响，常规的解决方案是禁用资源管理，禁用缺省的维护计划(DEFAULT_MAINTENANCE_PLAN Metalink:786346.1)。

经过确认，每天00:00-02:00，启动了缺省的维护窗口，为了保障一些后台任务的执行，update等待resmgr:cpu quantum很可能是因为更新操作消耗了太多的CPU，触发了Oracle对update操作的资源限制，所以应该是正常现象，因此，找到update消耗更多CPU才是问题的关键。

通过SQL AWR，确认update语句的执行计划只有一个，而且用的INDEX UNIQUE SCAN，相对来说是很高效的，

通过计算，发现故障期间，一条update操作消耗的逻辑读高达20多万，而正常时间段，一条update操作仅消耗20多。

基于以上信息，初步得到问题的主线，夜维执行期间，正常业务的update操作逻辑读超高(20多万)，消耗CPU异常，导致Oracle启动了资源限制，限制了更新操作CPU的使用，等待事件是resmgr:cpu quantum，update操作变慢了，前面的请求未处理完成，后面的请求就进入了等待队列，发生了雪崩效应，进而搞挂了应用。

现在的问题是，为什么故障期间，一条update操作消耗的逻辑读如此之多？

应用逻辑：

梳理下应用逻辑，出现问题的功能，是记录流水信息，大致的操作步骤，

1. insert一条记录，其中包括插入第一个CLOB列。
2. update这条记录的第二个CLOB列。
3. update这条记录的第三个CLOB列。
4. update这条记录的第四个CLOB列。

其中CLOB是个大报文，从容量看，这张表是100G，其中一个CLOB是300G，另外三个CLOB将近100G。

深入分析：

数据库是11.2.0.4，根据故障的现象，一条update操作在delete删除的同时，逻辑读超高。MOS上有这个bug描述，Bug 19791273 - Poor UPDATE SQL performance due to space search cache for updates on ASSM segment (Doc ID 19791273.8)

指出当使用ASSM位图管理段的时候，可能因为对update开启了space search cache的功能而导致update性能降低。

出现这个问题，另外有个前提，就是已经修复了13641076这个bug(换句话说，很可能是因为修复了13641076这个bug，而引出了19791273这个bug，数据库是11.2.0.4，包含了13641076的patch)，这个bug。13641076这个bug，是让update和insert操作一样能使用space search cache功能，尽管这会降低update的一些性能。

19791273这个bug的fix，会对update操作禁用space search cache，避免性能过载。作为这个fix的替代方案，就是设置10019事件。

space search cache是什么？那再看下13641076这个bug，Bug 13641076 - High buffer gets for insert statement - rejection list does not fire - superseded (Doc ID 13641076.8)，

这个bug同样和ASSM空间管理相关，指出当存在一个并发未提交的大数据量delete操作时，insert操作会消耗大量buffer gets。在这种情况下，insert首次尝试寻找段空闲空间的时候，需要访问很多的块数据，但是下次执行时，就会访问一个“黑名单”列表(即space search cache)，其中标记了哪些块不可用，因此利用这个“黑名单”就可做到避免读取那些不可用的块。但是这个“黑名单”是基于游标的，如果DML游标关闭，下次打开新游标，“黑名单”就需要重建。因此这个fix所要做的就是让“黑名单”改为基于会话，而不是游标。换句话说，推测这个cache会存储在PGA中，基于会话存储。

因此，当存在一个并发未提交的大数据量delete操作，而insert操作消耗了超高的buffer gets，同一个会话下次访问相同对象的时候，利用这个fix，就能从这个“黑名单”缓存中得到性能的提升。

有些蒙圈了，我们重新梳理这两个bug，首先，第二个bug(13641076)，是说当存在一个并发未提交的大数据量delete操作时，insert操作会消耗大量逻辑读，原因就是在ASSM下寻找段空闲空间时需要访问的space search cache是基于游标的，下次使用新游标，会导致space search cache重建，因此这个bug对应的fix，会让这个“黑名单”改为基于会话，而不是游标。13641076这个bug，是让update和insert操作一样能使用space search cache功能，尽管这会降低update的一些性能。但是因为这个bug，引入了另一个bug(19791273)，他会让更新update操作在使用space search cache的时候出现性能问题，对应这个fix，会让update禁用space search cache，以缓解性能问题，他的替代方案，就是设置10019事件。

初步定位到这个bug，那就顺着看，能不能通过patch解决，19791273的patch在11.2.0.4.17和19中都有，唯独没18的，但我们的数据库，恰巧就是18，而且尝试使用这两个patch，都出现了和当前PSU冲突的提示，

从这张图上，可以看出让Oracle给个18的patch，更困难些。。。

所以，在数据库层面，通过patch解决问题就比较难了，根据MOS，另一种方案，就是设置10019事件，关闭space search cache。

第一次测试：

在DG备库，开启snapshot闪回，在一个PLSQL Developer中手工执行delete批量删除的操作，模拟夜维，在另一个PLSQL Developer中利用从数据库提取的业务数据拼接出的update语句，执行更新操作，模拟业务。

update操作在更新CLOB列的时候，需要向空值处填充一个很大的值，可能出现当前块无法容纳所要更新的内容，需要找到新的块空间操作，因此可能进入到上面bug描述的场景中。

发现确实出现了update逻辑读高的现象，大约2万多。设置10019事件，再次执行上述的操作，逻辑读降到200多，

alter system set events '10019 trace name context forever, level 1';

但是当进行第二次测试的时候，注意此处使用的数据，无论是delete还是update都和首次相同，即使未设置10019事件，并未出现逻辑读高的现象。

对他的猜测，很可能是首次delete和update，update已经找到了新的块空间，再次做相同数据的测试，虽然从数据层面来看，是从0变成了大值(CLOB)，但是从块空间看，是可以重用的，无需申请新的块空间，所以未出现逻辑读高的现象。

第二次测试：

在生产环境中，设置了10019事件，执行夜维程序，发现日志记录删除到第10次10000的时候，数据库的CPU idle开始下降，业务服务的响应时间开始飙升，此时为了避免出现问题，及时kill了程序。难道是10019未生效？还是未启作用？bug的定位有问题？

推测是这样，虽然设置了10019事件，关闭space search cache，但上面说了，这个cache是基于会话级别的，因此只有重新创建会话(PGA)，所做操作，才能生效，应用使用的是连接池，所以要么重启连接池，或者重启数据库节点，否则当前会话，还是会使用sapce search cache。

DG备库测试的时候，无论是重启数据库节点，还是重新打开PLSQL Developer，每次都相当于一个新连接，和这个测试不同。

在这次测试中，发现了另外一个问题，虽然夜维程序每次日志记录了删除10000条记录，但实际上他是执行了所有delete表数据的操作，才做了commit，并未真正实现批量提交，因此和上面bug提到“a concurrent uncommitted large DELETE”更加吻合。

解决方案：

1.数据库层面，设置10019事件，应用重启连接池(相比重启数据库节点成本要低)，或许即使不改夜维的批量提交，这个问题也能得到解决。

2.应用层面，夜维程序增加真正的批量提交，降低一次delete操作涉及的数据块个数，减少space search cache的重建，避免出现“a concurrent uncommitted large DELETE”的场景，即使没打patch，应该能减小影响。

3.应用层面，考虑使用分区表，drop partition的方式，将数据删除时间降到最低。但是，如果原表改为分区表，会导致全局索引重建。可以换另外的一种思路，修改业务逻辑，将这几个CLOB单独创建成一张interval的间隔分区子表，按天做分区，业务操作的时候，关联主子表，夜维操作的时候，drop partition直接删除分区，让CLOB的删除操作几乎瞬时完成，将update受到delete影响的可能性，将到最低。

其实，从应用设计角度来看，无论patch、10019事件是否有作用，夜维程序做到批量提交，还是需要的，毕竟即使不会触发逻辑读高的问题，这种未提交的大事务，还是会对UNDO等资源有冲击，而且若从业务逻辑上看，更是没这必要，不用关心数据是不是一次能全部删除，即使中间异常了，只是删除了部分的数据，再执行就可以了，数据之间，不存在任何关联。因此，这个问题虽然根源是数据库的一个bug，但实际上也考察了开发人员对delete删除的原理、UNDO的原理、批量提交的原理的理解，以及应用的设计。