On Oracle: Oracle PLITBLM "library cache: mutex X"

PLITBLM is Oracle kernel package for the operations of collections (associative array, nested table and varray array).

In this Blog, we first show Oracle 19c new behaviour of PLITBLM on library cache locks and pins in comparing to Oracle 12c, and then demonstrate its consequence of "library cache: mutex X" in Oracle 19c.

After the tests, we first compose gdb scripts to trace PLITBLM Library Cache Locks and Pins (kglLock and kglpin). Then we further compose gdb scripts to reveal the calls of the triggered kgxExclusive and kgxRelease for mutex request and release.

We conclude the Blog with some rough estimations of PLITBLM execution duration and throughput.

As a further study, we also try to list all the calls of Mutex kgxExclusive and kgxRelease.

Note: Tested in Oracle 19c (19.9) and 12c(12.1.0.2.0).

Update (29Jun2021): With test code of this Blog, Oracle delivered fix: "Patch 32831855: NESTED TABLE CONSUMES MORE TIME IN 19C".

1. Test Setup

We create two procedures, one is coded in static, another in dynamic with execute immediate. Both are using a simple nested table.


create or replace procedure test_proc_static(p_cnt_1 number, p_cnt_2 number := 100) as
begin
  for i in 1..p_cnt_1 loop
	  declare
	    type t_num_tab   is table of number;
	    l_num_tab        t_num_tab   := t_num_tab();
	    l_val            number;
	    l_bool           boolean;
	  begin
	    for i in 1..p_cnt_2 loop
	      l_num_tab.extend;
	      l_num_tab(i) := i;   
	      l_val        := l_num_tab.count;
	      l_val        := l_num_tab(i);
	      l_val        := l_num_tab.first;
	      l_val        := l_num_tab.prior(i);
	      l_bool       := l_num_tab.exists(i);
	    end loop;
	      l_num_tab.delete(2);
	  end;
	end loop;
end;
/

create or replace procedure test_proc_dynamic(p_cnt_1 number, p_cnt_2 number := 100) as
begin
  for i in 1..p_cnt_1 loop
    execute immediate '
	    declare
	      type t_num_tab   is table of number;
	      l_num_tab        t_num_tab   := t_num_tab();
	      l_val            number;
	      l_bool           boolean;
	    begin
	      for i in 1..' ||p_cnt_2|| ' loop
	        l_num_tab.extend;
	        l_num_tab(i) := i;   
	        l_val        := l_num_tab.count;
	        l_val        := l_num_tab(i);
	        l_val        := l_num_tab.first;
	        l_val        := l_num_tab.prior(i);
	        l_bool       := l_num_tab.exists(i);
	      end loop;
	        l_num_tab.delete(2);
	    end;' ;
	end loop;
end;
/

And also create a job launcher for later "library cache: mutex X" concurrency test.


create or replace procedure test_job(p_type varchar2, p_job_cnt number, p_cnt_1 number :=10, p_cnt_2 number := 100, p_job_start_nr number := 0) as
  l_call_proc varchar2(20);
begin
  case p_type 
    when 'static'  then l_call_proc := 'test_proc_static';
    when 'dynamic' then l_call_proc := 'test_proc_dynamic';
  end case;
  
  for i in 1..p_job_cnt loop
    dbms_scheduler.create_job (
      job_name        => 'TEST_JOB_'||p_type||'_'||(p_job_start_nr + i),
      job_type        => 'PLSQL_BLOCK',
      job_action      => 'begin '||l_call_proc|| '('||p_cnt_1||','||p_cnt_2||'); end;',
      start_date      => systimestamp,
      repeat_interval => 'systimestamp',
      auto_drop       => true,
      enabled         => true);
  end loop;
end;
/

2. Library Cache Locks and Pins Test

First we run a small test and look the objects named as "PLITBLM":


exec test_proc_static(1);

select owner||'.'||name source, namespace, type, hash_value, locks, pins, locked_total, pinned_total
from v$db_object_cache v 
where name like 'PLITBLM' order by source;

SOURCE          NAMESPACE        TYPE       HASH_VALUE      LOCKS       PINS     LOCKED_TOTAL     PINNED_TOTAL
--------------- ---------------- ---------- ---------- ---------- ---------- ---------------- ----------------
APP.PLITBLM     TABLE/PROCEDURE  CURSOR     1153620443          0          0                1        1
PUBLIC.PLITBLM  TABLE/PROCEDURE  SYNONYM    1353169941          0          0               51       51
SYS.PLITBLM     TABLE/PROCEDURE  PACKAGE    4251528005          3          0               56       69
SYS.PLITBLM     BODY             CURSOR     4039937844          0          0               66       66

"APP.PLITBLM" is one non-existent object in application schema: APP.
"PUBLIC.PLITBLM" is a synonym.
Two "SYS.PLITBLM" are package spec and body, with HASH_VALUE: 4251528005 and 4039937844, which are the two main objects we are focused on.

2.1 Oracle 19c

In an Oracle 19c DB, we run both test_proc_static and test_proc_dynamic, and get library cache lock and pins stats:


select owner||'.'||name source, namespace, type, hash_value, locks, pins, locked_total, pinned_total
from v$db_object_cache v where hash_value in (4251528005, 4039937844);

exec test_proc_static(1e6, 1);  

select owner||'.'||name source, namespace, type, hash_value, locks, pins, locked_total, pinned_total
from v$db_object_cache v where hash_value in (4251528005, 4039937844);

exec test_proc_dynamic(1e6, 1); 

select owner||'.'||name source, namespace, type, hash_value, locks, pins, locked_total, pinned_total
from v$db_object_cache v where hash_value in (4251528005, 4039937844);

Here the output:


SQL(19c)> select owner||'.'||name source, namespace, type, hash_value, locks, pins, locked_total, pinned_total
          from v$db_object_cache v where hash_value in (4251528005, 4039937844);

SOURCE          NAMESPACE        TYPE       HASH_VALUE      LOCKS       PINS     LOCKED_TOTAL     PINNED_TOTAL
--------------- ---------------- ---------- ---------- ---------- ---------- ---------------- ----------------
SYS.PLITBLM     BODY             CURSOR     4039937844          0          0               67       67
SYS.PLITBLM     TABLE/PROCEDURE  PACKAGE    4251528005          3          0               56       70

SQL(19c)> exec test_proc_static(1e6, 1);

  Elapsed: 00:00:00.84

SQL(19c)> select owner||'.'||name source, namespace, type, hash_value, locks, pins, locked_total, pinned_total
          from v$db_object_cache v where hash_value in (4251528005, 4039937844);

SOURCE          NAMESPACE        TYPE       HASH_VALUE      LOCKS       PINS     LOCKED_TOTAL     PINNED_TOTAL
--------------- ---------------- ---------- ---------- ---------- ---------- ---------------- ----------------
SYS.PLITBLM     BODY             CURSOR     4039937844          0          0               70       70
SYS.PLITBLM     TABLE/PROCEDURE  PACKAGE    4251528005          3          0               57       74

SQL(19c)> exec test_proc_dynamic(1e6, 1);

  Elapsed: 00:00:12.75

SQL(19c)> select owner||'.'||name source, namespace, type, hash_value, locks, pins, locked_total, pinned_total
          from v$db_object_cache v where hash_value in (4251528005, 4039937844);

SOURCE          NAMESPACE        TYPE       HASH_VALUE      LOCKS       PINS     LOCKED_TOTAL     PINNED_TOTAL
--------------- ---------------- ---------- ---------- ---------- ---------- ---------------- ----------------
SYS.PLITBLM     BODY             CURSOR     4039937844          0          0        1,000,072     1,000,072
SYS.PLITBLM     TABLE/PROCEDURE  PACKAGE    4251528005          3          0               58     1,000,077

We can see that test_proc_static has locked_total and pinned_total almost not increased.

However test_proc_dynamic has noticeable differences:

  -. for PLITBLM BODY, locked_total and pinned_total increased (1,000,072 - 70), almost same as the number of run count (1e6).
  -. for PLITBLM SPEC, only PINNED_TOTAL increased (1,000,077 - 74), almost same as the number of run count (1e6).
  -. test_proc_static vs. test_proc_static elpased time are (00.84 vs. 12.75).

2.2 Oracle 12c

Repeat the same test in Oracle 12c. Here the output:


SQL(12c)> select owner||'.'||name source, namespace, type, hash_value, locks, pins, locked_total, pinned_total
    from v$db_object_cache v where hash_value in (4251528005, 4039937844);

SOURCE          NAMESPACE        TYPE       HASH_VALUE      LOCKS       PINS     LOCKED_TOTAL     PINNED_TOTAL
--------------- ---------------- ---------- ---------- ---------- ---------- ---------------- ----------------
SYS.PLITBLM     BODY             CURSOR     4039937844          0          0               49       49
SYS.PLITBLM     TABLE/PROCEDURE  PACKAGE    4251528005          4          0               51       56

SQL(12c)> exec test_proc_static(1e6, 1);

  Elapsed: 00:00:00.57

SQL(12c)> select owner||'.'||name source, namespace, type, hash_value, locks, pins, locked_total, pinned_total
    from v$db_object_cache v where hash_value in (4251528005, 4039937844);

SOURCE          NAMESPACE        TYPE       HASH_VALUE      LOCKS       PINS     LOCKED_TOTAL     PINNED_TOTAL
--------------- ---------------- ---------- ---------- ---------- ---------- ---------------- ----------------
SYS.PLITBLM     BODY             CURSOR     4039937844          0          0               51       51
SYS.PLITBLM     TABLE/PROCEDURE  PACKAGE    4251528005          4          0               53       59

SQL(12c)> exec test_proc_dynamic(1e6, 1);

  Elapsed: 00:00:07.46

SQL(12c)> select owner||'.'||name source, namespace, type, hash_value, locks, pins, locked_total, pinned_total
    from v$db_object_cache v where hash_value in (4251528005, 4039937844);

SOURCE          NAMESPACE        TYPE       HASH_VALUE      LOCKS       PINS     LOCKED_TOTAL     PINNED_TOTAL
--------------- ---------------- ---------- ---------- ---------- ---------- ---------------- ----------------
SYS.PLITBLM     BODY             CURSOR     4039937844          0          0               52       52
SYS.PLITBLM     TABLE/PROCEDURE  PACKAGE    4251528005          4          0               54       61

We can see that both test_proc_static and test_proc_dynamic have similar behaviour in Oracle 12c, in which locked_total and pinned_total almost not increased. test_proc_static vs. test_proc_static elpased time are (00.57 vs. 07.46).

3. "library cache: mutex X" Test

Now we will use dbms_scheduler to start a few job sessions and watch "library cache: mutex X" concurrency.

3.1 Oracle 19c

We start 64 job sessions with test_proc_dynamic, and look "library cache: mutex X".


exec test_job('dynamic', 64, 1e7, 1e4);

Here some monitoring queries and the output:


SQL(19c)> select sid, event, p1, p2, p3 
   from v$session where event in ('library cache: mutex X', 'library cache: bucket mutex X');

  SID EVENT                                   P1                P2                      P3
----- ------------------------------ ----------- ----------------- -----------------------
   14 library cache: mutex X          4251528005     1632087572480          20383914852447
   15 library cache: mutex X          4251528005      854698491904          20383914852447
   16 library cache: mutex X          4039937844      854698491904    18446744069414715498
   17 library cache: bucket mutex X        36660       98784247808                      62
   18 library cache: mutex X          4039937844      833223655424    18446744069414715498
  ...
  918 library cache: mutex X          4039937844      854698491904    18446744069414715498
  919 library cache: bucket mutex X        36660       98784247808                      62

48 rows selected.


-- Only top 5 showed
SQL(19c)> select * from v$mutex_sleep where mutex_type in ('Library Cache') order by sleeps desc;

MUTEX_TYPE       LOCATION             SLEEPS  WAIT_TIME     CON_ID
---------------- ---------------- ---------- ---------- ----------
Library Cache    kglhdgn2 106          37602 1280758050          0
Library Cache    kglpndl1  95          33147 1243018303          0
Library Cache    kglhdgn1  62           4129  129689067          0
Library Cache    kglpin1   4            1085   75769882          0
Library Cache    kglpnal1  90            270   25476440          0


