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
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.
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
(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.
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
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;
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
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");
}
}
