Tracing Library Cache Locks

While working on a recent problem, I missed a possibility of tracing library cache locks. In contrast, row cache locks can be traced with the event 10222:

...
kqrpre: optimistic lookup: success
kqrpre: done po=7fffbd990200 cid=8 flg=0 eq=0 pso=99184ec8 dur=CALL
kqrpre: keyIndex=0 hash=162240d8 d53980ff 0
kqrpre: obobn=690 obname=OPTSTAT_HIST_CONTROL$ obtyp=2 obsta=1 obflg=4194304
kqrpre: returnVal: TRUE
...

As far as I know, there isn’t anything similar for library cache locks. If you were thinking of querying x$kgllk or dumping the library cache, they provide just a momentary snapshot of the current state. But sometimes, it’s useful to observe the library cache locks over time. SQL trace shows that information, but only for blocked requests.

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.

That being said, it’s easy to come up with the DTrace script which assembles the useful information:

#pragma D option quiet

pid$target:oracle:kgllkal:entry
{
  printf("%Y\n", walltimestamp);
  ustack();
  self->kgllkhdl = arg2;
  self->kgllkmod = arg3;
}

pid$target:oracle:kglGetSO:entry
/ self->kgllkhdl /
{
  self->kglGetSO = 1;
}

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

pid$target:oracle:kgllkal:return
{
  self->kgllkhdl = 0;
  self->kgllkmod = 0;
}

Here’s a sample output:

...
==========================

2020 May  8 22:02:18

              oracle`kgllkal
              oracle`kglLockCursor+0x83c
              oracle`kkspbd0+0x161
              oracle`kksParseCursory+0x1a5
              oracle`opiosq0+0xb72
              oracle`opipls+0x1a52
              oracle`opiodr+0x439
              oracle`rpidrus+0xdc
              oracle`skgmstack+0x59
              oracle`rpidru+0x9f
              oracle`rpiswu2+0x22e
              oracle`rpidrv+0x551
              oracle`psddr0+0x22f
              oracle`psdnal+0x31a
              oracle`pevm_EXECC+0x14a
              oracle`pfrinstr_EXECC+0x41
              oracle`pfrrun_no_tool+0x3c
              oracle`pfrrun+0x54a
              oracle`plsql_run+0x2c0
              oracle`peicnt+0x16c

KGLLKHDL KGLLKMOD KGLLKADR
-------- -------- --------
9E4C2908        1 99B2BFA8

==========================

2020 May  8 22:02:18

              oracle`kgllkal
              oracle`kglLockCursor+0x83c
              oracle`kxsGetLookupLock+0x67
              oracle`kkscsCheckCursor+0x1b2
              oracle`kkscsSearchChildList+0x398
              oracle`kksfbc+0xabd
              oracle`kkspbd0+0x39f
              oracle`kksParseCursor+0x1a5
              oracle`opiosq0+0xb72
              oracle`opipls+0x1a52
              oracle`opiodr+0x439
              oracle`rpidrus+0xdc
              oracle`skgmstack+0x59
              oracle`rpidru+0x9f
              oracle`rpiswu2+0x22e
              oracle`rpidrv+0x551
              oracle`psddr0+0x22f
              oracle`psdnal+0x31a
              oracle`pevm_EXECC+0x14a
              oracle`pfrinstr_EXECC+0x41

KGLLKHDL KGLLKMOD KGLLKADR
-------- -------- --------
9C7093A8        1 99B2BDD8

==========================

The script shows the call stacks, thus, providing the context of each lock allocation. In the example above, the first entry is for parsing a parent cursor, the second for a child cursor.

The script also shows the columns from x$kgllk, which is, by the way, the SQL interface to the shared memory structure underpinning library cache locks:

• KGLLKHDL: handle address (parameter 1 of library cache lock wait event)
• KGLLKADR: lock address (parameter 2 of library cache lock wait event)
• KGLLKMOD: lock mode (contained in the parameter 3 of library cache lock wait event)

You can use these values for querying the database:

select kgllkhdl,kglhdpar,kgllkmod,kglnaobj,kgllkuse from x$kgllk 
  where kgllkadr in ('0000000099B2BFA8','0000000099B2BDD8') ;

KGLLKHDL         KGLHDPAR           KGLLKMOD KGLNAOBJ                                                     KGLLKUSE
---------------- ---------------- ---------- ------------------------------------------------------------ ----------------
000000009C7093A8 000000009E4C2908          1 UPDATE /*+ OPT_PARAM('_parallel_syspls_obey_force' 'false')  00000000BA662B50
000000009E4C2908 000000009E4C2908          1 UPDATE /*+ OPT_PARAM('_parallel_syspls_obey_force' 'false')  00000000BA662B50

Note that the output above confirms the relationship between the parent and the child cursor that we deduced by observing the call stacks.

Once more, DTrace proved invaluable for extending the observability in the Oracle database.