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;