数据库性能问题导致应用单次SQL效率10ms变为10s

昨日,同事发来一则微信反馈前一天晚应用SQL查询缓慢,原本10ms内能完成的查询SQL在一时间段内:19号22:10到22:45突然执行效率下降到10分钟,然而在22:45后自动恢复正常,想分析一下根因。数据库为一套2节点RAC,Linux -x86 数据库版本为11.2.0.4。

有了明确的时间段,登录到数据库内看看到底这个期间产生了什么性能问题?

数据库DB_TIME、活动会话数与应用反馈的时间基本吻合,从22点10分开始,数据库中的Active_Session数量开始飙升,并且数据库活动会话基本都被Library Cache Lock与Cursor Pin S wait on X等待事件所阻塞。

故障时间段内Top Event百分比

从ASH中看,活动会话最早被节点1的4327会话所阻塞,并且等待的是LIBRARY CACHE LOCK,随后,开始出现sql尝试软解析,遭遇Cursor pin s wait on x,且被节点1的2060会话所阻塞

我们看一下4237与2060在故障期间在干什么?

4327这个会话为oracle auto_task的sql auto tunning advisor job,并且他持有了Library Cache Lock Handle “0x1f9bc9bb98″导致了会话3877想以Mode=3(X)独占模式持有Library Cache Lock不成功,被阻塞。
2060为正常的应用会话,并且同样等待LIBRARY CACHE LOCK,没有阻塞者,这是一个奇怪的现象

但是2060会话在systemstate dump的trace文件中找到阻塞者,同样被4327会话阻塞

从相同时间段的systemstate dump trace文件中看到,2060会话在等待library cache lock,申请的同样是0x1f9bc9bb98的Library Cache Lock Handle (Mode=2(s) 共享模式),虽然没有Dump出2060的阻塞者,但是从申请的Handle上可以推断,都是被4327会话sql auto tunning advisor job阻塞。

分析结论: 此时间段确实为oracle autotask作业的时间窗口,但是job会话并不会长时间持有Library Cache Lock,这个会话当时在等待db file scattered read,数据库当时物理读非常高并且io链路上没有明显异常,异常点1:此JOB作业长时间持有LIBRARY CACHE LOCK不释放且JOB涉及的SQL造成物理读很高,异常点2:内存lock与Mutex争用又会导致cpu Idle低,从而进一步导致io无法调度完成,造成会话JOB工作效率下降,从而没有及时的释放LIBRARY CACHE LOCK的可能性会加大,这些都是非常不正常的行为,所以我决定disable sql tunning advisor功能,规避此问题再次发生。