[20240828]分析為什麼出現library cache lock等待事件5.txt

[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