SQL(19c)> select mutex_identifier, sleep_timestamp, mutex_type, gets, sleeps
                ,requesting_session, blocking_session, location
   from v$mutex_sleep_history
  where mutex_identifier in (4251528005, 4039937844) and sleep_timestamp > sysdate-1/1440 and sleeps > 3
  order by sleep_timestamp desc, location;

MUTEX_IDENTIFIER SLEEP_TIME MUTEX_TYPE           GETS  SLEEPS REQUESTING_SESSION BLOCKING_SESSION LOCATION
---------------- ---------- -------------- ---------- ------- ------------------ ---------------- ------------
      4039937844 21:27:36   Library Cache    11363330       4                 15              555 kglhdgn2 106
      4251528005 21:27:33   Library Cache     6807823       4                913              201 kglpndl1  95
      4251528005 21:27:33   Library Cache     6807823       4                912              201 kglpin1   4
      4251528005 21:27:33   Library Cache     6807823       4                914              201 kglpndl1  95
      4251528005 21:27:33   Library Cache     6807823       4                193              201 kglpndl1  95
      4039937844 21:27:19   Library Cache    11262862       5                919              560 kglhdgn2 106
      4039937844 21:27:19   Library Cache    11262705       4                 20               19 kglhdgn2 106
      4251528005 21:27:16   Library Cache     6749768       4                555               24 kglpndl1  95
      4251528005 21:27:16   Library Cache     6749768       4                918               24 kglpndl1  95


SQL(19c)> select chain_signature, sid, p1 
   from v$wait_chains where p1 in (4251528005, 4039937844) or chain_signature = 'library cache: mutex X';

CHAIN_SIGNATURE                  SID         P1
------------------------- ---------- ----------
'library cache: mutex X'          23 4251528005
'library cache: mutex X'         201 4039937844
'library cache: mutex X'         382 4251528005
'library cache: mutex X'         385 4251528005
'library cache: mutex X'         561 4251528005
'library cache: mutex X'         562 4251528005

After the test, we stop all jobs by (see appended code):


exec clearup_test;

If we also start 64 job sessions with test_proc_static, there is no "library cache: mutex X" observed.


exec test_job('static', 64, 1e7, 1e4);

3.2 Oracle 12c

In Oracle 12c, we start 64 job sessions with test_proc_dynamic, and look "library cache: mutex X".


exec test_job('dynamic', 64, 1e7, 1e4);

Run the same monitoring queries. There is no sessions in 'library cache: mutex X' wait event.


SQL(12c)> select sid, event, p1, p2, p3 from v$session where event in ('library cache: mutex X', 'library cache: bucket mutex X');

no rows selected

After the test, we stop all jobs by (see appended code):


exec clearup_test;

If we also start 64 job sessions with test_proc_static, there is also no "library cache: mutex X" observed.


exec test_job('static', 64, 1e7, 1e4);

4. Library Cache Locks and Pins (added in 25-Apr-2021)

We will use the findings in Blog:
Tracing Library Cache Locks 3: Object Names
and follow the similar approach in Blog:
Row Cache Object and Row Cache Mutex Case Study
to compose gdb scripts to reveal Library Cache Locks and Pins (kgllkal, kglpnal) activities.

4.1. 19c Library Cache Locks and Pins

At first, we run query below to list meta info of PLITBLM and our two test procedures in library objects of 19c DB. V$DB_OBJECT_CACHE.addr is the object_handle address, which will be used in gdb script.
(Note: object_handle address is changed after each DB restart or shared_pool flush).


select owner, name, namespace, type, hash_value, addr, to_number(addr, 'xxxxxxxxxxxxxxxx') addr_nr
  from v$db_object_cache v 
 where hash_value in (4251528005, 4039937844) and name like 'PLITBLM' or name in ('TEST_PROC_STATIC', 'TEST_PROC_DYNAMIC')
 order by v.name desc;

OWNER  NAME                   NAMESPACE           TYPE       HASH_VALUE  ADDR      ADDR_NR
------ ---------------------- ------------------- ---------- ---------- --------- -----------
K      TEST_PROC_STATIC       TABLE/PROCEDURE     PROCEDURE  1186232128  9DEB95E0  2649462240
K      TEST_PROC_DYNAMIC      TABLE/PROCEDURE     PROCEDURE   313204667  9DD7BC98  2648161432
SYS    PLITBLM                TABLE/PROCEDURE     PACKAGE    4251528005  A454FEB0  2757033648
SYS    PLITBLM                BODY                CURSOR     4039937844  9EC403D0  2663646160

Then we can compose a gdb script: "gdb_script_kgl_19c" (see Appendix 7.1).

4.1.1 19c Static Call

As first test, we run static call with 10 executions, and trace kgllkal and kglpnal with the script.

Here the output of Sqlplus:


ORA19C> select owner||'.'||name source, namespace, type, hash_value, locks, pins, locked_total, pinned_total
    from v$db_object_cache v
    where hash_value in (4251528005, 4039937844) and name like 'PLITBLM' or name in ('TEST_PROC_STATIC') order by source;

SOURCE                  NAMESPACE        TYPE       HASH_VALUE  LOCKS  PINS  LOCKED_TOTAL  PINNED_TOTAL
----------------------- ---------------- ---------- ---------- ------ ----- ------------- -------------
K.TEST_PROC_STATIC      TABLE/PROCEDURE  PROCEDURE  1186232128      1     0            70           126
SYS.PLITBLM             TABLE/PROCEDURE  PACKAGE    4251528005      8     0           343         1,771
SYS.PLITBLM             BODY             CURSOR     4039937844      0     0           978           978

ORA19C> exec test_proc_static(10, 1);
PL/SQL procedure successfully completed.
Elapsed: 00:00:00.00

ORA19C> select owner||'.'||name source, namespace, type, hash_value, locks, pins, locked_total, pinned_total
    from v$db_object_cache v
    where hash_value in (4251528005, 4039937844) and name like 'PLITBLM' or name in ('TEST_PROC_STATIC') order by source;

SOURCE                  NAMESPACE        TYPE       HASH_VALUE  LOCKS  PINS  LOCKED_TOTAL  PINNED_TOTAL
----------------------- ---------------- ---------- ---------- ------ ----- ------------- -------------
K.TEST_PROC_STATIC      TABLE/PROCEDURE  PROCEDURE  1186232128      1     0            70           127
SYS.PLITBLM             TABLE/PROCEDURE  PACKAGE    4251528005      8     0           343         1,774
SYS.PLITBLM             BODY             CURSOR     4039937844      0     0           981           981

Here the output of gdb script:


Breakpoint 4, 0x0000000004c57ff0 in kglpnal ()
===== Spec PIN (-2) <<< kgllkhdl: A454FEB0, kgllkmod 2, kglnaobj: PLITBLMSYS >>>=====
Breakpoint 5, 0x0000000004c504b0 in kgllkal ()
====== Body LOCK (-2) <<< kgllkhdl: 9EC403D0, kgllkmod 1, kglnaobj: PLITBLMSYS >>>=====
Breakpoint 6, 0x0000000004c57ff0 in kglpnal ()
===== Body PIN (-2) <<< kgllkhdl: 9EC403D0, kgllkmod 2, kglnaobj: PLITBLMSYS >>>=====
Breakpoint 2, 0x0000000004c57ff0 in kglpnal ()
===== Proc Pin (0) <<< kgllkhdl: 9DEB95E0, kgllkmod 2, kglnaobj: TEST_PROC_STATICK >>>=====
#0  0x0000000004c57ff0 in kglpnal ()
#1  0x0000000004c1f8c4 in kglpin ()
#2  0x0000000004c2307c in kglpnp ()
#3  0x0000000012b6e545 in kgiind ()
#4  0x000000000569b7dc in pfri8_inst_spec ()
#5  0x000000000569b604 in pfri1_inst_spec ()
#6  0x0000000012b7d020 in pfrrun ()
#7  0x0000000012b86bab in plsql_run ()

Breakpoint 4, 0x0000000004c57ff0 in kglpnal ()
===== Spec PIN (-1) <<< kgllkhdl: A454FEB0, kgllkmod 2, kglnaobj: PLITBLMSYS >>>=====
Breakpoint 5, 0x0000000004c504b0 in kgllkal ()
====== Body LOCK (-1) <<< kgllkhdl: 9EC403D0, kgllkmod 1, kglnaobj: PLITBLMSYS >>>=====
Breakpoint 6, 0x0000000004c57ff0 in kglpnal ()
===== Body PIN (-1) <<< kgllkhdl: 9EC403D0, kgllkmod 2, kglnaobj: PLITBLMSYS >>>=====
Breakpoint 4, 0x0000000004c57ff0 in kglpnal ()
===== Spec PIN (0) <<< kgllkhdl: A454FEB0, kgllkmod 2, kglnaobj: PLITBLMSYS >>>=====
Breakpoint 5, 0x0000000004c504b0 in kgllkal ()
====== Body LOCK (0) <<< kgllkhdl: 9EC403D0, kgllkmod 1, kglnaobj: PLITBLMSYS >>>=====
Breakpoint 6, 0x0000000004c57ff0 in kglpnal ()
===== Body PIN (0) <<< kgllkhdl: 9EC403D0, kgllkmod 2, kglnaobj: PLITBLMSYS >>>=====
Breakpoint 4, 0x0000000004c57ff0 in kglpnal ()
#0  0x0000000004c57ff0 in kglpnal ()
#1  0x0000000004c1f8c4 in kglpin ()
#2  0x0000000004c2307c in kglpnp ()
#3  0x0000000012b6e545 in kgiind ()
#4  0x000000000569b7dc in pfri8_inst_spec ()
#5  0x000000000569b604 in pfri1_inst_spec ()
#6  0x0000000012b7d020 in pfrrun ()
#7  0x0000000012b86bab in plsql_run ()
===== Spec PIN (1) <<< kgllkhdl: A454FEB0, kgllkmod 2, kglnaobj: PLITBLMSYS >>>=====
Breakpoint 5, 0x0000000004c504b0 in kgllkal ()
#0  0x0000000004c504b0 in kgllkal ()
#1  0x0000000004c33e9d in kglLock ()
#2  0x0000000004c22e0c in kglget ()
#3  0x0000000004c1cb78 in kglgob ()
#4  0x0000000004de210f in kgiinbgob_swcb ()
#5  0x0000000004de115e in kgiinb ()
#6  0x000000000569d1bb in pfri7_inst_body_common ()
#7  0x000000000569cf38 in pfri3_inst_body ()
====== Body LOCK (1) <<< kgllkhdl: 9EC403D0, kgllkmod 1, kglnaobj: PLITBLMSYS >>>=====
Breakpoint 6, 0x0000000004c57ff0 in kglpnal ()
#0  0x0000000004c57ff0 in kglpnal ()
#1  0x0000000004c1f8c4 in kglpin ()
#2  0x0000000004c1cd80 in kglgob ()
#3  0x0000000004de210f in kgiinbgob_swcb ()
#4  0x0000000004de115e in kgiinb ()
#5  0x000000000569d1bb in pfri7_inst_body_common ()
#6  0x000000000569cf38 in pfri3_inst_body ()
#7  0x0000000012b7d0a6 in pfrrun ()
===== Body PIN (1) <<< kgllkhdl: 9EC403D0, kgllkmod 2, kglnaobj: PLITBLMSYS >>>=====

In gdb script, for both kgllkal and kglpnal, we start the counting from -2 to skip the first warmup (-2) run and two additional runs (-1, 0), so the last counter is "(1)".

In third run (0), we print out Call Stack (backtrace) of "Proc Pin TEST_PROC_STATICK". in the last run (1), we print out Call Stack (backtrace) for "Spec PIN PLITBLMSYS", "Body LOCK PLITBLMSYS", and "Body PIN PLITBLMSYS".

The above two outputs showed:


   -. Sqlplus TEST_PROC_STATIC.PINNED_TOTAL increased 1 (127-126). Script has one "Proc Pin TEST_PROC_STATICK".
   -. Sqlplus Spec PLITBLM.PINNED_TOTAL increased 3 (1,774-1,771). Script has 3 "Spec PIN PLITBLMSYS" (exclude first warmup).
   -. Sqlplus Body PLITBLM.LOCKED_TOTAL increased 3 (981-978). Script has 3 "Body LOCK PLITBLMSYS" (exclude first warmup).
   -. Sqlplus Body PLITBLM.PINNED_TOTAL increased 3 (981-978). Script has 3 "Body PIN PLITBLMSYS" (exclude first warmup).

