library cache lock引发的一个案例
本站文章除注明转载外,均为本站原创: 转载自love wife love life —Roger的Oracle/MySQL/PostgreSQL数据恢复博客
本文链接地址: library cache lock引发的一个案例
美女同事说某个客户有个问题,系统出现了大量的library cache lock. 导致业务严重受阻,具体表现是所有访问某个表的SQL语句都会挂起. 首先我们来看hanganalyze 的结果:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 100 101 102 103 104 105 106 107 108 109 110 111 112 113 114 115 116 117 118 119 |
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 。。。。。。 |
这里对对一部分是内容进行简单的解释:
1 2 3 4 5 |
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 可能花了几分钟才完成)。
第二部分内容是死锁信息,如下:
1 2 3 4 5 6 |
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部分内容:
1 2 3 4 5 6 7 8 |
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 ..... |
这部分内容显示了所有进程的状态以及阻塞情况。对于进程的状态,主要是分为如下几种:
1 2 3 4 5 6 7 8 |
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,如下:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 |
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在干些什么 ?
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 |
*** 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 可以发现如下内容:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 |
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 操作,如下:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 |
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是什么进程,在干些什么 ?
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 |
---------------------------------------- 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.
针对这一点,我们可以通过如下的实验来进行验证:
首先调整游标缓存的参数:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 |
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呢? 首先来看下文档说明:
1 2 3 4 5 6 7 8 9 10 |
<pre class="brush:plain">...... #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 , 至于如何计算,我们来看文档示意图:
1 2 3 4 5 |
+-------------------------------> Trace by hash turned on | +-------------------> Trace pin operations | | +-----> Trace invalidation | | | operations 0xb0f30000 | KGLTRCHSH | KGLTRCPIN | KGLTRCLCK |
根据Oracle 文档描述,这里还需要针对pin、lock以及hash的操作,对应的level分别是:
0x00002000
0x00000020
0x00000010
那么最后的level应该是.
b0f30000+2000+20+10=b0f32030
最后再将其转换为10进制,则如下:
1 2 3 4 5 |
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;
下面我们开始进行测试,首先我们来测试硬解析.
### 硬解析
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 |
--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的内容:
1 2 3 4 5 6 7 8 9 10 11 12 |
*** 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.
### 测试软解析
1 2 3 4 5 6 7 8 9 10 11 12 13 |
--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 内容如下:
1 |
*** 2015-05-20 21:19:40.799 |
1 2 3 4 5 6 7 8 |
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。
### 软软解析
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 |
--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 |
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 |
---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 内容:
1 2 3 4 5 6 |
*** 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)
One Response to “library cache lock引发的一个案例”
这个是bug,只要再次分析表,还会出现,除非取消这个表的分析.
http://yangtingkun.net/?p=1359
Leave a Reply
You must be logged in to post a comment.