X$mutex_sleep.location 的官方解释是 Location that attempted to acquire the latch (Mutex’s code location (where field) ,这个解释看上去还是有些模糊,我们来做个试验看看
我们简单地使用 gdb来模拟一个Curosr : Pin S on X等待事件,并以此事件来解释X$mutex_sleep.location 的真实含义
我们会打开3个session 分别为A、B、C , 一个gdb , 和一个sqlplus 用以oradebug
Session A:
[oracle@mlab2 ~]$ sqlplus / as sysdba SQL*Plus: Release 11.2.0.4.0 Production on Tue Oct 8 21:40:19 2013 Copyright (c) 1982, 2013, Oracle. All rights reserved. Connected to: Oracle Database 11g Enterprise Edition Release 11.2.0.4.0 - 64bit Production With the Partitioning, OLAP, Data Mining and Real Application Testing options SQL> select * from v$version; BANNER -------------------------------------------------------------------------------- Oracle Database 11g Enterprise Edition Release 11.2.0.4.0 - 64bit Production PL/SQL Release 11.2.0.4.0 - Production CORE 11.2.0.4.0 Production TNS for Linux: Version 11.2.0.4.0 - Production NLSRTL Version 11.2.0.4.0 - Production create table emp as select * from scott.emp; SQL> var b1 number; SQL> begin :b1 := 7902; end; 2 / PL/SQL procedure successfully completed. SQL> select * from emp where empno = :b1 2 / EMPNO ENAME JOB MGR HIREDATE SAL COMM ---------- ---------- --------- ---------- --------- ---------- ---------- DEPTNO ---------- 7902 FORD ANALYST 7566 03-DEC-81 3000 20
获取session A的SPID , 使用gdb attach到该SPID
[oracle@mlab2 ~]$ gdb $ORACLE_HOME/bin/oracle 26868 break kxsPeekBinds bt 4 end cont
登录session B 并flush shared pool:
alter system flush shared_pool;
登录session C 并执行上面的查询语句:
var b1 number; begin :b1 := 7902; end; / select * from emp where empno = :b1 /
如上如果顺利的话session C会hang在cursor: pin S wait on X 等待事件上, 而gdb中显示 session A 的stack call为:
(gdb) cont Continuing. Breakpoint 1, 0x0000000002123fa0 in kxsPeekBinds () #0 0x0000000002123fa0 in kxsPeekBinds () #1 0x00000000025b821c in opitca () #2 0x0000000001ecf7a9 in kksSetBindType () #3 0x0000000009641a89 in kksfbc () (gdb) bt #0 0x0000000002123fa0 in kxsPeekBinds () #1 0x00000000025b821c in opitca () #2 0x0000000001ecf7a9 in kksSetBindType () #3 0x0000000009641a89 in kksfbc () #4 0x00000000095bff0a in opiexe () #5 0x0000000001ba5992 in kpoal8 () #6 0x00000000095bbdad in opiodr () #7 0x00000000097a629f in ttcpip () #8 0x000000000186470e in opitsk () #9 0x0000000001869235 in opiino () #10 0x00000000095bbdad in opiodr () #11 0x00000000018607ac in opidrv () #12 0x0000000001e3a48f in sou2o () #13 0x0000000000a29265 in opimai_real () #14 0x0000000001e407ad in ssthrdmain () #15 0x0000000000a291d1 in main ()
即 session A在kxsPeekBinds 窥视绑定变量过程中 以EXCL排它模式PIN住 child cursor,而 session C需要执行该SQL 需要以SHRD PIN该child cursor 并进入cursor: pin S wait on X 等待
select * from x$mutex_sleep; ADDR INDX INST_ID MUTEX_TYPE MUTEX_TYPE_ID LOCATION_ID LOCATION SLEEPS WAIT_TIME ---------------- ---------- ---------- -------------------------------- ------------- ----------- ---------------------------------------- ---------- ---------- 00007F6D82F54108 15 1 Cursor Pin 7 5 kkslce [KKSCHLPIN2] 1500022 0 SQL> select mutex_type,location_id,location,sleeps from x$mutex_sleep_history order by sleeps asc; MUTEX_TYPE LOCATION_ID LOCATION SLEEPS -------------------------------- ----------- ---------------------------------------- ---------- Cursor Pin 5 kkslce [KKSCHLPIN2] 1 Library Cache 109 kglllal1 109 1 Library Cache 95 kglpndl1 95 1 Library Cache 57 kgllkc1 57 1 Cursor Pin 5 kkslce [KKSCHLPIN2] 1 Cursor Pin 5 kkslce [KKSCHLPIN2] 1 Library Cache 32 kglini1 32 1 Library Cache 4 kglpin1 4 1 Library Cache 2 kglget2 2 1 Library Cache 62 kglhdgn1 62 1 Library Cache 106 kglhdgn2 106 1 Library Cache 4 kglpin1 4 1 Library Cache 4 kglpin1 4 1 Library Cache 111 kglllal3 111 1 Library Cache 4 kglpin1 4 1 Library Cache 85 kgllkdl1 85 1 Library Cache 62 kglhdgn1 62 1 Library Cache 62 kglhdgn1 62 1 Cursor Pin 5 kkslce [KKSCHLPIN2] 1 Library Cache 111 kglllal3 111 1 Library Cache 85 kgllkdl1 85 1 Library Cache 32 kglini1 32 1 Cursor Parent 34 kkscsAddChildNode [KKSPRTLOC34] 1 Library Cache 62 kglhdgn1 62 1 Library Cache 62 kglhdgn1 62 1 Cursor Pin 5 kkslce [KKSCHLPIN2] 2 Library Cache 90 kglpnal1 90 2 Cursor Pin 5 kkslce [KKSCHLPIN2] 2 Library Cache 57 kgllkc1 57 2 Library Cache 106 kglhdgn2 106 2 Library Cache 119 kglUpgradeLock 119 2 Library Cache 102 kglhdgc1 102 2 Library Cache 106 kglhdgn2 106 2 Library Cache 57 kgllkc1 57 2 Library Cache 90 kglpnal1 90 2 Cursor Pin 5 kkslce [KKSCHLPIN2] 2 Cursor Pin 5 kkslce [KKSCHLPIN2] 3 Library Cache 112 kgllldl2 112 3 Library Cache 106 kglhdgn2 106 3 Cursor Pin 5 kkslce [KKSCHLPIN2] 3 Library Cache 4 kglpin1 4 3 Library Cache 57 kgllkc1 57 3 Cursor Pin 5 kkslce [KKSCHLPIN2] 3 Library Cache 57 kgllkc1 57 3 Library Cache 4 kglpin1 4 3 Cursor Pin 5 kkslce [KKSCHLPIN2] 4 Library Cache 57 kgllkc1 57 4 Cursor Pin 5 kkslce [KKSCHLPIN2] 4 Cursor Pin 5 kkslce [KKSCHLPIN2] 4 Cursor Pin 5 kkslce [KKSCHLPIN2] 5 Cursor Pin 5 kkslce [KKSCHLPIN2] 6 Library Cache 4 kglpin1 4 6 Cursor Pin 5 kkslce [KKSCHLPIN2] 179 Cursor Pin 5 kkslce [KKSCHLPIN2] 2657144 SQL> select event from v$session where sid=138; EVENT ---------------------------------------------------------------- cursor: pin S wait on X session C对应的stack call: SQL> oradebug short_stack; ksedsts()+465<-ksdxfstk()+32<-ksdxcb()+1927<-sspuser()+112<-__sighandler()<-__select()+19<-skgpwwait()+332<-kgxWait()+774<-kgxSharedExamine()+568 <-kxsGetRuntimeLock()+240<-kkscsCheckCursor()+556<-kkscsSearchChildList()+1171<-kksfbc()+12417<-kkspsc0()+1171<-kksParseCursor()+116<-opiosq0()+2027 <-kpooprx()+274<-kpoal8()+842<-opiodr()+917<-ttcpip()+2183<-opitsk()+1710<-opiino()+969<-opiodr()+917<-opidrv()+570<-sou2o()+103<-opimai_real()+133 <-ssthrdmain()+265<-main()+201<-__libc_start_main()+244 kkscsSearchChildList 搜索child cursor list kkscsCheckCursor 检查child cursor kxsGetRuntimeLock kgxSharedExamine 尝试获取child cursor上的SHRD 共享PIN 尝试获取失败后 进入Mutex等待 kgxWait
查询 x$mutex_sleep 发现 location为 kkslce [KKSCHLPIN2] ,LOCATION_ID为 5 , 我们通过 systemstate 266来看一下Mutex的情况:
SQL> oradebug setmypid Statement processed. SQL> oradebug dump systemstate 266; Statement processed. SQL> oradebug tracefile_name /s01/diag/rdbms/g11r204/G11R204/trace/G11R204_ora_26999.trc SO: 0x11b8900d0, type: 4, owner: 0x11b528118, flag: INIT/-/-/0x00 if: 0x3 c: 0x3 proc=0x11b528118, name=session, file=ksu.h LINE:12729, pg=0 (session) sid: 138 ser: 29 trans: (nil), creator: 0x11b528118 flags: (0x41) USR/- flags_idl: (0x1) BSY/-/-/-/-/- flags2: (0x40009) -/-/INC DID: , short-term DID: txn branch: (nil) edition#: 100 oct: 3, prv: 0, sql: 0x11412a3e8, psql: 0x10f565680, user: 0/SYS ksuxds FALSE at location: 0 service name: SYS$USERS client details: O/S info: user: oracle, term: pts/2, ospid: 26921 machine: mlab2.oracle.com program: sqlplus@mlab2.oracle.com (TNS V1-V3) application name: sqlplus@mlab2.oracle.com (TNS V1-V3), hash value=339804622 Current Wait Stack: 0: waiting for 'cursor: pin S wait on X' idn=0xc97fc340, value=0x8e00000000, where=0x500000000 wait_id=12 seq_num=13 snap_id=1 wait times: snap=2.245331 sec, exc=2.245331 sec, total=2.245331 sec wait times: max=infinite, heur=1 min 12 sec wait counts: calls=0 os=0 in_wait=1 iflags=0x5a2 There is at least one session blocking this session. Dumping 1 direct blocker(s): inst: 1, sid: 142, ser: 253 Dumping final blocker: inst: 1, sid: 142, ser: 253 mutex的idn=0xc97fc340 KGX Atomic Operation Log 0x10f10c230 Mutex 0x10ef26e68(142, 0) idn c97fc340 oper LONG_EXCL(18) Cursor Pin uid 142 efd 0 whr 1 slp 0 opr=3 pso=0x1140fa930 flg=0 pcs=0x10ef26dd0 nxt=(nil) flg=34 cld=0 hd=0x10f24b0a0 par=0x10ef268d0 ct=1 hsh=0 unp=(nil) unn=0 hvl=ef276c0 nhv=1 ses=0x11b883d50 hep=0x10ef26e68 flg=80 ld=1 ob=0x10ef25830 ptr=0x1163cc070 fex=0x1163cb430 KGX Atomic Operation Log 0x10eee2a10 Mutex 0x10ef26e68(142, 0) idn c97fc340 oper GET_SHRD(1) Cursor Pin uid 138 efd 0 whr 5 slp 2074 opr=2 pso=0x10eedbd60 flg=0 pcs=0x10ef26dd0 nxt=(nil) flg=34 cld=0 hd=0x10f24b0a0 par=0x10ef268d0 ct=1 hsh=0 unp=(nil) unn=0 hvl=ef276c0 nhv=1 ses=0x11b883d50 hep=0x10ef26e68 flg=80 ld=1 ob=0x10ef25830 ptr=0x1163cc070 fex=0x1163cb430 SO: 0x1140fa930, type: 78, owner: 0x11b883d50, flag: INIT/-/-/0x00 if: 0x3 c: 0x3 proc=0x11b51fb58, name=LIBRARY OBJECT LOCK, file=kgl.h LINE:8751, pg=0 LibraryObjectLock: Address=0x1140fa930 Handle=0x10f24b0a0 Mode=N CanBeBrokenCount=2 Incarnation=2 ExecutionCount=0 ClusterLock=0x10f10c230 Context=0x7f5dfce48600 User=0x11b883d50 Session=0x11b883d50 ReferenceCount=1 Flags=CBK/[0020] SavepointNum=0 LibraryHandle: Address=0x10f24b0a0 Hash=0 LockMode=N PinMode=X LoadLockMode=0 Status=VALD Name: Namespace=SQL AREA(00) Type=CURSOR(00) Statistics: InvalidationCount=1 ExecutionCount=0 LoadCount=2 ActiveLocks=2 TotalLockCount=3 TotalPinCount=5 Counters: BrokenCount=2 RevocablePointer=2 KeepDependency=0 Version=0 BucketInUse=0 HandleInUse=0 HandleReferenceCount=0 Concurrency: DependencyMutex=0x10f24b150(0, 0, 0, 0) Mutex=0x11412a528(0, 35, 0, 0) Flags=RON/PIN/PN0/EXP/CHD/[10012111] WaitersLists: Lock=0x10f24b130[0x10f24b130,0x10f24b130] Pin=0x10f24b110[0x10f24b110,0x10f24b110] LoadLock=0x10f24b188[0x10f24b188,0x10f24b188] LibraryObject: Address=0x10ef25830 HeapMask=0000-0001-0001-0000 Flags=EXS[0000] Flags2=[0000] PublicFlags=[0000] DataBlocks: Block: #='0' name=KGLH0^c97fc340 pins=0 Change=NONE Heap=0x10f24afe8 Pointer=0x10ef258d0 Extent=0x10ef257b0 Flags=I/-/P/A/-/- FreedLocation=0 Alloc=2.304688 Size=3.976562 LoadTime=4377720080 Block: #='6' name=SQLA^c97fc340 pins=0 Change=NONE Heap=0x10ef26f10 Pointer=0x1163cc070 Extent=0x1163cb430 Flags=I/-/P/A/-/E FreedLocation=0 Alloc=10.718750 Size=11.859375 LoadTime=0 NamespaceDump: Child Cursor: Heap0=0x10ef258d0 Heap6=0x1163cc070 Heap0 Load Time=10-08-2013 21:43:08 Heap6 Load Time=10-08-2013 21:43:08 SO: 0x1140fab30, type: 78, owner: 0x11b883d50, flag: INIT/-/-/0x00 if: 0x3 c: 0x3 proc=0x11b51fb58, name=LIBRARY OBJECT LOCK, file=kgl.h LINE:8751, pg=0 LibraryObjectLock: Address=0x1140fab30 Handle=0x11412a3e8 Mode=N CanBeBrokenCount=1 Incarnation=1 ExecutionCount=0 User=0x11b883d50 Session=0x11b883d50 ReferenceCount=1 Flags=CNB/[0001] SavepointNum=5254b4ac LibraryHandle: Address=0x11412a3e8 Hash=c97fc340 LockMode=N PinMode=0 LoadLockMode=0 Status=VALD ObjectName: Name=select * from emp where empno = :b1 FullHashValue=2d346c57ec22f350eb98796dc97fc340 Namespace=SQL AREA(00) Type=CURSOR(00) Identifier=3380593472 OwnerIdn=0 Statistics: InvalidationCount=1 ExecutionCount=1 LoadCount=3 ActiveLocks=2 TotalLockCount=3 TotalPinCount=1 Counters: BrokenCount=1 RevocablePointer=1 KeepDependency=1 Version=0 BucketInUse=2 HandleInUse=2 HandleReferenceCount=0 Concurrency: DependencyMutex=0x11412a498(0, 1, 0, 0) Mutex=0x11412a528(0, 35, 0, 0) Flags=RON/PIN/TIM/PN0/DBN/[10012841] WaitersLists: Lock=0x11412a478[0x11412a478,0x11412a478] Pin=0x11412a458[0x11412a458,0x11412a458] LoadLock=0x11412a4d0[0x11412a4d0,0x11412a4d0] Timestamp: Current=10-08-2013 21:40:55 HandleReference: Address=0x11412a5b8 Handle=(nil) Flags=[00] LibraryObject: Address=0x10ef26830 HeapMask=0000-0001-0001-0000 Flags=EXS[0000] Flags2=[0000] PublicFlags=[0000] ChildTable: size='16' Child: id='0' Table=0x10ef276e0 Reference=0x10ef27140 Handle=0x10f24b0a0 NamespaceDump: Parent Cursor: sql_id=fr63tdr4rzhu0 parent=0x10ef268d0 maxchild=1 plk=y ppn=n
结论:
如上述trace ,以LONG_EXCL(18)方式持有Mutex 0x10ef26e68的是SID=142的session 其whr 即location id 为1, 而对应的 等待cursor:pin S on X的session的whr 为5 sleep 为2074次 ,这里whr=5 对应了 x$mutex_sleep.location , 所以我们可以明确知道 x$mutex_sleep 也即v$MUTEX_SLEEP视图上的 LOCATION字段指的是发起对该Mutex申请的代码路径code location,而不是还持有该Mutex的代码路径或曰内核函数。
Comment