kgllkmod is documented in V$LIBCACHE_LOCKS.

4.1.4.1.2 19c Dynamic Call2 19c Dynamic Call

Now we run dynamic call with 10 executions, and trace kgllkal and kglpnal with the same script.

Here the output of Sqlplus:


ORA19C> select owner||'.'||name source, namespace, type, hash_value, locks, pins, locked_total, pinned_total
    from v$db_object_cache v
    where hash_value in (4251528005, 4039937844) and name like 'PLITBLM' or name in ('TEST_PROC_DYNAMIC') order by source;

SOURCE                  NAMESPACE        TYPE       HASH_VALUE  LOCKS  PINS LOCKED_TOTAL  PINNED_TOTAL
----------------------- ---------------- ---------- ---------- ------ ----- ------------ -------------
K.TEST_PROC_DYNAMIC     TABLE/PROCEDURE  PROCEDURE   313204667      1     0           20            56
SYS.PLITBLM             TABLE/PROCEDURE  PACKAGE    4251528005      8     0          343         1,775
SYS.PLITBLM             BODY             CURSOR     4039937844      0     0          982           982

ORA19C> exec test_proc_dynamic(10, 1);
PL/SQL procedure successfully completed.
Elapsed: 00:00:00.03

ORA19C> select owner||'.'||name source, namespace, type, hash_value, locks, pins, locked_total, pinned_total
    from v$db_object_cache v
    where hash_value in (4251528005, 4039937844) and name like 'PLITBLM' or name in ('TEST_PROC_DYNAMIC') order by source;

SOURCE                  NAMESPACE        TYPE       HASH_VALUE  LOCKS  PINS  LOCKED_TOTAL  PINNED_TOTAL
----------------------- ---------------- ---------- ---------- ------ ----- ------------- -------------
K.TEST_PROC_DYNAMIC     TABLE/PROCEDURE  PROCEDURE   313204667      1     0            20            57
SYS.PLITBLM             TABLE/PROCEDURE  PACKAGE    4251528005      8     0           343         1,787
SYS.PLITBLM             BODY             CURSOR     4039937844      0     0           994           994

Here the output of gdb script:


Breakpoint 4, 0x0000000004c57ff0 in kglpnal ()
===== Spec PIN (-2) <<< kgllkhdl: A454FEB0, kgllkmod 2, kglnaobj: PLITBLMSYS >>>=====
Breakpoint 5, 0x0000000004c504b0 in kgllkal ()
====== Body LOCK (-2) <<< kgllkhdl: 9EC403D0, kgllkmod 1, kglnaobj: PLITBLMSYS >>>=====
Breakpoint 6, 0x0000000004c57ff0 in kglpnal ()
===== Body PIN (-2) <<< kgllkhdl: 9EC403D0, kgllkmod 2, kglnaobj: PLITBLMSYS >>>=====
Breakpoint 2, 0x0000000004c57ff0 in kglpnal ()
===== Proc Pin (0) <<< kgllkhdl: 9DD7BC98, kgllkmod 2, kglnaobj: TEST_PROC_DYNAMICK >>>=====
#0  0x0000000004c57ff0 in kglpnal ()
#1  0x0000000004c1f8c4 in kglpin ()
#2  0x0000000004c2307c in kglpnp ()
#3  0x0000000012b6e545 in kgiind ()
#4  0x000000000569b7dc in pfri8_inst_spec ()
#5  0x000000000569b604 in pfri1_inst_spec ()
#6  0x0000000012b7d020 in pfrrun ()
#7  0x0000000012b86bab in plsql_run ()

Breakpoint 4, 0x0000000004c57ff0 in kglpnal ()
===== Spec PIN (-1) <<< kgllkhdl: A454FEB0, kgllkmod 2, kglnaobj: PLITBLMSYS >>>=====
Breakpoint 5, 0x0000000004c504b0 in kgllkal ()
====== Body LOCK (-1) <<< kgllkhdl: 9EC403D0, kgllkmod 1, kglnaobj: PLITBLMSYS >>>=====
Breakpoint 6, 0x0000000004c57ff0 in kglpnal ()
===== Body PIN (-1) <<< kgllkhdl: 9EC403D0, kgllkmod 2, kglnaobj: PLITBLMSYS >>>=====
Breakpoint 4, 0x0000000004c57ff0 in kglpnal ()
===== Spec PIN (0) <<< kgllkhdl: A454FEB0, kgllkmod 2, kglnaobj: PLITBLMSYS >>>=====
Breakpoint 5, 0x0000000004c504b0 in kgllkal ()
====== Body LOCK (0) <<< kgllkhdl: 9EC403D0, kgllkmod 1, kglnaobj: PLITBLMSYS >>>=====
Breakpoint 6, 0x0000000004c57ff0 in kglpnal ()
===== Body PIN (0) <<< kgllkhdl: 9EC403D0, kgllkmod 2, kglnaobj: PLITBLMSYS >>>=====
Breakpoint 4, 0x0000000004c57ff0 in kglpnal ()
#0  0x0000000004c57ff0 in kglpnal ()
#1  0x0000000004c1f8c4 in kglpin ()
#2  0x0000000004c2307c in kglpnp ()
#3  0x0000000012b6e545 in kgiind ()
#4  0x000000000569b7dc in pfri8_inst_spec ()
#5  0x000000000569b604 in pfri1_inst_spec ()
#6  0x0000000012b7d020 in pfrrun ()
#7  0x0000000012b86bab in plsql_run ()
===== Spec PIN (1) <<< kgllkhdl: A454FEB0, kgllkmod 2, kglnaobj: PLITBLMSYS >>>=====
Breakpoint 5, 0x0000000004c504b0 in kgllkal ()
#0  0x0000000004c504b0 in kgllkal ()
#1  0x0000000004c33e9d in kglLock ()
#2  0x0000000004c22e0c in kglget ()
#3  0x0000000004c1cb78 in kglgob ()
#4  0x0000000004de210f in kgiinbgob_swcb ()
#5  0x0000000004de115e in kgiinb ()
#6  0x000000000569d1bb in pfri7_inst_body_common ()
#7  0x000000000569cf38 in pfri3_inst_body ()
====== Body LOCK (1) <<< kgllkhdl: 9EC403D0, kgllkmod 1, kglnaobj: PLITBLMSYS >>>=====
Breakpoint 6, 0x0000000004c57ff0 in kglpnal ()
#0  0x0000000004c57ff0 in kglpnal ()
#1  0x0000000004c1f8c4 in kglpin ()
#2  0x0000000004c1cd80 in kglgob ()
#3  0x0000000004de210f in kgiinbgob_swcb ()
#4  0x0000000004de115e in kgiinb ()
#5  0x000000000569d1bb in pfri7_inst_body_common ()
#6  0x000000000569cf38 in pfri3_inst_body ()
#7  0x0000000012b7d0a6 in pfrrun ()
===== Body PIN (1) <<< kgllkhdl: 9EC403D0, kgllkmod 2, kglnaobj: PLITBLMSYS >>>=====
Breakpoint 4, 0x0000000004c57ff0 in kglpnal ()
===== Spec PIN (2) <<< kgllkhdl: A454FEB0, kgllkmod 2, kglnaobj: PLITBLMSYS >>>=====
Breakpoint 5, 0x0000000004c504b0 in kgllkal ()
====== Body LOCK (2) <<< kgllkhdl: 9EC403D0, kgllkmod 1, kglnaobj: PLITBLMSYS >>>=====
Breakpoint 6, 0x0000000004c57ff0 in kglpnal ()
===== Body PIN (2) <<< kgllkhdl: 9EC403D0, kgllkmod 2, kglnaobj: PLITBLMSYS >>>=====
Breakpoint 4, 0x0000000004c57ff0 in kglpnal ()
===== Spec PIN (3) <<< kgllkhdl: A454FEB0, kgllkmod 2, kglnaobj: PLITBLMSYS >>>=====
Breakpoint 5, 0x0000000004c504b0 in kgllkal ()
====== Body LOCK (3) <<< kgllkhdl: 9EC403D0, kgllkmod 1, kglnaobj: PLITBLMSYS >>>=====
Breakpoint 6, 0x0000000004c57ff0 in kglpnal ()
===== Body PIN (3) <<< kgllkhdl: 9EC403D0, kgllkmod 2, kglnaobj: PLITBLMSYS >>>=====

....

Breakpoint 4, 0x0000000004c57ff0 in kglpnal ()
===== Spec PIN (9) <<< kgllkhdl: A454FEB0, kgllkmod 2, kglnaobj: PLITBLMSYS >>>=====
Breakpoint 5, 0x0000000004c504b0 in kgllkal ()
====== Body LOCK (9) <<< kgllkhdl: 9EC403D0, kgllkmod 1, kglnaobj: PLITBLMSYS >>>=====
Breakpoint 6, 0x0000000004c57ff0 in kglpnal ()
===== Body PIN (9) <<< kgllkhdl: 9EC403D0, kgllkmod 2, kglnaobj: PLITBLMSYS >>>=====
Breakpoint 4, 0x0000000004c57ff0 in kglpnal ()
===== Spec PIN (10) <<< kgllkhdl: A454FEB0, kgllkmod 2, kglnaobj: PLITBLMSYS >>>=====
Breakpoint 5, 0x0000000004c504b0 in kgllkal ()
====== Body LOCK (10) <<< kgllkhdl: 9EC403D0, kgllkmod 1, kglnaobj: PLITBLMSYS >>>=====
Breakpoint 6, 0x0000000004c57ff0 in kglpnal ()
===== Body PIN (10) <<< kgllkhdl: 9EC403D0, kgllkmod 2, kglnaobj: PLITBLMSYS >>>=====

In gdb script, for both kgllkal and kglpnal, we start the counting from -2 to skip the first warmup (-2) run and two additional runs (-1, 0), so the last counter is "(10)".

In third run (0), we print out Call Stack (backtrace) of "Proc Pin TEST_PROC_DYNAMICK". in run (1), we print out Call Stack (backtrace) for "Spec PIN PLITBLMSYS", "Body LOCK PLITBLMSYS", and "Body PIN PLITBLMSYS".

The above two outputs showed:


   -. Sqlplus TEST_PROC_DYNAMICK.PINNED_TOTAL increased 1 (57-56). Script has one "Proc Pin TEST_PROC_DYNAMICK".
   -. Sqlplus Spec PLITBLM.PINNED_TOTAL increased 12 (1,787-1,775). Script has 12 "Spec PIN PLITBLMSYS" (exclude first warmup).
   -. Sqlplus Body PLITBLM.LOCKED_TOTAL increased 12 (994-982). Script has 12 "Body LOCK PLITBLMSYS" (exclude first warmup).
   -. Sqlplus Body PLITBLM.PINNED_TOTAL increased 12 (994-982). Script has 12 "Body PIN PLITBLMSYS" (exclude first warmup).

We can see all PIN in kgllkmod 2, whereas LOCK in kgllkmod 1 (kgllkmod is documented in V$LIBCACHE_LOCKS).

4.2. 12c1 (12.1.0.2.0) Library Cache Locks and Pins

First run query below to list meta info of PLITBLM and our two test procedures in library objects of 12c1 DB. V$DB_OBJECT_CACHE.addr is the object_handle address, which will be used in gdb script. (Note: object_handle address is changed after each DB restart or shared_pool flush).


select owner, name, namespace, type, hash_value, hash_value, addr, to_number(addr, 'xxxxxxxxxxxxxxxx') addr_nr
  from v$db_object_cache v 
 where hash_value in (4251528005, 4039937844) and name like 'PLITBLM' or name in ('TEST_PROC_STATIC', 'TEST_PROC_DYNAMIC')
 order by v.name desc;

OWNER  NAME                   NAMESPACE         TYPE       HASH_VALUE HASH_VALUE  ADDR       ADDR_NR
------ ---------------------- ----------------- ---------- ---------- ----------  ---------  ----------
K      TEST_PROC_STATIC       TABLE/PROCEDURE   PROCEDURE  1186232128 1186232128  1565EBC10  5744016400
K      TEST_PROC_DYNAMIC      TABLE/PROCEDURE   PROCEDURE   313204667  313204667  15756B220  5760266784
SYS    PLITBLM                TABLE/PROCEDURE   PACKAGE    4251528005 4251528005  15D175E20  5856779808
SYS    PLITBLM                BODY              CURSOR     4039937844 4039937844  15CA06D80  5848984960

