Tuesday, August 2, 2016

ORA-04025 library object lock on AQ queue and SQL cursor

AQ dequeue throws:
     ORA-04025: maximum allowed library object lock allocated for S.KSUN_QUEUE
in an Oracle 12c batch application when number of concurrent jobs greater than 65, where KSUN_QUEUE is the queue name, and DB is set up with following relevant parameters:
  _session_cached_instantiations       integer     1001
  cursor_sharing                       string      exact
  cursor_space_for_time                boolean     FALSE
  open_cursors                         integer     800
  session_cached_cursors               integer     600


Adhere to Oracle Documentation on ORA-04025:
  Cause:  Too many active locks for the object has been allocated.
               This error can be a result of too many cursors kept open per session.
  Action: Close cursors, reduce session_cached_cursors value.

Halving session_cached_cursors from 600 to 300 does not make the error disappear.

This Blog will try to demonstrate:
(a). there probably exists a hard limit of 65535 locks per library object:
             LIBRARY OBJECT LOCK: MAXIMUM 65535
       internally it could be implemented by a 16-bits u16.
(b). locks per Oracle session is imposed by
             _session_cached_instantiations
(c). maximum number of concurrent sessions to avoid ORA-04025 is
             floor(65535/_session_cached_instantiations)
      It is 65 for above settings.

Tests done on Solaris and AIX with Oracle 12.1.0.2.0.
See Blog appended Test Code.
Note: to make the test reproducible, before each test, restart DB to remove any un-released locks.

Update: By using the test code provided in this Blog, the Bug was investigated and fixed in Sep 2016 by:
    Patch 24509056: NUMBER OF LIBRARY OBJECT LOCKS OF QUEUE INCREASED AFTER EACH DEQUEUE IN 12.1.0.2

1. Library object lock on AQ queue


1.1 Single session dequeue/enqueue test:


SQL> exec test_deq(1200, 0, 0, true);
 deq_cnt: 1, lock_cnt: 1
 deq_cnt: 2, lock_cnt: 2
 deq_cnt: 3, lock_cnt: 3
 ...
 deq_cnt: 1000, lock_cnt: 1000
 deq_cnt: 1001, lock_cnt: 1001
 deq_cnt: 1002, lock_cnt: 1002
 deq_cnt: 1003, lock_cnt: 1002
 ...
 deq_cnt: 1199, lock_cnt: 1002
 deq_cnt: 1200, lock_cnt: 1002

It shows that number of locks on the queue object is increased for each dequeue call till 1002,
and then maintained at 1002.

Open a new session, make a similar enqueue test.

  SQL> exec test_enq(1200, 0, true);

The lock behavior is similar to dequeue. Therefore all the discussion on dequeue applies to enqueue as well.

1.2   66 Batch sessions dequeue test


In this test, we will start 66 dequeue sessions to provoke ORA-04025. All 3 monitoring queries can be run during whole tests to watch the progress of locks. Once total number of locks on KSUN_QUEUE is approaching to 65535, some sessions raise ORA_04025.

(A). Launch 66 concurrent Jobs by:


  SQL> exec test_deq_jobs(66, 2000);  

After about 18 minutes (1003 times of one-second dequeue wait), we will see some trace files like:

 ORA-12012: error on auto execute of job 86367
 ORA-04025: maximum allowed library object lock allocated for S.KSUN_QUEUE
 ORA-06512: at "S.TEST_DEQ", line 40
 ORA-06512: at line 1

(B). Watch total number of locks on KSUN_QUEUE:


SQL> select name, locks, pins, locked_total, pinned_total
       from v$db_object_cache l
      where hash_value = 3868150627 or name = 'KSUN_QUEUE';

 NAME         LOCKS  PINS LOCKED_TOTAL PINNED_TOTAL
 ----------- ------ ----- ------------ ------------
 KSUN_QUEUE   65106     0       321935       428400

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

 NAME               OBJECT_HANDLE    TYPE  MODE_HELD MODE_REQUESTED    CNT
 ------------------ ---------------- ---- ---------- -------------- ------
 KSUN_QUEUE(QUEUE)  0000000167A4B2E0 LOCK          1              0  65224

