[20240920]跟蹤library cache lock library cache pin使用gdb.txt

lfree發表於2024-09-22
[20240920]跟蹤library cache lock library cache pin使用gdb.txt

--//前一陣子，寫的使用gdb跟蹤library cache lock library cache pin的指令碼有一個小問題，無法獲得lock address以及pin address
--//地址,有一點點小缺陷，嘗試修改完善看看。

--//按照https://nenadnoveljic.com/blog/tracing-library-cache-locks/介紹：
In order to close this gap I, first, examined the following two Oracle C functions on the release 19.6.0.0.200114:
kgllkal and kglGetSO.

kgllkal allocates a library cache lock. It receives the following arguments:

rdx: handle address
rcx: lock mode

Further, it calls kglGetSO to allocate the library cache state object. kglGetSO returns the lock address.
--//按照介紹呼叫kglGetSO返回lock address.我猜測 library cache pind的pin地址也是類似的情況。

$ ./lookup.awk kglGetSO
kglGetSO : kernel generic library cache management get state object

--//如何使用gdb實現，自己嘗試看看。

--//仔細看連結https://nenadnoveljic.com/blog/tracing-library-cache-locks/
pid$target:oracle:kglGetSO:return
/ self->kglGetSO /
{
printf("\n");
printf("KGLLKHDL KGLLKMOD KGLLKADR\n");
printf("-------- -------- --------\n");
printf("%X %8d %X\n" , self->kgllkhdl, self->kgllkmod, arg1 );
printf("\n");
printf("==========================\n");
printf("\n");
self->kglGetSO = 0;
}
--//dtrace可以設定在kglGetSO return獲取arg1就是KGLLKADR，gdb如何實現呢？想起測試學習使用的方法，建立一個過程lcp加入sleep 3600，
--//先執行它，然後開啟另外一個會話編譯它，就會出現library cache pin，再開啟另外的會話編譯它，就會出現library cache lock，使用它
--//測試看看。

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.

SYS@book> @ sed "library cache pin"
SYS@book> @ pr
==============================
SED_EVENT# : 375
SED_NAME : library cache pin
SED_WAIT_CLASS : Concurrency
SED_P1 : handle address
SED_P2 : pin address
SED_P3 : 100*mode+namespace
SED_EQ_NAME :
SED_REQ_REASON :
SED_REQ_DESCRIPTION :
PL/SQL procedure successfully completed.
--//library cache lock類似

--//grant execute on sys.dbms_lock to scott;
create procedure lcp
is
begin
sys.dbms_lock.sleep(3600);
end;
/

2.測試1：
--//session 1:
SCOTT@book01p(412,5770)> exec lcp

--//session 2:
SCOTT@book01p(148,4168)> set timing on
SCOTT@book01p(148,4168)> alter procedure lcp compile;
--//掛起!!

SYS@book> @ ashtop event,p1hex,p2hex,p2,p3hex 1=1 &10s
Total Distinct Distinct Distinct
Seconds AAS %This EVENT P1HEX P2HEX P2 P3HEX FIRST_SEEN LAST_SEEN Execs Seen Tstamps Execs Seen1
--------- ------- ------- ------------------------------------------ ----------------- ----------------- ---------- ----------------- ------------------- ------------------- ---------- -------- -----------
10 1.0 83% | library cache pin 00000000635F4DA0 000000006C0DCDD8 1812843992 00012A0300010003 2024-09-20 16:59:23 2024-09-20 16:59:32 1 10 1
2 .2 17% | 0 2024-09-20 16:59:23 2024-09-20 16:59:31 1 2 2
--//出現library cache pin等待事件，P1hex=00000000635F4DA0就是物件控制代碼。
$ source ext_kglobj.sh 00000000635F4DA0
(gdb) 0x635f4f68: "LCPSCOTTBOOK01P"
(gdb) quit
--//使用我前面寫的抽取物件指令碼ext_kglobj.sh，可以發現就是物件lcp。中斷上面的執行。

3.編寫指令碼如下：
$ cat lkpn.gdb2
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 kglpnal if $rcx==3
break kglpnal if ($rcx=3 && $rdx=0x00000000635F4DA0)
commands
silent
printf "kglpnal count %02d -- handle address: %016x, mode: %d ", ++$pn ,$rdx ,$rcx
echo kglnaobj address:
x/s $rdx+0x1c8
c
end

break kglGetSO
commands
silent
finish
end

--//注：設定斷點在控制代碼$rdx=0x00000000635F4DA0，kglGetSO執行最後是finish，這樣停止在該函式kglGetSO的返回。