Then we can compose a gdb script: "gdb_script_kgl_12c1" (see Appendix 7.2).

4.2.1 12c1 Static Call

First we run static call with 10 executions, and trace kgllkal and kglpnal with the script.

Note that each time we need to run the test in a new Sqlplus connection, the second and later runs will not increase LOCKED_TOTAL and PINNED_TOTAL (that is probably why PLITBLM "library cache: mutex X" contention is in 19c. Whereas in 12c1, it is cached).

Here the output of Sqlplus:


ORA12C1> select owner||'.'||name source, namespace, type, hash_value, locks, pins, locked_total, pinned_total
    from v$db_object_cache v
    where hash_value in (4251528005, 4039937844) and name like 'PLITBLM' or name in ('TEST_PROC_STATIC') order by source;

SOURCE                  NAMESPACE         TYPE       HASH_VALUE  LOCKS  PINS  LOCKED_TOTAL  PINNED_TOTAL
----------------------- ----------------- ---------- ---------- ------ ----- ------------- -------------
K.TEST_PROC_STATIC      TABLE/PROCEDURE   PROCEDURE  1186232128      0     0            82            95
SYS.PLITBLM             TABLE/PROCEDURE   PACKAGE    4251528005      5     0           802           916
SYS.PLITBLM             BODY              CURSOR     4039937844      0     0           869           869

ORA12C1> exec test_proc_static(10, 1);
PL/SQL procedure successfully completed.
Elapsed: 00:00:00.01

ORA12C1> select owner||'.'||name source, namespace, type, hash_value, locks, pins, locked_total, pinned_total
    from v$db_object_cache v
    where hash_value in (4251528005, 4039937844) and name like 'PLITBLM' or name in ('TEST_PROC_STATIC') order by source;

SOURCE                  NAMESPACE         TYPE       HASH_VALUE  LOCKS   PINS  LOCKED_TOTAL  PINNED_TOTAL
----------------------- ----------------- ---------- ---------- ------ ------ ------------- -------------
K.TEST_PROC_STATIC      TABLE/PROCEDURE   PROCEDURE  1186232128      1      0            83            96
SYS.PLITBLM             TABLE/PROCEDURE   PACKAGE    4251528005      5      0           803           919
SYS.PLITBLM             BODY              CURSOR     4039937844      0      0           871           871

Here the output of gdb script:


Breakpoint 4, 0x000000000cac5190 in kglpnal ()
===== Spec PIN (1) <<< kgllkhdl: 5D175E20, kgllkmod 2, kglnaobj: PLITBLMSYS >>>=====
Breakpoint 5, 0x000000000cac18c0 in kgllkal ()
#0  0x000000000cac18c0 in kgllkal ()
#1  0x000000000cab9b8d in kglLock ()
#2  0x000000000cab2e62 in kglget ()
#3  0x000000000cab120f in kglgob ()
#4  0x0000000004b1961b in kgiinb ()
#5  0x0000000004c64ab9 in pfri3_inst_body ()
#6  0x000000000caf9a4b in pfrrun ()
#7  0x000000000cb02104 in plsql_run ()
====== Body LOCK (1) <<< kgllkhdl: 5CA06D80, kgllkmod 1, kglnaobj: PLITBLMSYS >>>=====
Breakpoint 6, 0x000000000cac5190 in kglpnal ()
#0  0x000000000cac5190 in kglpnal ()
#1  0x000000000cab397d in kglpin ()
#2  0x000000000cab12f6 in kglgob ()
#3  0x0000000004b1961b in kgiinb ()
#4  0x0000000004c64ab9 in pfri3_inst_body ()
#5  0x000000000caf9a4b in pfrrun ()
#6  0x000000000cb02104 in plsql_run ()
#7  0x0000000004c4b345 in peicnt ()
===== Body PIN (1) <<< kgllkhdl: 5CA06D80, kgllkmod 2, kglnaobj: PLITBLMSYS >>>=====
Breakpoint 1, 0x000000000cac18c0 in kgllkal ()
===== Proc LOCK (1) <<< kgllkhdl: 565EBC10, kgllkmod 1, kglnaobj: TEST_PROC_STATICK >>>=====
#0  0x000000000cac18c0 in kgllkal ()
#1  0x000000000cab9b8d in kglLock ()
#2  0x000000000cab2e62 in kglget ()
#3  0x000000000cab120f in kglgob ()
#4  0x0000000004b17225 in kgiind ()
#5  0x0000000004c64072 in pfri1_inst_spec ()
#6  0x000000000caf99c3 in pfrrun ()
#7  0x000000000cb02104 in plsql_run ()

Breakpoint 2, 0x000000000cac5190 in kglpnal ()
===== Proc Pin (1) <<< kgllkhdl: 565EBC10, kgllkmod 2, kglnaobj: TEST_PROC_STATICK >>>=====
#0  0x000000000cac5190 in kglpnal ()
#1  0x000000000cab397d in kglpin ()
#2  0x000000000cab12f6 in kglgob ()
#3  0x0000000004b17225 in kgiind ()
#4  0x0000000004c64072 in pfri1_inst_spec ()
#5  0x000000000caf99c3 in pfrrun ()
#6  0x000000000cb02104 in plsql_run ()
#7  0x0000000004c4b345 in peicnt ()

Breakpoint 3, 0x000000000cac18c0 in kgllkal ()
#0  0x000000000cac18c0 in kgllkal ()
#1  0x000000000cab9b8d in kglLock ()
#2  0x000000000cab2e62 in kglget ()
#3  0x000000000cab120f in kglgob ()
#4  0x000000000cab1dc2 in kglgob ()
#5  0x0000000004b17225 in kgiind ()
#6  0x0000000004c64072 in pfri1_inst_spec ()
#7  0x000000000caf99c3 in pfrrun ()
===== Spec LOCK (1) <<< kgllkhdl: 5D175E20, kgllkmod 1, kglnaobj: PLITBLMSYS >>>=====
Breakpoint 4, 0x000000000cac5190 in kglpnal ()
===== Spec PIN (2) <<< kgllkhdl: 5D175E20, kgllkmod 2, kglnaobj: PLITBLMSYS >>>=====
Breakpoint 4, 0x000000000cac5190 in kglpnal ()
===== Spec PIN (3) <<< kgllkhdl: 5D175E20, kgllkmod 2, kglnaobj: PLITBLMSYS >>>=====
Breakpoint 5, 0x000000000cac18c0 in kgllkal ()
====== Body LOCK (2) <<< kgllkhdl: 5CA06D80, kgllkmod 1, kglnaobj: PLITBLMSYS >>>=====
Breakpoint 6, 0x000000000cac5190 in kglpnal ()
===== Body PIN (2) <<< kgllkhdl: 5CA06D80, kgllkmod 2, kglnaobj: PLITBLMSYS >>>=====

The above two outputs showed:


   -. Sqlplus TEST_PROC_STATICK.LOCKED_TOTAL and PINNED_TOTAL increased 1 (83-82, 96-95). 
      Script has one "Proc LOCK TEST_PROC_STATICK" and one "Proc Pin TEST_PROC_STATICK".
   -. Sqlplus Spec PLITBLM.LOCKED_TOTAL increased 1 (803-802). Script has 1 "Spec LOCK PLITBLMSYS".
   -. Sqlplus Spec PLITBLM.PINNED_TOTAL increased 3 (919-916). Script has 3 "Spec PIN PLITBLMSYS".
   -. Sqlplus Body PLITBLM.LOCKED_TOTAL increased 2 (871-869). Script has 2 "Body PIN PLITBLMSYS".
   -. Sqlplus Body PLITBLM.PINNED_TOTAL increased 2 (871-869). Script has 2 "Body LOCK PLITBLMSYS".

4.2.1 12c1 Dynamic Call

Now we run dynamic call with 10 executions, and trace kgllkal and kglpnal with the same script.

Here the output of Sqlplus:


ORA12C1> select owner||'.'||name source, namespace, type, hash_value, locks, pins, locked_total, pinned_total
    from v$db_object_cache v
    where hash_value in (4251528005, 4039937844) and name like 'PLITBLM' or name in ('TEST_PROC_DYNAMIC') order by source;

SOURCE                  NAMESPACE         TYPE       HASH_VALUE  LOCKS  PINS  LOCKED_TOTAL  PINNED_TOTAL
----------------------- ----------------- ---------- ---------- ------ ----- ------------- -------------
K.TEST_PROC_DYNAMIC     TABLE/PROCEDURE   PROCEDURE   313204667      0     0            79            85
SYS.PLITBLM             TABLE/PROCEDURE   PACKAGE    4251528005      5     0           822           939
SYS.PLITBLM             BODY              CURSOR     4039937844      0     0           890           890

ORA12C1> exec test_proc_dynamic(10, 1);
PL/SQL procedure successfully completed.
Elapsed: 00:00:00.01

ORA12C1> select owner||'.'||name source, namespace, type, hash_value, locks, pins, locked_total, pinned_total
    from v$db_object_cache v
    where hash_value in (4251528005, 4039937844) and name like 'PLITBLM' or name in ('TEST_PROC_DYNAMIC') order by source;

SOURCE                  NAMESPACE         TYPE       HASH_VALUE  LOCKS  PINS  LOCKED_TOTAL  PINNED_TOTAL
----------------------- ----------------- ---------- ---------- ------ ----- ------------- -------------
K.TEST_PROC_DYNAMIC     TABLE/PROCEDURE   PROCEDURE   313204667      1     0            80            86
SYS.PLITBLM             TABLE/PROCEDURE   PACKAGE    4251528005      5     0           822           941
SYS.PLITBLM             BODY              CURSOR     4039937844      0     0           892           892

Here the output of gdb script:


Breakpoint 4, 0x000000000cac5190 in kglpnal ()
===== Spec PIN (1) <<< kgllkhdl: 5D175E20, kgllkmod 2, kglnaobj: PLITBLMSYS >>>=====
Breakpoint 5, 0x000000000cac18c0 in kgllkal ()
#0  0x000000000cac18c0 in kgllkal ()
#1  0x000000000cab9b8d in kglLock ()
#2  0x000000000cab2e62 in kglget ()
#3  0x000000000cab120f in kglgob ()
#4  0x0000000004b1961b in kgiinb ()
#5  0x0000000004c64ab9 in pfri3_inst_body ()
#6  0x000000000caf9a4b in pfrrun ()
#7  0x000000000cb02104 in plsql_run ()
====== Body LOCK (1) <<< kgllkhdl: 5CA06D80, kgllkmod 1, kglnaobj: PLITBLMSYS >>>=====
Breakpoint 6, 0x000000000cac5190 in kglpnal ()
#0  0x000000000cac5190 in kglpnal ()
#1  0x000000000cab397d in kglpin ()
#2  0x000000000cab12f6 in kglgob ()
#3  0x0000000004b1961b in kgiinb ()
#4  0x0000000004c64ab9 in pfri3_inst_body ()
#5  0x000000000caf9a4b in pfrrun ()
#6  0x000000000cb02104 in plsql_run ()
#7  0x0000000004c4b345 in peicnt ()
===== Body PIN (1) <<< kgllkhdl: 5CA06D80, kgllkmod 2, kglnaobj: PLITBLMSYS >>>=====
Breakpoint 1, 0x000000000cac18c0 in kgllkal ()
===== Proc LOCK (1) <<< kgllkhdl: 5756B220, kgllkmod 1, kglnaobj: TEST_PROC_DYNAMICK >>>=====
#0  0x000000000cac18c0 in kgllkal ()
#1  0x000000000cab9b8d in kglLock ()
#2  0x000000000cab2e62 in kglget ()
#3  0x000000000cab120f in kglgob ()
#4  0x0000000004b17225 in kgiind ()
#5  0x0000000004c64072 in pfri1_inst_spec ()
#6  0x000000000caf99c3 in pfrrun ()
#7  0x000000000cb02104 in plsql_run ()

