On Oracle: April 2021

Sunday, April 11, 2021

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;

Saturday, April 10, 2021

The Third Test of ORA-04025: maximum allowed library object lock

In two previous Blogs of ORA-04025:
ORA-04025 library object lock on AQ queue and SQL cursor
ORA-04025 library object lock on DATABASE Truncate Triggers
we provided tests and revealed the hard limit of 65535 locks per library object, which caused ORA-04025.

In this Blog, we will present one third case of ORA-04025 because of 65535 locks limit, and demonstrate the ORA-04025 Oracle's workaround: "reduce session_cached_cursors value".

At first, we will make test with Oracle provided dbms_lock package, then we construct a standalone test.

Test databases are set up with following relevant parameters:

  _session_cached_instantiations       integer    1001     
  open_cursors                         integer     800     
  session_cached_cursors               integer     600     
  cursor_sharing                       string    EXACT    
  cursor_space_for_time                boolean   FALSE    
  _cursor_obsolete_threshold	       integer    1024     

  (Oracle MOS Note "Error in the Alert Log: ORA-600[kgiLRUResize] (Doc ID 2569458.1)" said:
      alter system set "_session_cached_instantiations"= <open_cursors+1> scope=spfile;)

Note: (a). Tested in Oracle 19c (19.8), 18c (18.12), 12c (12.1).
      (b). dbms_lock test not reproduced in Oracle 18c and 12c.
      (c). standalone test not reproduced in Oracle and 12c.

1. Test Setup

In this Blog, we will take dbms_lock.allocate_unique_autonomous as an example to generate ORA-04025. It is one frequent used procedure to allocate a unique lock identifier (in the range of 1073741824 to 1999999999) for a specified lock name. dbms_lock.allocate_unique_autonomous is using autonomous transaction and was introduced in 12.1. The previous dbms_lock.allocate_unique is changed as a simple wrapper of dbms_lock.allocate_unique_autonomous.

The one-to-one mapping between lockid and lock name is based on table SYS.DBMS_LOCK_ALLOCATED and ensured by its primary key index on name and unique index on lockid.


CREATE TABLE SYS.DBMS_LOCK_ALLOCATED
(
  NAME        VARCHAR2(128 BYTE),
  LOCKID      INTEGER,
  EXPIRATION  DATE
)

ALTER TABLE SYS.DBMS_LOCK_ALLOCATED ADD (
  PRIMARY KEY(NAME) USING INDEX
 ,UNIQUE (LOCKID) USING INDEX)

Given a lock name, dbms_lock.allocate_unique gets the respective lockid by:


  SELECT LOCKID FROM DBMS_LOCK_ALLOCATED WHERE NAME = :B1 FOR UPDATE

and return the mapped lockhandle (up to VARCHAR2 (128)), which is simply a combined form of lockid:


  lockhandle := to_char(lockid)||to_char(lockid)||to_char(lockid mod 239)

In this test, we create one procedure calling dbms_lock.allocate_unique_autonomous to allocate 80 distinct lockhanle, and a dbms_scheduler job dispatcher:


create or replace procedure ora_4025_test_proc as
  l_lockhandle varchar2(100);
  l_ret        number;
  type         tab is table of varchar2(100);
  l_tab_lang   tab;
  l_tab_terr   tab;