(C). Watch number of locks per session on KSUN_QUEUE:


SQL> with sq 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%' or module like '%deq%')
     select s.sid, holding_user_session, object_handle, l.type, 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, sq s
      where o.kglnaobj = 'KSUN_QUEUE'
        and l.object_handle = o.kglhdadr
        and l.holding_user_session = s.saddr
     group by s.sid, holding_user_session, object_handle, l.type, mode_held, mode_requested
     order by lock_cnt desc, s.sid, holding_user_session, l.type, mode_held, mode_requested;

   SID HOLDING_USER_SES OBJECT_HANDLE    TYPE  MODE_HELD MODE_REQUESTED   LOCK_CNT
 ----- ---------------- ---------------- ---- ---------- -------------- ----------
     6 000000018FA49D60 0000000167A4B2E0 LOCK          1              0       1003
    70 000000018FA93AA0 0000000167A4B2E0 LOCK          1              0       1003
 ...
  1058 000000018FE84A60 0000000167A4B2E0 LOCK          1              0       1002
  1059 000000018D19A168 0000000167A4B2E0 LOCK          1              0       1002
   173 000000018ED35840 0000000167A4B2E0 LOCK          1              0        739
  1025 000000018D177398 0000000167A4B2E0 LOCK          1              0        739        

66 rows selected.        

Examining maximum number of locks per session, they oscillate between 1002 and 1003.

There exist sessions whose LOCK_CNT is not able to reach 1002 because
    66 x 1002 > 65535
hence ORA-04025.

(D). Match Oracle parameters with value like '100%':


To figure out what is the limit of 1003, run:

SQL> select name, value from v$parameter where value like '100%';

 NAME                             VALUE
 -------------------------------- -----
 _session_cached_instantiations   1001

That is _session_cached_instantiations.

(E). Finally clean-up all jobs

  SQL> exec clean_jobs;

1.3   65 Batch sessions dequeue test


Repeat the same test by launching 65 concurrent Jobs. No ORA-04025 occurs.

  SQL> exec test_deq_jobs(65, 2000);

Wait about 18 minutes, run above 3 monitoring queries.
Here the output:

SQL> query_1

 NAME         LOCKS  PINS LOCKED_TOTAL PINNED_TOTAL
 ----------- ------ ----- ------------ ------------
 KSUN_QUEUE   65130     0      2493796      3324170

SQL> query_2

 NAME               OBJECT_HANDLE    TYPE  MODE_HELD MODE_REQUESTED    CNT
 ------------------ ---------------- ---- ---------- -------------- ------
 KSUN_QUEUE(QUEUE)  0000000167A4B2E0 LOCK          1              0  65130
 
SQL> query_3
 
   SID HOLDING_USER_SES OBJECT_HANDLE    TYPE  MODE_HELD MODE_REQUESTED   LOCK_CNT
 ----- ---------------- ---------------- ---- ---------- -------------- ----------
     6 000000018FA49D60 0000000167A4B2E0 LOCK          1              0       1003
    40 000000018FA6CB30 0000000167A4B2E0 LOCK          1              0       1003
 ...   
  1027 000000018D1752C8 0000000167A4B2E0 LOCK          1              0       1002
  1058 000000018FE84A60 0000000167A4B2E0 LOCK          1              0       1002

65 rows selected.        

All sessions can own a minimum LOCK_CNT of 1002 because
    65 x 1002 < 65535
hence no ORA-04025.

To terminate the test, clean-up all jobs

  SQL> exec clean_jobs;

1.4 _session_cached_instantiations


Lowering _session_cached_instantiations from 1001 to 401, restart DB:
   alter system set "_session_cached_instantiations"=401 scope=spfile;
repeat the test, no more error even for 100 Jobs; but error reappears with 200 Jobs.

Since not clear what is the limit of "_session_cached_instantiations", it is worth of gambling its extreme behavior with two additional tests, one with 65535, another with 65536.

alter system set "_session_cached_instantiations"=65535 scope=spfile;

restart DB

SQL> exec test_deq(65536, 0, 0);

 deq_cnt: 65536, lock_cnt: 65535
 ORA-04025: maximum allowed library object lock allocated for S.KSUN_QUEUE