Breakpoint 2, 0x000000000cac5190 in kglpnal ()
===== Proc Pin (1) <<< kgllkhdl: 5756B220, kgllkmod 2, kglnaobj: TEST_PROC_DYNAMICK >>>=====
#0  0x000000000cac5190 in kglpnal ()
#1  0x000000000cab397d in kglpin ()
#2  0x000000000cab12f6 in kglgob ()
#3  0x0000000004b17225 in kgiind ()
#4  0x0000000004c64072 in pfri1_inst_spec ()
#5  0x000000000caf99c3 in pfrrun ()
#6  0x000000000cb02104 in plsql_run ()
#7  0x0000000004c4b345 in peicnt ()

Breakpoint 4, 0x000000000cac5190 in kglpnal ()
===== Spec PIN (2) <<< kgllkhdl: 5D175E20, kgllkmod 2, kglnaobj: PLITBLMSYS >>>=====
Breakpoint 5, 0x000000000cac18c0 in kgllkal ()
====== Body LOCK (2) <<< kgllkhdl: 5CA06D80, kgllkmod 1, kglnaobj: PLITBLMSYS >>>=====
Breakpoint 6, 0x000000000cac5190 in kglpnal ()
===== Body PIN (2) <<< kgllkhdl: 5CA06D80, kgllkmod 2, kglnaobj: PLITBLMSYS >>>=====

All LOCKED_TOTAL and PINNED_TOTAL for PLITBLM.LOCKED_TOTAL and PLITBLM are smilar to static call, Script output are also similar to static call.

4.3 Test Observations and Discussions


(a). Above tests showed that only dynamic call in Oracle 19c has the number of executions (almost) equal to:
         Spec PLITBLM.PINNED_TOTAL = Body PLITBLM.LOCKED_TOTAL = Body PLITBLM.PINNED_TOTAL.
         
     Therefore in case of dynamic call in Oracle 19c, 
     the number of kglLock and kglpin subroutine calls are linear to the number of executions.
     
(b). It seems that Oracle 19c has some new behaviour on "execute immediate" PL/SQL block.
     Probably dynamic parsed PL/SQL cursor is not cached, or cannot be re-used. 
     Hence it incurs one hard parsing for each execution.
     
(c). Here the Call Stack for kglpin & kglLock in Oracle 19c vs. 12c1.
     In 19c, pfri1_inst_spec invokes pfri8_inst_spec, pfri3_inst_body invokes pfri7_inst_body_common.
     Whereas in 12c1, they are not possible.
     
     It looks like PL/SQL engine changed.

       -------- 19c kglpin & kglLock --------------------      -------- 12c1 kglpin & kglLock --------
       
       #0  0x0000000004c57ff0 in kglpnal ()                    #0  0x000000000cac18c0 in kgllkal ()        
       #1  0x0000000004c1f8c4 in kglpin ()                     #1  0x000000000cab9b8d in kglLock ()        
       #2  0x0000000004c2307c in kglpnp ()                     #2  0x000000000cab2e62 in kglget ()         
       #3  0x0000000012b6e545 in kgiind ()                     #3  0x000000000cab120f in kglgob ()         
       #4  0x000000000569b7dc in pfri8_inst_spec ()            #4  0x0000000004b1961b in kgiinb ()         
       #5  0x000000000569b604 in pfri1_inst_spec ()            #5  0x0000000004c64ab9 in pfri3_inst_body ()
       #6  0x0000000012b7d020 in pfrrun ()                     #6  0x000000000caf9a4b in pfrrun ()         
       #7  0x0000000012b86bab in plsql_run ()                  #7  0x000000000cb02104 in plsql_run ()      
                                                   
       #0  0x0000000004c504b0 in kgllkal ()                    #0  0x000000000cac5190 in kglpnal ()        
       #1  0x0000000004c33e9d in kglLock ()                    #1  0x000000000cab397d in kglpin ()         
       #2  0x0000000004c22e0c in kglget ()                     #2  0x000000000cab12f6 in kglgob ()         
       #3  0x0000000004c1cb78 in kglgob ()                     #3  0x0000000004b1961b in kgiinb ()         
       #4  0x0000000004de210f in kgiinbgob_swcb ()             #4  0x0000000004c64ab9 in pfri3_inst_body ()
       #5  0x0000000004de115e in kgiinb ()                     #5  0x000000000caf9a4b in pfrrun ()         
       #6  0x000000000569d1bb in pfri7_inst_body_common ()     #6  0x000000000cb02104 in plsql_run ()      
       #7  0x000000000569cf38 in pfri3_inst_body ()            #7  0x0000000004c4b345 in peicnt ()         

(d). There does not exist PLITBLM PACKAGE BODY. It is defined as PRAGMA INTERFACE(C, ...).
     (See later Section: "6. Full List of Mutex kgxExclusive and kgxRelease").
     The new 19c call of pfri7_inst_body_common can be a problem.

In all above tests, we have not yet include kglUnLock and kglUnPin.

5. 19c Mutex kgxExclusive and kgxRelease from kglLock and kglpin

After looking kglLock and kglpin in the last section, now we can have a look of their triggered kgxExclusive and kgxRelease for mutex request and release.

We only look kglLock and kglpin on PLITBLM Body in dynamic call. The same approach can be applied on PLITBLM Spec.

5.1. 19c kglLock triggered Mutex kgxExclusive and kgxRelease

Run dynamic call for 10 executions, and trace kglLock mutex Request/Release with appended "gdb_script_mutex_19c_body_lock" (see Appendix 7.3)


exec test_proc_dynamic(10, 1);

Here the gdb output:


Breakpoint 1, 0x0000000004c504b0 in kgllkal ()
====== Body LOCK (0) <<< kgllkhdl: 9EC403D0, kgllkmod 1, kglnaobj: PLITBLMSYS >>>=====
Breakpoint 1, 0x0000000004c504b0 in kgllkal ()
#0  0x0000000004c504b0 in kgllkal ()
#1  0x0000000004c33e9d in kglLock ()
#2  0x0000000004c22e0c in kglget ()
#3  0x0000000004c1cb78 in kglgob ()
#4  0x0000000004de210f in kgiinbgob_swcb ()
#5  0x0000000004de115e in kgiinb ()
#6  0x000000000569d1bb in pfri7_inst_body_common ()
#7  0x000000000569cf38 in pfri3_inst_body ()
====== Body LOCK (1) <<< kgllkhdl: 9EC403D0, kgllkmod 1, kglnaobj: PLITBLMSYS >>>=====
Breakpoint 2, 0x0000000004deb0e0 in kgxExclusive ()
------------ Body LOCK kgxExclusive (1) --->  Mutex addr (rsi): 9EC40520
Breakpoint 3, 0x0000000004dee690 in kgxRelease ()
------------ Body LOCK kgxRelease (1) --->  Mutex addr (r15): 9EC40520 
$1 = {0, 551, 7207, 10791}
Breakpoint 2, 0x0000000004deb0e0 in kgxExclusive ()
------------ Body LOCK kgxExclusive (2) --->  Mutex addr (rsi): 9EC40520
Breakpoint 3, 0x0000000004dee690 in kgxRelease ()
------------ Body LOCK kgxRelease (2) --->  Mutex addr (r15): 9EC40520 
$2 = {0, 551, 7208, 10791}
Breakpoint 2, 0x0000000004deb0e0 in kgxExclusive ()
------------ Body LOCK kgxExclusive (3) --->  Mutex addr (rsi): 9EC40520
Breakpoint 3, 0x0000000004dee690 in kgxRelease ()
------------ Body LOCK kgxRelease (3) --->  Mutex addr (r15): 9EC40520 
$3 = {0, 551, 7209, 10791}
Breakpoint 2, 0x0000000004deb0e0 in kgxExclusive ()
------------ Body LOCK kgxExclusive (4) --->  Mutex addr (rsi): 9EC40520
Breakpoint 3, 0x0000000004dee690 in kgxRelease ()
------------ Body LOCK kgxRelease (4) --->  Mutex addr (r15): 9EC40520 
$4 = {0, 551, 7210, 10791}
Breakpoint 2, 0x0000000004deb0e0 in kgxExclusive ()
------------ Body LOCK kgxExclusive (5) --->  Mutex addr (rsi): 9EC40520
Breakpoint 1, 0x0000000004c504b0 in kgllkal ()

====== Body LOCK (2) <<< kgllkhdl: 9EC403D0, kgllkmod 1, kglnaobj: PLITBLMSYS >>>=====
Breakpoint 3, 0x0000000004dee690 in kgxRelease ()
------------ Body LOCK kgxRelease (5) --->  Mutex addr (r15): 9EC40520 
$5 = {0, 551, 7211, 10791}
Breakpoint 2, 0x0000000004deb0e0 in kgxExclusive ()
------------ Body LOCK kgxExclusive (6) --->  Mutex addr (rsi): 9EC40520
Breakpoint 3, 0x0000000004dee690 in kgxRelease ()
------------ Body LOCK kgxRelease (6) --->  Mutex addr (r15): 9EC40520 
$6 = {0, 551, 7212, 10791}
Breakpoint 2, 0x0000000004deb0e0 in kgxExclusive ()
------------ Body LOCK kgxExclusive (7) --->  Mutex addr (rsi): 9EC40520
Breakpoint 3, 0x0000000004dee690 in kgxRelease ()
------------ Body LOCK kgxRelease (7) --->  Mutex addr (r15): 9EC40520 
$7 = {0, 551, 7213, 10791}
Breakpoint 2, 0x0000000004deb0e0 in kgxExclusive ()
------------ Body LOCK kgxExclusive (8) --->  Mutex addr (rsi): 9EC40520
Breakpoint 3, 0x0000000004dee690 in kgxRelease ()
------------ Body LOCK kgxRelease (8) --->  Mutex addr (r15): 9EC40520 
$8 = {0, 551, 7214, 10791}
Breakpoint 2, 0x0000000004deb0e0 in kgxExclusive ()
------------ Body LOCK kgxExclusive (9) --->  Mutex addr (rsi): 9EC40520
Breakpoint 3, 0x0000000004dee690 in kgxRelease ()
------------ Body LOCK kgxRelease (9) --->  Mutex addr (r15): 9EC40520 
$9 = {0, 551, 7215, 10791}
Breakpoint 2, 0x0000000004deb0e0 in kgxExclusive ()
------------ Body LOCK kgxExclusive (10) --->  Mutex addr (rsi): 9EC40520
Breakpoint 1, 0x0000000004c504b0 in kgllkal ()

...

====== Body LOCK (10) <<< kgllkhdl: 9EC403D0, kgllkmod 1, kglnaobj: PLITBLMSYS >>>=====
Breakpoint 3, 0x0000000004dee690 in kgxRelease ()
------------ Body LOCK kgxRelease (45) --->  Mutex addr (r15): 9EC40520 
$45 = {0, 551, 7251, 10791}
Breakpoint 2, 0x0000000004deb0e0 in kgxExclusive ()
------------ Body LOCK kgxExclusive (46) --->  Mutex addr (rsi): 9EC40520
Breakpoint 3, 0x0000000004dee690 in kgxRelease ()
------------ Body LOCK kgxRelease (46) --->  Mutex addr (r15): 9EC40520 
$46 = {0, 551, 7252, 10791}
Breakpoint 2, 0x0000000004deb0e0 in kgxExclusive ()
------------ Body LOCK kgxExclusive (47) --->  Mutex addr (rsi): 9EC40520
Breakpoint 3, 0x0000000004dee690 in kgxRelease ()
------------ Body LOCK kgxRelease (47) --->  Mutex addr (r15): 9EC40520 
$47 = {0, 551, 7253, 10791}
Breakpoint 2, 0x0000000004deb0e0 in kgxExclusive ()
------------ Body LOCK kgxExclusive (48) --->  Mutex addr (rsi): 9EC40520
Breakpoint 3, 0x0000000004dee690 in kgxRelease ()
------------ Body LOCK kgxRelease (48) --->  Mutex addr (r15): 9EC40520 
$48 = {0, 551, 7254, 10791}
Breakpoint 2, 0x0000000004deb0e0 in kgxExclusive ()
------------ Body LOCK kgxExclusive (49) --->  Mutex addr (rsi): 9EC40520
Breakpoint 3, 0x0000000004dee690 in kgxRelease ()
------------ Body LOCK kgxRelease (49) --->  Mutex addr (r15): 9EC40520 
$49 = {0, 551, 7255, 10791}

