记一次cursor pin s wait on X的处理

今天遇到个问题,客户说某天的11:45开始,系统遇到了大量的cursor pin s wait on X,经历一个小时后自动消失,需要查找原因。

这报错一般是某个会话需要申请S模式的mutex,而mutex被其他会话以X模式占有了。查holder也很容易,11g版本前看p2raw的前8位,将16进制转换成10进制即为holder的sid,在11g之后只需直接看blocking_session即可。

在11g中,我们有ash,这个很方便能查到过去发生的一切。

(1)根据客户反馈的情况,cursor pin S wait on X最严重的一个时间段为12:25~12:35,取这个时间段为例。发现cursor: pin S wait on X的进程都被sid为2的进程堵塞。

(2)SID为2的进程被sid为1129的进程堵塞:

(3)sid为1129的进程被sid 951的堵塞:

(4)sid 951的进程被Wnnn的进程堵塞:

(5)最终的堵塞进程为Wnnn。

Wnnn是11g新的进程,有SMCO进程spawn出来,用于主动空间的管理(It perform proactive space allocation and space reclaimation)。
从上述SQL看,由于有insert又有truncate,因此空间清理将有SMCO和Wnnn进程介入。在操作的过程中,堵塞其他的进程的操作。

到这里,我们可以有个初步的解决方案:

既然是Wnnn进程堵塞了其他进程的操作,那么我们禁用这个11g的新功能,禁用SMCO的空间管理 “Tablespace-level space(Extent)pre-allocation”,即可避免该问题的发生。

还原的反向操作为:

注:

但是我们到这里也会问一个问题,为什么Wnnn的操作没有blocking_session,却要操作那么久的时间。这时一个不常见的等待事件映入眼帘:log file sequential read 。

log file sequential read 一般是在恢复或者logmnr的时候,才将redo log file的内容顺序的读入到内存中,此时为什么需要做log file sequential read?

根据上述的时间点,我们进一步结合alertlog看,我们发现在对应的时间点,都有关于w004的ora600的报错。

结合ora -600 [ktecgsc:kcbz_objdchk]查询MOS,我们可以定位到一个11.2.0.2的bug 10237773,并且从该bug的Rediscovery Note中,也可以看到:The problem is likely to occur in a Wnnn background process ktssupd_segment_extblks_bkg is likely to appear on the stack.

进一步分析trace文件,我们可以看到11:40到12:43都在dump redo record。因此,我们在那段时间看到wnnn进程的log file sequential read的等待。即wnnn进程在读取redo log file做dump。

Dump redo record(11:40到12:43):

另外,在trace文件中,也查到的bug中所说的ktssupd_segment_extblks_bkg的调用。

因此,问题的原因应该是这样的:

找到了问题根源,对应的解决方法也就明了了。workaround是禁用11g新特性,SMCO的空间管理,fix是打bug 10237773的补丁,或者升级到11.2.0.3。

相关文章

发表评论

电子邮件地址不会被公开。 必填项已用*标注

此站点使用Akismet来减少垃圾评论。了解我们如何处理您的评论数据