Then make some unrealistic adventure:

alter system set "_session_cached_instantiations"=65536 scope=spfile;

restart DB

SQL> exec test_deq(65536, 0, 0);

 deq_cnt: 65536, lock_cnt: 65535
 ORA-04025: maximum allowed library object lock allocated for K.KSUN_QUEUE


Both identical outputs show that sessions raise ORA-04025 at limit 65535. "_session_cached_instantiations" has to be less than 65535.

1.5   12c vs. 11g dequeue behavior


Running the same tests in 11.2.0.4.0, number of locks per session on KSUN_QUEUE is constantly kept as 1. Hence, 12c dequeue behavior is perturbed, in which each dequeue call opens a new lock on the queue, but never release it till ceiling _session_cached_instantiations. One can wonder if that can be classified as a library object lock leak.

Oracle Database Advanced Queuing 12c seems introduced some new AQ background architecture, for example, AQPC (GV$AQ_BACKGROUND_COORDINATOR).

1.6 MOS Note


Resorting to MOS, there is one hit of 65535 hinting to ORA-4025.

MOS Bug 14542720 - ORA-4025 with CURSOR_SHARING / Dynamic Sampling (Doc ID 14542720.8) said:
  Look for the ActiveLocks value of some cursor to show very high values  (when it reaches 65535 the ora-4025 is raised)

2. SQL cursor and ORA-04025


As a general understanding of ORA-04025, it is necessary to examine its original designation for SQL Cursors. Pick the JAVA test code provided by Oracle MOS, we will make 3 tests.

Note: the same Java code is tested on both 11.2.0.4.0 and 12.1.0.2.0, the behaviors are identical.

At first, set open_cursors:
  alter system set open_cursors=50000 scope=both;

2.1 Single session


Start one single session, monitor by:

SQL> select sid, sql_id, sql_text, count(*) cnt
       from v$open_cursor
      where cursor_type in ('OPEN')
      group by sid, sql_id, sql_text
      order by cnt desc;

when opened cursors reaching 50000, it hits:
 ORA-01000: maximum open cursors exceeded
    
$1 > java OracleJdbcExample4025
 Count=49998, Date : 2016-07-21 10:50:17
 Count=49999, Date : 2016-07-21 10:50:17
 Exception in thread "main" java.sql.SQLException: ORA-01000: maximum open cursors exceeded


2.2 Two concurrent sessions


Start two sessions, both throw ORA-04025:

$1 > java OracleJdbcExample4025

 Count=25115, Date : 2016-07-21 11:46:45.0
 Count=25116, Date : 2016-07-21 11:46:45.0
 Exception in thread "main" java.sql.SQLException: 
  ORA-04025: maximum allowed library object lock allocated for select sysdate as current_day from dual

$2 > java OracleJdbcExample4025

 Count=40418, Date : 2016-07-21 11:46:45.0
 Count=40419, Date : 2016-07-21 11:46:45.0
 Exception in thread "main" java.sql.SQLException: 
  ORA-04025: maximum allowed library object lock allocated for select sysdate as current_day from dual

Summing two outputs agrees the equality:
   25116 + 40419 = 65535
which confirms "LIBRARY OBJECT LOCK: MAXIMUM 65535".

2.3 Boundary value


According to Oracle Documentation, open_cursors has a legal range of values:
    0 to 65535
what happens when setting open_cursors=65535 ?
Both ORA-01000 and ORA-04025 are satisfied by boundary value 65535, which one is raised at first ? (second will never be presented).

Here the test output:

alter system set open_cursors=65535 scope=both;

$1 > java OracleJdbcExample4025

  Count=65533, Date : 2016-07-22 08:01:49.0
  Count=65534, Date : 2016-07-22 08:01:49.0
  Exception in thread "main" java.sql.SQLException: ORA-01000: maximum open cursors exceeded


So we can guess that ORA-04025 is ordered after ORA-01000 in the code path. That is also why to provoke ORA-04025 for SQL cursor, minimum two sessions are required.

Summary


Recapping all the tests, we can draw a few possible observations, but I would be careful to have any earlier conclusions before Oracle says.