begin
  -- simulate session NLS setting
  select value bulk collect into l_tab_lang from v$nls_valid_values where parameter='LANGUAGE';
  select value bulk collect into l_tab_terr from v$nls_valid_values where parameter='TERRITORY';

  for j in 1..least(40, l_tab_lang.count) loop
    dbms_session.set_nls('nls_language', ''''||l_tab_lang(j)||'''');
    --execute immediate q'[alter session set nls_language=']'||l_tab_lang(j)||q'[']';
    for k in 1..least(20, l_tab_terr.count) loop
      dbms_session.set_nls('nls_territory', ''''||l_tab_terr(k)||'''');
      --execute immediate q'[alter session set nls_territory=']'||l_tab_terr(k)||q'[']';
		  dbms_lock.allocate_unique_autonomous('TEST_LOCK_NAME#'||mod(j*k, 80), l_lockhandle, 86400);  
    end loop;
  end loop;
end;
/

create or replace procedure start_ora_4025_test_job(p_count number, p_start_nr number := 0) as
begin
  for i in 1..p_count loop
    dbms_scheduler.create_job (
      job_name        => 'ORA_4025_TEST_JOB_'||(p_start_nr + i),
      job_type        => 'PLSQL_BLOCK',
      job_action      => 'begin ora_4025_test_proc; end;',   
      start_date      => systimestamp,
      repeat_interval => 'systimestamp',
      auto_drop       => true,
      enabled         => true);
  end loop;
end;
/

ora_4025_test_proc calls dbms_lock.allocate_unique_autonomous with different NLS settings with 80 different lock names. (see Blog: One Mutex Collision Test)

2. Test Run

Now we start the test in Oracle 19c DB:


exec start_ora_4025_test_job(300);

After a few minutes, we can see ORA-04025 in DB alert.log and session trace files with different languages:


ORA-12012: erreur d'exécution automatique du travail "K"."ORA_4025_TEST_JOB_837"
ORA-04025: le nombre maximal de verrous d'objet de bibliothèque autorisé a été alloué pour SELECT LOCKID FROM DBMS_LOCK_ALLOCATED WHERE NAME = :B1 FOR UPDATE

ORA-12012: error on auto execute of job "K"."ORA_4025_TEST_JOB_1007"
ORA-04025: maximum allowed library object lock allocated for SELECT LOCKID FROM DBMS_LOCK_ALLOCATED WHERE NAME = :B1 FOR UPDATE

ORA-12012: Fout op automatisch uitvoeren van taak "K"."ORA_4025_TEST_JOB_148".
<error barrier> at 0x7ffed0da8e20 placed jslv.c@1731
ORA-04025: Maximum toegestane bibliotheekobjectvergrendeling toegewezen aan SELECT LOCKID FROM DBMS_LOCK_ALLOCATED WHERE NAME = :B1 FOR UPDATE

(Note: only a few ORA-04025 errors are reported in DB alert.log 
       although there are much more ORA-04025 session trace files, probably due to )

In the above test, we start 300 job sessions to provoke ORA-04025. During the test, we can monitor library cache locks on the mapping statement (hash_value = 1493897133) with following queries. Once max number of locks on the statement is approaching to 65535, some sessions raise ORA_04025.


(Note: the SQL SELECT FOR UPDATE statement has hash_value='1493897133' and sql_id = '19x1189chq3xd'.
       Oracle 18c and 12c behaviour is added as a comment line)
              
select max(locks)
  from v$db_object_cache v
 where name = 'SELECT LOCKID FROM DBMS_LOCK_ALLOCATED WHERE NAME = :B1 FOR UPDATE'
   and hash_value = 1493897133
 order by v.locks desc;
 
MAX(LOCKS)
----------
     65436
  
(Note: in Oracle 18c and 12c, max(locks) is 303, close to the number of job sessions)

select locks, hash_value, name, addr
  from v$db_object_cache v
 where name = 'SELECT LOCKID FROM DBMS_LOCK_ALLOCATED WHERE NAME = :B1 FOR UPDATE'
   and hash_value = 1493897133
 order by v.locks desc;
     
 LOCKS HASH_VALUE NAME                                                                ADDR
------ ---------- ------------------------------------------------------------------- ----------------
 65494 1493897133 SELECT LOCKID FROM DBMS_LOCK_ALLOCATED WHERE NAME = :B1 FOR UPDATE  00000000A17B6BB8
   207 1493897133 SELECT LOCKID FROM DBMS_LOCK_ALLOCATED WHERE NAME = :B1 FOR UPDATE  00000000992A0E38
   206 1493897133 SELECT LOCKID FROM DBMS_LOCK_ALLOCATED WHERE NAME = :B1 FOR UPDATE  0000000099A78AF8
...
     1 1493897133 SELECT LOCKID FROM DBMS_LOCK_ALLOCATED WHERE NAME = :B1 FOR UPDATE  0000000095D6BC88
     1 1493897133 SELECT LOCKID FROM DBMS_LOCK_ALLOCATED WHERE NAME = :B1 FOR UPDATE  00000000968297A0

578 rows selected.

We can also list the details of library OBJECT_HANDLE and the number of locks.


select kglnaobj||'('||kglobtyd||')' name, object_handle, type, mode_held, mode_requested, count(*) cnt
  from v$libcache_locks l, x$kglob o
 where kglnahsh = 1493897133   
   and l.object_handle = o.kglhdadr
 group by object_handle, kglnaobj, kglobtyd, type, mode_held, mode_requested
 order by cnt desc;

NAME                                                                        OBJECT_HANDLE        TYPE  MODE_HELD MODE_REQUESTED        CNT
--------------------------------------------------------------------------- -------------------- ---- ---------- -------------- ----------
SELECT LOCKID FROM DBMS_LOCK_ALLOCATED WHERE NAME = :B1 FOR UPDATE(CURSOR)  00000000A16E8600     LOCK          1              0      65251
SELECT LOCKID FROM DBMS_LOCK_ALLOCATED WHERE NAME = :B1 FOR UPDATE(CURSOR)  0000000095AA7240     LOCK          1              0        204
SELECT LOCKID FROM DBMS_LOCK_ALLOCATED WHERE NAME = :B1 FOR UPDATE(CURSOR)  0000000094A92708     LOCK          1              0        204
...
SELECT LOCKID FROM DBMS_LOCK_ALLOCATED WHERE NAME = :B1 FOR UPDATE(CURSOR)  0000000090715A70     LOCK          1              0          1
SELECT LOCKID FROM DBMS_LOCK_ALLOCATED WHERE NAME = :B1 FOR UPDATE(CURSOR)  0000000094E960D0     LOCK          1              0          1

691 rows selected.

Query below lists the number of locks for each session. It shows that cumulative value (COUNT(*)=65373) for all sessions is approaching 65535. For each single session, SUM(LOCK_CNT) is always under 600, which is probably limited by session_cached_cursors (600), whereas COUNT(*) is almost half of SUM(LOCK_CNT).


with sq1 as
     (select /*+ materialize */ sid, program, saddr, event
            ,to_char(p1, 'xxxxxxxxxxxxxxx') p1, p1text
            ,to_char(p2, 'xxxxxxxxxxxxxxx') p2, p2text
            ,to_char(p3, 'xxxxxxxxxxxxxxx') p3, p3text
        from v$session
       where program like '%(J%')
  ,sq2 as 
     (select s.sid, holding_user_session, object_handle, l.type, refcount, mode_held, mode_requested,
             count(*) lock_cnt    
        from v$libcache_locks l, x$kglob o, sq1 s
       where kglnahsh = 1493897133  
         and l.object_handle = o.kglhdadr
         and l.holding_user_session = s.saddr
       group by s.sid, holding_user_session, object_handle, l.type, refcount, mode_held, mode_requested
       order by s.sid, lock_cnt desc, holding_user_session, l.type, refcount, mode_held, mode_requested)
select sid,  count(*), sum(lock_cnt), min(lock_cnt), max(lock_cnt) from  sq2   
group by rollup(sid)
order by 3 desc;

  SID   COUNT(*) SUM(LOCK_CNT) MIN(LOCK_CNT) MAX(LOCK_CNT)
----- ---------- ------------- ------------- -------------
           65373        130494             1           285
  961        285           569             1           285
  744        285           569             1           285
  738        285           568             1           284
...
  241          7            10             1             4
  759          5             8             1             4

301 rows selected.

Query on v$sqlarea shows that number of EXECUTIONS is almost same as that of PARSE_CALLS, and IS_BIND_SENSITIVE='Y'.


select executions, parse_calls, version_count, loaded_versions, open_versions, users_opening
      ,is_obsolete, is_bind_sensitive, is_bind_aware, sql_text
  from v$sqlarea v 
 where hash_value='1493897133' and sql_id = '19x1189chq3xd';

EXECUTIONS PARSE_CALLS VERSION_COUNT LOADED_VERSIONS OPEN_VERSIONS USERS_OPENING I I I SQL_TEXT
---------- ----------- ------------- --------------- ------------- ------------- - - - --------------------------------------------------------------------------------
    714119      714109           744             744           -25         32729 N Y N SELECT LOCKID FROM DBMS_LOCK_ALLOCATED WHERE NAME = :B1 FOR UPDATE
    
(Note: in Oracle 18c and 12c, EXECUTIONS is always increasing, but PARSE_CALLS remains 303, close to the number of job sessions)

The WAIT_EVENTs are 'cursor: mutex S' or 'cursor: mutex X'. CHAIN_SIGNATURE shows "cursor: mutex S" blocks 'cursor: mutex X'.


select chain_id, chain_signature, sid, blocker_sid, wait_event_text, p1, p2, p3
 from v$wait_chains;

  CHAIN_ID CHAIN_SIGNATURE                        SID BLOCKER_SID WAIT_EVENT_TEXT       P1 P2                P3          
---------- ------------------------------------- ---- ----------- ---------------- ---------- -------------- ------------
         1 'cursor: mutex S'<='cursor: mutex X'    10          62 cursor: mutex X  1493897133 266287972352   120259084288
         1 'cursor: mutex S'<='cursor: mutex X'    62             cursor: mutex S  1493897133 1675037245440  115964116992
         2 'cursor: mutex S'<='cursor: mutex X'   755         224 cursor: mutex X  1493897133 128849018880   120259084288
         2 'cursor: mutex S'<='cursor: mutex X'   224             cursor: mutex S  1493897133 996432412672   115964116992
         3 'cursor: mutex S'<='cursor: mutex X'    11          62 cursor: mutex X  1493897133 42949672960    120259084288
...                                              
        45 'cursor: mutex S'<='cursor: mutex X'   202          62 cursor: mutex X  1493897133 3367254360064  120259084288
        46 'cursor: mutex S'<='cursor: mutex X'   206          62 cursor: mutex X  1493897133 828928688128   120259084288

48 rows selected.

Once ORA_04025 occurs, the number of occurrences for each job session is showed in FAILURE_COUNT of dba_scheduler_jobs:


select job_name, enabled, state, run_count, failure_count
  from dba_scheduler_jobs v 
 where job_name like '%TEST_JOB%'
   and failure_count > 0
  order by failure_count desc;
   
JOB_NAME                  ENABL STATE     RUN_COUNT FAILURE_COUNT
------------------------- ----- -------- ---------- -------------
ORA_4025_TEST_JOB_286     TRUE  RUNNING          20            20
ORA_4025_TEST_JOB_148     TRUE  RUNNING          18            18
ORA_4025_TEST_JOB_43      TRUE  RUNNING          16            16
...
ORA_4025_TEST_JOB_83      TRUE  RUNNING           1             1
ORA_4025_TEST_JOB_194     TRUE  RUNNING           1             1

129 rows selected.

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


exec clearup_test;

Follow Oracle Documentation on ORA-04025:

  Action: Close cursors, reduce session_cached_cursors value.

We reduce session_cached_cursors from 600 to 100, restart DB.


  alter system set session_cached_cursors= 100 scope=spfile;

Launch the same 300 jobs to make one more test:


exec start_ora_4025_test_job(300);

And monitor the behaviour with the same queries.

MAX(LOCKS) is 12003, far below the hard limit: 65535.


select max(locks)
  from v$db_object_cache v
 where name = 'SELECT LOCKID FROM DBMS_LOCK_ALLOCATED WHERE NAME = :B1 FOR UPDATE'
   and hash_value = 1493897133
 order by v.locks desc;
 
MAX(LOCKS)
----------
     12003
     
select locks, hash_value, name, addr
  from v$db_object_cache v
 where name = 'SELECT LOCKID FROM DBMS_LOCK_ALLOCATED WHERE NAME = :B1 FOR UPDATE'
   and hash_value = 1493897133
 order by v.locks desc;
 
     LOCKS HASH_VALUE NAME                                                                             ADDR
---------- ---------- -------------------------------------------------------------------------------- ----------------
     12003 1493897133 SELECT LOCKID FROM DBMS_LOCK_ALLOCATED WHERE NAME = :B1 FOR UPDATE               00000000A173FCE0
       294 1493897133 SELECT LOCKID FROM DBMS_LOCK_ALLOCATED WHERE NAME = :B1 FOR UPDATE               000000009561AF88
       294 1493897133 SELECT LOCKID FROM DBMS_LOCK_ALLOCATED WHERE NAME = :B1 FOR UPDATE               000000009560CA60
       294 1493897133 SELECT LOCKID FROM DBMS_LOCK_ALLOCATED WHERE NAME = :B1 FOR UPDATE               00000000955D55C0
...
         0 1493897133 SELECT LOCKID FROM DBMS_LOCK_ALLOCATED WHERE NAME = :B1 FOR UPDATE               0000000094FE9718
         0 1493897133 SELECT LOCKID FROM DBMS_LOCK_ALLOCATED WHERE NAME = :B1 FOR UPDATE               0000000094FE1EC8

713 rows selected.

Query below lists the number of locks for each session. It shows that cumulative value (COUNT(*)=12241) for all sessions is much less than 65535. For each single session, SUM(LOCK_CNT) is always under 100, which is probably limited by session_cached_cursors (100), whereas COUNT(*) is almost half of SUM(LOCK_CNT).


with sq1 as
     (select /*+ materialize */ sid, program, saddr, event
            ,to_char(p1, 'xxxxxxxxxxxxxxx') p1, p1text
            ,to_char(p2, 'xxxxxxxxxxxxxxx') p2, p2text
            ,to_char(p3, 'xxxxxxxxxxxxxxx') p3, p3text
        from v$session
       where program like '%(J%')
  ,sq2 as 
     (select s.sid, holding_user_session, object_handle, l.type, refcount, mode_held, mode_requested,
             count(*) lock_cnt     -- it goes up to maximum 1003, and then back 1002
        from v$libcache_locks l, x$kglob o, sq1 s
       where kglnahsh = 1493897133  
         and l.object_handle = o.kglhdadr
         and l.holding_user_session = s.saddr
       group by s.sid, holding_user_session, object_handle, l.type, refcount, mode_held, mode_requested
       order by s.sid, lock_cnt desc, holding_user_session, l.type, refcount, mode_held, mode_requested)
select sid,  count(*), sum(lock_cnt), min(lock_cnt), max(lock_cnt) from  sq2   
group by rollup(sid)
order by 3 desc;

       SID   COUNT(*) SUM(LOCK_CNT) MIN(LOCK_CNT) MAX(LOCK_CNT)
---------- ---------- ------------- ------------- -------------
                12241         23975             1            41
       592         41            81             1            41
       762         41            81             1            41
        13         40            80             1            40
...
       955         40            79             1            40
        24         40            79             1            40

Now there is no more ORA-04025 when session_cached_cursors is reduced from 600 to 100. Therefore, when setting session_cached_cursors=100, we can avoid ORA-04025 for 300 job sessions.

By above tests, we can see that SUM(LOCK_CNT) is close to session_cached_cursors, whereas COUNT(*) is about half of SUM(LOCK_CNT) for each session.

  Approximately, MAX(LOCKS) = #sessions * COUNT(*).

When MAX(LOCKS) is close to hard limit 65535, ORA-04025 occurs. Therefore, we can roughly conclude that there are no ORA-04025 errors if:

  #sessions < 65535/(session_cached_cursors/2)

So when setting session_cached_cursors=100, 2000 sessions can still hit ORA-04025 since (2000*50 > 65535).
(Note: from Oracle 12cR2, JOB_QUEUE_PROCESSES max value is increased to 4000 from 1000)

After the test, we stop all jobs by (see appended code), set back session_cached_cursors to 600 and restart DB:


exec clearup_test;  

alter system set session_cached_cursors= 600 scope=spfile;

startup force;

3. Standalone Test

In order to further understand the problem, we can try to construct a standalone test. We will make the tests in Oracle 19, 18 and 12, once in SYS schema, once in application schema: APP, and check the behaviour differences.


create or replace procedure try_4025_allocate_unique(p_lockname in varchar2) as
  l_lockid   integer;
begin
  -- hash_value: 2526571634 for the sql_text in v$db_object_cache and v$sqlarea
  -- sql_text:   SELECT LOCKID FROM SYS.DBMS_LOCK_ALLOCATED WHERE NAME = :B1  
  select lockid into l_lockid from sys.dbms_lock_allocated where name = p_lockname;
end;
/

create or replace procedure try_4025_test_proc as
  type         tab is table of varchar2(100);
  l_tab_lang   tab;
  l_tab_terr   tab;
begin
  -- simulate session NLS setting
  select value bulk collect into l_tab_lang from v$nls_valid_values where parameter='LANGUAGE';
  select value bulk collect into l_tab_terr from v$nls_valid_values where parameter='TERRITORY';

  for j in 1..least(20, l_tab_lang.count) loop
    dbms_session.set_nls('nls_language', ''''||l_tab_lang(j)||'''');
    for k in 1..least(40, l_tab_terr.count) loop
      dbms_session.set_nls('nls_territory', ''''||l_tab_terr(k)||'''');
      try_4025_allocate_unique('TEST_LOCK_NAME#'||mod(j*k, 80));
    end loop;
  end loop;
end;
/

create or replace procedure try_4025_test_job(p_count number, p_start_nr number := 0) as
	l_current_schema varchar2(100);
begin
  l_current_schema := sys_context( 'userenv', 'current_schema' );
  for i in 1..p_count loop
    dbms_scheduler.create_job (
      job_name        => l_current_schema||'#'||'TRY_4025_TEST_JOB_'||(p_start_nr + i),
      job_type        => 'PLSQL_BLOCK',
      job_action      => 'begin try_4025_test_proc; end;',
      start_date      => systimestamp,
      repeat_interval => 'systimestamp',
      auto_drop       => true,
      enabled         => true);
  end loop;
end;
/

At first, we deploy it to SYS schema, and fill (or refresh if already exist) data into sys.dbms_lock_allocated with:


declare
  l_lockhandle varchar2(100);
begin
  for i in 1..80 loop
    dbms_lock.allocate_unique_autonomous('TEST_LOCK_NAME#'||mod(i, 80), l_lockhandle, 86400); 
  end loop;
end;
/

Then launch 300 job sessions in SYS schema:


------------  SYS schema ------ ------ 
exec try_4025_test_job(300, 0);

After a few minutes, in Oracle 19 and 18, we can see ORA-04025 in DB alert.log and session trace files with different languages.

Here a list of queries we can use to observe ORA-04025 and library cache lock. For each query, we add a comment about the different behaviour in SYS schema vs. APP schema from Oracle 19, 18 and 12.

The query output is from Oracle 19 and 18 in SYS schema.


-- In SYS schema: max(locks) close to 65536. Observed in Oracle 19 and 18, not 12
-- In APP schema: max(locks) close to 303 in Oracle 19 and 18, and 12
select max(locks)
  from v$db_object_cache v
 where hash_value = 2526571634;
 
-- Output of Oracle 19 and 18 in SYS schema

MAX(LOCKS)
----------
     65535


-- In SYS schema: executions and parse_calls are almost equal. Observed in Oracle 19 and 18, not 12
-- In APP schema: executions increasing, parse_calls remains same in Oracle 19 and 18, and 12
select sql_id, hash_value, executions, parse_calls, version_count, loaded_versions, open_versions, users_opening
      ,is_obsolete, is_bind_sensitive, is_bind_aware
      ,v.* 
 from v$sqlarea v 
where hash_value = 2526571634 and sql_id in ('2r99nzub9hv3k');


-- Output of Oracle 19 and 18 in SYS schema

SQL_ID        HASH_VALUE EXECUTIONS PARSE_CALLS VERSION_COUNT LOADED_VERSIONS OPEN_VERSIONS USERS_OPENING I I I SQL_TEXT
------------- ---------- ---------- ----------- ------------- --------------- ------------- ------------- - - - ------------------------------------------------------------
2r99nzub9hv3k 2526571634    2691495     2341897           800             800           -86         23223 N Y N SELECT LOCKID FROM SYS.DBMS_LOCK_ALLOCATED WHERE NAME = :B1


-- In SYS schema: count(*) is close to parameter session_cached_cursors for each session (600 in our test). Observed in Oracle 19 and 18, not 12
-- In APP schema: count(*) is around 2 in Oracle 19 and 18, and 12
with sq1 as
  (select /*+ materialize */ j.owner||'.'||job_name job_name, sid, program, saddr, event
    from v$session s, dba_scheduler_running_jobs j where s.sid=j.session_id)
 ,sq2 as 
  (select s.job_name, s.sid, holding_user_session, object_handle, l.type, refcount, mode_held, mode_requested, count(*) lock_cnt     
      from v$libcache_locks l, x$kglob o, sq1 s
     where kglnahsh = 2526571634 
       and l.object_handle = o.kglhdadr
       and l.holding_user_session = s.saddr
    group by s.job_name, s.sid, holding_user_session, object_handle, l.type, refcount, mode_held, mode_requested)
select job_name||'#SID_'||sid session_source, count(*), sum(lock_cnt), min(lock_cnt), max(lock_cnt) 
  from sq2   
 group by rollup(job_name||'#SID_'||sid)
 order by 3 desc;


-- Output of Oracle 19 and 18 in SYS schema

SESSION_SOURCE                             COUNT(*) SUM(LOCK_CNT) MIN(LOCK_CNT) MAX(LOCK_CNT)
---------------------------------------- ---------- ------------- ------------- -------------
                                              62902        124703             1           550
SYS.SYS#TRY_4025_TEST_JOB_276#SID_223           546          1095             1           550
SYS.SYS#TRY_4025_TEST_JOB_291#SID_570           544          1094             1           550
SYS.SYS#TRY_4025_TEST_JOB_21#SID_602            545          1094             1           550
...
SYS.SYS#TRY_4025_TEST_JOB_225#SID_16            114           179             1            66
SYS.SYS#TRY_4025_TEST_JOB_162#SID_960            60           148             1            88

301 rows selected.


-- In SYS schema: failure_count is non zero (the number of ORA-04025 per job session). Observed in Oracle 19 and 18, not 12
-- In APP schema: failure_count is zero in Oracle 19 and 18, and 12
select owner, job_creator, job_name, enabled, state, run_count, failure_count, retry_count, start_date, last_start_date, next_run_date
  from dba_scheduler_jobs v 
 where job_name like '%TEST_JOB%' 
 order by failure_count desc;
 

-- Output of Oracle 19 and 18 in SYS schema

OWNE JOB_ JOB_NAME                       ENABL STATE     RUN_COUNT FAILURE_COUNT RETRY_COUNT START_DATE   LAST_START_D NEXT_RUN_DAT
---- ---- ------------------------------ ----- -------- ---------- ------------- ----------- ------------ ------------ ------------
SYS  SYS  SYS#TRY_4025_TEST_JOB_72       TRUE  RUNNING          65            65           0 06:16:08     06:31:48     06:31:34
SYS  SYS  SYS#TRY_4025_TEST_JOB_197      TRUE  RUNNING          61            61           0 06:16:08     06:31:34     06:31:27
SYS  SYS  SYS#TRY_4025_TEST_JOB_80       TRUE  RUNNING          59            59           0 06:16:08     06:31:34     06:31:12
...
SYS  SYS  SYS#TRY_4025_TEST_JOB_280      TRUE  RUNNING          34            34           0 06:16:09     06:31:34     06:31:27
SYS  SYS  SYS#TRY_4025_TEST_JOB_158      TRUE  RUNNING          35            34           0 06:16:08     06:31:48     06:31:34

300 rows selected.

In SYS schema, ORA-04025 can be reproduced for Oracle 19 and 18, but not Oracle 12.

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


exec clearup_test;

However, if we deploy the same code to an APP schema, and launch 300 job sessions, there are much less library cache locks, and hence no ORA-04025 errors.

For Oracle 18c, it is not clear why Standalone Test can generate ORA-04025 in SYS schema, but the test of sys.dbms_lock.allocate_unique_autonomous in Section 1 cannot generate ORA-04025.

4. 'enq: UL - contention' Test

As an additional test of dbms_lock, we can try to use our created lockhandle in calling dbms_lock.request / dbms_lock.release and generate heavy wait event: 'enq: UL - contention'.

Here the modified ora_4025_test_proc to allocate lockhandle, request UL lock, then release it after a short sleep (simulating application logic).


create or replace procedure ora_4025_test_proc as
  l_lockhandle varchar2(100);
  l_ret        number;
  type         tab is table of varchar2(100);
  l_tab_lang   tab;
  l_tab_terr   tab;
begin
  -- simulate session NLS (BU) setting
  select value bulk collect into l_tab_lang from v$nls_valid_values where parameter='LANGUAGE';
  select value bulk collect into l_tab_terr from v$nls_valid_values where parameter='TERRITORY';

  for j in 1..least(40, l_tab_lang.count) loop
    dbms_session.set_nls('nls_language', ''''||l_tab_lang(j)||'''');
    for k in 1..least(20, l_tab_terr.count) loop
      dbms_session.set_nls('nls_territory', ''''||l_tab_terr(k)||'''');
		  for i in 1..100 loop
				dbms_lock.allocate_unique_autonomous('TEST_LOCK_NAME#'||mod(j*k, 80), l_lockhandle, 86400);
				l_ret := dbms_lock.request(l_lockhandle);
				dbms_session.sleep(dbms_random.value(1,10)/100);
				l_ret := dbms_lock.release(l_lockhandle);
		  end loop;
    end loop;
  end loop;
end;
/

Launch 4 jobs:


exec start_ora_4025_test_job(4);

Queries below show the wait event: 'enq: UL - contention':


select chain_id, chain_signature, sid, blocker_sid, wait_event_text, p1, p2, p3
 from v$wait_chains v;
 
  CHAIN_ID CHAIN_SIGNATURE                                SID BLOCKER_SID WAIT_EVENT_TEXT              P1         P2         P3
---------- --------------------------------------------- ---- ----------- -------------------- ---------- ---------- ----------
         1 'PL/SQL lock timer'<='enq: UL - contention'    907         592 enq: UL - contention 1431044102 1073780706          0
         1 'PL/SQL lock timer'<='enq: UL - contention'    592             PL/SQL lock timer             0          0          0
         2 'PL/SQL lock timer'<='enq: UL - contention'    413         592 enq: UL - contention 1431044102 1073780706          0
         3 'PL/SQL lock timer'<='enq: UL - contention'    770         592 enq: UL - contention 1431044102 1073780706          0
         

select name, parameter1, parameter2, parameter3 from v$event_name where name = 'enq: UL - contention';

   NAME                  PARAMETER1     PARAMETER2     PARAMETER3
  --------------------- -------------- -------------- ----------
  enq: UL - contention  name|mode      id             0

select * from sys.dbms_lock_allocated where lockid = 1073780706;

  NAME                     LOCKID EXPIRATION
  -------------------- ---------- --------------------
  TEST_LOCK_NAME#3     1073780706 2021-APR-04 11:51:50


--  P1=1431044102=0x554c0006=UL 6 (exclusive)
--  P2=1073780706(LOCKID)=TEST_LOCK_NAME#3(NAME)

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


exec clearup_test;

5. Appendix: 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;