Above output shows:


  (a). There are 10 "Body LOCK PLITBLMSYS", each for one dynamic call execution.
  (b). For each "Body LOCK PLITBLMSYS", there are 5 pairs of kgxExclusive / kgxRelease on mutex address: 9EC40520.

For each kgxRelease, we show a tuple like:


      {0, 551, 7255, 10791}
   where
      551: session_id (SID) of dynamic call session (mutex holding session) = V$MUTEX_SLEEP_HISTORY.blocking_session
      7255: mutex gets = V$MUTEX_SLEEP_HISTORY.gets
      10791: mutex sleeps = V$MUTEX_SLEEP_HISTORY.sleeps
             
      (V$MUTEX_SLEEP_HISTORY.mutex_identifier = V$DB_OBJECT_CACHE.hash_value
       V$MUTEX_SLEEP_HISTORY.p1raw = V$DB_OBJECT_CACHE.adrr: object_handle addr)

5.1. 19c kglpin triggered Mutex kgxExclusive and kgxRelease

Run dynamic call for 10 executions, and trace kglpin mutex Rquests/Release with appended "gdb_script_mutex_19c_body_pin" (see Appendix 7.4)


exec test_proc_dynamic(10, 1);

Here the gdb output:


Breakpoint 1, 0x0000000004c57ff0 in kglpnal ()
====== Body PIN (0) <<< kgllkhdl: 9EC403D0, kgllkmod 2, kglnaobj: PLITBLMSYS >>>=====
Breakpoint 1, 0x0000000004c57ff0 in kglpnal ()
#0  0x0000000004c57ff0 in kglpnal ()
#1  0x0000000004c1f8c4 in kglpin ()
#2  0x0000000004c1cd80 in kglgob ()
#3  0x0000000004de210f in kgiinbgob_swcb ()
#4  0x0000000004de115e in kgiinb ()
#5  0x000000000569d1bb in pfri7_inst_body_common ()
#6  0x000000000569cf38 in pfri3_inst_body ()
#7  0x0000000012b7d0a6 in pfrrun ()
====== Body PIN (1) <<< kgllkhdl: 9EC403D0, kgllkmod 2, kglnaobj: PLITBLMSYS >>>=====
Breakpoint 2, 0x0000000004deb0e0 in kgxExclusive ()
------------ Body PIN kgxExclusive (1) --->  Mutex addr (rsi): 9EC40520
Breakpoint 3, 0x0000000004dee690 in kgxRelease ()
------------ Body PIN kgxRelease (1) --->  Mutex addr (r15): 9EC40520 
$1 = {0, 551, 7263, 10791}
Breakpoint 2, 0x0000000004deb0e0 in kgxExclusive ()
------------ Body PIN kgxExclusive (2) --->  Mutex addr (rsi): 9EC40520
Breakpoint 3, 0x0000000004dee690 in kgxRelease ()
------------ Body PIN kgxRelease (2) --->  Mutex addr (r15): 9EC40520 
$2 = {0, 551, 7264, 10791}
Breakpoint 2, 0x0000000004deb0e0 in kgxExclusive ()
------------ Body PIN kgxExclusive (3) --->  Mutex addr (rsi): 9EC40520
Breakpoint 3, 0x0000000004dee690 in kgxRelease ()
------------ Body PIN kgxRelease (3) --->  Mutex addr (r15): 9EC40520 
$3 = {0, 551, 7265, 10791}
Breakpoint 2, 0x0000000004deb0e0 in kgxExclusive ()
------------ Body PIN kgxExclusive (4) --->  Mutex addr (rsi): 9EC40520
Breakpoint 3, 0x0000000004dee690 in kgxRelease ()
------------ Body PIN kgxRelease (4) --->  Mutex addr (r15): 9EC40520 
$4 = {0, 551, 7266, 10791}
Breakpoint 2, 0x0000000004deb0e0 in kgxExclusive ()
------------ Body PIN kgxExclusive (5) --->  Mutex addr (rsi): 9EC40520
Breakpoint 3, 0x0000000004dee690 in kgxRelease ()
------------ Body PIN kgxRelease (5) --->  Mutex addr (r15): 9EC40520 
$5 = {0, 551, 7267, 10791}

Breakpoint 1, 0x0000000004c57ff0 in kglpnal ()
====== Body PIN (2) <<< kgllkhdl: 9EC403D0, kgllkmod 2, kglnaobj: PLITBLMSYS >>>=====
Breakpoint 2, 0x0000000004deb0e0 in kgxExclusive ()
------------ Body PIN kgxExclusive (6) --->  Mutex addr (rsi): 9EC40520
Breakpoint 3, 0x0000000004dee690 in kgxRelease ()
------------ Body PIN kgxRelease (6) --->  Mutex addr (r15): 9EC40520 
$6 = {0, 551, 7268, 10791}
Breakpoint 2, 0x0000000004deb0e0 in kgxExclusive ()
------------ Body PIN kgxExclusive (7) --->  Mutex addr (rsi): 9EC40520
Breakpoint 3, 0x0000000004dee690 in kgxRelease ()
------------ Body PIN kgxRelease (7) --->  Mutex addr (r15): 9EC40520 
$7 = {0, 551, 7269, 10791}
Breakpoint 2, 0x0000000004deb0e0 in kgxExclusive ()
------------ Body PIN kgxExclusive (8) --->  Mutex addr (rsi): 9EC40520
Breakpoint 3, 0x0000000004dee690 in kgxRelease ()
------------ Body PIN kgxRelease (8) --->  Mutex addr (r15): 9EC40520 
$8 = {0, 551, 7270, 10791}
Breakpoint 2, 0x0000000004deb0e0 in kgxExclusive ()
------------ Body PIN kgxExclusive (9) --->  Mutex addr (rsi): 9EC40520
Breakpoint 3, 0x0000000004dee690 in kgxRelease ()
------------ Body PIN kgxRelease (9) --->  Mutex addr (r15): 9EC40520 
$9 = {0, 551, 7271, 10791}
Breakpoint 2, 0x0000000004deb0e0 in kgxExclusive ()
------------ Body PIN kgxExclusive (10) --->  Mutex addr (rsi): 9EC40520
Breakpoint 3, 0x0000000004dee690 in kgxRelease ()
------------ Body PIN kgxRelease (10) --->  Mutex addr (r15): 9EC40520 
$10 = {0, 551, 7272, 10791}

...

Breakpoint 1, 0x0000000004c57ff0 in kglpnal ()
====== Body PIN (10) <<< kgllkhdl: 9EC403D0, kgllkmod 2, kglnaobj: PLITBLMSYS >>>=====
Breakpoint 2, 0x0000000004deb0e0 in kgxExclusive ()
------------ Body PIN kgxExclusive (46) --->  Mutex addr (rsi): 9EC40520
Breakpoint 3, 0x0000000004dee690 in kgxRelease ()
------------ Body PIN kgxRelease (46) --->  Mutex addr (r15): 9EC40520 
$46 = {0, 551, 7308, 10791}
Breakpoint 2, 0x0000000004deb0e0 in kgxExclusive ()
------------ Body PIN kgxExclusive (47) --->  Mutex addr (rsi): 9EC40520
Breakpoint 3, 0x0000000004dee690 in kgxRelease ()
------------ Body PIN kgxRelease (47) --->  Mutex addr (r15): 9EC40520 
$47 = {0, 551, 7309, 10791}
Breakpoint 2, 0x0000000004deb0e0 in kgxExclusive ()
------------ Body PIN kgxExclusive (48) --->  Mutex addr (rsi): 9EC40520
Breakpoint 3, 0x0000000004dee690 in kgxRelease ()
------------ Body PIN kgxRelease (48) --->  Mutex addr (r15): 9EC40520 
$48 = {0, 551, 7310, 10791}

Above output shows:


  (a). There are 10 "Body PIN PLITBLMSYS", each for one dynamic call execution.
  (b). For each "Body PIN PLITBLMSYS", there are 5 pairs of kgxExclusive / kgxRelease on mutex address: 9EC40520.

5.3 Test Observations and Discussions: PLITBLM Execution Limit

In 19c, when we run:


  exec test_proc_dynamic(10, 1);

It makes 10 dynamic Pl/SQL anonymous block executions.

Each execution incurs:


  1 kglpin  on PLITBLM Spec
  1 kglLock on PLITBLM Body
  1 kglpin  on PLITBLM Body

Above tests showed that each kglpin or each kglLock incurs 5 pairs of mutex kgxExclusive / kgxRelease. So for each dynamic execution, there are 15 (3*5) pairs of mutex kgxExclusive / kgxRelease. For 10 dynamic executions in 19c, it triggers 150 (3*5*10) mutex kgxExclusive / kgxRelease.

Whereas in all other cases (19c static, 12c1 static/dynamic), they are below constant (less than 3*5*3=45), independent of the number of executions.

Assume each mutex kgxExclusive or each kgxRelease take 100 microseconds,


  the duration of one ksun_pickler_test_1d execution can be estimated as:
     
       Dur_Per_Exe = (3*5*2*100) = 3000
       
  The throughput of ksun_pickler_test_1d executions per second can be estimated as
  (each kgxExclusive / kgxRelease is independently performed):
     
       Exec_Per_Second = 1000,000/100 = 10,000
         
  if there is sufficient resource (specially CPU) and does not take account of queuing effect in concurrency system.
  
       where  
              3: 1 kglpin on PLITBLM Spec, 1 kglLock on PLITBLM Body, 1 kglpin on PLITBLM Body
              5: each kglpin/kglLock requires 5 pairs of mutex kgxExclusive / kgxRelease 
              2: 1 kgxExclusive and 1 kgxRelease
            100: mutex time in microsecond

If we markhot PLITBLM, it will create hot copy PLITBLM objects. Each hot copy object has a different object_handle, hence different mutex to protect it. (see Blog: "library cache: mutex X" and Application Context ). The maximum number of test_proc_dynamic executions per second can increase to:


   Exec_Per_Second * "_kgl_hot_object_copies"
   
      _kgl_hot_object_copies: controls the maximum number of copies, maximum value: 255

      (Note Oracle MOS: 
          Bug 19373224 - dbms_shared_pool.unmarkhot spins if _kgl_hot_object_copies is 255 (Doc ID 19373224.8)
       wrote:
          Executing dbms_shared_pool.unmarkhot() might have entered a spin under kglget() if 
             _kgl_hot_object_copies was set (or derived) to a value of 255.
          Workaround
             Reduce the value of _kgl_hot_object_copies to 254 or below).

Each object is protected by its own mutex (single point). Its performance (mutex time) is related to Processor Clock Speed and scheduler time slice.

Till now, we only looked part of mutex kgxExclusive/kgxRelease. In next Section (6. "Full List of Mutex kgxExclusive and kgxRelease"), we will dig further to list all pairs of mutex kgxExclusive/kgxRelease (So the above estimation of execution duration has to be increased). At the same time, we will show how to observe that kgxExclusive / kgxRelease is independently performed.

By the way, subroutine "kglLock" has Uppercase "L" for "lock", whereas subroutine "kglpin" has lowercase "p" for "pin", probably to avoid two adjacent lowercase "l" in "kgllock".

There seem some behaviour changes in Oracle 19c and latest 18c version. For example: Blog: The Third Test of ORA-04025: maximum allowed library object lock showed session_cached_cursors changes from 18c to 19c in the call of dbms_lock.allocate_unique_autonomous.

Blog: DBMS_SCHEDULER Job Not Running and Used Slaves showed DBMS_SCHEDULER changes from Oracle 18.10 to Oracle 19.8.

6. Full List of Mutex kgxExclusive and kgxRelease

In Section 5.1. "19c kglLock triggered Mutex kgxExclusive and kgxRelease", we use "gdb_script_mutex_19c_body_lock" (see Appendix 7.3) to collect Mutex kgxExclusive and kgxRelease triggered by kglLock on PLITBLM Body.

It only traced kglGetMutex on one mutex (Mutex addr: 9EC40520) for object handle (9EC403D0) of PLITBLM Body.

In this session, we will compose a new gdb script: "gdb_script_mutex_19c_body_lock_all" (see Appendix 7.5) to trace both kglGetMutex and kglGetBucketMutex on all mutexes triggered by kglLock on PLITBLM Body. (see Blog: Row Cache Object and Row Cache Mutex Case Study about Row Cache "BUCKET mutex").

