导读：东方龙马致力数据库 | 中间件领域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%以上。
申请创业报道，分享创业好点子。点击此处，共同探讨创业新机遇！
