[20240921]跟踪library cache lock library cache pin使用gdb(补充测试).txt

--//补充测试，session 1执行exec lcp，sessin 2执行alter procedure lcp compile;sessin 3执行alter procedure lcp compile;
--//然后kill -9 session 2，看看sessin 3的相关等待事件，再kill -9 session 1,看看sessin 3的相关等待事件。

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;
/

$ 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
 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


2.测试：
--//session 1:
SCOTT@book01p(149,63787)> exec lcp

--//session 2:
SCOTT@book01p(404,9633)> alter procedure lcp compile;

--//session 3:
SCOTT@book01p(146,11322)> @ spid

       SID    SERIAL# PROCESS                  SERVER    SPID                               PID  P_SERIAL# C50
---------- ---------- ------------------------ --------- ------------------------------ ------- ---------- --------------------------------------------------
       146      11322 4396                     DEDICATED 4398                                73          4 alter system kill session '146,11322' immediate;


SCOTT@book01p(146,11322)> alter procedure lcp compile;

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

(gdb) c
Continuing.
kgllkal count 01 -- handle address: 000000006b0a7390, mode: 1 kglnaobj address:0x6b0a7558:      "alter procedure lcp compile"
kglGetS0 lock address : 0000000066610a00
kgllkal count 02 -- handle address: 00000000643f44b0, mode: 1 kglnaobj address:0x643f4678:      ""
kglGetS0 lock address : 00000000666103f8
kglpnal count 01 -- handle address: 00000000643f44b0, mode: 3 kglnaobj address:0x643f4678:      ""
kglGetS0 pin address : 00000000666104e8
kgllkal count 03 -- handle address: 00000000707e1048, mode: 2 kglnaobj address:0x707e1210:      "bookSYSCDB$ROOT"
kglGetS0 lock address : 0000000066610820
kgllkal count 04 -- handle address: 000000006b97c9f8, mode: 2 kglnaobj address:0x6b97cbc0:      "1073777561SYSCDB$ROOT"
kglGetS0 lock address : 0000000066610910
kgllkal count 05 -- handle address: 00000000643f3080, mode: 1 kglnaobj address:0x643f3248:      "e985fc239b919877f25909e8f398a456Child:1BOOK01P"
kglGetS0 lock address : 0000000066610730
kglpnal count 02 -- handle address: 00000000643f3080, mode: 3 kglnaobj address:0x643f3248:      "e985fc239b919877f25909e8f398a456Child:1BOOK01P"
kglGetS0 pin address : 0000000066610640
kgllkal count 06 -- handle address: 0000000066590ed0, mode: 1 kglnaobj address:0x66591098:      "SCOTTBOOK01P"
kglGetS0 lock address : 0000000066610730
kgllkal count 07 -- handle address: 00000000707e1048, mode: 2 kglnaobj address:0x707e1210:      "bookSYSCDB$ROOT"
kglGetS0 lock address : 00000000666104e8
kgllkal count 08 -- handle address: 000000006b97c9f8, mode: 2 kglnaobj address:0x6b97cbc0:      "1073777561SYSCDB$ROOT"
kglGetS0 lock address : 0000000066610820
kglpnal count 03 -- handle address: 0000000069def070, mode: 2 kglnaobj address:0x69def238:      "DATABASESYSBOOK01P"
kglGetS0 pin address : 00000000666104e8
kgllkal count 09 -- handle address: 0000000069c3dc30, mode: 1 kglnaobj address:0x69c3ddf8:      " SELECT VALUE$ FROM SYS.PROPS$ WHERE NAME = 'OGG_TRIGGER_OPTIMIZATION'"
kglGetS0 lock address : 00000000666104e8
kgllkal count 10 -- handle address: 00000000643fcdd0, mode: 1 kglnaobj address:0x643fcf98:      ""
kglGetS0 lock address : 0000000066610820
kgllkal count 11 -- handle address: 000000006ab05ef0, mode: 2 kglnaobj address:0x6ab060b8:      "PROPS$SYSBOOK01P(\f\273j"
kglGetS0 lock address : 0000000066610910
kglpnal count 04 -- handle address: 000000006ab05ef0, mode: 2 kglnaobj address:0x6ab060b8:      "PROPS$SYSBOOK01P(\f\273j"
kglGetS0 pin address : 0000000066610640
kglpnal count 05 -- handle address: 0000000069def070, mode: 2 kglnaobj address:0x69def238:      "DATABASESYSBOOK01P"
kglGetS0 pin address : 0000000066610910
kgllkal count 12 -- handle address: 0000000064a28260, mode: 1 kglnaobj address:0x64a28428:      "LOGMNRGGC_TRIGGERSYSBOOK01P"
kglGetS0 lock address : 0000000066610640
kglpnal count 06 -- handle address: 0000000064a28260, mode: 2 kglnaobj address:0x64a28428:      "LOGMNRGGC_TRIGGERSYSBOOK01P"
kglGetS0 pin address : 0000000066610308
kgllkal count 13 -- handle address: 0000000064a05d70, mode: 1 kglnaobj address:0x64a05f38:      "NO_VM_DDLWMSYSBOOK01P"
kglGetS0 lock address : 0000000066610640
kglpnal count 07 -- handle address: 0000000064a05d70, mode: 2 kglnaobj address:0x64a05f38:      "NO_VM_DDLWMSYSBOOK01P"
kglGetS0 pin address : 0000000066610308
kgllkal count 14 -- handle address: 0000000064a03320, mode: 1 kglnaobj address:0x64a034e8:      "LBAC$BEFORE_ALTERLBACSYSBOOK01P"
kglGetS0 lock address : 0000000066610640
kglpnal count 08 -- handle address: 0000000064a03320, mode: 2 kglnaobj address:0x64a034e8:      "LBAC$BEFORE_ALTERLBACSYSBOOK01P"
kglGetS0 pin address : 0000000066610308
kgllkal count 15 -- handle address: 00000000643f9470, mode: 1 kglnaobj address:0x643f9638:      "select count(*)", ' ' <repeats 38 times>, "from user$ u", ' ' <repeats 41 times>, "where bitand(u.spare1, 256) = 256", ' ' <repeats 22 times>, "and u.type#", ' ' <repeats 15 times>, "= 1          "...
kglGetS0 lock address : 0000000066610910
kgllkal count 16 -- handle address: 00000000643f7d10, mode: 1 kglnaobj address:0x643f7ed8:      ""
kglGetS0 lock address : 0000000066610640
kgllkal count 17 -- handle address: 000000006b83c168, mode: 2 kglnaobj address:0x6b83c330:      "USER$SYSBOOK01P"
kglGetS0 lock address : 0000000066610308
kglpnal count 09 -- handle address: 000000006b83c168, mode: 2 kglnaobj address:0x6b83c330:      "USER$SYSBOOK01P"
kglGetS0 pin address : 0000000066610218
kgllkal count 18 -- handle address: 0000000066532600, mode: 1 kglnaobj address:0x665327c8:      "LCPSCOTTBOOK01P"
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
kglGetS0 lock address : 0000000066610910
kgllkal count 19 -- handle address: 0000000066532600, mode: 3 kglnaobj address:0x665327c8:      "LCPSCOTTBOOK01P"
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
kglGetS0 lock address : 0000000066610910