Run dynamic call for 10 executions, and trace kglLock mutex Request/Release with appended "gdb_script_mutex_19c_body_lock_all" (see Appendix 7.5).


exec test_proc_dynamic(10, 1);

Here the gdb output (unrelated content removed):


Breakpoint 1, 0x0000000004c504b0 in kgllkal ()
===Body LOCK (1) <<< kgllkhdl: 9EC403D0, kgllkmod 1, kglnaobj: PLITBLMSYS>>>=====
  #0  kgllkal ()
  #1  kglLock ()
  #2  kglget ()
  #3  kglgob ()
  #4  kgiinbgob_swcb ()
  #5  kgiinb ()
  #6  pfri7_inst_body_common ()
  #7  pfri3_inst_body ()
------kglGetMutex (1) ---> Mutex addr (rsi): 9EC40520, Location(r8d): 4
  #0  kglGetMutex ()
  #1  kglpin ()
  #2  kglgob ()
  #3  kgiinbgob_swcb ()
----------kgxExclusive (1) ---> Mutex addr (rsi): 9EC40520
------------kgxRelease (1) ---> Mutex addr (r15): 9EC40520 
$1 = {0, 551, 11144, 17474}
------kglGetMutex (2) ---> Mutex addr (rsi): 9EC40520, Location(r8d): 90
  #0  kglGetMutex ()
  #1  kglpnal ()
  #2  kglpin ()
  #3  kglgob ()
----------kgxExclusive (2) ---> Mutex addr (rsi): 9EC40520
------kglGetMutex (3) ---> Mutex addr (rsi): 9EC40520, Location(r8d): 71
  #0  kglGetMutex ()
  #1  kglobpn ()
  #2  kglpim ()
  #3  kglpin ()
------kglGetMutex (4) ---> Mutex addr (rsi): 9EC40520, Location(r8d): 72
  #0  kglGetMutex ()
  #1  kglobpn ()
  #2  kglpim ()
  #3  kglpin ()
------------kgxRelease (2) ---> Mutex addr (r15): 9EC40520 
$2 = {0, 551, 11145, 17474}
------kglGetMutex (5) ---> Mutex addr (rsi): 9EC40520, Location(r8d): 95
  #0  kglGetMutex ()
  #1  kglpndl ()
  #2  kglUnPin ()
  #3  kgiinb ()
----------kgxExclusive (3) ---> Mutex addr (rsi): 9EC40520
------------kgxRelease (3) ---> Mutex addr (r15): 9EC40520 
$3 = {0, 551, 11146, 17474}
------kglGetMutex (6) ---> Mutex addr (rsi): 9EC40520, Location(r8d): 85
  #0  kglGetMutex ()
  #1  kgllkdl ()
  #2  kglUnLock ()
  #3  kgiinb ()
----------kgxExclusive (4) ---> Mutex addr (rsi): 9EC40520
------kglGetMutex (7) ---> Mutex addr (rsi): 9EC40520, Location(r8d): 86
  #0  kglGetMutex ()
  #1  kgllkdl ()
  #2  kglUnLock ()
  #3  kgiinb ()
------------kgxRelease (4) ---> Mutex addr (r15): 9EC40520 
$4 = {0, 551, 11147, 17474}
------kglGetMutex (8) ---> Mutex addr (rsi): A4550000, Location(r8d): 95
  #0  kglGetMutex ()
  #1  kglpndl ()
  #2  kss_del_cb ()
  #3  kssdel ()
----------kgxExclusive (5) ---> Mutex addr (rsi): A4550000
------------kgxRelease (5) ---> Mutex addr (r15): A4550000 
$5 = {0, 551, 11349, 51801}
------kglGetMutex (9) ---> Mutex addr (rsi): A4550000, Location(r8d): 4
  #0  kglGetMutex ()
  #1  kglpin ()
  #2  kglpnp ()
  #3  kgiind ()
----------kgxExclusive (6) ---> Mutex addr (rsi): A4550000
------------kgxRelease (6) ---> Mutex addr (r15): A4550000 
$6 = {0, 551, 11350, 51801}
------kglGetMutex (10) ---> Mutex addr (rsi): A4550000, Location(r8d): 90
  #0  kglGetMutex ()
  #1  kglpnal ()
  #2  kglpin ()
  #3  kglpnp ()
----------kgxExclusive (7) ---> Mutex addr (rsi): A4550000
------kglGetMutex (11) ---> Mutex addr (rsi): A4550000, Location(r8d): 71
  #0  kglGetMutex ()
  #1  kglobpn ()
  #2  kglpim ()
  #3  kglpin ()
------kglGetMutex (12) ---> Mutex addr (rsi): A4550000, Location(r8d): 72
  #0  kglGetMutex ()
  #1  kglobpn ()
  #2  kglpim ()
  #3  kglpin ()
------------kgxRelease (7) ---> Mutex addr (r15): A4550000 
$7 = {0, 551, 11351, 51801}
------kglGetBucketMutex (1) ---> BucketMutex hash_value (rsi): 36660, Location(r8d): 62
  #0  kglGetBucketMutex ()
  #1  kglhdgn ()
  #2  kglLock ()
  #3  kglget ()
------kglGetMutex (13) ---> Mutex addr (rsi): A614A230, Location(r8d): 62
  #0  kglGetMutex ()
  #1  kglhdgn ()
  #2  kglLock ()
  #3  kglget ()
----------kgxExclusive (8) ---> Mutex addr (rsi): A614A230
------------kgxRelease (8) ---> Mutex addr (r15): A614A230 
$8 = {0, 551, 4832, 0}
------kglGetMutex (14) ---> Mutex addr (rsi): 9EC40520, Location(r8d): 106
  #0  kglGetMutex ()
  #1  kglhdgn ()
  #2  kglLock ()
  #3  kglget ()
----------kgxExclusive (9) ---> Mutex addr (rsi): 9EC40520
------------kgxRelease (9) ---> Mutex addr (r15): 9EC40520 
$9 = {0, 551, 11148, 17474}

There are (about) 10 such output, each for one execution.

Above output shows:


(a). kglGetMutex
       8 kglGetMutex on Mutex addr (rsi): 9EC40520 in 8 different Location(r8d)
       5 kglGetMutex on Mutex addr (rsi): A4550000 in 5 different Location(r8d) 
       1 kglGetMutex on Mutex addr (rsi): A614A230 in 1 different Location(r8d) (from kglGetBucketMutex)
       
(b). kglGetBucketMutex
       1 kglGetBucketMutex with BucketMutex hash_value (rsi): 36660, Location(r8d): 62
            (v$db_object_cache.hash_value=36660)
       kglGetBucketMutex calls kglGetMutex, which then calls 
       
(c). kgxExclusive/kgxExclusive
       5 kgxExclusive/kgxRelease on Mutex addr (rsi): 9EC40520
       3 kgxExclusive/kgxRelease on Mutex addr (rsi): A4550000
       1 kgxExclusive/kgxRelease on Mutex addr (rsi): A614A230 (from kglGetBucketMutex)
       
       where:  Mutex addr (rsi): 9EC40520 is for PLITBLM Pacakge Body
               Mutex addr (rsi): A4550000 is for PLITBLM Pacakge Spec
               Mutex addr (rsi): A614A230 is fir BucketMutex
               
(d). Location
       multiple kglGetMutex trigger one kgxExclusive/kgxExclusive, for example,
         kglGetMutex on Mutex addr (rsi): 9EC40520 with Location: 71, 72, 95 trigger one kgxExclusive/kgxRelease. 
   
(e). Between kgxExclusive and kgxRelease for the same mutex addr, there is no other kgxExclusive (not interleaved).

(f). Each mutex addr has its own counter recorded in the form of four element tuple:
         {0,  holding session_id, mutex gets, mutex sleeps}
         
       9EC40520: from {0, 730, 11144, 17474} to {0, 551, 11148, 17474}, 5 tuples (gets counter from 11144 to 11148)
       A4550000: from {0, 551, 11349, 51801} to {0, 551, 11351, 51801}, 3 tuples (gets counter from 11349 to 11351)
       A614A230: from {0, 551, 4832, 0},                                1 tuple  (gets counter 4832)

In summary, one dynamic execution incurs one kglLock on PLITBLM Body, which requires 9 pairs of kgxExclusive/kgxRelease. The 9 pairs are distributed in 3 different mutex addr.

As showed in Section 5.3 "Test Observations and Discussions: PLITBLM Execution Limit", one dynamic execution also incurs one kglpin on PLITBLM Spec and one kglpin on PLITBLM Body, which have the similar requests on kgxExclusive/kgxRelease.

If we make a PROCESSSTATE (level 10) or SYSTEMSTATE (level 10) dump, we can see object handle: "LibraryHandle: Address=0xa454feb0":


  LibraryHandle:  Address=0xa454feb0 Hash=fd692b45 LockMode=N PinMode=0 LoadLockMode=0 Status=VALD 
    ObjectName:  Name=SYS.PLITBLM   
      FullHashValue=6e9b4ca99d9498e62b2af8bafd692b45 Namespace=TABLE/PROCEDURE(01) Type=PACKAGE(09) ContainerId=0 ContainerUid=0 Identifier=4746 OwnerIdn=0 
    Statistics:  InvalidationCount=0 ExecutionCount=2795763211 LoadCount=4 ActiveLocks=7 TotalLockCount=392941 TotalPinCount=13513812 
    Counters:  BrokenCount=1 RevocablePointer=1 KeepDependency=0 Version=0 BucketInUse=821 HandleInUse=821 HandleReferenceCount=0 
    Concurrency:  DependencyMutex=0xa454ff60(0, 747294, 0, 0) Mutex=0xa4550000(0, 42469882, 52549, 0)

It contains tuple:


	   Mutex=0xa4550000(0, 42469882, 52549, 0)  
	     where   mutex gets:   42469882
	             mutex sleeps:    52549


      (By the way, in AIX, we saw heavy "library cache: mutex X" Wait Event with:
                 Mutex=70001067e219fb0(9859, 1144748, 67542, 6)
              	     where   mutex holder Session_ID:      9859
              	             mutex gets:                1144748
              	             mutex sleeps:                67542
              	             mutex block mode:                6
      )

However in PROCESSSTATE / SYSTEMSTATE dumps, we cannot find anything about PLITBLM PACKAGE BODY, such as:


    ObjectName:  Name=SYS.PLITBLM   
      ... Namespace=BODY(02) Type=PACKAGE BODY(11)

because PLITBLM PACKAGE BODY is defined as PRAGMA INTERFACE(C, ...), and there is no PLITBLM PACKAGE BODY.

Following query also shows no PLITBLM PACKAGE BODY:


select owner, object_name, object_type from dba_objects where object_name in ('PLITBLM', 'STANDARD');

  OWNER    OBJECT_NAME  OBJECT_TYPE
  -------- ------------ ------------
  SYS      STANDARD     PACKAGE
  SYS      STANDARD     PACKAGE BODY
  SYS      PLITBLM      PACKAGE
  PUBLIC   PLITBLM      SYNONYM

In the above gdb output, "mutex gets" in all the tuples of one particular "mutex addr" are consecutive because we have only one single test session. In case of real applications, there are many concurrent sessions. For example, if we start the same jobs in Section 3. "library cache: mutex X" Test:


   exec test_job('dynamic', 64, 1e7, 1e4);

And then run the gdb script again, we can observe that "mutex gets" are jumping one after another (inconsecutive). By measuring the gap between two "mutex gets" (discontinuity), we can also estimate the degree of concurrency.

By the way, we can print outl kgl Mutex Locations listed in kglMutexLocations[] array. (similar to kqrMutexLocations[] array in Blog: Row Cache Object and Row Cache Mutex Case Study)


#Define Command to PrintkglMutexLocations
define PrintkglMutexLocations
  set $i = 0
  while $i < $arg0 + $arg0
    x /s *(&kglMutexLocations + $i)
    set $i = $i + 2
  end
end

(gdb) PrintkglMutexLocations 174

7. Appendix

7.1 gdb_script_kgl_19c


set pagination off
set logging file library_cache_kgl_19c.log
set logging overwrite on
set logging on
set $proc_lck = 0
set $proc_pin = 0
set $spec_lck = -2
set $spec_pin = -2
set $body_lck = -2
set $body_pin = -2
set $bt_print = -2

