【天天资讯网】欢迎您,今天是2019年09月23日 星期一

当前位置: 首页 >  技术 >  正文

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

2017-09-25 14:36  来源:互联网 我来投稿 我要评论
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和相关的内存组件进行了调整,调整配置如下:

  

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

 

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

  

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

 

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

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

  

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

 

  

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

 

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

  

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

 

  

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

 

  

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

 

  

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

 

  

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

 

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

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

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

  

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

 

  

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

 

  

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

 

  

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

 

  

OLM·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%以上。

    信息推荐