Tracing Library Cache Locks Using _kgl_debug

A recent blog post from Nenad Noveljic prompted me to review the library cache tracing facilities available in Oracle database.

After a bit of tinkering I discovered the actual library cache lock tracing is governed by the _kgl_debug parameter.

Here is a little sample code to demonstrate that - I borrowed part of it from the excellent Nenad's blog post:

SQL> create table t (n1 integer,n2 integer);

Table created.

SQL> create index ix_t on t(n1,n2);

Index created.

SQL> exec dbms_stats.gather_table_stats ('', 'T', cascade => true)

PL/SQL procedure successfully completed.

SQL>
SQL> alter system set "_kgl_debug"=32 scope=memory;

System altered.

SQL>
SQL> alter index ix_t invisible ;

Index altered.

In a nutshell, _kgl_debug=32 appears to result in writing information about library cache locks in the trace file. Here is how it looks:

SQL> col trace_file old_v tf for a72
SQL> col dirname old_v dn for a50
SQL> col basename old_v bn for a21
SQL>
SQL> select value trace_file,
  2         substr(value, 1, instr(value, '/', -1)-1) dirname,
  3         substr(value, instr(value, '/', -1)+1) basename
  4    from v$diag_info
  5   where name='Default Trace File';

TRACE_FILE                                                               DIRNAME                                            BASENAME
------------------------------------------------------------------------ -------------------------------------------------- ---------------------
/u01/app/oracle/diag/rdbms/racdba/racdba1/trace/racdba1_ora_16440.trc    /u01/app/oracle/diag/rdbms/racdba/racdba1/trace    racdba1_ora_16440.trc

SQL>
SQL> ho tail -64 &tf.
    <Mode>N</Mode>
  </LibraryObjectLock>
</KGLTRACE>
<KGLTRACE>
  <Timestamp>2021-02-12 15:41:23.656</Timestamp>
  <SID>136</SID>
  <Function>kglLock</Function>
  <Reason>TRACELOCK</Reason>
  <Param1>0x706c20e0</Param1>
  <Param2>1</Param2>
  <LibraryHandle>
    <Address>0x67f78888</Address>
    <Hash>94e2179b</Hash>
    <LockMode>N</LockMode>
    <PinMode>0</PinMode>
    <LoadLockMode>0</LoadLockMode>
    <Status>VALD</Status>
    <ObjectName>
      <Name>select value trace_file,
       substr(value, 1, instr(value, '/', -1)-1) dirname,
       substr(value, instr(value, '/', -1)+1) basename
  from v$diag_info
 where name='Default Trace File'</Name>
      <FullHashValue>8c302f585b9b9a83239f686f94e2179b</FullHashValue>
      <Namespace>SQL AREA(00)</Namespace>
      <Type>CURSOR(00)</Type>
      <ContainerId>1</ContainerId>
      <ContainerUid>1</ContainerUid>
      <Identifier>2497845147</Identifier>
      <OwnerIdn>89</OwnerIdn>
    </ObjectName>
  </LibraryHandle>
  <LibraryObjectLock>
    <Address>0x706c20e0</Address>
    <Handle>0x67f78888</Handle>
    <Mode>N</Mode>
  </LibraryObjectLock>
</KGLTRACE>
<KGLTRACE>
  <Timestamp>2021-02-12 15:41:23.657</Timestamp>
  <SID>136</SID>
  <Function>kgllkal</Function>
  <Reason>TRACELOCK</Reason>
  <Param1>0x706c1ff8</Param1>
  <Param2>0</Param2>
  <LibraryHandle>
    <Address>0x67f78328</Address>
    <Hash>0</Hash>
    <LockMode>N</LockMode>
    <PinMode>0</PinMode>
    <LoadLockMode>0</LoadLockMode>
    <Status>VALD</Status>
    <Name>
      <Namespace>SQL AREA(00)</Namespace>
      <Type>CURSOR(00)</Type>
      <ContainerId>3</ContainerId>
    </Name>
  </LibraryHandle>
  <LibraryObjectLock>
    <Address>0x706c1ff8</Address>
    <Handle>0x67f78328</Handle>
    <Mode>N</Mode>
  </LibraryObjectLock>
</KGLTRACE>

It is quite convenient that the trace data is provided in XML - it can be parsed easily:

SQL> create or replace directory trace_dir as '&dn.';
old   1: create or replace directory trace_dir as '&dn.'
new   1: create or replace directory trace_dir as '/u01/app/oracle/diag/rdbms/racdba/racdba1/trace'

Directory created.

SQL>
SQL> create table trace_ext (
  2    trace_data clob
  3  )
  4  organization external (
  5    type oracle_loader
  6    default directory trace_dir
  7    access parameters (
  8      records
  9      xmltag ("KGLTRACE")
 10      fields ldrtrim
 11      missing field values are null (
 12        trace_data char(1000000)
 13      )
 14    )
 15    location ('&bn.')
 16  )
 17  reject limit unlimited;
old  15:   location ('&bn.')
new  15:   location ('racdba1_ora_16440.trc')