4.繼續測試：
--//session 2:
SCOTT@book01p(148,4168)> @ spid
SID SERIAL# PROCESS SERVER SPID PID P_SERIAL# C50
---------- ---------- ------------------------ --------- ------------------------------ ------- ---------- --------------------------------------------------
148 4168 5283 DEDICATED 5285 69 14 alter system kill session '148,4168' immediate;
--//獲得session 2的spid=5285。
--//window 1：
$ rlgdb -f -p 5285 -x lkpn.gdb2
...
/usr/src/debug/glibc-2.17-c758a686/sysdeps/unix/syscall-template.S:81:3374:beg:0x7f35cf359480
Breakpoint 1 at 0x1536c020
Breakpoint 2 at 0x1536f9c0

--//重複前面的測試：
--//window 1,不停按c繼續，直到出現：
(gdb) c
Continuing.
0x0000000015367fbe in kgllkal ()
(gdb) c
Continuing.
0x0000000015367fbe in kgllkal ()
(gdb) c
Continuing.
0x000000001536c16a in kglpnal ()
(gdb) c
....
(gdb) c
Continuing.
kglpnal count 01 -- handle address: 00000000635f4da0, mode: 3 kglnaobj address:0x635f4f68: "LCPSCOTTBOOK01P"
0x000000001536c16a in kglpnal ()

--//session 3:
SYS@book> @ ashtop event,p1hex,p2hex,p2,p3hex 1=1 &10s

Total Distinct Distinct Distinct
Seconds AAS %This EVENT P1HEX P2HEX P2 P3HEX FIRST_SEEN LAST_SEEN Execs Seen Tstamps Execs Seen1
--------- ------- ------- ------------------------------------------ ----------------- ----------------- ---------- ----------------- ------------------- ------------------- ---------- -------- -----------
10 1.0 77% | 1 2024-09-20 18:00:02 2024-09-20 18:00:11 1 10 1
3 .3 23% | 0 2024-09-20 18:00:03 2024-09-20 18:00:08 1 2 2

--//沒有獲得相應等待事件。

--//window 1:
(gdb) c
Continuing.
kglpnal count 01 -- handle address: 00000000635f4da0, mode: 3 kglnaobj address:0x635f4f68: "LCPSCOTTBOOK01P"
0x000000001536c16a in kglpnal ()
--//現在停在函式kglGetSO的返回處。記住停止在地址：0x000000001536c16a

(gdb) info regi
rax 0x6c09abb8 1812573112
rbx 0x0 0
rcx 0x71fa9128 1912246568
rdx 0x6c09abb8 1812573112
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
rsi 0x71fbca40 1912326720
rdi 0x3 3
rbp 0x7ffd091a1540 0x7ffd091a1540
rsp 0x7ffd091a1120 0x7ffd091a1120
r8 0x7f35d2e33570 139869148099952
r9 0x6fb37c20 1874033696
r10 0x76c84268 1992835688
r11 0x3 3
r12 0x6c297cc8 1814658248
r13 0x7f35d2dee060 139869147816032
r14 0x635f4da0 1667190176
r15 0x3 3
rip 0x1536c16a 0x1536c16a <kglpnal+330>
eflags 0x246 [ PF ZF IF ]
cs 0x33 51
ss 0x2b 43
ds 0x0 0
es 0x0 0
fs 0x0 0
gs 0x0 0

(gdb) c
Continuing.
Program received signal SIGUSR2, User defined signal 2.
0x00007f35cee68fca in semtimedop () at ../sysdeps/unix/syscall-template.S:81
/usr/src/debug/glibc-2.17-c758a686/sysdeps/unix/syscall-template.S:81:3374:beg:0x7f35cee68fca

--//session 3:
SYS@book> @ ashtop event,p1hex,p2hex,p2,p3hex 1=1 &10s

Total Distinct Distinct Distinct
Seconds AAS %This EVENT P1HEX P2HEX P2 P3HEX FIRST_SEEN LAST_SEEN Execs Seen Tstamps Execs Seen1
--------- ------- ------- ------------------------------------------ ----------------- ----------------- ---------- ----------------- ------------------- ------------------- ---------- -------- -----------
9 .9 64% | 1 2024-09-20 18:02:13 2024-09-20 18:02:22 2 9 2
2 .2 14% | library cache pin 00000000635F4DA0 000000006C09ABB8 1812573112 00012A0300010003 2024-09-20 18:02:21 2024-09-20 18:02:22 1 2 1
2 .2 14% | 0 2024-09-20 18:02:14 2024-09-20 18:02:17 1 2 2
--//P2hex=000000006C09ABB8,正好是前面rdx=0x6c09abb8對上，實際上這個就是pin address地址。
--//p3hex=00012A0300010003,100*mode+namespace,這裡稍微有點不同，前面8位，00012A03 = 76291對應lcp的object_id.
--//mode=0003，namespace=0001。

