当前位置:首页 >  站长 >  编程技术 >  正文

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

 2017-09-25 14:36  来源: 互联网   我来投稿 撤稿纠错

  域名预订/竞价,好“米”不错过

导读:东方龙马致力数据库 | 中间件领域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%以上。

申请创业报道,分享创业好点子。点击此处,共同探讨创业新机遇!

相关文章

热门排行

信息推荐