1. SQL cursor is a library object, but not each library object is a SQL cursor, for example, AQ queue.

2. OPEN_CURSORS specifies the maximum number of open cursors per session can have at each instant. HARD Limit.

3. SESSION_CACHED_CURSORS specifies the number of cursors to cache per session, an optimization advice. SOFT Limit.

4. OPEN_CURSORS, SESSION_CACHED_CURSORS are parameters applied to SQL cursor.

5. "LIBRARY OBJECT LOCK: MAXIMUM 65535" specifies limit per library object. HARD Limit.

6. 12c _SESSION_CACHED_INSTANTIATIONS specifies number of library object lock on AQ queue per session.
    HARD Limit, but not raising error.

7. "LIBRARY OBJECT LOCK: MAXIMUM 65535" and _SESSION_CACHED_INSTANTIATIONS together defines
     maximum number of concurrent sessions to avoid ORA-04025:
            floor(65535/_session_cached_instantiations)

References


1. open_cursors, session_cached_cursors: cursordump

2. Oracle 12c single session "library cache lock (cycle)" deadlock

3. Foreign Keys and Library Cache Locks: Analysis

Test Code



------------------------------------- AQ dequeue ---------------------------------
--alter system set "_session_cached_instantiations"=1001 scope=spfile;
--alter system set open_cursors=800 scope=both;
--alter system set session_cached_cursors=600 scope=spfile;

drop type Q_OBJ force;

create or replace type Q_OBJ is object (id number, name varchar2(100));
/       

begin sys.dbms_aqadm.drop_queue_table(queue_table => 'Q_TAB', force=> TRUE); end;
/

begin
  sys.dbms_aqadm.create_queue_table
  (queue_table        => 'Q_TAB'
  ,queue_payload_type => 'Q_OBJ'
  ,compatible         => '10.0.0'  
  ,sort_list          => 'PRIORITY,ENQ_TIME'
  ,multiple_consumers =>  false
  ,message_grouping   =>  0
  ,comment            =>  'queue table'
  ,secure             =>  false);
end;
/

begin
  sys.dbms_aqadm.stop_queue (queue_name => 'KSUN_QUEUE');
  sys.dbms_aqadm.drop_queue (queue_name => 'KSUN_QUEUE');
end;
/

begin
  sys.dbms_aqadm.create_queue
  (queue_name     => 'KSUN_QUEUE'
  ,queue_table    => 'Q_TAB'
  ,queue_type     => sys.dbms_aqadm.normal_queue
  ,max_retries    => 100
  ,retry_delay    => 2
  ,retention_time => 604800
  ,comment        => 'ksun queue');
end;
/

begin sys.dbms_aqadm.start_queue(queue_name => 'KSUN_QUEUE', enqueue => true, dequeue => true); end;
/
  
create or replace procedure test_enq(p_cnt number := 1, p_sleep number := 0, p_prt boolean :=false) as
  l_enqueue_options dbms_aq.enqueue_options_t;
  l_msg_properties  dbms_aq.message_properties_t;
  l_msg_handle      raw(16);
  l_msg             q_obj;
  l_lock_cnt        number;
  
  procedure prt(i_cnt number, i_prt boolean) as
   begin
    if i_prt then
     select locks into l_lock_cnt from v$db_object_cache where name = 'KSUN_QUEUE';
     dbms_output.put_line ('deq_cnt: '||i_cnt||', lock_cnt: '||l_lock_cnt);
   end if;
   end;
begin 
 dbms_application_info.set_module(module_name => 'enq session', action_name => 'enqueue');
  for i in 1..p_cnt loop
    l_msg := q_obj(i, rpad(i, 10, 'X'));
            
    dbms_aq.enqueue(queue_name         => 'KSUN_QUEUE',
                    enqueue_options    => l_enqueue_options,
                    message_properties => l_msg_properties,
                    payload            => l_msg,
                    msgid              => l_msg_handle);
    prt(i, p_prt);
    
    commit;
    
    if p_sleep > 0 then
      dbms_lock.sleep(p_sleep);
    end if;
  end loop;
end;
/