Table created.

SQL>
SQL> select count(*) from trace_ext;

  COUNT(*)
----------
       275

SQL> ho grep KGLTRACE &tf. | wc -l
550

Looks good. 275 rows in the external table for 550 KGLTRACE tags - these are both opening and closing tags, so that the number of rows matches precisely the number of XML elements in the trace file.

Finally, we can retrieve the information about kgllkal calls for interesting objects:

SQL> select xt."Timestamp",
  2         xt."Function",
  3         xt."Reason",
  4         xt."Param1",
  5         lh."LockMode",
  6         lh."PinMode",
  7         obj."Name",
  8         obj."Namespace",
  9         obj."Type",
 10         lol."Address" lol_address,
 11         lol."Mode" lol_mode
 12    from trace_ext,
 13         xmltable('/KGLTRACE' passing xmltype(trace_data)
 14           columns "Timestamp" varchar2(24),
 15                   sid number,
 16                   "Function" varchar2(20),
 17                   "Reason" varchar2(10),
 18                   "Param1" varchar2(14),
 19                   "Param2" number,
 20                   "LibraryHandle" xmltype,
 21                   "LibraryObjectLock" xmltype
 22         )(+) xt,
 23         xmltable('/LibraryHandle' passing xt."LibraryHandle"
 24           columns "Address" varchar2(10),
 25                   "Hash" varchar2(10),
 26                   "LockMode" varchar2(8),
 27                   "PinMode" varchar2(8),
 28                   "LoadLockMode" varchar2(8),
 29                   "Status" varchar2(10),
 30                   "ObjectName" xmltype
 31         )(+) lh,
 32         xmltable('/ObjectName' passing lh."ObjectName"
 33           columns "Name" varchar2(64),
 34                   "FullHashValue" varchar2(32),
 35                   "Namespace" varchar2(32),
 36                   "Type" varchar2(32),
 37                   "ContainerId" number,
 38                   "ContainerUid" number,
 39                   "Identifier" number,
 40                   "OwnerIdn" number
 41         )(+) obj,
 42         xmltable('/LibraryObjectLock' passing xt."LibraryObjectLock"
 43           columns "Address" varchar2(10),
 44                   "Handle" varchar2(10),
 45                   "Mode"   varchar2(4)
 46         )(+) lol
 47   where 1=1
 48     and obj."Name" like '%PDB.TC.%'
 49     and xt."Function"='kgllkal';

Timestamp                Function Reason     Param1         LockMode PinMode  Name            Namespace            Type       LOL_ADDRES LOL_MODE
------------------------ -------- ---------- -------------- -------- -------- --------------- -------------------- ---------- ---------- --------
2021-02-12 15:41:23.595  kgllkal  TRACELOCK  0x62da2ef0     S        0        PDB.TC.IX_T     INDEX(04)            INDEX(01)  0x62da2ef0 S
2021-02-12 15:41:23.598  kgllkal  TRACELOCK  0x62da2ef0     S        0        PDB.TC.T        TABLE/PROCEDURE(01)  TABLE(02)  0x62da2ef0 S
2021-02-12 15:41:23.599  kgllkal  TRACELOCK  0x62c9f8d0     S        0        PDB.TC.IX_T     INDEX(04)            INDEX(01)  0x62c9f8d0 S
2021-02-12 15:41:23.601  kgllkal  TRACELOCK  0x62c9f8d0     S        S        PDB.TC.T        TABLE/PROCEDURE(01)  TABLE(02)  0x62c9f8d0 S
2021-02-12 15:41:23.613  kgllkal  TRACELOCK  0x65db4480     S        0        PDB.TC.IX_T     INDEX(04)            INDEX(01)  0x65db4480 S
2021-02-12 15:41:23.617  kgllkal  TRACELOCK  0x65db4480     S        0        PDB.TC.T        TABLE/PROCEDURE(01)  TABLE(02)  0x65db4480 S
2021-02-12 15:41:23.618  kgllkal  TRACELOCK  0x62db5708     S        0        PDB.TC.IX_T     INDEX(04)            INDEX(01)  0x62db5708 S
2021-02-12 15:41:23.626  kgllkal  TRACELOCK  0x65db4480     S        0        PDB.TC.IX_T     INDEX(04)            INDEX(01)  0x65db4480 S
2021-02-12 15:41:23.629  kgllkal  TRACELOCK  0x65db4480     X        0        PDB.TC.T        TABLE/PROCEDURE(01)  TABLE(02)  0x65db4480 X
2021-02-12 15:41:23.632  kgllkal  TRACELOCK  0x62da2ef0     X        0        PDB.TC.IX_T     INDEX(04)            INDEX(01)  0x62da2ef0 X

10 rows selected.

Conclusion

We can trace library cache locks, or more specifically certain kgllkal calls. The resulting trace data is written to the trace file in the XML format. It can be loaded into the database for further analysis.

Usual disclaimer

This blog post is a pure speculation. Although the results might be be reasonable and suggestive, I have no idea whether or not _kgl_debug=32 covers all or most library cache locks.