Program received signal SIGUSR2, User defined signal 2.
0x00007f873a656fca in semtimedop () at ../sysdeps/unix/syscall-template.S:81
/usr/src/debug/glibc-2.17-c758a686/sysdeps/unix/syscall-template.S:81:3374:beg:0x7f873a656fca
--//显示出现library cache lock。

--//kill session 2:
--//session 4:
SYS@book> alter system kill session '404,9633' immediate;
System altered.

--//session 2:
SCOTT@book01p(404,9633)> alter procedure lcp compile;
alter procedure lcp compile
*
ERROR at line 1:
ORA-03113: end-of-file on communication channel
Process ID: 4339
Session ID: 404 Serial number: 9633

--//window 1:
(gdb) c
Continuing.

Program received signal SIGSEGV, Segmentation fault.
0x0000000015330bbe in slrac_can_access ()
(gdb) c
Continuing.

Program received signal SIGSEGV, Segmentation fault.
0x0000000015330bbe in slrac_can_access ()
(gdb) c
Continuing.

Program received signal SIGSEGV, Segmentation fault.
0x0000000015330bbe in slrac_can_access ()
(gdb) c
Continuing.

Program received signal SIGSEGV, Segmentation fault.
0x0000000015330bbe in slrac_can_access ()
(gdb) c
Continuing.
kgllkal count 20 -- handle address: 00000000707e1048, mode: 2 kglnaobj address:0x707e1210:      "bookSYSCDB$ROOT"
kglGetS0 lock address : 0000000066610308
kgllkal count 21 -- handle address: 000000006b97c9f8, mode: 2 kglnaobj address:0x6b97cbc0:      "1073777561SYSCDB$ROOT"
kglGetS0 lock address : 0000000066610218
kgllkal count 22 -- handle address: 0000000066590ed0, mode: 1 kglnaobj address:0x66591098:      "SCOTTBOOK01P"
kglGetS0 lock address : 000000006660b9d0
kglpnal count 10 -- handle address: 0000000066532600, mode: 3 kglnaobj address:0x665327c8:      "LCPSCOTTBOOK01P"
kglGetS0 pin address : 0000000066610640
--//kill session 2后，因为session 1还在运行，出现library cache pin。

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

