love wife love life —Roger的Oracle/MySQL/PostgreSQL数据恢复博客

Phone:18180207355 提供专业Oracle/MySQL/PostgreSQL数据恢复、性能优化、迁移升级、紧急救援等服务

library cache lock引发的一个案例

本站文章除注明转载外,均为本站原创: 转载自love wife love life —Roger的Oracle/MySQL/PostgreSQL数据恢复博客

本文链接地址: library cache lock引发的一个案例

美女同事说某个客户有个问题,系统出现了大量的library cache lock. 导致业务严重受阻,具体表现是所有访问某个表的SQL语句都会挂起. 首先我们来看hanganalyze 的结果:

这里对对一部分是内容进行简单的解释:

上述信息表上在进行dump时发现1513 会话阻塞了341个数据库会话(session)。 阻塞了300多个会话,这在任何系统中恐怕都会导致很大的影响。在一个稍微的时间点dump 又发现982会话阻塞了346个会话.
虽然这里有多条阻塞的记录,但是这不难理解,可以理解为是不同的时间点进行的(因为dump 可能花了几分钟才完成)。
第二部分内容是死锁信息,如下:

这是cycle 即循环,跟死锁类似。一般来讲,如果trace中出现了cycle,而cycle 涉及的进程又阻塞了大量的会话、那么系统估计都可能已经hang了。从上述信息来看,节点2的1488 会话和节点1的700 会话互为”死锁”. 比较怪异的是,这2个会话都在等待library cache lock.而下面的1012 和1513 会话也是类似,也都在等待library cache lock.
下面我们来继续解释第3部分内容:

这部分内容显示了所有进程的状态以及阻塞情况。对于进程的状态,主要是分为如下几种:

我们这里再回到主题上来、通过如下内容我们可以看到,此次故障的源头应该是会话1516,如下:

注意,这部分内容告诉我们的是,如下的会话982,627,1488,700,1012,1513等都12个进程都是被1516 锁阻塞。
但是这需要我们注意的是,虽然这部分会话是被1516 锁阻塞,但是并不是说这部分进程是1516 直接阻塞,因为很有可能是间接性的。从上述内容我们可以发现,cycle的4个会话其实都被1516 阻塞了。这也说明一点,这里的cycle其实并不是真正意义上的死锁.
当然,客户解决这个问题很简单,通过将会话1516 kill即可。 但是客户不明白的是,为什么会出现这个问题?
首先我们来看看客户的困惑是什么? 他们困惑的是为什么访问某个表的sql都不会挂起,哪怕是如下的sql也会挂起:
SQL> select count(1) from GEOSTAR.ATT_PT_LINE;
看到这里,可能很多人都会疑问,为什么select 也会挂起? 有什么锁会阻塞select 呢?
首先,我们来看下源头会话1516在干些什么 ?

该进程的dump内容比较长,有几千行,因为这里直接跳到最后。我们可以看到该会话持有了一个Mode=x的CU锁,所谓的CU enqueue其实是指Bind Enqueue。我们看该cursor的夫游标地址是:7000004aa597e30
我们直接搜索:7000004aa597e30 可以发现如下内容:

我们可以看到,该会话在执行一个insert语句,访问的正是att_pt_line表,而且是通过dblink进行操作。 同时我们也可以看到该会话对这个表上进行了library cache lock和pin 操作,如下:

我们知道,对应library cache latch的的获取,实际上Oracle SQL语句的硬解析、软解析、甚至软软解析都是需要获取的。 对应软软解析、是否需要获得library cache latch,在11g中有所改变,但是客户这里是10205版本。
这里我们已经知道了1516 会话在干什么,那么仍然不知道为什么1516 会导致后面的982会话被阻塞呢 ?
我们接着来看下会话982是什么进程,在干些什么 ?

我们可以看到982会话是Oracle的定时任务发起的,通过actiion name我们可以知道、这是调用GATHER_STATS_JOB。
很明显这是对于数据库全库的统计信息的收集。对应统计信息的收集,大家应该清楚,这其实类似DDL操作、默认情况之下会会导致cursor 失效,而且还会导致library cache lock的产生。
出问题的这天正好是周日,对应这个定时任务,大家应该知道,周末是全天运行,如果收集失败也不会被强行终止掉。我们可以可以看到1516会话进程的dump时间点是2015-05-09 06:16:26.707,这正好位于统计信息时候点之后不久。
于是我们可以大胆的猜测,统计信息后面其实是没有运行完成的,这也就是为什么982会话会导致大量的library cache lock等待的原因。
那么最后,为什么select 这个表会挂起呢?
其实很简单,这是因为这个表的统计信息收集其实未完成,正在在进行中。而我们也知道这是会导致cursor失效的,那么针对这个表的所有SQL都必须进行硬解析,这毫无疑问,解析是需要获得library cache pin和lock的。 所有客户会发现任何一个会话去访问这个表出现的等待事件都是library cache lock.

针对这一点,我们可以通过如下的实验来进行验证:

首先调整游标缓存的参数:

那么如何选择trace 的level呢? 首先来看下文档说明:

这里取后两位:b0f3 ,  至于如何计算,我们来看文档示意图:

根据Oracle 文档描述,这里还需要针对pin、lock以及hash的操作,对应的level分别是:

0x00002000

0x00000020

0x00000010
那么最后的level应该是.
b0f30000+2000+20+10=b0f32030
最后再将其转换为10进制,则如下:

那么最后针对该SQL的library cache pin/lock操作trace即:

oradebug setospid  xxx

oradebug event 10049 trace name context forever,level 2968723504

oradebug event 10049 trace name context off;
下面我们开始进行测试,首先我们来测试硬解析.

### 硬解析

我们来看下trace的内容:

从trace的内容我们可以清楚的看到,对应SQL的硬解析,是需要获得library cache lock和library cache pin操作的。
而且对应select 语句,library cache lock的mode是NULL,而library cache pin的mode是X.

### 测试软解析

此时的trace 内容如下:

我们可以看到,对应SQL语句的软解析是不需要获得library cache pin操作的,只需要获得library cache lock即可,而且mode为NULL。

### 软软解析

我们来看下软软解析的trace 内容:

我们可以看到,SQL的软软解析这里其实没有获得library cache pin和library cache lock操作.
最后我们来总结一下:
1、10205版本中,SQL硬解析是需要获得library cache pin和lock的,且分别的mode是X和NULL。

2、10205版本中,SQL软解析是需要获得library cache lock,mode为NULL。

3、10205版本中,SQL软软解析是不需要获得library cache lock和pin的。

4、其他版本可能不同、尤其是mutex的引入,11g中可能有很大的变化,这一点稍后再进行验证。
详见:TRACING KGL CALLS IN A OCI PROGRAM USING THE EVENT 10049 NEW FEATURES (Doc ID 334636.1)

One Response to “library cache lock引发的一个案例”

  1. zws Says:

    这个是bug,只要再次分析表,还会出现,除非取消这个表的分析.

    http://yangtingkun.net/?p=1359

Leave a Reply

You must be logged in to post a comment.