案例:”WAITED TOO LONG FOR A ROW CACHE ENQUEUE LOCK! “等待的诊断

2020-03-26 10:35:41 浏览数 (1)

Keyword:

代码语言:javascript复制
'WAITED TOO LONG FOR A ROW CACHE ENQUEUE LOCK! '
ROW CACHE LOCK 
HANG
Wait event
'ksim generic wait event'

本文将通过某客户环境中发生的”WAITED TOO LONG FOR A ROW CACHE ENQUEUE LOCK! “现象介绍如何分析跟踪文件来确定原因。

客户的问题

DB环境:

从何着手?

首先通过用户的描述,我们可以明确本次问题关键是调查【[WAITED TOO LONG FOR A ROW CACHE ENQUEUE LOCK! pid=XXX]】以及探究无法连接的原因。 我们可以从用户提供的警告日志发现到如下的输出:

警告日志:

因此我们可以从最初发生WAITED TOO LONG FOR A ROW CACHE ENQUEUE LOCK!的进程入手调查。

现在我们面临着以下的一些问题:

关于”WAITED TOO LONG FOR A ROW CACHE ENQUEUE LOCK!”

这部分,我们可以参考 【 “WAITED TOO LONG FOR A ROW CACHE ENQUEUE LOCK! “等待原理】 一文中的介绍。

如何分析跟踪日志文件?

根据用户提供的信息,我们可以先从警告日志中最先生成的信息和跟踪文件入手:

Step 0:警告日志

0.警告日志:

Step 1:从最初的进程入手

根据上面的输出,我们知道本次发生等待的进程是pid=203的进程。 这一点我们通过跟踪文件的最初输出内容也可以确认到:

1.接下来我们进一步分析SYSTEM STATE中,等待锁的 Oracle 进程(进程号为203的):

根据上面的输出,我们可以看到,进程203在请求S模式的row cache lock时发生等待,并且等待了502分钟。而请求的row cache lock类型是dc_users型enqueue ,并且请求对象的地址为【c0000003786fd3a0 】。

关于’row cache lock’

row cache lock是对共享内存(Shared pool)中数据字典信息(dc_XXX)进行操作时,加载的锁(Enqueue )。

Step 2:搜索请求的对象

2.接着下面我们搜索请求的对象”c0000003786fd3a0”:

根据上面的检索结果,我们可以看到大量的会话以S模式(request=S)请求【c0000003786fd3a0 】;并且我们发现只有一个会话以S模式(mode=S)持有【c0000003786fd3a0 】。

现在我们其实有了一个问题:

为什么S模式(mode=S)持有锁对象的会话,阻塞S模式(request=S)请求的会话?

我们暂时保留这个问题,接着分析资料。

Step 3:搜索持有的对象

3.我们接着查看以S模式(mode=S)持有【c0000003786fd3a0 】会话所在的进程202: (以会话c00000037719df40为关键字搜索进程)

根据上面的输出我们可以看到,以S模式持有object=c0000003786fd3a0对象的进程202,正在等待’cursor: pin S wait on X’,以共享模式(S)请求【idn f0b72ce1】的Mutex。 而持有该Mutex的会话为SID=4225的会话。

(关于Mutex的详细确认方法可参考 【如何从SYSTEMSTATE DUMP查看Mutex的持有者和请求者】)

虽然当前等待【waiting for ‘cursor: pin S wait on X’】的时间很短【total=0.021034 sec】,但是我们可以看到等待历史中其实也一直在等待’cursor: pin S wait on X’。 因此因为获取不到Mutex,才引起该进程202的等待。

现在我们明白为什么S模式(mode=S)持有锁对象的会话,阻塞S模式(request=S)请求的会话了,原因在于Mutex的获得上:

Mutex用于保护锁对象,在获取锁对象前需要先获得【保护该锁对象的Mutex】。 S模式(mode=S)持有锁对象的会话在请求Mutex,而S模式(request=S)请求锁对象的会话也先需要获得Mutex,所以造成了S模式(mode=S)持有锁对象的会话,阻塞S模式(request=S)请求的会话的现象。

关于’cursor: pin S wait on X’

'cursor: pin S wait on X'等待通常和解析有关系, 当一个会话试图以共享(S)模式请求某mutex时,但是其他会话正以专有(X)模式持有该mutex。

Step 4:搜索请求的Mutex对象

4.下面我们搜索进程202要获得的Mutex对象:

Step 5:搜索持有的Mutex对象

5.我们接着查看以排他模式(EXCL)持有该Mutex(idn f0b72ce1)的会话所在的进程200: (以会话(4225, 0)为关键字搜索进程)

