OLM·BUG原因引发的性能故障分析与处理案例

导读：东方龙马致力数据库 | 中间件领域20余年，积累很多宝贵的业内经验和专业人才，今天由东方龙马高级工程师阮文强，向大家讲述一次因BUG原因引发的性能故障分析与处理案例。希望对你有所帮助。

一般情况下，对于ORACLE数据库来说，一说到性能问题，我们都是联想到是否SQL执行出现了性能问题?是否配置不合理?是否CPU和IO等操作系统资源使用出现问题?但最近我们遇到了一个由于ORACLE BUG引发的数据库性能问题。

背景：用户反馈有一套系统运行很慢，包括所有的操作如一般的登录、查询、编辑、报表输出都突然变得很慢，开发人员和运维人员都做了相关的检查和一般分析，但都没发现任何可疑的地方，开发人员还对中间件tomcat服务器进行了重启，运维人员也对ORACLE数据库服务重启。重启后，系统仍然很慢，最终用户不断的抱怨。

根据技术人员的反映和之前的操作，我们第一分析就是检查分析当前系统资源使用情况，发现包括Cpu、IO、内存均使用正常，然后开始把焦点放在数据库本身。

首先，从数据库中抓取AWR报告，确认一下整体上的性能问题，整体数据库时间消耗如下：

Snap IdSnap TimeSessionsCursors/Session

Begin Snap:2158928-Dec-12 09:00:231073.9

End Snap:2159028-Dec-12 10:00:251314.0

Elapsed:60.04 (mins)

DB Time:532.21 (mins)

我们可以看到，一共收集了60分钟的报告，DB TIME即数据库实际运行时间占到了532分钟，即相当于差不多9个线程核的CPU满负载运行。根据我们对这套系统了解，业务量一般不大，数据库压力也不大，我们暂时确认是数据库整体上性能问题，并判断可能是锁(包括lock锁和Latch锁)资源等待问题，然后进一步看等待事件：

EventWaitsTime(s)Avg wait (ms)% DB timeWait Class

row cache lock5,91927,841470487.19Concurrency

DB CPU7542.36

cursor: pin S wait on X26851019041.60Concurrency

direct path read46,3803910.12User I/O

log file sync9,6991210.04Commit

参考：row cache lock 解释：

Row Cache Lock：

When DDLs execute, it must acquire a row cache latch to lock the Data Dictionary information. The shared pool contains a cache of rows from the data dictionary that helps reduce physical I/O to the data dictionary tables. This allows locking of individual data dictionary rows.

我们根据后台等待事件发现，row cache lock等待事件占了87%以上，占了运行时间27841秒，相当于约450分钟以上，占了所有运行时间的约87%(27841/(532*60)=87.2%)。理论上这个事件是不能出现在TOP 5事件中的，说明当前系统性能差、数据库运行时间消耗时间长都是由row cache lock等待事件引发起。我们再去看整体时间使用模型：

Time Model Statistics

Total time in database user-calls (DB Time): 31932.9s

Statistics including the word "background" measure background process time, and so do not contribute to the DB time statistic

Ordered by % or DB time desc, Statistic name

Statistic NameTime (s)% of DB Time

parse time elapsed25,552.0080.02

hard parse elapsed time24,988.4678.25

sql execute elapsed time6,906.2921.63

根据时间模型数据，可以看到60分钟之内，用于SQL或PLSQL解释的时间就占了80%以上，即25552秒，我们可以推测出由于与共享池相关的row cache lock等待事件导致了SQL解释出现问题，并最终大量的SQL运行变成缓慢，从于引发了系统的整体上性问题。

根据上面的分析数据，我们第一步就是先确认数据库配置是否存在问题，对于我们认为不合理的配置，就是调整到相对合理或我们认为合理的配置。对于当前的配置数据，我们主要对SGA和相关的内存组件进行了调整，调整配置如下：

同时，对操作系统内核的一些参数据进行了调整：

通过调整后，根据对数据库的监控，系统性能有一点提升，可没从实质上解决整体上系统慢的性能问题。

我们继续深入分析，通过hanganalyz level 3进行跟踪，得到相关TRACE文件，关键内容如下：

我们发现，当前大量的会话都是在等待nodenum=349(session id=350)的会话，然后再看具体会话TRACE信息，如下：

从上面的信息我们发现，上面row cache lock 的引发主要是由于在执行常规SQL语句等待另一个会话(SID=350)释放相关资源，可我们发现SID=350的会话当前却未执行任何SQL，而且是空闲等待，这是非常不合理的。

这时，我们可以初步确认：当前的性能问题和相关的SQL执行并没有直接联系，很大概率是ORACLE的内部运行机制出现问题，即可能是BUG的问题!

我们通过METALINK发现该问题进一步确认是BUG方面的问题，如下：

注：具体见METALINK DOC ID：1162566.1

从上面的信息我们发现，当前系统问题与BUG 9776608有一定的符合性：

当前版本都是11.2.0.0.1

出现大量row cache lock，而且都是短的大量的row cache lock等待。

通过进一步分析系统底层调用都是ksedsts()+644<- ksdxfstk() +44<- ksdxcb()……等函数开头。

根据文档要求，该问题可升级到11.2.0.2以上版本或安装补丁包patch9776608解决问题。

随后，我们配合运维人员进行系统ORACLE数据库基于PSU补丁升级：

考虑到当前系统最新版本，我们直接把数据库升级到11.2.0.3.4版本。

考虑到系统升级的安全性，我们先对测试环境进行PSU补丁的升级，然后再对正式环境进行升级。

完成升级后，对系统进行监控，确认性能问题得到彻底解决!

附录：问题解决后前后性能对比解释

Snap IdSnap TimeSessionsCursors/Session

Begin Snap:2182807-Jan-13 09:00:17812.7

End Snap:2182907-Jan-13 10:00:26953.2

Elapsed:60.15 (mins)

DB Time:59.09 (mins)

我们同样收集系统相对压力比较大的时间段1小时的工作日志，DBTIME 只运行 59分钟，为存在性能问题时间段(之前同一时间段DBTIME为532分钟)的10分之一左右。

EventWaitsTime(s)Avg wait (ms)% DB timeWait Class

DB CPU70119.78

virtual circuit wait51,5953711.03Network

db file sequential read6,6762440.68User I/O

db file scattered read4,1632050.56User I/O

library cache lock91718950.48Concurrenc

在TOP 5事件中，不再存在row cache lock等待事件!

Time Model Statistics

Total time in database user-calls (DB Time): 3545.3s

Statistics including the word "background" measure background process time, and so do not contribute to the DB time statistic

Ordered by % or DB time desc, Statistic name

Statistic NameTime (s)% of DB Time

connection management call elapsed time2,802.1379.04

DB CPU701.3419.78

sql execute elapsed time473.9213.37

parse time elapsed218.526.16

hard parse elapsed time176.294.97

在整个系统时间模型中，解释的时间仅占到数据库运行时间的6.16%，比之前的80%以上下降了75%以上。