create or replace procedure test_deq(p_cnt number := 1, p_sleep number := 0, p_wait number := 1, 
                                     p_prt boolean :=false) as
 l_dequeue_options     dbms_aq.dequeue_options_t;
 l_msg_properties      dbms_aq.message_properties_t;
 l_msg_handle          raw(16);
 l_msg                 q_obj;
 l_lock_cnt            number;
 no_messages_excp      exception;
 pragma exception_init (no_messages_excp, -25228);
  
  procedure prt(i_cnt number, i_prt boolean) as
   begin
    if i_prt then
     select locks into l_lock_cnt from v$db_object_cache where name = 'KSUN_QUEUE';
     dbms_output.put_line ('deq_cnt: '||i_cnt||', lock_cnt: '||l_lock_cnt);
   end if;
   end;
begin
 dbms_application_info.set_module(module_name => 'deq session', action_name => 'dequeue');
 l_dequeue_options.wait := p_wait;
  for i in 1..p_cnt loop
  begin 
   if p_sleep > 0 then
    dbms_lock.sleep(p_sleep);
   end if;
   
    dbms_aq.dequeue(queue_name            => 'KSUN_QUEUE',
                    dequeue_options       => l_dequeue_options,
                    message_properties    => l_msg_properties,
                    payload               => l_msg,
                    msgid                 => l_msg_handle);
          
    dbms_output.put_line ('MSG id: '||l_msg.id||', name: '||l_msg.name);
    
    prt(i, p_prt);
    
    commit;
      exception when no_messages_excp then prt(i, p_prt);
         when others then prt(i, true); 
                  raise;  
   end;
 end loop;
end;
/    

create or replace procedure test_deq_jobs (p_jobs number := 66, p_cnt number := 2000) as
 l_job_id pls_integer;
begin
  for i in 1..p_jobs loop
  dbms_job.submit(l_job_id, 'begin while true loop test_deq('||p_cnt||'); end loop; end;');
  commit;
  dbms_output.put_line(l_job_id);
 end loop;
end;
/        

create or replace procedure clean_jobs as
  begin
   for c in (select job from dba_jobs) loop
      begin
         dbms_job.remove (c.job);
      exception when others then null;
      end;
      commit;
   end loop;

   for c in (select d.job, d.sid, (select serial# from v$session where sid = d.sid) ser 
               from dba_jobs_running d) loop
      begin
         execute immediate
               'alter system kill session '''|| c.sid|| ',' || c.ser|| ''' immediate';
         dbms_job.remove (c.job);
      exception when others then null;
      end;
      commit;
   end loop;
   
   -- select * from dba_jobs;
   -- select * from dba_jobs_running;
end;
/

------------------------------------- SQL curosr and ORA-04025 Test ---------------------------------

import java.sql.Connection; 
import java.sql.DriverManager; 
import java.sql.PreparedStatement; 
import java.sql.ResultSet; 
import java.sql.SQLException;

public class OracleJdbcExample4025 { 

public static void main(String args[]) throws SQLException { 
 System.out.println("--------SQL curosr and ORA-04025 Test ------");
 try {
  Class.forName("oracle.jdbc.driver.OracleDriver");
 } catch (ClassNotFoundException e) {
  System.out.println("Where is your Oracle JDBC Driver?");
  e.printStackTrace();
  return;
 }
 System.out.println("Oracle JDBC Driver Registered!");
 Connection connection = null;
 try {
  connection = DriverManager.getConnection(
    "jdbc:oracle:thin:@testdb:1522:testdb", "s", "s");  // adapt it
 } catch (SQLException e) {
  System.out.println("Connection Failed! Check output console");
  e.printStackTrace();
  return;
 }    
 String sql ="select sysdate as current_day from dual"; 
 int cnt = 0;
 while (true) { 
  //creating PreparedStatement object to execute query 
  PreparedStatement preStatement = connection.prepareStatement(sql); //<<< this opening cursor 
  ResultSet result = preStatement.executeQuery(); 
  while(result.next()){ 
   System.out.println("Count=" + (++cnt) + ", Date : " + result.getString("current_day")); 
  } 
 // preStatement.close();  //<<< if this is uncommented cursor is closed, otherwise not. 
 } 
 // System.out.println("done"); 
 } 
}