[20240828]分析为什么出现library cache lock等待事件5.txt
--//前几天测试遇到的问题,假如表不存在的情况下,如果密集执行这类sql语句,不理解为什么出现library cache lock等待事件.
--//验证如果有1个会话,是否会持有mode=3的情况出现.
--//上午使用gdb设置断点来验证,这次直接密集执行看看.
1.环境:
SCOTT@book01p> @ver2
==============================
PORT_STRING : x86_64/Linux 2.4.xx
VERSION : 21.0.0.0.0
BANNER : Oracle Database 21c Enterprise Edition Release 21.0.0.0.0 - Production
BANNER_FULL : Oracle Database 21c Enterprise Edition Release 21.0.0.0.0 - Production
Version 21.3.0.0.0
BANNER_LEGACY : Oracle Database 21c Enterprise Edition Release 21.0.0.0.0 - Production
CON_ID : 0
PL/SQL procedure successfully completed.
2.首先定位该对象handle address:
--//换一个方式验证:
$ sql_idz.sh 'select count(1) from deptxxx' 0
sql_text = select count(1) from deptxxx\0
full_hash_value(16) = AA0B8A5E997323CE2D65F9B7AF91ED4F or aa0b8a5e997323ce2d65f9b7af91ed4f
hash_value(10) = 2945576271
sql_id(32) = 2utgtqyrt3vag
sql_id(32) = 2utgtqyrt3vag
sql_id(32) = 2utgtqyrt3vag
SYS@book> @nmsp '' x52
@ nmsp table -1
@ nmsp '' 74 or @ @ nmsp '' 0x4a|x4a
KGLSTDSC KGLSTIDN KGLSTIDN_HEX
-------------- -------- ------------
SQL AREA BUILD 82 52
--//阻塞的对象在aa0b8a5e997323ce2d65f9b7af91ed4f.$BUILD$.BOOK01P\x52\0\0\0
$ sql_idz.sh 'aa0b8a5e997323ce2d65f9b7af91ed4f.$BUILD$.BOOK01P\x52\0\0\0' 3
sql_text = aa0b8a5e997323ce2d65f9b7af91ed4f.$BUILD$.BOOK01P\x52\0\0\0
full_hash_value(16) = 21DBAB24066F9561659DE3D1D5F8B304 or 21dbab24066f9561659de3d1d5f8b304
xxxxx_matching_signature(10) = 7322259059551810308 or 25769003133261361924
hash_value(10) = 3589845764
sql_id(32) = 6b7g3u7azjcs4
sql_id(32) = 6b7g3u7azjcs4
sql_id(32) = 6b7g3u7azjcs4
--//hash_value(10) = 3589845764
SCOTT@book01p> select count(1) from deptxxx;
select count(1) from deptxxx
*
ERROR at line 1:
ORA-00942: table or view does not exist
--//执行多次。
SYS@book> @ kglob 0 3589845764
==============================
INST_ID : 1
OWNER : $BUILD$
NAME : aa0b8a5e997323ce2d65f9b7af91ed4f
DB_LINK :
NAMESPACE : SQL AREA BUILD
TYPE : CURSOR
NAMESPACE_NUM : 82
NAMESPACE_HEX : 52
SHARABLE_MEM : 0
LOADS : 0
EXECUTIONS : 0
LOCKS : 0
PINS : 0
KEPT : NO
CHILD_LATCH : 45828
INVALIDATIONS : 0
HASH_VALUE : 3589845764
LOCK_MODE : NONE
PIN_MODE : NONE
STATUS : UNKOWN
TIMESTAMP :
PREVIOUS_TIMESTAMP :
LOCKED_TOTAL : 5
PINNED_TOTAL : 0
PROPERTY :
FULL_HASH_VALUE : 21dbab24066f9561659de3d1d5f8b304
CON_ID : 3
CON_NAME : BOOK01P
ADDR : 0000000062E09BD0
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
EDITION :
SQL_ID :
OBJECT_STR : aa0b8a5e997323ce2d65f9b7af91ed4f.$BUILD$.BOOK01P\x52\0\0\0
PL/SQL procedure successfully completed.
--//其handle address=0000000062E09BD0
--//建立bbb.txt包含50000个/
--//$ rm bbb.txt
$ seq 50000 | xargs -IQ echo / >> bbb.txt
$ uniq -c bbb.txt
50000 /
3.开始测试：
--//session 1:
SCOTT@book01p> select count(1) from deptxxx;
select count(1) from deptxxx
*
ERROR at line 1:
ORA-00942: table or view does not exist
--//session 2:
SYS@book> spool /tmp/lk1.txt
SYS@book> column KGLNAOBJ format a32
SYS@book> select KGLLKSNM sid ,KGLLKMOD,KGLLKREQ,KGLNAOBJ,KGLLKHDL from x$kgllk where KGLLKHDL=hextoraw(upper('0000000062E09BD0'));
no rows selected
--//两边同时调用bbb.txt执行,等待执行完成.我的测试在执行session 2执行,然后快速切换到session 1执行.
$ egrep "0000000062E09BD0$|---| KGLLKHDL$" /tmp/lk1.txt | sort |uniq -c
959 ---------- ---------- ---------- -------------------------------- ----------------
1 268 0 0 aa0b8a5e997323ce2d65f9b7af91ed4f 0000000062E09BD0
9 268 2 0 aa0b8a5e997323ce2d65f9b7af91ed4f 0000000062E09BD0
949 268 3 0 aa0b8a5e997323ce2d65f9b7af91ed4f 0000000062E09BD0
959 SID KGLLKMOD KGLLKREQ KGLNAOBJ KGLLKHDL
--//可以看出出现9次KGLLKMOD=3的情况,奇怪这样抓不到KGLLKMOD=0,KGLLKREQ=3的情况.也许这样的状态阻塞查询.
4.最后一个问题为什么这么多对象,最容易阻塞的在这里呢?
$ cat lcl.gdb
set pagination off
set logging file /tmp/lkpn.log
set logging overwrite on
set logging on
set $lk = 0
set $pn = 0
set $lock = 0
#break kgllkal if ( $rdx==0x0000000062E09BD0)
break kgllkal
commands
silent
printf "kgllkal count %02d -- handle address: %016x, mode: %d ", ++$lk ,$rdx ,$rcx
echo kglnaobj address:
x/s $rdx+0x1c8
c
#finish
end
#break kglpnal if $rcx==3
break kglpnal
commands
silent
printf "kglpnal count %02d -- handle address: %016x, mode: %d ", ++$pn ,$rdx ,$rcx
echo kglnaobj address:
x/s $rdx+0x1c8
c
end
break kglLock
commands
silent
#printf "kglLock count %02d -- handle address: %016x, mode: %d \n", ++$lock ,$rdx ,$rcx
printf "kglLock count %02d -- mode: %d \n", ++$lock ,$rcx
c
finish
end
Breakpoint 1 at 0x15367e90
Breakpoint 2 at 0x1536c020
Breakpoint 3 at 0x15363530
(gdb) c
Continuing.
kglLock count 01 ----------------------
kgllkal count 01 -- handle address: 0000000062e0b100, mode: 1 kglnaobj address:0x62e0b2c8: "select count(1) from deptxxx"
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
kglLock count 02 ----------------------
kgllkal count 02 -- handle address: 0000000062e09bd0, mode: 2 kglnaobj address:0x62e09d98: "aa0b8a5e997323ce2d65f9b7af91ed4f$BUILD$BOOK01P"
kgllkal count 03 -- handle address: 0000000062e099a0, mode: 1 kglnaobj address:0x62e09b68: ""
kglpnal count 01 -- handle address: 0000000062e099a0, mode: 3 kglnaobj address:0x62e09b68: ""
kglLock count 03 ----------------------
++++++++++++++++++++++++++++++++++++++
kgllkal count 04 -- handle address: 00000000702c73a0, mode: 2 kglnaobj address:0x702c7568: "bookSYSCDB$ROOT"
kglLock count 04 ----------------------
kgllkal count 05 -- handle address: 000000006b57c9f8, mode: 2 kglnaobj address:0x6b57cbc0: "1073777561SYSCDB$ROOT"
kglLock count 05 ----------------------
kgllkal count 06 -- handle address: 0000000062e08570, mode: 1 kglnaobj address:0x62e08738: "aa0b8a5e997323ce2d65f9b7af91ed4fChild:0BOOK01P"
kglpnal count 02 -- handle address: 0000000062e08570, mode: 3 kglnaobj address:0x62e08738: "aa0b8a5e997323ce2d65f9b7af91ed4fChild:0BOOK01P"
kglLock count 06 ----------------------
kgllkal count 07 -- handle address: 000000006e1370d8, mode: 1 kglnaobj address:0x6e1372a0: "SCOTTBOOK01P"
kglLock count 07 ----------------------
kglLock count 08 ----------------------
kgllkal count 08 -- handle address: 00000000702c73a0, mode: 2 kglnaobj address:0x702c7568: "bookSYSCDB$ROOT"
kglLock count 09 ----------------------
kgllkal count 09 -- handle address: 000000006b57c9f8, mode: 2 kglnaobj address:0x6b57cbc0: "1073777561SYSCDB$ROOT"
kglLock count 10 ----------------------
kgllkal count 10 -- handle address: 0000000062e07040, mode: 2 kglnaobj address:0x62e07208: "DEPTXXXSCOTTBOOK01P"
kglpnal count 03 -- handle address: 0000000062e07040, mode: 2 kglnaobj address:0x62e07208: "DEPTXXXSCOTTBOOK01P"
kglLock count 11 ----------------------
kgllkal count 11 -- handle address: 0000000062e055e0, mode: 2 kglnaobj address:0x62e057a8: "DEPTXXXPUBLICBOOK01P"
kglpnal count 04 -- handle address: 0000000062e055e0, mode: 2 kglnaobj address:0x62e057a8: "DEPTXXXPUBLICBOOK01P"
--//为什么没有出现在下划线位置呢?
SYS@book> select KGLLKSNM sid ,KGLLKMOD,KGLLKREQ,KGLNAOBJ,KGLLKHDL from x$kgllk where KGLLKHDL=hextoraw(upper('0000000062e0b100'));
SID KGLLKMOD KGLLKREQ KGLNAOBJ KGLLKHDL
---------- ---------- ---------- -------------------------------- ----------------
268 1 0 select count(1) from deptxxx 0000000062E0B100
--//在语句的父游标句柄上KGLLKMOD=1.重新前面的测试.
$ egrep "0000000062E0B100$|---| KGLLKHDL$" /tmp/lk2.txt | sort |uniq -c
1 ---------- ---------- ---------- -------------------------------- ----------
6247 ---------- ---------- ---------- -------------------------------- ----------------
1 268 0 0 select count(1) from deptxxx 0000000062E0B100
6246 268 1 0 select count(1) from deptxxx 0000000062E0B100
6248 SID KGLLKMOD KGLLKREQ KGLNAOBJ KGLLKHDL
--//KGLLKMOD=1,NULL模式,表示易碎解析锁,表示是否有效,失效的状态.根本不存在阻塞.
--//在+++++++位置出现阻塞，就很容易理解，不知道是否与前面的kglpnal mode=3,不过对象不同.
kglpnal count 01 -- handle address: 0000000062e099a0, mode: 3 kglnaobj address:0x62e09b68: "" --//子游标句柄有关。
--//现在想想oracle从12c开始在alter日志中记录执行超过100次以上的有问题的sql语句，有其道理的。
$ grep deptxxx alert_book.log |uniq -c
7006 BOOK01P(3):select count(1) from deptxxx