根据上面的输出我们可以看到,以排他模式(EXCL)持有该Mutex(idn f0b72ce1)的进程200; 进程200正在等待’ksim generic wait event’,等待历史中也一直在等待’ksim generic wait event’。 并且我们可以看到该进程被sid: 4396的进程阻塞。

关于’ksim generic wait event’

关于”ksim generic wait event”

"ksim generic wait event"是进程(Process)在获得实例注册信息过程中使用的等待事件。 因为它被定义为一种通用的等待事件,所以并不能够明确的指明发生了某种特定状况。 "ksim generic wait event"的发生例: 某进程要执行一个跨节点并行查询,在获得可使用的进程数的过程中可能会发生这个等待事件。 通常来讲,这个等待事件并不会频繁的发生。

Step 6:搜索阻塞进程

6.下面我们搜索sid: 4396所在的进程:

根据上面的检索结果,我们可以看到sid: 4396所在的进程【creator: 0xc00000037f385f60】

Step 7:查看阻塞进程

7.查看sid: 4396所在的进程10: (以会话【creator: 0xc00000037f385f60】为关键字搜索进程)

通过上面的输出,我们可以看到PROCESS 10是LMON进程,并且正在等待’rdbms ipc message’ .

关于’rdbms ipc message’

关于’rdbms ipc message’

通过下面的在线文档描述,我们知道'rdbms ipc message'这个事件由后台进程(LGWR,DBWR,LMS0)使用;并表明后台进程处于空闲状态, 等待从前台进程发送的IPC消息以执行一些工作.

参考:

Database Reference 11.1 http://t.cn/RomYvqc >rdbms ipc message The background processes (LGWR, DBWR, LMS0) use this event to indicate that they are idle and are waiting for the foreground processes to send them an IPC message to do some work.

所以,PROCESS 10(LMON进程)的这个’rdbms ipc message’等待事件并不能代表什么问题。

跟踪日志文件分析结果总结

根据上面对跟踪文件的分析,我们可以看到整个等待链如下:

从PROCESS 203发生「WAITED TOO LONG FOR A ROW CACHE ENQUEUE LOCK!」开始入手

根据上面的内容来看,似乎并没有什么异常,但从等待的关系来看,问题很可能出在PROCESS 200 和PROCESS 10上.我们再回顾两个进程的ErrorStack信息,来看看有没有什么发现:

PROCESS 10:

PROCESS 200:

对于普通的用户而言,也许ErrorStack信息和天书一样,但是不要紧,我们可以暂且搁置。

ErrorStack信息

Oracle数据库是用C语言写的; ErrorStack信息其实就是Oracle数据库在运行过程中,调用的源代码中的函数名,通常用于缩小调查范围。

我们对日志文件再进行分析和检索时发现,’ksim generic wait event’等待的次数非常的多,所以可以猜测很有可能跟’ksim generic wait event’等待有关;而’rdbms ipc message’等待时通常数据库没有什么实质性的工作,所以可以暂且忽略。

问题原因

基于上面的分析结果,我们通过MOS使用Keyword:’ksim generic wait event’进行搜索 ,我们会发现在用户的版本上11.1.0.7有一个类似的Bug。

并且根据其的描述,我们知道Bug 10129643的内容为在于并行执行,在获得服务(Service)和实例(Instance)信息时有问题,导致大量的”ksim generic wait event” 等待发生。

当发生Bug 10129643问题时会有如下的表象:

・并行处理时发生大量的"ksim generic wait event" 等待 ・等待的进程的会包括如下的ErrorStack信息 ksimilist<-kxfpActiveInstList<-kxfpFindAvailableInstCnt

本次日志文件的特征基本符合,另外确认opatch信息用户并没有打相关的Patch,所以可以判断本次现象的原因是由于Bug 10129643导致的。

推荐的解决方案

由于对这个问题并没有合适的回避方法,所以为了避免现象的再次发生,需要下载相关的one-off path. 该问题在最新PSU 上也得到了修正,升级也可以解决。

※经用户确认打了one-off path后,问题没有再现。

知识点总结(KM)

通过本次案例, 我们详细描述了”WAITED TOO LONG FOR A ROW CACHE ENQUEUE LOCK! “相关内容和解决问题的思路及过程,并介绍了以下等待事件的相关内容。

・"WAITED TOO LONG FOR A ROW CACHE ENQUEUE LOCK! " ・'row cache lock' ・'cursor: pin S wait on X' ・"ksim generic wait event" ・'rdbms ipc message'

※结果代表过去,重要的是追寻结果的过程!!

0 人点赞