SCOTT@book01p> @ o2 lcp
owner object_name object_type SEG_PART_NAME status OID D_OID CREATED LAST_DDL_TIME
----- ----------- ----------- ------------- --------- ----- ----- ------------------- -------------------
SCOTT LCP PROCEDURE VALID 76291 2024-08-18 11:51:35 2024-09-21 12:07:05

SYS@book> @nmsp procedure -1
@ nmsp table -1
@ nmsp '' 74 or @ nmsp '' 0x4a|x4a
KGLSTDSC KGLSTIDN KGLSTIDN_HEX
--------------- -------- ------------
TABLE/PROCEDURE 1 1

--//有了前面的資訊，改寫指令碼如下：
$ cat lkpn.gdb2
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 $rcx==3
#break kgllkal if ( $rcx==3 && $rdx==0x00000000670C9E58 )
#break kgllkal if $rdx==0x00000000670C9E58
break kgllkal
condition 1
commands
silent
printf "kgllkal count %02d -- handle address: %016x, mode: %d ", ++$lk ,$rdx ,$rcx
echo kglnaobj address:
x/s $rdx+0x1c8
c
end

#break kglpnal if $rcx==3
#break kglpnal if $rdx==0x00000000635F4DA0
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 kglGetSO
#commands
# silent
# finish
#end

break *0x0000000015367fbe
commands
silent
printf "kglGetS0 return lock address : %016x\n", $rdx
c
end

break *0x1536c16a
commands
silent
printf "kglGetS0 return pin address : %016x\n", $rdx
c
end
--//注：呼叫kgllkal在呼叫kglGetS0的返回停止在0x15367fbe地址時，對應暫存器rdx的就是lock地址(猜測)。

4.繼續測試，驗證lock address是否正確。
--//session 3,再開啟新的會話：
SCOTT@book01p(272,12390)> @spid
SID SERIAL# PROCESS SERVER SPID PID P_SERIAL# C50
---------- ---------- ------------------------ --------- ------------------------------ ------- ---------- --------------------------------------------------
272 12390 6427 DEDICATED 6429 70 20 alter system kill session '272,12390' immediate;

--//window 1：
$ rlgdb -f -p 6429 -x lkpn.gdb2
...
/usr/src/debug/glibc-2.17-c758a686/sysdeps/unix/syscall-template.S:81:3374:beg:0x7f931703e480
Breakpoint 1 at 0x15367e90
Breakpoint 2 at 0x1536c020
Breakpoint 3 at 0x15367fbe
Breakpoint 4 at 0x1536c16a
(gdb) c

--//重複前面的測試，只不過這次是3個會話。

--//session 1:
SCOTT@book01p(412,5770)> exec lcp

--//session 2:
SCOTT@book01p(148,4168)> set timing on
SCOTT@book01p(148,4168)> alter procedure lcp compile;
--//掛起!!

--//session 4:
SCOTT@book01p(272,12390)> set timing on
SCOTT@book01p(272,12390)> alter procedure lcp compile;
--//掛起!!