break kgllkal if $rdx==0X9DEB95E0 ||  $rdx==0X9DD7BC98
commands
printf "===== Proc LOCK (%i) <<< kgllkhdl: %X, kgllkmod %x, kglnaobj: %s >>>=====\n", $proc_lck++, $rdx, $rcx, ($rdx+0x1c0)
backtrace 8
continue
end

break kglpnal if $rdx==0X9DEB95E0 ||  $rdx==0X9DD7BC98
commands
printf "===== Proc Pin (%i) <<< kgllkhdl: %X, kgllkmod %x, kglnaobj: %s >>>=====\n", $proc_pin++, $rdx, $rcx, ($rdx+0x1c0)
backtrace 8
continue
end

break kgllkal if $rdx==0XA454FEB0
commands
while $spec_lck ==1 && $bt_print==0
  backtrace 8
  set $bt_print = 1
end
set $bt_print = 0
printf "===== Spec LOCK (%i) <<< kgllkhdl: %X, kgllkmod %x, kglnaobj: %s >>>=====", $spec_lck++, $rdx, $rcx, ($rdx+0x1c0)
continue
end

break kglpnal if $rdx==0XA454FEB0
commands
while $spec_pin ==1 && $bt_print==0
  backtrace 8
  set $bt_print = 1
end
set $bt_print = 0
printf "===== Spec PIN (%i) <<< kgllkhdl: %X, kgllkmod %x, kglnaobj: %s >>>=====", $spec_pin++, $rdx, $rcx, ($rdx+0x1c0)
continue
end

break kgllkal if $rdx==0X9EC403D0
commands
while $body_lck ==1 && $bt_print==0
  backtrace 8
  set $bt_print = 1
end
set $bt_print = 0
printf "====== Body LOCK (%i) <<< kgllkhdl: %X, kgllkmod %x, kglnaobj: %s >>>=====", $body_lck++, $rdx, $rcx, ($rdx+0x1c0)
continue
end

break kglpnal if $rdx==0X9EC403D0
commands
while $body_pin ==1 && $bt_print==0
  backtrace 8
  set $bt_print = 1
end
set $bt_print = 0
printf "===== Body PIN (%i) <<< kgllkhdl: %X, kgllkmod %x, kglnaobj: %s >>>=====", $body_pin++, $rdx, $rcx, ($rdx+0x1c0)
continue
end

7.2 gdb_script_kgl_12c1


set pagination off
set logging file library_cache_kgl_12c1.log
set logging overwrite on
set logging on
set $proc_lck = 1
set $proc_pin = 1
set $spec_lck = 1
set $spec_pin = 1
set $body_lck = 1
set $body_pin = 1
set $bt_print = 1

break kgllkal if $rdx==0x1565ebc10 ||  $rdx==0x15756b220
commands
printf "===== Proc LOCK (%i) <<< kgllkhdl: %X, kgllkmod %x, kglnaobj: %s >>>=====\n", $proc_lck++, $rdx, $rcx, ($rdx+0x1b8)
backtrace 8
continue
end

break kglpnal if $rdx==0x1565ebc10 ||  $rdx==0x15756b220
commands
printf "===== Proc Pin (%i) <<< kgllkhdl: %X, kgllkmod %x, kglnaobj: %s >>>=====\n", $proc_pin++, $rdx, $rcx, ($rdx+0x1b8)
backtrace 8
continue
end

break kgllkal if $rdx==0x15d175e20
commands
while $spec_lck ==1 && $bt_print==0
  backtrace 8
  set $bt_print = 1
end
set $bt_print = 0
printf "===== Spec LOCK (%i) <<< kgllkhdl: %X, kgllkmod %x, kglnaobj: %s >>>=====", $spec_lck++, $rdx, $rcx, ($rdx+0x1b8)
continue
end

break kglpnal if $rdx==0x15d175e20
commands
while $spec_pin ==1 && $bt_print==0
  backtrace 8
  set $bt_print = 1
end
set $bt_print = 0
printf "===== Spec PIN (%i) <<< kgllkhdl: %X, kgllkmod %x, kglnaobj: %s >>>=====", $spec_pin++, $rdx, $rcx, ($rdx+0x1b8)
continue
end

break kgllkal if $rdx==0x15ca06d80
commands
while $body_lck ==1 && $bt_print==0
  backtrace 8
  set $bt_print = 1
end
set $bt_print = 0
printf "====== Body LOCK (%i) <<< kgllkhdl: %X, kgllkmod %x, kglnaobj: %s >>>=====", $body_lck++, $rdx, $rcx, ($rdx+0x1b8)
continue
end

break kglpnal if $rdx==0x15ca06d80
commands
while $body_pin ==1 && $bt_print==0
  backtrace 8
  set $bt_print = 1
end
set $bt_print = 0
printf "===== Body PIN (%i) <<< kgllkhdl: %X, kgllkmod %x, kglnaobj: %s >>>=====", $body_pin++, $rdx, $rcx, ($rdx+0x1b8)
continue
end

7.3 gdb_script_mutex_19c_body_lock


set pagination off
set logging file mutex_19c_body_lock.log
set logging overwrite on
set logging on
set $body_lck = 0
set $bt_print = -2
set $k = 1
set $r = 1
set $mutex_addr = 0x0


break kgllkal if $rdx==0X9EC403D0
commands
while $body_lck ==1 && $bt_print==0
  backtrace 8
  set $bt_print = 1
end
set $bt_print = 0
printf "====== Body LOCK (%i) <<< kgllkhdl: %X, kgllkmod %x, kglnaobj: %s >>>=====", $body_lck++, $rdx, $rcx, ($rdx+0x1c0)
continue
end

break kgxExclusive if $r9==0X9EC403D0 && $body_lck > 1 
command 
printf "------------ Body LOCK kgxExclusive (%i) --->  Mutex addr (rsi): %X\n", $k++, $rsi
set $mutex_addr = $rsi     
continue
end

break kgxRelease if $r15==$mutex_addr && $body_lck > 1  
command 
printf "------------ Body LOCK kgxRelease (%i) --->  Mutex addr (r15): %X \n", $r++, $r15 
p/d (int[4])*$r15
# x/4dw $r15     
continue
end

7.4 gdb_script_mutex_19c_body_pin


set pagination off
set logging file mutex_19c_body_pin.log
set logging overwrite on
set logging on
set $body_pin = 0
set $bt_print = -2
set $k = 1
set $r = 1
set $mutex_addr = 0x0


break kglpnal if $rdx==0X9EC403D0
commands
while $body_pin ==1 && $bt_print==0
  backtrace 8
  set $bt_print = 1
end
set $bt_print = 0
printf "====== Body PIN (%i) <<< kgllkhdl: %X, kgllkmod %x, kglnaobj: %s >>>=====", $body_pin++, $rdx, $rcx, ($rdx+0x1c0)
continue
end

break kgxExclusive if $r9==0X9EC403D0 && $body_pin > 1 
command 
printf "------------ Body PIN kgxExclusive (%i) --->  Mutex addr (rsi): %X\n", $k++, $rsi
set $mutex_addr = $rsi     
continue
end

break kgxRelease if $r15==$mutex_addr && $body_pin > 1  
command 
printf "------------ Body PIN kgxRelease (%i) --->  Mutex addr (r15): %X \n", $r++, $r15 
p/d (int[4])*$r15
# x/4dw $r15     
continue
end

7.5 gdb_script_mutex_19c_body_lock_all


set pagination off
set logging file mutex_19c_body_lock_all.log
set logging overwrite on
set logging on
set $body_lck = 0
set $k = 1
set $r = 1
set $kget = 1
set $kbucketget = 1
set $mutex_addr = 0x0

break kgllkal if $rdx==0X9EC403D0
commands
printf "===Body LOCK (%i) <<< kgllkhdl: %X, kgllkmod %x, kglnaobj: %s>>>=====\n", $body_lck++, $rdx, $rcx, ($rdx+0x1c0)
backtrace 8 
set $bt_print = 1
continue
end

break kglGetMutex if $body_lck > 1 
command 
printf "------kglGetMutex (%i) ---> Mutex addr (rsi): %X, Location(r8d): %d\n", $kget++, $rsi, $r8d
backtrace 4
continue
end

break kglGetBucketMutex if $body_lck > 1 
command 
printf "------kglGetBucketMutex (%i) ---> BucketMutex hash_value (rsi): %d, Location(r8d): %d\n", $kbucketget++, $rsi, $r8d
backtrace 4
continue
end

break kgxExclusive if $body_lck > 1 
#break kgxExclusive if $r9==0X9EC403D0 && $body_lck > 1 
command 
printf "----------kgxExclusive (%i) ---> Mutex addr (rsi): %X\n", $k++, $rsi
#backtrace 4
set $mutex_addr = $rsi  
continue
end

break kgxRelease if $r15==$mutex_addr && $body_lck > 1 
command 
printf "------------kgxRelease (%i) ---> Mutex addr (r15): %X \n", $r++, $r15 
p/d (int[4])*$r15
# x/4dw $r15     
continue
end


#break kglReleaseMutex
#break kglReleaseBucketMutex

7.6 Test Cleanup

After test, we can cleanup the test by following procedure:


create or replace procedure clearup_test as
begin
  for c in (select * from dba_scheduler_jobs where job_name like '%TEST_JOB%') loop
    begin
      --set DBA_SCHEDULER_JOBS.enabled=FALSE
	    dbms_scheduler.disable (c.job_name, force => true, commit_semantics =>'ABSORB_ERRORS');
	    --set DBA_SCHEDULER_JOBS.enabled=TRUE, so that it can be scheduled to run (state='RUNNING')
	    --  dbms_scheduler.enable (c.job_name, commit_semantics =>'ABSORB_ERRORS');
	  exception when others then null;
	  end;
	end loop;
	
  for c in (select * from dba_scheduler_running_jobs where job_name like '%TEST_JOB%') loop
    begin
      --If force=FALSE, gracefully stop the job, slave process can update the status of the job in the job queue.
      --If force= TRUE, the Scheduler immediately terminates the job slave.
      --For repeating job with attribute "start_date => systimestamp" and enabled=TRUE, 
      --re-start immediate (state changed from 'SCHEDULED to 'RUNNING'), DBA_SCHEDULER_JOBS.run_count increases 1.
	    dbms_scheduler.stop_job (c.job_name, force => true, commit_semantics =>'ABSORB_ERRORS');
	  exception when others then null;
	  end;
	end loop;
	
  for c in (select * from dba_scheduler_jobs where job_name like '%TEST_JOB%') loop
    begin
      --If force=TRUE, the Scheduler first attempts to stop the running job instances 
      --(by issuing the STOP_JOB call with the force flag set to false), and then drops the jobs.
	    dbms_scheduler.drop_job (c.job_name, force => true, commit_semantics =>'ABSORB_ERRORS');
	  exception when others then null;
	  end;
	end loop;
end;
/

exec clearup_test;

Sunday, April 11, 2021

Oracle PLITBLM "library cache: mutex X"

1. Test Setup

2. Library Cache Locks and Pins Test

2.1 Oracle 19c

2.2 Oracle 12c

3. "library cache: mutex X" Test

3.1 Oracle 19c

3.2 Oracle 12c

4. Library Cache Locks and Pins (added in 25-Apr-2021)

4.1. 19c Library Cache Locks and Pins

4.1.1 19c Static Call

4.1.4.1.2 19c Dynamic Call2 19c Dynamic Call

4.2. 12c1 (12.1.0.2.0) Library Cache Locks and Pins

4.2.1 12c1 Static Call

4.2.1 12c1 Dynamic Call

4.3 Test Observations and Discussions

5. 19c Mutex kgxExclusive and kgxRelease from kglLock and kglpin

5.1. 19c kglLock triggered Mutex kgxExclusive and kgxRelease

5.1. 19c kglpin triggered Mutex kgxExclusive and kgxRelease

5.3 Test Observations and Discussions: PLITBLM Execution Limit

6. Full List of Mutex kgxExclusive and kgxRelease

7. Appendix

7.1 gdb_script_kgl_19c

7.2 gdb_script_kgl_12c1

7.3 gdb_script_mutex_19c_body_lock

7.4 gdb_script_mutex_19c_body_pin

7.5 gdb_script_mutex_19c_body_lock_all

7.6 Test Cleanup