--//session 4:
SYS@book> alter system kill session '149,63787' immediate;
System altered.

--//session 1:
SCOTT@book01p(149,63787)> exec lcp
BEGIN lcp; END;

*
ERROR at line 1:
ORA-03113: end-of-file on communication channel
Process ID: 4332
Session ID: 149 Serial number: 63787

--//window 1:
(gdb) c
Continuing.

Program received signal SIGSEGV, Segmentation fault.
0x0000000015330bbe in slrac_can_access ()
(gdb) c
Continuing.

Program received signal SIGSEGV, Segmentation fault.
0x0000000015330bbe in slrac_can_access ()
(gdb) c
Continuing.

Program received signal SIGSEGV, Segmentation fault.
0x0000000015330bbe in slrac_can_access ()
(gdb) c
Continuing.

Program received signal SIGSEGV, Segmentation fault.
0x0000000015330bbe in slrac_can_access ()
(gdb) c
Continuing.
kgllkal count 23 -- handle address: 00000000707e1048, mode: 2 kglnaobj address:0x707e1210:      "bookSYSCDB$ROOT"
kglGetS0 lock address : 0000000066610308
kgllkal count 24 -- handle address: 000000006b97c9f8, mode: 2 kglnaobj address:0x6b97cbc0:      "1073777561SYSCDB$ROOT"
kglGetS0 lock address : 0000000066610218
kgllkal count 25 -- handle address: 0000000061f0fe90, mode: 1 kglnaobj address:0x61f10058:      "select source from source$ where obj#=:1 order by line"
kglGetS0 lock address : 000000006660bac0
kglpnal count 11 -- handle address: 0000000061f0fe90, mode: 2 kglnaobj address:0x61f10058:      "select source from source$ where obj#=:1 order by line"
... --//输出太多，snapid。
kgllkal count 888 -- handle address: 000000006b845468, mode: 2 kglnaobj address:0x6b845630:     "OBJ$SYSBOOK01P"
kglGetS0 lock address : 00000000666487b0
kglpnal count 294 -- handle address: 000000006b845468, mode: 2 kglnaobj address:0x6b845630:     "OBJ$SYSBOOK01P"
kglGetS0 pin address : 0000000066612930
--//执行完成

SYS@book> @ ashtop event,p1hex,p2hex,p3hex sid=146 sysdate-15/1440 sysdate
    Total                                                                                                                                                            Distinct Distinct    Distinct
  Seconds     AAS %This   EVENT                                      P1HEX             P2HEX             P3HEX             FIRST_SEEN          LAST_SEEN           Execs Seen  Tstamps Execs Seen1
