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

逃离我推掉我的手 2023-08-17 16:58 9阅读 0赞

**问题现象**：

一套十几个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排在榜首，

![640?wx\_fmt=png][640_wx_fmt_png]

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

![640?wx\_fmt=png][640_wx_fmt_png 1]

这个等待事件，参考了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，相对来说是很高效的，

![640?wx\_fmt=png][640_wx_fmt_png 2]

通过计算，发现故障期间，一条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)

> This bug is only relevant when using ASSM Space Management (Bitmap Managed Segments)
> 
> This problem can occur if the fix for bug 13641076 is present. That fix enables the use of space search cache in updates as well as inserts but this can degrade the performance of the UPDATE SQL operations.
> 
> This fix disables the space search cache for UPDATE operations to avoid the performance overhead.
> 
> Workaround

指出当使用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)，

> This bug is only relevant when using ASSM Space Management (Bitmap Managed Segments)

这个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冲突的提示，

![640?wx\_fmt=png][640_wx_fmt_png 3]

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

![640?wx\_fmt=png][640_wx_fmt_png 4]

所以，在数据库层面，通过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的原理、批量提交的原理的理解，以及应用的设计。

[640_wx_fmt_png]: /images/20230809/1c51e5343b50414a9c8236da5b64bffb.png
[640_wx_fmt_png 1]: /images/20230809/d99eb24437f84f5b8276959cb1090458.png
[640_wx_fmt_png 2]: /images/20230809/df4fe72c0f524a7dbb4bf5d91cf2aba3.png
[640_wx_fmt_png 3]: /images/20230809/bcced8a46cf4447eb26747d3b9c29e87.png
[640_wx_fmt_png 4]: /images/20230809/b29cb73c757d40689e2c1269b1ced3c3.png