Library cache lock 引发的一个案例

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

ec79b428a3eeca4afffbf800b758c8cd.png

1244c212abed2a8bb8c83719d6ec0482.png
e308d71b5ed2331b4124e58848c0825b.png


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

31930329c47fc9d9c9d0a52c3dd6eff5.png


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


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


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

fa683a93cb16279c237a1ec89cee3959.png


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


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

4de2b2cf83b60ac3e6e129de473afa71.png


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

d8a0430412f0d69b05b9e204c9910df7.png


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

5bef228bbd381b83b1da32e67c7d28e3.png


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

233cdbdb8f89b639b2e7baaa703930e8.png


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


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

f48b010ff2081ab4fe238305dfcc38b4.png


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

e1c93a41ebc5f1204e30e02c90dae67e.png


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


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


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

214bbe8f58d391a594ad4acb7881135e.png

我们可以看到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 呢? 首先来看下文档说明:

7b492a2a3bf6da30583d7ed280e96ce1.png


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

c720ae606898d42c028fa8ee9d65b5af.png

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

0×00002000

0×00000020

0×00000010


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


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

0afc109010a878182f1659f302735385.png

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


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

### 硬解析

735c9354b7106d9ec716b0cae3d7be4e.png


我们来看下 trace 的内容:

e9b400b12de05059ab14a5b3b09aadc6.png


从 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 内容如下:

a14643a3a1e7649b5d2d212b265a83ee.png

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

### 软软解析

78ae06234b6b61be7a2710a40e36d697.png
9dbbdb152e6a63b193ba83e254ba51f9.png


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

edaf9f0c10a537a1ca2301ab1e30d82d.png

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

文章来源:【love wife & love life —Roger 的 Oracle 技术博客】

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

11b7f87540a18a03b35f8683a985bf98.png

2015 Oracle 技术嘉年华10月7日前五折门票抢购进行中,长按上方图片识别二维码注册参会!

271e3c43782b6ab39dbc364884c735b5.png

点击“阅读原文”查看原文章详情。

  • 0
    点赞
  • 1
    收藏
    觉得还不错? 一键收藏
  • 0
    评论

“相关推荐”对你有帮助么?

  • 非常没帮助
  • 没帮助
  • 一般
  • 有帮助
  • 非常有帮助
提交
评论
添加红包

请填写红包祝福语或标题

红包个数最小为10个

红包金额最低5元

当前余额3.43前往充值 >
需支付:10.00
成就一亿技术人!
领取后你会自动成为博主和红包主的粉丝 规则
hope_wisdom
发出的红包
实付
使用余额支付
点击重新获取
扫码支付
钱包余额 0

抵扣说明:

1.余额是钱包充值的虚拟货币,按照1:1的比例进行支付金额的抵扣。
2.余额无法直接购买下载,可以购买VIP、付费专栏及课程。

余额充值