--------- ------- ------- ------------------------------------------ ----------------- ----------------- ----------------- ------------------- ------------------- ---------- -------- -----------
      181      .2   54% | library cache lock                          0000000066532600  0000000066610910  00012A0300010003 2024-09-21 10:54:14 2024-09-21 10:57:14          1      181           1
      148      .2   44% | library cache pin                           0000000066532600  0000000066610640  00012A0300010003 2024-09-21 10:57:15 2024-09-21 10:59:43          1      148           1
        3      .0    1% |                                                                                                  2024-09-21 10:51:23 2024-09-21 10:59:45          2        3           3
        1      .0    0% | db file sequential read                     0000000000000001  0000000000008584  0000000000000001 2024-09-21 10:49:10 2024-09-21 10:49:10          1        1           1
        1      .0    0% | db file sequential read                     0000000000000001  00000000000085FC  0000000000000001 2024-09-21 10:49:08 2024-09-21 10:49:08          1        1           1
        1      .0    0% | db file sequential read                     0000000000000001  0000000000008A87  0000000000000001 2024-09-21 10:49:09 2024-09-21 10:49:09          1        1           1
        1      .0    0% | db file sequential read                     0000000000000001  0000000000018EF1  0000000000000001 2024-09-21 10:49:07 2024-09-21 10:49:07          1        1           1
        1      .0    0% | db file sequential read                     0000000000000003  00000000000015DB  0000000000000001 2024-09-21 10:49:11 2024-09-21 10:49:11          1        1           1
8 rows selected.
--//session 3先出现library cache lock，然后出现library cache pin等待事件，注意看FIRST_SEEN，LAST_SEEN列。

SYS@book> @ ashtop event,p1hex,p2hex,p3hex sid=404 sysdate-15/1440 sysdate
    Total                                                                                                                                                            Distinct Distinct    Distinct
  Seconds     AAS %This   EVENT                                      P1HEX             P2HEX             P3HEX             FIRST_SEEN          LAST_SEEN           Execs Seen  Tstamps Execs Seen1
--------- ------- ------- ------------------------------------------ ----------------- ----------------- ----------------- ------------------- ------------------- ---------- -------- -----------
      109      .1  100% | library cache pin                           0000000066532600  0000000066680B88  00012A0300010003 2024-09-21 10:54:08 2024-09-21 10:55:56          1      109           1
--//session 2出现library cache pin等待事件.

--//这里显示比较怪异，单独看看：
kgllkal count 15 -- handle address: 00000000643f9470, mode: 1 kglnaobj address:0x643f9638:      "select count(*)", ' ' <repeats 38 times>, "from user$ u", ' ' <repeats 41 times>, "where bitand(u.spare1, 256) = 256", ' ' <repeats 22 times>, "and u.type#", ' ' <repeats 15 times>, "= 1          "...
kglGetS0 lock address : 0000000066610910

SYS@book> @ sharepool/shp4 00000000643f9470 0
HANDLE_TYPE            KGLHDADR         KGLHDPAR         C40                                        KGLHDLMD   KGLHDPMD   KGLHDIVC KGLOBHD0         KGLOBHD6           KGLOBHS0   KGLOBHS6   KGLOBT16   N0_6_16        N20   KGLNAHSH KGLOBT03        KGLOBT09
---------------------- ---------------- ---------------- ---------------------------------------- ---------- ---------- ---------- ---------------- ---------------- ---------- ---------- ---------- --------- ---------- ---------- ------------- ----------
child handle address   00000000643F7D10 00000000643F9470 select count(*)                                   0          0          0 00000000643F7B50 00000000643F8A80       8128      16176       3509     27813      27813 1788700000 3pzwf21p9utb0          0
parent handle address  00000000643F9470 00000000643F9470 select count(*)                                   0          0          0 00000000643F92B0 00                     4064          0          0      4064       4064 1788700000 3pzwf21p9utb0      65535

SYS@book> @ sql_id 3pzwf21p9utb0
--SQL_ID = 3pzwf21p9utb0
select count(*)                                      from user$ u                                         where bitand(u.spare1, 256) = 256                      and u.type#               = 1                        and u.name                = :1;
--//' ' <repeats 38 times>,表示重复38个空格的意思。
--//只要设置set print repeats 0就不会出现这样的情况。

kgllkal count 16 -- handle address: 00000000643f9470, mode: 1 kglnaobj address:0x643f9638:      "select count(*)                                      from user$ u                                         where bitand(u.spare1, 256) = 256                      and u.type#               = 1                        and u.name                = :1"
kglGetS0 return lock address : 0000000065ae53b0