In this Blog, we will look three wait events in using dbms_alert:
-. pipe get
-. enq: UL - contention
-. enq: TX - row lock contention
Note: Tested in Oracle 19c
1. Receiver and Sender Lock Mode
dbms_alert receiver (waitany/waitone) requests SX_Mode, whereas Sender (signal) requests S_Mode.
Refer to Compatibility Rules defined in dbms_lock:
Lock Compatibility Rules:
held get-> NL SS SX S SSX X
NL SUCC SUCC SUCC SUCC SUCC SUCC
SS SUCC SUCC SUCC SUCC SUCC fail
SX SUCC SUCC SUCC fail fail fail
S SUCC SUCC fail SUCC fail fail
SSX SUCC SUCC fail fail fail fail
X SUCC fail fail fail fail fail
(Look middle diagonal, except pair (SX, S)=fail, (S, SX)=fail and (S, S)=SUCC, all in diagonal and above it are "SUCC", all under it are "fail").
To test above Compatibility Rules, we can open two Sqlplus sessions, then run one of following blocks in one of them (there are 4 combinations).
-- Receiver (procedure waitany) session
declare
register_name varchar2(30) := 'TEST_ALERT_1';
lockid integer;
lock_status integer;
begin
lockid := dbms_utility.get_hash_value(register_name, 2000000000, 2048);
lock_status := dbms_lock.request(lockid, dbms_lock.x_mode, dbms_lock.maxwait, release_on_commit => true);
insert into dbms_alert_info values (register_name, receiver_session_id, 'N', null);
commit;
end;
/
-- Sender (procedure signal) session
declare
lockid integer := dbms_utility.get_hash_value('TEST_ALERT_1', 2000002048, 2048);
lock_status integer;
begin
lock_status := dbms_lock.request(lockid, dbms_lock.s_mode, dbms_lock.maxwait, release_on_commit => true);
dbms_output.put_line('lockide='||lockid||', Status='||lock_status);
end;
/
--SX: name|mode=1431044099 = 0x554C0003 = UL-3
--S: name|mode=1431044100 = 0x554C0004 = UL-4
--X: name|mode=1431044102 = 0x554C0006 = UL-6 (used by register)
2. Wait Event: "pipe get" and "enq: UL - contention"
Open two Sqlplus sessions, R1 as receiver, S1 as sender. Then run following test steps.
2.1 R1@T1 - Receiver register an alert name
At first, we register an alert name:
exec dbms_alert.register('TEST_ALERT_1');
-- Register (procedure register)
declare
register_name varchar2(30) := 'TEST_ALERT_1';
lockid integer;
lock_status integer;
begin
lockid := dbms_utility.get_hash_value(register_name, 2000000000, 2048);
lock_status := dbms_lock.request(lockid, dbms_lock.x_mode, dbms_lock.maxwait, release_on_commit => true);
insert into dbms_alert_info values (register_name, receiver_session_id, 'N', null);
commit;
end;
/
select * from sys.dbms_alert_info;
NAME SID CHANGED MESSAGE
------------ ------------ ------- -------
TEST_ALERT_1 0394D2BB0001 N
-- sid||serial#||instance_number (each 4 hex numbers)
select lpad(trim(to_char(sid, 'XXXX')), 4, '0')||lpad(trim(to_char(serial#, 'XXXX')), 4, '0')||lpad(trim(to_char(inst_id, 'XXXX')), 4, '0')
my_unique_sid
,dbms_session.unique_session_id unique_sid
from gv$session where sid = 916;
MY_UNIQUE_SID UNIQUE_SID
------------- ------------
0394D2BB0001 0394D2BB0001
select dbms_utility.get_hash_value('TEST_ALERT_1', 2000000000, 2048) lockid from dual;
LOCKID
----------
2000000030
-- Note: Lockids from 2000000000 to 2147483647 are reserved for products supplied by Oracle Corporation.
2.2 R1@T2 - Receiver wait for registered name to occur
We start waitany with trace and PL/SQL hierarchical profiler:
alter session set events='10046 trace name context forever, level 12: 10704 trace name context forever, level 15'
tracefile_identifier='trc_1';
exec dbms_hprof.start_profiling('PLSHPROF_DIR', 'hprpf_1');
declare
l_message varchar2(1800);
l_status pls_integer;
l_name varchar2(30);
begin
dbms_alert.waitany(name=>l_name, message=>l_message, status=>l_status);
--dbms_alert.waitone(name=>'TEST_ALERT_1', message=>l_message, status=>l_status);
dbms_output.put_line('Received Name='||l_name||', Message='||l_message||', Status='||to_char(l_status));
end;
/
exec dbms_hprof.stop_profiling;
alter session set events='10046 trace name context off: 10704 trace name context off';
WAIT nam='pipe get' ela= 1999731 handle address=2401626056 buffer length=4096 timeout=86400000 obj#=3481822 tim=216712862038
WAIT nam='pipe get' ela= 2999855 handle address=2401626056 buffer length=4096 timeout=86400000 obj#=3481822 tim=216715862043
WAIT nam='pipe get' ela= 3999860 handle address=2401626056 buffer length=4096 timeout=86400000 obj#=3481822 tim=216719862055
WAIT nam='pipe get' ela= 4999839 handle address=2401626056 buffer length=4096 timeout=86400000 obj#=3481822 tim=216724862058
WAIT nam='pipe get' ela= 4999825 handle address=2401626056 buffer length=4096 timeout=86400000 obj#=3481822 tim=216729862028
...
WAIT nam='pipe get' ela= 4999871 handle address=2401626056 buffer length=4096 timeout=86400000 obj#=3481822 tim=216774862040
WAIT nam='pipe get' ela= 1150252 handle address=2401626056 buffer length=4096 timeout=86400000 obj#=3481822 tim=216776012435
-- obj#=3481822 = SYS.DBMS_ALERT_INFO
-- handle address=2401626056 = 0x8F25E7C8
We can see that the name of 'pipe get' handle address=2401626056 (0x8F25E7C8) is a concatenation of 'ORA$ALERT$' and above UNIQUE_SID:
select c.addr, c.hash_value, c.name, c.namespace from v$db_object_cache c where addr like '%8F25E7C8';
ADDR HASH_VALUE NAME NAMESPACE
-------- ---------- ---------------------- ---------
8F25E7C8 3820773965 ORA$ALERT$0394D2BB0001 PIPE
P#C PLSQL."SYS"."DBMS_UTILITY"::11."GET_HASH_VALUE"#2300a0448782c31d #574
P#X 6
P#C PLSQL."SYS"."DBMS_LOCK"::11."REQUEST"#e72e757eb117d2ba #111
P#X 158
P#C SQL."SYS"."DBMS_ALERT"::11."__static_sql_exec_line275" #275."6q6u3ab0st2pj"
P#! SELECT CHANGED, MESSAGE FROM DBMS_ALERT_INFO WHERE
P#X 572
P#C PLSQL."SYS"."DBMS_LOCK"::11."RELEASE"#3048d2af80817a01 #199
P#X 45
P#C PLSQL."SYS"."DBMS_PIPE"::11."RECEIVE_MESSAGE"#9d831f6c5a526d3e #163
P#X 65150257
2.3 S1@T3 - Send a signal
Wait about 60 seconds, then we send a signal from session S1:
exec dbms_alert.signal('TEST_ALERT_1', 'alert_msg_1');
*** 2021-06-10T15:55:59.084868+02:00
ksucti: init DID: 0001-0035-00000082 WAIT nam='enq: UL - contention' ela= 1000005 name|mode=1431044099 id=2000000030 0=0 obj#=3481822 tim=216777013038
ksucti: init DID: 0001-0035-00000082 WAIT nam='enq: UL - contention' ela= 1999250 name|mode=1431044099 id=2000000030 0=0 obj#=3481822 tim=216779013052
ksucti: init DID: 0001-0035-00000082 WAIT nam='enq: UL - contention' ela= 3999985 name|mode=1431044099 id=2000000030 0=0 obj#=3481822 tim=216783014039
ksucti: init DID: 0001-0035-00000082 WAIT nam='enq: UL - contention' ela= 8000198 name|mode=1431044099 id=2000000030 0=0 obj#=3481822 tim=216791015030
ksucti: init DID: 0001-0035-00000082 WAIT nam='enq: UL - contention' ela= 16000115 name|mode=1431044099 id=2000000030 0=0 obj#=3481822 tim=216807016041
ksucti: init DID: 0001-0035-00000082 WAIT nam='enq: UL - contention' ela= 32000110 name|mode=1431044099 id=2000000030 0=0 obj#=3481822 tim=216839017040
ksucti: init DID: 0001-0035-00000082 WAIT nam='enq: UL - contention' ela= 32000237 name|mode=1431044099 id=2000000030 0=0 obj#=3481822 tim=216871018073
ksucti: init DID: 0001-0035-00000082 WAIT nam='enq: UL - contention' ela= 32000841 name|mode=1431044099 id=2000000030 0=0 obj#=3481822 tim=216903020049
ksucti: init DID: 0001-0035-00000082 WAIT nam='enq: UL - contention' ela= 4693093 name|mode=1431044099 id=2000000030 0=0 obj#=3481822 tim=216907714067
*** 2021-06-10T15:58:10.786177+02:00
-- name|mode=1431044099 = 0x554C0003 = UL-3
Oracle dbms_alert package document wrote:
Waitany call: The polling loop begins at a one second interval and exponentially backs off to 30 second intervals.
"tail -f hprpf_1" shows the similar info:
P#C PLSQL."SYS"."DBMS_LOCK"::11."REQUEST"#e72e757eb117d2ba #111
P#X 1000256
P#C PLSQL."SYS"."DBMS_LOCK"::11."REQUEST"#e72e757eb117d2ba #111
P#X 1999479
P#C PLSQL."SYS"."DBMS_LOCK"::11."REQUEST"#e72e757eb117d2ba #111
P#X 4000224
P#C PLSQL."SYS"."DBMS_LOCK"::11."REQUEST"#e72e757eb117d2ba #111
P#X 8000401
P#C PLSQL."SYS"."DBMS_LOCK"::11."REQUEST"#e72e757eb117d2ba #111
P#X 16000326
P#C PLSQL."SYS"."DBMS_LOCK"::11."REQUEST"#e72e757eb117d2ba #111
P#X 32000317
P#C PLSQL."SYS"."DBMS_LOCK"::11."REQUEST"#e72e757eb117d2ba #111
P#X 32000459
P#C PLSQL."SYS"."DBMS_LOCK"::11."REQUEST"#e72e757eb117d2ba #111
P#X 32001077
P#C PLSQL."SYS"."DBMS_LOCK"::11."REQUEST"#e72e757eb117d2ba #111
P#X 4693322
exec dbms_alert.register('TEST_ALERT_1');
name|mode=1431044102 = 0x554C0006 = UL-6 (dbms_lock.x_mode)
2.4 S1@T4 - Sender Commit
Wait about 120 seconds, then we issue the commit in session S2:
commit;
2.5 R1@T5 - Receiver Return
R1 returns with the received message.
Received Name=TEST_ALERT_1, Message=alert_msg_1, Status=0
3. Wait Event: 'pipe get', 'enq: UL - contention' and 'enq: TX - row lock contention'
Now we run one more complicated test case.
Open three Sqlplus sessions, R1 (sid: 916) as receiver, S1 (sid: 371) and S2 (sid: 366) as sender. Then run following test steps.
3.1 R1@T1 - Receiver register an alert name
exec dbms_alert.register('TEST_ALERT_1');
3.2 R1@T2 - Receiver wait for registered name to occur
declare
l_message varchar2(1800);
l_status pls_integer;
l_name varchar2(30);
begin
dbms_alert.waitany(name=>l_name, message=>l_message, status=>l_status);
--dbms_alert.waitone(name=>'TEST_ALERT_1', message=>l_message, status=>l_status);
dbms_output.put_line('Received Name='||l_name||', Message='||l_message||', Status='||to_char(l_status));
end;
/
3.3 S1@T3 - S1 send to R1 'TEST_ALERT_1' with message 'alert_msg_1'
exec dbms_alert.signal('TEST_ALERT_1', 'alert_msg_1');
3.4 S2@T4 - S2 send to R1 'TEST_ALERT_1' with message 'alert_msg_2'
In S2, We start dbms_alert.signal with trace and PL/SQL hierarchical profiler:
alter session set events='10046 trace name context forever, level 12: 10704 trace name context forever, level 15'
tracefile_identifier='trc_2';
exec dbms_hprof.start_profiling('PLSHPROF_DIR', 'hprpf_2');
exec dbms_alert.signal('TEST_ALERT_1', 'alert_msg_2');
exec dbms_hprof.stop_profiling;
alter session set events='10046 trace name context off: 10704 trace name context off';
Then it is in 'enq: TX - row lock contention' for 64 seconds (ela= 64240041) blocked by Sender S1 till S1 commit.
BEGIN dbms_alert.signal('TEST_ALERT_1', 'alert_msg_2'); END;
*** 2021-06-10T17:02:29.147764+02:00
ksucti: WAIT: nam='enq: UL - contention' ela= 23999086 name|mode=1431044100 id=2000000030 0=0 obj#=58968 tim=220790075023
*** 2021-06-10T17:02:53.147188+02:00
=====================
UPDATE DBMS_ALERT_INFO SET CHANGED = 'Y', MESSAGE = :B2 WHERE NAME = UPPER(:B1 )
*** 2021-06-10T17:02:53.147277+02:00
ksucti: init session DID from txn DID: 0001-0032-000000DEBINDS #140582426666432:
*** 2021-06-10T17:02:53.147524+02:00
ksucti: WAIT: nam='enq: TX - row lock contention' ela= 64240041 name|mode=1415053318 usn<<16 | slot=524302 sequence=280482 obj#=3481822 tim=220854315708
*** 2021-06-10T17:03:57.387773+02:00
-- name|mode=1431044100 = 0x554C0004 = UL-4
-- name|mode=1415053318=54580006=TX-6
P#C PLSQL."SYS"."DBMS_LOCK"::11."REQUEST"#e72e757eb117d2ba #111
P#X 23999402
P#C SQL."SYS"."DBMS_ALERT"::11."__static_sql_exec_line431" #431."6tmkh8j0d3w0p"
P#! UPDATE DBMS_ALERT_INFO SET CHANGED = 'Y', MESSAGE
P#X 64241029
3.5 S1@T5 - Sender S1 Commit
Wait about 60 seconds, S1 commit:
commit;
3.6 S2@T6 - Sender S2 Commit
commit;
3.7 R1@T7 - Receiver Return
R1 returns with the received message 'alert_msg_2' ('alert_msg_1' was overwritten).
Received Name=TEST_ALERT_1, Message=alert_msg_2, Status=0
select session_id, event, p1, p2, p3, blocking_session
,min(sample_time) start_time, max(sample_time) end_time
,max(sample_time) - min(sample_time) delta
from v$active_session_history v
where session_id in (916 ,371, 366)
and sample_time between timestamp'2021-06-10 16:59:00' and timestamp'2021-06-10 17:05:00'
group by session_id, event, p1, p2, p3, blocking_session
order by min(sample_time);
SESSION_ID EVENT P1 P2 P3 BLOCKING_SESSION START_TIME END_TIME DELTA
---------- ------------------------------ ---------- ---------- ------ ---------------- ---------- -------- --------
916 enq: UL - contention 1431044099 2000000030 0 371 16:59:09 17:03:57 00:04:48
366 enq: UL - contention 1431044100 2000000030 0 916 17:02:29 17:02:52 00:00:23
366 enq: TX - row lock contention 1415053318 524302 280482 371 17:02:53 17:03:57 00:01:04
916 enq: UL - contention 1431044099 2000000030 0 366 17:03:58 17:04:25 00:00:27
Time Sequence:
R1(sid 916)@T1=16:57:01 - dbms_alert.register('TEST_ALERT_1');
R1(sid 916)@T2=16:58:02 - dbms_alert.waitany start
S1(sid 371)@T3=16:59:09 - dbms_alert.signal('TEST_ALERT_1', 'alert_msg_1');
S2(sid 366)@T4=17:02:29 - dbms_alert.signal('TEST_ALERT_1', 'alert_msg_2');
S1(sid 371)@T5=17:03:57 - commit
S2(sid 366)@T6=17:04:25 - commit
R1(sid 916)@T7=17:04:25 - dbms_alert.waitany end
S2 (sid 366) is first in 'enq: UL - contention' blocked by Receiver R1 (sid: 916) for 23 seconds between 17:02:29 and 17:02:52, then in 'enq: TX - row lock contention' blocked by Sender S1 (sid: 371) for 64 seconds between 17:02:53 and 17:03:57 till S1 commit at 17:03:57.
In the first test, we showed that Receiver is in 'enq: UL - contention' for a timeout of 1, 2, 4, 8, 16, 32, 32 ...32 seconds.
In this test, S2 is first in 'enq: UL - contention' (P1=1431044100=UL-4(S)) for 23 seconds, that is because S2 sends signal after R1 is getting into an UL lock request with timeout of 32 seconds, 9 seconds already passed (See Note* below), and it still has remaining 23 seconds.
Note*: from 16:59:09 to 17:02:29 is 200 seconds, mod((200-(1+2+4+8+16)), 32) = 9 seconds.
Once the remaining 23 seconds passed, S2 gets requested lock (S1 has already UL-4(S) on lockid: 2000000030 and it is compatible with S2).
S2 is in 'enq: TX - row lock contention' because it executes:
UPDATE DBMS_ALERT_INFO SET CHANGED = 'Y', MESSAGE = :B2 WHERE NAME = UPPER(:B1 )
After timeout of 32 seconds at 17:02:52, R1 is back to make anew UL lock request (P1=1431044100=UL-3(SX)), it is first blocked by S1 till 17:03:57 (S1 commit), then blocked by S2 till 17:04:25 (S2 commit).
4. Waitone vs. Waitany
In the above test, if we use waitone, instead of waitany, in receiver session R1:
--dbms_alert.waitany(name=>l_name, message=>l_message, status=>l_status);
dbms_alert.waitone(name=>'TEST_ALERT_1', message=>l_message, status=>l_status);
select session_id, event, p1, p2, p3, blocking_session
,min(sample_time) start_time, max(sample_time) end_time
,max(sample_time) - min(sample_time) delta
from v$active_session_history v
where session_id in (916 ,371, 366)
and sample_time between timestamp'2021-06-10 17:06:00' and timestamp'2021-06-10 17:25:58'
group by session_id, event, p1, p2, p3, blocking_session
order by min(sample_time);
SESSION_ID EVENT P1 P2 P3 BLOCKING_SESSION START_TIME END_TIME DELTA
---------- -------------------- ---------- ---------- --- ---------------- ---------- -------- --------
916 enq: UL - contention 1431044099 2000000030 0 371 17:07:42 17:25:57 00:18:15
366 enq: UL - contention 1431044100 2000000030 0 916 17:08:16 17:25:57 00:17:41
select chain_signature, sid, blocker_sid, blocker_is_valid, in_wait_secs, time_remaining_secs, p1, p2, p3 from v$wait_chains v order by v.sid;
CHAIN_SIGNATURE SID BLOCKER_SID BLOCK IN_WAIT_SECS TIME_REMAINING_SECS P1 P2 P3
--------------------------------------------------- --- ----------- ----- ------------ ------------------- ---------- ---------- ---
'SQL*Net message from client'<='enq: UL'<='enq: UL' 916 371 TRUE 1094 -1 1431044099 2000000030 0
'SQL*Net message from client'<='enq: UL'<='enq: UL' 371 FALSE 178 -1 1413697536 1 0
'SQL*Net message from client'<='enq: UL'<='enq: UL' 366 916 TRUE 1060 -1 1431044100 2000000030 0
-- P1=1431044099 = 0x554C0003 = UL-3
-- P1=1431044100 = 0x554C0004 = UL-4
* S1(sid 371) has a much smaller IN_WAIT_SECS (178) because we run monitoring queries in S1.
Time Sequence:
R1(sid 916)@T1=17:06:16 - dbms_alert.register('TEST_ALERT_1');
R1(sid 916)@T2=17:06:46 - dbms_alert.waitone start
S1(sid 371)@T3=17:07:42 - dbms_alert.signal('TEST_ALERT_1', 'alert_msg_1');
S2(sid 366)@T4=17:08:16 - dbms_alert.signal('TEST_ALERT_1', 'alert_msg_2');
query execution time@17:25:57
If there is no alert registered, the behaviours of waitany and waitone are different, waitany returns ORU-10024 immediately, waitone will return Status=1 after the timeout period expires.
exec dbms_alert.removeall;
PL/SQL procedure successfully completed.
select * from sys.dbms_alert_info;
no rows selected
declare
l_message varchar2(1800);
l_status pls_integer;
l_name varchar2(30);
begin
dbms_alert.waitany(name=>l_name, message=>l_message, status=>l_status, timeout=>60);
dbms_output.put_line('Received Name='||l_name||', Message='||l_message||', Status='||to_char(l_status));
end;
/
ERROR at line 1:
ORA-20000: ORU-10024: there are no alerts registered.
ORA-06512: at "SYS.DBMS_ALERT", line 295
ORA-06512: at line 6
declare
l_message varchar2(1800);
l_status pls_integer;
l_name varchar2(30);
begin
dbms_alert.waitone(name=>'TEST_ALERT_DUMMY', message=>l_message, status=>l_status, timeout=>60);
dbms_output.put_line('Received Name='||l_name||', Message='||l_message||', Status='||to_char(l_status));
end;
/
Received Name=, Message=, Status=1
5. Discussions
From above waiting history query result, we can see that blocked session can be Receiver or Sender (R1 or S2), and blocking session can also be Receiver or Sender (R1, S1 or S2).
For related discussions on dbms_alert, see
Blog: dbms_alert lock hash collision investigated false 'enq: UL - contention' caused by lockid hash collision.
Blog: One case of dbms_alert.signal deadlock demonstrated one case of deadlock generated by dbms_alert.signal.
6. dbms_alert Pseudo Code
Based on above tests, we can dipict dbms_alert logic in pseudo code as follows:
create table sys.dbms_alert_info
(name varchar2(30 byte),
sid varchar2(30 byte),
changed varchar2(1 byte),
message varchar2(1800 byte));
alter table sys.dbms_alert_info add (primary key (name, sid));
receiver_session_id varchar2(30) := dbms_session.unique_session_id; -- sid||serial#||instance_number (each 4 hex numbers)
receiver_pipename varchar2(30) := 'ORA$ALERT$' || receiver_session_id;
------------------------ Receiver ------------------------
register
lockid := dbms_utility.get_hash_value(register_name, 2000000000, 2048);
lock_status := dbms_lock.request(lockid, dbms_lock.x_mode, dbms_lock.maxwait, release_on_commit => true);
insert into dbms_alert_info values (register_name, receiver_session_id, 'N', null);
waitany
--'pipe get' wait. Polling 2, 3, 4, 5, 5, ... 5 seconds. Immediate return when signal received (non-transactional).
pipe_status := dbms_pipe.receive_message(receiver_pipename, timeout);
lockid := dbms_utility.get_hash_value(register_name, 2000000000, 2048);
waitime := 1;
loop
--'enq: UL - contention' wait. Iterate wait: 1, 2, 4, 8, ..32, ... 32 seconds.
-- Immediate return when received signal committed by sender (transactional).
lock_status := dbms_lock.request(lockid, dbms_lock.sx_mode, waitime, release_on_commit => true);
select changed, message from dbms_alert_info where sid = receiver_session_id and name = register_name; -- 6q6u3ab0st2pj
if changed = 'Y' then
update dbms_alert_info set changed = 'N' where sid = :b2 and name = :b1; -- 0g5b4j61q042t, reset Flag "changed"
return message,
end if;
if lock_status = 1 then -- timeout
waitime := least(waitime*2, 32);
end if;
if receiver_timeout then
return 1; -- timeout
end if;
end loop;
------------------------ Sender ------------------------
signal
lockid := dbms_utility.get_hash_value(signal_name, 2000000000, 2048);
lock_status := dbms_lock.request(lockid, dbms_lock.s_mode, dbms_lock.maxwait, release_on_commit => true);
update dbms_alert_info set changed = 'Y', message = message where name = signal_name; -- 6tmkh8j0d3w0p
pipe_status := dbms_pipe.send_message(receiver_pipename);