--//window 1：
(gdb) c
Continuing.
kgllkal count 01 -- handle address: 0000000063cb7b20, mode: 1 kglnaobj address:0x63cb7ce8: "alter procedure lcp compile"
kglGetS0 lock address : 0000000063634090
kgllkal count 02 -- handle address: 000000006134f840, mode: 1 kglnaobj address:0x6134fa08: ""
kglGetS0 lock address : 00000000610c6b90
kglpnal count 01 -- handle address: 000000006134f840, mode: 3 kglnaobj address:0x6134fa08: ""
kglGetS0 pin address : 00000000610c6d70
kgllkal count 03 -- handle address: 00000000702d5908, mode: 2 kglnaobj address:0x702d5ad0: "bookSYSCDB$ROOT"
kglGetS0 lock address : 00000000610c6c80
kgllkal count 04 -- handle address: 000000006b97c9f8, mode: 2 kglnaobj address:0x6b97cbc0: "1073777561SYSCDB$ROOT"
kglGetS0 lock address : 0000000063633eb0
kgllkal count 05 -- handle address: 0000000069c6b610, mode: 1 kglnaobj address:0x69c6b7d8: "e985fc239b919877f25909e8f398a456Child:2BOOK01P"
kglGetS0 lock address : 0000000063633dc0
kglpnal count 02 -- handle address: 0000000069c6b610, mode: 3 kglnaobj address:0x69c6b7d8: "e985fc239b919877f25909e8f398a456Child:2BOOK01P"
kglGetS0 pin address : 00000000610c6aa0
kgllkal count 06 -- handle address: 0000000060d45130, mode: 1 kglnaobj address:0x60d452f8: "SCOTTBOOK01P"
kglGetS0 lock address : 0000000063633dc0
kgllkal count 07 -- handle address: 00000000702d5908, mode: 2 kglnaobj address:0x702d5ad0: "bookSYSCDB$ROOT"
kglGetS0 lock address : 00000000610c6d70
kgllkal count 08 -- handle address: 000000006b97c9f8, mode: 2 kglnaobj address:0x6b97cbc0: "1073777561SYSCDB$ROOT"
kglGetS0 lock address : 00000000610c6c80
kglpnal count 03 -- handle address: 00000000697c1220, mode: 2 kglnaobj address:0x697c13e8: "DATABASESYSBOOK01P"
kglGetS0 pin address : 00000000610c6d70
kglpnal count 04 -- handle address: 00000000697c1220, mode: 2 kglnaobj address:0x697c13e8: "DATABASESYSBOOK01P"
kglGetS0 pin address : 00000000610c6d70
kgllkal count 09 -- handle address: 0000000067570378, mode: 1 kglnaobj address:0x67570540: "LOGMNRGGC_TRIGGERSYSBOOK01P"
kglGetS0 lock address : 00000000610c6c80
kglpnal count 05 -- handle address: 0000000067570378, mode: 2 kglnaobj address:0x67570540: "LOGMNRGGC_TRIGGERSYSBOOK01P"
kglGetS0 pin address : 0000000063633eb0
kgllkal count 10 -- handle address: 00000000674b5f50, mode: 1 kglnaobj address:0x674b6118: "NO_VM_DDLWMSYSBOOK01P"
kglGetS0 lock address : 00000000610c6c80
kglpnal count 06 -- handle address: 00000000674b5f50, mode: 2 kglnaobj address:0x674b6118: "NO_VM_DDLWMSYSBOOK01P"
kglGetS0 pin address : 0000000063633eb0
kgllkal count 11 -- handle address: 0000000066fe8790, mode: 1 kglnaobj address:0x66fe8958: "LBAC$BEFORE_ALTERLBACSYSBOOK01P"
kglGetS0 lock address : 00000000610c6c80
kglpnal count 07 -- handle address: 0000000066fe8790, mode: 2 kglnaobj address:0x66fe8958: "LBAC$BEFORE_ALTERLBACSYSBOOK01P"
kglGetS0 pin address : 0000000063633eb0
kgllkal count 12 -- handle address: 00000000635f4da0, mode: 1 kglnaobj address:0x635f4f68: "LCPSCOTTBOOK01P"
kglGetS0 lock address : 00000000610c6d70
kgllkal count 13 -- handle address: 00000000635f4da0, mode: 3 kglnaobj address:0x635f4f68: "LCPSCOTTBOOK01P"
kglGetS0 lock address : 00000000610c6d70
--//物件LCPSCOTTBOOK01P ，session 4先呼叫kgllkal mode=1，因為session 2出現library cache pin的mode=3，無法獲取，出現
--//library cache lock等待事件，mode=3.
Program received signal SIGUSR2, User defined signal 2.
0x00007f9316b4dfca in semtimedop () at ../sysdeps/unix/syscall-template.S:81
/usr/src/debug/glibc-2.17-c758a686/sysdeps/unix/syscall-template.S:81:3374:beg:0x7f9316b4dfca
--//進入休眠，每3秒探測1次。

SYS@book> @ ashtop event,p1hex,p2hex,p2,p3hex 1=1 &10s
Total Distinct Distinct Distinct
Seconds AAS %This EVENT P1HEX P2HEX P2 P3HEX FIRST_SEEN LAST_SEEN Execs Seen Tstamps Execs Seen1
--------- ------- ------- ------------------------------------------ ----------------- ----------------- ---------- ----------------- ------------------- ------------------- ---------- -------- -----------
10 1.0 48% | library cache lock 00000000635F4DA0 00000000610C6D70 1628204400 00012A0300010003 2024-09-20 18:22:19 2024-09-20 18:22:28 1 10 1
10 1.0 48% | library cache pin 00000000635F4DA0 000000006198F7B0 1637414832 00012A0300010003 2024-09-20 18:22:19 2024-09-20 18:22:28 1 10 1
1 .1 5% | 0 2024-09-20 18:22:20 2024-09-20 18:22:20 1 1 1
--//可以發現等待事件library cache lock的P2的資訊完全可以對上。

5.簡單小結：

--//透過呼叫kglGetSO的返回獲得library cache lock/library cache pin的lock pin address。
--//gdb不知道如何寫在kglGetSO的返回處獲得相應地址，只能使用硬程式碼獲得相應暫存器資訊，那位知道gdb如何寫。

相關文章