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

Library cache lock 引发的一个案例_java

Library cache lock 引发的一个案例_java_02


Library cache lock 引发的一个案例_java_03

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

Library cache lock 引发的一个案例_oracle_04

上述信息表上在进行 dump 时发现1513 会话阻塞了341个数据库会话 (session)。 阻塞了300多个会话,这在任何系统中恐怕都会导致很大的影响。在一个稍微的时间点 dump 又发现982会话阻塞了346个会话.

虽然这里有多条阻塞的记录,但是这不难理解,可以理解为是不同的时间点进行的(因为 dump 可能花了几分钟才完成)。

第二部分内容是死锁信息,如下:

Library cache lock 引发的一个案例_linux_05

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

下面我们来继续解释第3部分内容:

Library cache lock 引发的一个案例_java_06

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

Library cache lock 引发的一个案例_oracle_07

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

Library cache lock 引发的一个案例_数据库_08

注意,这部分内容告诉我们的是,如下的会话 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在干些什么 ?

Library cache lock 引发的一个案例_java_09

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

我们直接搜索:7000004aa597e30 可以发现如下内容:

Library cache lock 引发的一个案例_java_10

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

Library cache lock 引发的一个案例_python_11

我们知道,对应 library cache latch 的获取,实际上 Oracle SQL 语句的硬解析、软解析、甚至软软解析都是需要获取的。 对应软软解析、是否需要获得 library cache latch,在11g 中有所改变,但是客户这里是10205版本。

这里我们已经知道了1516 会话在干什么,那么仍然不知道为什么1516 会导致后面的982会话被阻塞呢 ?

我们接着来看下会话982是什么进程,在干些什么 ?

Library cache lock 引发的一个案例_linux_12

我们可以看到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.

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

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

www.killdb.com>show parameter session_cached_cursors

NAME                                 TYPE        VALUE
------------------------------------ ----------- ------------------------------
session_cached_cursors               integer     0
www.killdb.com>select count(1) from t_library_lock;

  COUNT(1)
----------
     50042
www.killdb.com>select sql_id,hash_value,sql_Text from v$sqlarea where sql_text like '%t_library_lock%';

SQL_ID        HASH_VALUE SQL_TEXT
------------- ---------- --------------------------------------------------------------------------------
c7sdcrtz4t3k3 2118946371 select sql_id,sql_Text from v$sqlarea where sql_text like '%t_library_lock%'
f8m4jqsaypc7m  367702259 select count(1) from t_library_lock

www.killdb.com>select to_char(367702259,'xxxxxxxxxx') from dual;

TO_CHAR(367
-----------
   15eab0f3

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

Library cache lock 引发的一个案例_数据库_13

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

Library cache lock 引发的一个案例_python_14

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

0×00002000

0×00000020

0×00000010

那么最后的 level 应该是:b0f30000+2000+20+10=b0f32030

最后再将其转换为10进制,则如下:

Library cache lock 引发的一个案例_数据库_15

那么最后针对该 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;

下面我们开始进行测试,首先我们来测试硬解析.

### 硬解析

Library cache lock 引发的一个案例_linux_16

我们来看下 trace 的内容:

Library cache lock 引发的一个案例_数据库_17

从 trace 的内容我们可以清楚的看到,对应 SQL 的硬解析,是需要获得 library cache lock 和 library cache pin 操作的。

而且对应 select 语句,library cache lock 的 mode 是 NULL,而 library cache pin 的 mode 是 X.

### 测试软解析

--session 1
www.killdb.com>select count(1) from t_library_lock;

  COUNT(1)
----------
     50042

--session 2
www.killdb.com>oradebug event 10049 trace name context forever,level 2968723504
Statement processed.
www.killdb.com>oradebug tracefile_name
/home/ora10g/admin/test/udump/test_ora_10200.trc
www.killdb.com>

此时的 trace 内容如下:

Library cache lock 引发的一个案例_java_18

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

### 软软解析

Library cache lock 引发的一个案例_python_19


Library cache lock 引发的一个案例_oracle_20

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

Library cache lock 引发的一个案例_oracle_21

我们可以看到,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 中可能有很大的变化,这一点稍后再进行验证。

------The End

配图来源:http://supercom.com.tr/en/database-security/