本站文章除注明转载外，均为本站原创： 转载自love wife & love life —Roger 的Oracle技术博客
本文链接地址: library cache lock引发的一个案例
美女同事说某个客户有个问题，系统出现了大量的library cache lock. 导致业务严重受阻，具体表现是所有访问某个表的SQL语句都会挂起. 首先我们来看hanganalyze 的结果：
PORADEBUG END ORIGINATING INST:1 SERIAL:0 PID:38076802
********************************************************************
Found 341 objects waiting for <cnode/sid/sess_srno/proc_ptr/ospid/wait_event>
<1/1513/11901/library cache lock>
Found 341 objects waiting for <cnode/sid/sess_srno/proc_ptr/ospid/wait_event>
<1/1148/42016/library cache lock>
Found 341 objects waiting for <cnode/sid/sess_srno/proc_ptr/ospid/wait_event>
<1/1395/45772/library cache lock>
Found 341 objects waiting for <cnode/sid/sess_srno/proc_ptr/ospid/wait_event>
<1/1574/16193/library cache lock>
Found 341 objects waiting for <cnode/sid/sess_srno/proc_ptr/ospid/wait_event>
<1/1488/64080/library cache lock>
Found 346 objects waiting for <cnode/sid/sess_srno/proc_ptr/ospid/wait_event>
<0/982/38928/0x435d270/46727232/library cache lock>
Cycle 1 : <cnode/sid/sess_srno/proc_ptr/ospid/wait_event> :
<1/1488/64080/library cache lock>
-- <0/700/3738/0x4335f60/20840620/library cache lock>
Cycle 2 : <cnode/sid/sess_srno/proc_ptr/ospid/wait_event> :
<0/1012/44406/0xf35a3f8/17826228/library cache lock>
-- <1/1513/11901/library cache lock>
Open chains found:
Chain 1 : <cnode/sid/sess_srno/proc_ptr/ospid/wait_event> :
<0/1516/42489/0x4338f00/34996438/single-task message>
-- <0/982/38928/0x435d270/46727232/library cache lock>
-- <0/627/7616/0x7319538/47710688/library cache lock>
-- <1/1488/64080/library cache lock>
-- <0/700/3738/0x4335f60/20840620/library cache lock>
-- <1/1574/16193/library cache lock>
-- <0/1162/22132/0x4360a00/31260934/library cache lock>
-- <1/1395/45772/library cache lock>
-- <0/1380/41831/0xf358c28/19202486/library cache lock>
-- <1/1148/42016/library cache lock>
-- <0/1012/44406/0xf35a3f8/17826228/library cache lock>
-- <1/1513/11901/library cache lock>
-- <0/609/6726/0x634af60/24903782/library cache lock>
Other chains found:
Chain 2 : <cnode/sid/sess_srno/proc_ptr/ospid/wait_event> :
<0/610/13426/0x23460c0/29163888/Streams AQ: qmn slave idle wait>
Chain 3 : <cnode/sid/sess_srno/proc_ptr/ospid/wait_event> :
<0/612/572/0xf359418/26214770/cursor: pin S wait on X>
Chain 4 : <cnode/sid/sess_srno/proc_ptr/ospid/wait_event> :
<0/615/402/0x73555a8/14221446/cursor: pin S wait on X>
........
........
<0/1541/6064/0x4355370/52166804/cursor: pin S wait on X>
Chain 142 : <cnode/sid/sess_srno/proc_ptr/ospid/wait_event> :
<0/1553/56644/0x334f228/15991100/cursor: pin S wait on X>
Chain 143 : <cnode/sid/sess_srno/proc_ptr/ospid/wait_event> :
<0/1569/32611/0x23156e0/52756830/cursor: pin S wait on X>
Chain 144 : <cnode/sid/sess_srno/proc_ptr/ospid/wait_event> :
<0/1587/1/0x432e060/8323160/Streams AQ: waiting for time man>
Chain 145 : <cnode/sid/sess_srno/proc_ptr/ospid/wait_event> :
<0/1591/9/0x533f9e0/34406908/Streams AQ: waiting for messages>
Chain 146 : <cnode/sid/sess_srno/proc_ptr/ospid/wait_event> :
<0/1592/5/0x7312618/9502790/Streams AQ: qmn coordinator idle>
Chain 147 : <cnode/sid/sess_srno/proc_ptr/ospid/wait_event> :
<0/1654/1/0x230f7a0/21168480/No Wait>
Chain 148 : <cnode/sid/sess_srno/proc_ptr/ospid/wait_event> :
<1/1301/10502/cursor: pin S wait on X>
Chain 149 : <cnode/sid/sess_srno/proc_ptr/ospid/wait_event> :
<1/1468/31326/Streams AQ: qmn slave idle wait>
Chain 150 : <cnode/sid/sess_srno/proc_ptr/ospid/wait_event> :
<1/1471/39769/jobq slave wait>
Chain 151 : <cnode/sid/sess_srno/proc_ptr/ospid/wait_event> :
<1/1578/10/Streams AQ: waiting for time man>
Chain 152 : <cnode/sid/sess_srno/proc_ptr/ospid/wait_event> :
<1/1594/11/Streams AQ: qmn coordinator idle>
Chain 153 : <cnode/sid/sess_srno/proc_ptr/ospid/wait_event> :
<1/1654/1/No Wait>
Extra information that will be dumped at higher levels:
[level 3] : 346 node dumps -- [IN_HANG]
[level 4] : 1 node dumps -- [REMOTE_WT] [LEAF] [LEAF_NW]
[level 5] : 152 node dumps -- [SINGLE_NODE] [SINGLE_NODE_NW] [IGN_DMP]
[level 6] : 1 node dumps -- [NLEAF]
[level 10] : 704 node dumps -- [IGN]
State of nodes
([nodenum]/cnode/sid/sess_srno/session/ospid/state/start/finish/[adjlist]/predecessor):
[606]/0/607/27406/0x23f01f0/32702484/IGN/1/2//none
[608]/0/609/6726/0x641eeb0/24903782/IN_HANG/3/698/[3167][2802][3049][3228][3142][981]/none
[609]/0/610/13426/0x541b9b0/29163888/SINGLE_NODE/699/700//none
[610]/0/611/31/0xf3f9378/25231442/IN_HANG/37/38/[3167][2802][3049][3228][3142][981]/3142
[611]/0/612/572/0x440abd0/26214770/SINGLE_NODE/701/702//none
[614]/0/615/402/0x73ee5f0/14221446/SINGLE_NODE/703/704//none
[615]/0/616/223/0x6420428/13959648/SINGLE_NODE/705/706//none
[616]/0/617/10658/0x541cf28/19792010/IN_HANG/19/20/[3167][2802][3049][3228][3142][981]/3142
[617]/0/618/714/0xf3fa8f0/40632696/IN_HANG/43/44/[3167][2802][3049][3228][3142][981]/3142
[619]/0/620/1483/0x33f82f8/18219062/SINGLE_NODE/707/708//none
[620]/0/621/12164/0x23f2ce0/37552426/IGN/709/710//none
[621]/0/622/2718/0x73efb68/39911520/SINGLE_NODE/711/712//none
[622]/0/623/6949/0x64219a0/28049662/IGN/713/714//none
[623]/0/624/3802/0x541e4a0/6160704/SINGLE_NODE/715/716//none
[624]/0/625/883/0xf3fbe68/36438112/IGN/717/718//none
[626]/0/627/7616/0x33f9870/47710688/IN_HANG/13/18/[3167][2802][3049][3228][3142][981]/3142
[627]/0/628/4681/0x23f4258/14811164/SINGLE_NODE/719/720//none
[628]/0/629/833/0x73f10e0/5767552/IN_HANG/27/28/[3167][2802][3049][3228][3142][981]/3142
.......
.......
[973]/0/974/4600/0x5461610/12845484/IN_HANG/111/112/[3167][2802][3049][3228][3142][981]/3142
[974]/0/975/25532/0xf43efd8/53936616/IN_HANG/603/604/[3167][2802][3049][3228][3142][981]/3142
[975]/0/976/16608/0x4450830/20775322/SINGLE_NODE/993/994//none
[976]/0/977/4511/0x343c9e0/14287136/IGN/995/996//none
[977]/0/978/26807/0x24373c8/17760418/IGN/997/998//none
[978]/0/979/14805/0x7434250/42860784/IN_HANG/181/182/[3167][2802][3049][3228][3142][981]/3142
[980]/0/981/22918/0x5462b88/32374886/IN_HANG/429/430/[3167][2802][3049][3228][3142][981]/3142
[981]/0/982/38928/0xf440550/46727232/NLEAF/14/17/[1515]/626
[982]/0/983/19754/0x4451da8/10355146/IN_HANG/605/606/[3167][2802][3049][3228][3142][981]/3142
[983]/0/984/34596/0x343df58/50463108/IN_HANG/441/442/[3167][2802][3049][3228][3142][981]/3142
[984]/0/985/8594/0x2438940/21889486/SINGLE_NODE/999/1000//none
。。。。。。
[1512]/0/1513/6509/0x54c8b28/21692662/IN_HANG/247/248/[3167][2802][3049][3228][3142][981]/3142
[1513]/0/1514/47903/0xf4a64f0/30933308/IN_HANG/351/352/[3167][2802][3049][3228][3142][981]/3142
[1514]/0/1515/52967/0x44b7d48/11207134/IGN/1795/1796//none
[1515]/0/1516/42489/0x34a3ef8/34996438/LEAF/15/16//981
[1516]/0/1517/28157/0x249e8e0/19464364/IGN/1797/1798//none
[1517]/0/1518/28318/0x749b768/25166076/IGN/1799/1800//none
。。。。。。
这里对对一部分是内容进行简单的解释：
Found 341 objects waiting for <cnode/sid/sess_srno/proc_ptr/ospid/wait_event>
<1/1513/11901/library cache lock>
......
Found 346 objects waiting for <cnode/sid/sess_srno/proc_ptr/ospid/wait_event>
<0/982/38928/0x435d270/46727232/library cache lock>
上述信息表上在进行dump时发现1513 会话阻塞了341个数据库会话(session)。 阻塞了300多个会话，这在任何系统中恐怕都会导致很大的影响。在一个稍微的时间点dump 又发现982会话阻塞了346个会话.
虽然这里有多条阻塞的记录，但是这不难理解，可以理解为是不同的时间点进行的（因为dump 可能花了几分钟才完成）。
第二部分内容是死锁信息，如下：
Cycle 1 : <cnode/sid/sess_srno/proc_ptr/ospid/wait_event> :
<1/1488/64080/library cache lock>
-- <0/700/3738/0x4335f60/20840620/library cache lock>
Cycle 2 : <cnode/sid/sess_srno/proc_ptr/ospid/wait_event> :
<0/1012/44406/0xf35a3f8/17826228/library cache lock>
-- <1/1513/11901/library cache lock>
这是cycle 即循环，跟死锁类似。一般来讲，如果trace中出现了cycle，而cycle 涉及的进程又阻塞了大量的会话、那么系统估计都可能已经hang了。从上述信息来看，节点2的1488 会话和节点1的700 会话互为”死锁”. 比较怪异的是，这2个会话都在等待library cache lock.而下面的1012 和1513 会话也是类似，也都在等待library cache lock.
下面我们来继续解释第3部分内容：
State of nodes ([nodenum]/cnode/sid/sess_srno/session/ospid/state/start/finish/[adjlist]/predecessor): [606]/0/607/27406/0x23f01f0/32702484/IGN/1/2//none [608]/0/609/6726/0x641eeb0/24903782/IN_HANG/3/698/[3167][2802][3049][3228][3142][981]/none [609]/0/610/13426/0x541b9b0/29163888/SINGLE_NODE/699/700//none [610]/0/611/31/0xf3f9378/25231442/IN_HANG/37/38/[3167][2802][3049][3228][3142][981]/3142 [611]/0/612/572/0x440abd0/26214770/SINGLE_NODE/701/702//none .....
这部分内容显示了所有进程的状态以及阻塞情况。对于进程的状态，主要是分为如下几种：
IN_HANG ：该状态是一个非常危险的状态，通常表现该会话陷入了死循环或挂起(hang)。
一般来说出现这种情况，该节点的临近节点(adjlist)也是一样的状态.adjlist 其实就是表示session id.
LEAF ：通常是被认为blockers的重点对象。可以根据后面的predecesor来判断该session是不是blocker或者是waiter。
LEAF_NW ：跟leaf类似 不过可能会占用cpu
NLEAF ：该状态的session通常被认为 “stuck” session。即其他session所需要的资源正被其holding。
IGN ：该状态的session通常是处理IDLE状态，除非其adjlist存在，如果是，那么该session正在等待其他session。
IGN_DMP ：跟IGN类似。
SINGLE_NODE，SINGLE_NODE_NW 可以认为跟LEAF，LEAF_NW类似。
我们这里再回到主题上来、通过如下内容我们可以看到，此次故障的源头应该是会话1516，如下：
Chain 1 : <cnode/sid/sess_srno/proc_ptr/ospid/wait_event> :
<0/1516/42489/0x4338f00/34996438/single-task message>
-- <0/982/38928/0x435d270/46727232/library cache lock>
-- <0/627/7616/0x7319538/47710688/library cache lock>
-- <1/1488/64080/library cache lock>
-- <0/700/3738/0x4335f60/20840620/library cache lock>
-- <1/1574/16193/library cache lock>
-- <0/1162/22132/0x4360a00/31260934/library cache lock>
-- <1/1395/45772/library cache lock>
-- <0/1380/41831/0xf358c28/19202486/library cache lock>
-- <1/1148/42016/library cache lock>
-- <0/1012/44406/0xf35a3f8/17826228/library cache lock>
-- <1/1513/11901/library cache lock>
-- <0/609/6726/0x634af60/24903782/library cache lock>
注意，这部分内容告诉我们的是，如下的会话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在干些什么 ？
*** 2015-05-09 06:16:26.707
----------------------------------------
SO: 700000504338f00, type: 2, owner: 0, flag: INIT/-/-/0x00
(process) Oracle pid=204, calls cur/top: 70000043542b320/7000004b9323ec0, flag: (0) -
int error: 0, call error: 0, sess error: 0, txn error 0
(post info) last post received: 0 0 167
last post received-location: kqrbtm
last process to post me: 70000050533f1f0 1 6
last post sent: 0 0 24
last post sent-location: ksasnd
last process posted by me: 70000050533f1f0 1 6
(latch info) wait_event=0 bits=0
Process Group: DEFAULT, pseudo proc: 700000503379d38
O/S info: user: oracle, term: UNKNOWN, ospid: 34996438
OSD pid info: Unix process pid: 34996438, image: oracle@gisdata1
----------------------------------------
SO: 7000005034a3ef8, type: 4, owner: 700000504338f00, flag: INIT/-/-/0x00
(session) sid: 1516 trans: 0, creator: 700000504338f00, flag: (41) USR/- BSY/-/-/-/-/-
DID: 0001-00CC-00000175, short-term DID: 0001-00CC-00000176
txn branch: 0
oct: 2, prv: 0, sql: 70000044eb24610, psql: 70000050d2dec80, user: 58/GEOSTAR
service name: gissc
O/S info: user: Administrator, term: XF-PC, ospid: 9396:8644, machine: WORKGROUP\XF-PC
program: plsqldev.exe
application name: PL/SQL Developer, hash value=1190136663
action name: SQL Window - New, hash value=3399691616
waiting for 'single-task message' wait_time=0, seconds since wait started=402550
=0, =0, =0
blocking sess=0x0 seq=77
Dumping Session Wait History
for 'row cache lock' count=1 wait_time=0.000413 sec
cache id=f, mode=0, request=3
。。。。。。
for 'row cache lock' count=1 wait_time=0.000368 sec
cache id=10, mode=0, request=3
......
......省略部分内容
----------------------------------------
SO: 70000050f4db0e8, type: 5, owner: 7000004b9323ec0, flag: INIT/-/-/0x00
(enqueue) CU-3F99D598-07000004 DID: 0001-00CC-00000175
lv: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 res_flag: 0x2
mode: X, lock_flag: 0x0, lock: 0x70000050f4db108, res: 0x7000005045152f0
own: 0x7000005034a3ef8, sess: 0x7000005034a3ef8, proc: 0x700000504338f00, prv: 0x700000504515300
----------------------------------------
SO: 7000005086945a0, type: 59, owner: 7000004b9323ec0, flag: INIT/-/-/0x00
cursor enqueue
child: 7000004c38219e0, flag: 53, number: 0
parent: 7000004aa597e30
----------------------------------------
SO: 70000043a244e30, type: 16, owner: 700000504338f00, flag: INIT/-/-/0x00
(osp req holder)
PSO child state object changes :
该进程的dump内容比较长，有几千行，因为这里直接跳到最后。我们可以看到该会话持有了一个Mode=x的CU锁，所谓的CU enqueue其实是指Bind Enqueue。我们看该cursor的夫游标地址是：7000004aa597e30
我们直接搜索：7000004aa597e30 可以发现如下内容：
KGX Atomic Operation Log 7000005086941d0
Mutex 7000004c38219e0(1516, 0) idn fad52024 oper EXCL
Cursor Pin uid 1516 efd 0 whr 1 slp 0
opr=3 pso=700000437e79160 flg=0
pcs=7000004c38219e0 nxt=0 flg=35 cld=0 hd=70000043f99d598 par=7000004aa597e30
ct=0 hsh=0 unp=0 unn=0 hvl=643b5990 nhv=1 ses=7000005034a3ef8
hep=7000004c3821a60 flg=80 ld=1 ob=700000497c38fa8 ptr=700000445b2e260 fex=700000445b2d570
----------------------------------------
SO: 700000437e5d490, type: 53, owner: 7000005034a3ef8, flag: INIT/-/-/0x00
LIBRARY OBJECT LOCK: lock=700000437e5d490 handle=70000044eb24610 mode=N
call pin=0 session pin=0 hpc=0000 hlc=0000
htl=700000437e5d510[700000437e13b68,700000437e791e0] htb=7000004368e0fd0 ssga=7000004368e0c78
user=7000005034a3ef8 session=7000005034a3ef8 count=1 flags=[0000] savepoint=0x55471143
LIBRARY OBJECT HANDLE: handle=70000044eb24610 mtx=70000044eb24740(0) lct=3 pct=1 cdp=1
name=insert into zw_gis@cspmslink (OBJ_id, global_id,bz1,bz2,bz3, type,bz4)
select id, globeid, name,unit,gridtype,'输电','输电线路' from att_pt_line
我们可以看到，该会话在执行一个insert语句，访问的正是att_pt_line表，而且是通过dblink进行操作。 同时我们也可以看到该会话对这个表上进行了library cache lock和pin 操作，如下：
SO: 70000043a2a2d98, type: 54, owner: 70000043542b320, flag: INIT/-/-/0x00
LIBRARY OBJECT PIN: pin=70000043a2a2d98 handle=70000050c2183d0 mode=S lock=700000437ec2790
user=7000005034a3ef8 session=7000005034a3ef8 count=1 mask=0501 savepoint=0x92b flags=[00]
LIBRARY OBJECT HANDLE: handle=70000050c2183d0 mtx=70000050c218500(0) lct=28657 pct=28658 cdp=0
name=GEOSTAR.ATT_PT_LINE
hash=451da03ad5fcef0b5788626298294e0f timestamp=03-28-2015 10:45:18
namespace=TABL flags=KGHP/TIM/XLR/[00000020]
kkkk-dddd-llll=0000-0541-0749 lock=S pin=S latch#=40 hpc=77da hlc=77d2
lwt=70000050c218478[700000435ef9cc0,700000448ecdae0] ltm=70000050c218488[70000050c218488,70000050c218488]
pwt=70000050c218440[70000050c218440,70000050c218440] ptm=70000050c218450[70000050c218450,70000050c218450]
ref=70000050c2184a8[70000050c2184a8,70000050c2184a8] lnd=70000050c2184c0[70000044abad018,70000050c49edc8]
LOCK INSTANCE LOCK: id=LB451da03ad5fcef0b
PIN INSTANCE LOCK: id=NB451da03ad5fcef0b mode=S release=F flags=[00]
INVALIDATION INSTANCE LOCK: id=IV0000cfed1c0b2e13 mode=S
LIBRARY OBJECT: object=7000004a6d5e618
type=TABL flags=EXS/LOC[0005] pflags=[0000] status=VALD load=0
DATA BLOCKS:
data# heap pointer status pins change whr alloc(K) size(K)
----- -------- -------- --------- ---- ------ --- -------- --------
0 70000050c604d60 7000004a6d5e730 I/P/A/-/- 0 NONE 00 0.71 1.09
3 700000495a40b38 0 I/-/-/-/- 0 NONE 0c 0.00 0.00
8 7000004a6d5e910 700000476a42498 I/P/A/-/- 1 NONE 00 5.61 6.52
9 7000004a6d5e300 0 I/-/-/-/- 0 NONE 0c 0.00 0.00
10 7000004a6d5e388 70000047680edd8 I/P/A/-/- 1 NONE 00 6.77 7.77
----------------------------------------
SO: 700000437ec2790, type: 53, owner: 70000043542b320, flag: INIT/-/-/0x00
LIBRARY OBJECT LOCK: lock=700000437ec2790 handle=70000050c2183d0 mode=S
call pin=70000043a2a2d98 session pin=0 hpc=0000 hlc=0000
htl=700000437ec2810[7000004368e0e80,7000004368e0e80] htb=7000004368e0e80 ssga=7000004368e0c78
user=7000005034a3ef8 session=7000005034a3ef8 count=1 flags=PNC/[0400] savepoint=0x92b
LIBRARY OBJECT HANDLE: handle=70000050c2183d0 mtx=70000050c218500(0) lct=28657 pct=28658 cdp=0
name=GEOSTAR.ATT_PT_LINE
hash=451da03ad5fcef0b5788626298294e0f timestamp=03-28-2015 10:45:18
namespace=TABL flags=KGHP/TIM/XLR/[00000020]
kkkk-dddd-llll=0000-0541-0749 lock=S pin=S latch#=40 hpc=77da hlc=77d2
lwt=70000050c218478[700000435ef9cc0,700000448ecdae0] ltm=70000050c218488[70000050c218488,70000050c218488]
pwt=70000050c218440[70000050c218440,70000050c218440] ptm=70000050c218450[70000050c218450,70000050c218450]
ref=70000050c2184a8[70000050c2184a8,70000050c2184a8] lnd=70000050c2184c0[70000044abad018,70000050c49edc8]
LOCK INSTANCE LOCK: id=LB451da03ad5fcef0b
PIN INSTANCE LOCK: id=NB451da03ad5fcef0b mode=S release=F flags=[00]
INVALIDATION INSTANCE LOCK: id=IV0000cfed1c0b2e13 mode=S
LIBRARY OBJECT: object=7000004a6d5e618
type=TABL flags=EXS/LOC[0005] pflags=[0000] status=VALD load=0
DATA BLOCKS:
data# heap pointer status pins change whr
----- -------- -------- --------- ---- ------ ---
0 70000050c604d60 7000004a6d5e730 I/P/A/-/- 0 NONE 00
3 700000495a40b38 0 I/-/-/-/- 0 NONE 0c
8 7000004a6d5e910 700000476a42498 I/P/A/-/- 1 NONE 00
9 7000004a6d5e300 0 I/-/-/-/- 0 NONE 0c
10 7000004a6d5e388 70000047680edd8 I/P/A/-/- 1 NONE 00
----------------------------------------
我们知道，对应library cache latch的的获取，实际上Oracle SQL语句的硬解析、软解析、甚至软软解析都是需要获取的。 对应软软解析、是否需要获得library cache latch，在11g中有所改变，但是客户这里是10205版本。
这里我们已经知道了1516 会话在干什么，那么仍然不知道为什么1516 会导致后面的982会话被阻塞呢 ？
我们接着来看下会话982是什么进程，在干些什么 ？
----------------------------------------
SO: 70000050f440550, type: 4, owner: 70000050435d270, flag: INIT/-/-/0x00
(session) sid: 982 trans: 7000004d8e5f120, creator: 70000050435d270, flag: (48000041) USR/- BSY/-/-/-/-/-
DID: 0001-02CB-00000005, short-term DID: 0001-02CB-00000004
txn branch: 0
oct: 3, prv: 0, sql: 700000509e93e50, psql: 700000509e93e50, user: 0/SYS
O/S info: user: oracle, term: UNKNOWN, ospid: 46727232, machine: gisdata1
program: oracle@gisdata1 (J001)
application name: DBMS_SCHEDULER, hash value=2478762354
action name: GATHER_STATS_JOB, hash value=930355498
waiting for 'library cache lock' wait_time=0, seconds since wait started=148249
handle address=70000050c2183d0, lock address=700000435eee5a8, 100*mode+namespace=1f5
blocking sess=0x0 seq=7211
Dumping Session Wait History
for 'library cache lock' count=1 wait_time=0.488298 sec
handle address=70000050c2183d0, lock address=700000435eee5a8, 100*mode+namespace=1f5
for 'library cache lock' count=1 wait_time=0.488295 sec
......
我们可以看到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呢？ 首先来看下文档说明：
...... #define KGLTRCLCK 0×0010 /* trace lock operations */ #define KGLTRCPIN 0×0020 /* trace pin operations */ #define KGLTRCOBF 0×0040 /* trace object freeing */ #define KGLTRCINV 0×0080 /* trace invalidations */ #define KGLDMPSTK 0×0100 /* DUMP CALL STACK WITH TRACE */ #define KGLDMPOBJ 0×0200 /* DUMP KGL OBJECT WITH TRACE */ #define KGLDMPENQ 0×0400 /* DUMP KGL ENQUEUE WITH TRACE */ #define KGLTRCHSH 0×2000 /* DUMP BY HASH VALUE */ ......
这里取后两位：b0f3 , 至于如何计算，我们来看文档示意图：
+-------------------------------> Trace by hash turned on
| +-------------------> Trace pin operations
| | +-----> Trace invalidation
| | | operations
0xb0f30000 | KGLTRCHSH | KGLTRCPIN | KGLTRCLCK
根据Oracle 文档描述,这里还需要针对pin、lock以及hash的操作，对应的level分别是:
0×00002000
0×00000020
0×00000010
那么最后的level应该是.
b0f30000+2000+20+10=b0f32030
最后再将其转换为10进制，则如下：
www.killdb.com>select to_number('b0f32030','xxxxxxxxxxxxxxx') from dual;
TO_NUMBER('B0F32030','XXXXXXXXXXXXXXX')
---------------------------------------
2968723504
那么最后针对该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;
下面我们开始进行测试，首先我们来测试硬解析.
### 硬解析
--session 1
www.killdb.com>alter system flush shared_pool;
System altered.
www.killdb.com>select sid from v$mystat where rownum < 2;
SID
----------
159
www.killdb.com>select count(1) from t_library_lock;
COUNT(1)
----------
50042
--Session 2
www.killdb.com>select s.sid,s.serial#,s.username,p.spid from v$process p,v$session s where p.addr=s.paddr and s.sid=&sid;
Enter value for sid: 159
old 1: select s.sid,s.serial#,s.username,p.spid from v$process p,v$session s where p.addr=s.paddr and s.sid=&sid
new 1: select s.sid,s.serial#,s.username,p.spid from v$process p,v$session s where p.addr=s.paddr and s.sid=159
SID SERIAL# USERNAME SPID
---------- ---------- ------------------------- ------------
159 5 ROGER 10200
www.killdb.com>oradebug setospid 10200
Oracle pid: 15, Unix process pid: 10200, image: oracle@killdb.com (TNS V1-V3)
www.killdb.com> oradebug event 10049 trace name context forever,level 2968723504
Statement processed.
www.killdb.com>oradebug event 10049 trace name context off;
Statement processed.
www.killdb.com>oradebug tracefile_name
/home/ora10g/admin/test/udump/test_ora_10200.trc
www.killdb.com>
我们来看下trace的内容：
*** SESSION ID:(159.5) 2015-05-20 21:15:24.673 Received ORADEBUG command 'event 10049 trace name context forever,level 2968723504' from process Unix process pid: 10668, image: *** 2015-05-20 21:15:35.496 KGLTRCLCK kgllkal hd = 0x0x2997abdc KGL Lock addr = 0x0x27b751a8 mode = N KGLTRCLCK kglget hd = 0x0x2997abdc KGL Lock addr = 0x0x27b751a8 mode = N KGLTRCPIN kglpin hd = 0x0x2997abdc KGL Pin addr = 0x0x27b76010 mode = X KGLTRCPIN kglpndl hd = 0x0x2997abdc KGL Pin addr = 0x0x27b76010 mode = X KGLTRCLCK kgllkal hd = 0x0x298a1d10 KGL Lock addr = 0x0x27b4e038 mode = N KGLTRCLCK kglget hd = 0x0x298a1d10 KGL Lock addr = 0x0x27b4e038 mode = N KGLTRCPIN kglpin hd = 0x0x298a1d10 KGL Pin addr = 0x0x27b1935c mode = X KGLTRCPIN kglpndl hd = 0x0x298a1d10 KGL Pin addr = 0x0x27b1935c mode = X Received ORADEBUG command 'event 10049 trace name context off' from process Unix process pid: 10668, image:
从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 内容如下：
*** 2015-05-20 21:19:40.799
Received ORADEBUG command 'event 10049 trace name context forever,level 2968723504' from process Unix process pid: 10668, image: KGLTRCLCK kgllkdl hd = 0x0x298a1d10 KGL Lock addr = 0x0x27b4e038 mode = N KGLTRCLCK kgllkdl2 hd = 0x0x298a1d10 KGL Lock addr = 0x0x27b4e038 mode = 0 KGLTRCLCK kgllkdl hd = 0x0x2997abdc KGL Lock addr = 0x0x27b751a8 mode = N KGLTRCLCK kgllkdl2 hd = 0x0x2997abdc KGL Lock addr = 0x0x27b751a8 mode = 0 KGLTRCLCK kgllkal hd = 0x0x2997abdc KGL Lock addr = 0x0x27b2b5c0 mode = N KGLTRCLCK kglget hd = 0x0x2997abdc KGL Lock addr = 0x0x27b2b5c0 mode = N KGLTRCLCK kgllkal hd = 0x0x298a1d10 KGL Lock addr = 0x0x27b4e6b8 mode = N
我们可以看到，对应SQL语句的软解析是不需要获得library cache pin操作的，只需要获得library cache lock即可，而且mode为NULL。
### 软软解析
--session 1
www.killdb.com>show parameter session_cached_cursors
NAME TYPE VALUE
------------------------------------ ----------- ------------------------------
session_cached_cursors integer 20
www.killdb.com>conn roger/roger
Connected.
www.killdb.com>select count(1) from t_library_lock;
COUNT(1)
----------
50042
www.killdb.com>select count(1) from t_library_lock;
COUNT(1)
----------
50042
www.killdb.com>select count(1) from t_library_lock;
COUNT(1)
----------
50042
www.killdb.com>select sid from v$mystat where rownum < 2;
SID
----------
159
www.killdb.com>select count(1) from t_library_lock;
COUNT(1)
----------
50042
---session 2
www.killdb.com>select s.sid,s.serial#,s.username,p.spid from v$process p,v$session s where p.addr=s.paddr and s.sid=&sid;
Enter value for sid: 159
old 1: select s.sid,s.serial#,s.username,p.spid from v$process p,v$session s where p.addr=s.paddr and s.sid=&sid
new 1: select s.sid,s.serial#,s.username,p.spid from v$process p,v$session s where p.addr=s.paddr and s.sid=159
SID SERIAL# USERNAME SPID
---------- ---------- ------------------------- ------------
159 5 ROGER 11339
www.killdb.com>oradebug setospid 11339
Oracle pid: 15, Unix process pid: 11339, image: oracle@killdb.com (TNS V1-V3)
www.killdb.com>oradebug event 10049 trace name context forever,level 2968723504
Statement processed.
www.killdb.com>oradebug event 10049 trace name context off;
Statement processed.
www.killdb.com>oradebug tracefile_name
/home/ora10g/admin/test/udump/test_ora_11339.trc
我们来看下软软解析的trace 内容：
*** SESSION ID:(159.5) 2015-05-20 21:31:46.501 Received ORADEBUG command 'event 10049 trace name context forever,level 2968723504' from process Unix process pid: 11356, image: *** 2015-05-20 21:32:04.535 Received ORADEBUG command 'event 10049 trace name context off' from process Unix process pid: 11356, image: Received ORADEBUG command 'tracefile_name' from process Unix process pid: 11356, image: Received ORADEBUG command 'tracefile_name' from process Unix process pid: 11356, image:
我们可以看到，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)
Related posts:
