We will discuss Oracle Write Consistency and different error messages in two Blogs.
This Blog will make one test to demonstrate Write Consistency and error ORA-00600: [13030], [20].
Next Blog will show Write Consistency and ORA-30926: "unable to get a stable set of rows in the source tables".
We will show that error message depends on column declaration:
for column "not null", it is ORA-00600: [13030], [20]
for column "null", it is ORA-30926: "unable to get a stable set of rows in the source tables"
1. Test Setup
We create a simple table with two columns, and insert two rows:
drop table test_tab;
create table test_tab (id number, txt varchar2(1) not null, constraint test_tab_pk primary key (id));
-- ORA-30926: unable to get a stable set of rows
--create table test_tab (id number, txt varchar2(1), constraint test_tab_pk primary key (id));
insert into test_tab values (1, 'A');
insert into test_tab values (2, 'A');
commit;
SQL> select * from test_tab;
ID TXT
--- ----
1 A
2 A
create or replace package test_pkg as
b_1_cnt number := 0;
b_2_cnt number := 0;
function non_deterministic_fun(p_id number, p_sleep number := 10) return number;
procedure set_cnt (p_1_cnt number, p_2_cnt number);
procedure prt_tx_locks;
end;
/
create or replace package body test_pkg as
function non_deterministic_fun(p_id number, p_sleep number := 10) return number as
l_ret number;
l_cnt_str varchar2(20);
begin
case p_id
when 1 then
b_1_cnt := b_1_cnt + 1;
l_ret := mod(b_1_cnt, 2);
l_cnt_str := ': b_1_cnt='||b_1_cnt;
when 2 then
b_2_cnt := b_2_cnt + 1;
l_cnt_str := ': b_2_cnt='||b_2_cnt;
l_ret := mod(b_2_cnt, 2);
end case;
dbms_lock.sleep(p_sleep); --dbms_session.sleep(p_sleep); -- Oracle 19c
dbms_output.put_line('At '||localtimestamp ||l_cnt_str||', non_deterministic_fun('||p_id||', '||p_sleep||')='||l_ret);
prt_tx_locks; -- Print TX locks
return l_ret;
end;
procedure set_cnt (p_1_cnt number, p_2_cnt number) as
begin
b_1_cnt := p_1_cnt;
b_2_cnt := p_2_cnt;
dbms_output.put_line('At '||localtimestamp ||': Reset Package Variables: b_1_cnt='||b_1_cnt||', b_2_cnt='||b_2_cnt);
dbms_output.put_line('');
end;
procedure prt_tx_locks as
l_spaces varchar2(6) := ' ';
begin
dbms_output.put_line('');
dbms_output.put_line(l_spaces||'|------------------------------------------------------|');
dbms_output.put_line(l_spaces||'|SID ID1 ID2 LMODE REQUEST CTIME BLOCK|');
dbms_output.put_line(l_spaces||'|------ ------- ------- ------- ------- ------- -------|');
for c in (select * from v$lock where type='TX' order by sid, type)
loop
dbms_output.put_line(l_spaces||'|'||rpad(c.SID, 6)||lpad(c.ID1, 8)||lpad(c.ID2, 8)||lpad(c.LMODE, 8)||
lpad(c.REQUEST, 8)||lpad(c.CTIME, 8)||lpad(c.BLOCK, 8)||'|');
end loop;
dbms_output.put_line(l_spaces||'|------------------------------------------------------|');
dbms_output.put_line('');
end;
end;
/
2. Test Run
We open two Sqlplus sessions: SID-1 and SID-2.
At T1, SID-1 updates txt from 'A' to 'B' for id=2.
--========== 1. SID-1@T1 ==========--
begin
update test_tab set txt = 'A';
commit;
-- block id=2 update
update test_tab
set txt = 'B'
where txt = 'A'
and id = 2;
dbms_output.put_line('At '||localtimestamp ||': update id=2 from A to B');
end;
/
---- Output ----
At 16:12:11: update id=2 from A to B
We also use DML UTS (Unified Tracing Service) described in Blog: Write consistency and DML restart (Mahmoud Hatem) to monitor Oracle three phases of update restart.
--========== 2. SID-2@T2 ==========--
alter session set tracefile_identifier = 'NotNull_Error_1';
alter session set events 'trace[DML] disk=high ';
exec dbms_monitor.session_trace_enable;
--ALTER SESSION SET "_fix_control"='30681521:0';
begin
test_pkg.set_cnt(0, 0); -- reset package state
update test_tab -- update /*+ RETRY_ON_ROW_CHANGE */ test_tab -- hint has no effect
set txt = 'B'
where txt = 'A'
and test_pkg.non_deterministic_fun(id, 10) > 0;
end;
/
---- Output ----
At 16:12:50: Reset Package Variables: b_1_cnt=0, b_2_cnt=0
At 16:13:00: b_1_cnt=1, non_deterministic_fun(1, 10)=1
At 16:13:10: b_2_cnt=1, non_deterministic_fun(2, 10)=1
At 16:14:12: b_1_cnt=2, non_deterministic_fun(1, 10)=0
At 16:14:22: b_1_cnt=3, non_deterministic_fun(1, 10)=1
ORA-00600: internal error code, arguments: [13030], [20], [], [], [], [], [], [], [], [], [], []
Elapsed: 00:01:45.30
--========== 3. SID-1@T3 ==========--
begin
dbms_output.put_line('At '||localtimestamp ||': wait id=2 update for 30 seconds');
test_pkg.prt_tx_locks;
dbms_lock.sleep(30);
commit;
dbms_output.put_line('At '||localtimestamp ||': commit id=2 update. Then wait 5 seconds');
dbms_lock.sleep(5); -- This wait to de-block id=2 is critical, otherwise no error
update test_tab
set txt = 'B'
where txt = 'A'
and id = 1;
test_pkg.prt_tx_locks;
commit;
dbms_output.put_line('At '||localtimestamp ||': update id=1 from A to B, and commit');
end;
/
---- Output ----
At 16:13:32: wait id=2 update for 30 seconds
At 16:14:02: commit id=2 update. Then wait 5 seconds
At 16:14:07: update id=1 from A to B, and commit
Elapsed: 00:00:35.04
At 16:12:11: SID-1 update id=2 from A to B.
At 16:12:50: SID-2 start running. get into "phase=NOT LOCKED". sleep 10 seconds.
At 16:13:00: SID-2 update id=1 because non_deterministic_fun(1, 10)=1. sleep 10 seconds.
At 16:13:10: SID-2 update id=2, but SID-1 does not commit "id=2 update", it is blocked by "TX" lock for 52 seconds (ela= 52217121).
At 16:14:02: SID-1 commit "id=2 update". SID-2 is unlocked.
SID-2 restart update, get into "phase=LOCK" with "SELECT FOR UPDATE". sleep 10 seconds.
At 16:14:07: SID-1 update id=1 from A to B, and commit.
At 16:14:12: SID-2 get into "phase=NOT LOCKED". id=1 check non_deterministic_fun(1, 10)=0. sleep 10 seconds.
At 16:14:22: SID-2 id=1 check non_deterministic_fun(1, 10)=1.
SID-2 raise ORA-00600: internal error code, arguments: [13030], [20]
===================== *** 16:12:50
PARSING IN CURSOR tim=12445563522721 hv=3131174352 ad='c080e660' sqlid='6jabvd6xa3vfh'
UPDATE TEST_TAB SET TXT = 'B' WHERE TXT = 'A' AND TEST_PKG.NON_DETERMINISTIC_FUN(ID, 10) > 0
updThreePhaseExe: objn=3122646 phase=NOT LOCKED
updaul: phase is NOT LOCKED snap oldsnap env: (scn: 0x000009185dcf3734 xid: 0x0000.000.00000000 uba:
===================== *** 16:13:00
WAIT: nam='PL/SQL lock timer' ela= 10000786 tim=12445573526055
updrow: objn=3122646 phase=NOT LOCKED
updrow: kauupd objn:3122646 rowid 002fa5d6.000c9786.0 code 0
===================== *** 16:13:10
WAIT: nam='PL/SQL lock timer' ela= 10000287 tim=12445583549063
updrow: objn=3122646 phase=NOT LOCKED
===================== *** 16:14:02
WAIT: nam='enq: TX - row lock contention' ela= 52217121 name|mode=1415053318 usn<<16 | slot=8323077 sequence=80529 obj#=3122646 tim=12445635782319
dmlTrace:file:line (kdu.c:3505) cmpf 20 rowcol 1 piececol 1
updrow: kauupd objn:3122646 rowid 002fa5d6.000c9786.1 code 20
updThreePhaseExe: objn=3122646 phase=LOCK
===================== *** 16:14:12
WAIT: nam='PL/SQL lock timer' ela= 10000133 tim=12445645783076
updThreePhaseExe: objn=3122646 phase=ALL LOCKED
===================== *** 16:14:22
WAIT: nam='PL/SQL lock timer' ela= 10000583 tim=12445655800069
updrow: objn=3122646 phase=ALL LOCKED
Block header dump: 0x000c9786
Itl Xid Uba Flag Lck Scn/Fsc
0x01 0x007f.005.00013a91 0x00c026bf.2019.0f --U- 1 fsc 0x0000.5dcf3755
0x02 0x0075.010.00011cca 0x00c01798.1e21.21 --U- 1 fsc 0x0000.5dcf375a
===============
block_row_dump:
tab 0, row 0, @0x1f90
tl: 8 fb: --H-FL-- lb: 0x2 cc: 2
col 0: [ 2] c1 02
col 1: [ 1] 42
tab 0, row 1, @0x1f88
tl: 8 fb: --H-FL-- lb: 0x1 cc: 2
col 0: [ 2] c1 03
col 1: [ 1] 42
kflag
[0] CMPCOL
cmpp (2) c1 02
[1] CMPCOL UPDCOL
cmpp (1) 41
updp (1) 42
updrow: CR error table 0 - rowid: 002fa5d6.000c9786.0 code 20
dmlsrvRetryLogDump: seq:code:error:pass:hash:rowcol:piececol:currentLength:currentFlags:CRLength:CRFlags:rid:scn
dmlsrvRetryLogDump: 0:20:0:1:2139311695:1:1:1:0:1:0:002fa5d6.000c9786.1:0x000009185dcf3734
dmlsrvRetryLogDump: 1:20:0:3:2139311695:1:1:1:0:1:0:002fa5d6.000c9786.0:0x000009185dcf3757
=====================
ORA-00600: internal error code, arguments: [13030], [20], [], [], [], [], [], [], [], [], [], []
===================== *** 16:12:50
updThreePhaseExe: objn=3122646 phase=NOT LOCKED
===================== *** 16:14:02
updThreePhaseExe: objn=3122646 phase=LOCK
===================== *** 16:14:12
updThreePhaseExe: objn=3122646 phase=ALL LOCKED
SID-2 finished "TX" wait after 52 seconds (ela= 52217121).
dmlTrace shows code 20 error: "rowid 002fa5d6.000c9786.1 code 20".
(maybe "line (kdu.c:3505) cmpf 20" is interpreted as "code 20" or [20] in error message).
"phase=LOCK" signifies the update restart.
===================== *** 16:14:02
WAIT: nam='enq: TX - row lock contention' ela= 52217121 name|mode=1415053318 usn<<16 | slot=8323077 sequence=80529 obj#=3122646 tim=12445635782319
dmlTrace:file:line (kdu.c:3505) cmpf 20 rowcol 1 piececol 1
updrow: kauupd objn:3122646 rowid 002fa5d6.000c9786.1 code 20
updThreePhaseExe: objn=3122646 phase=LOCK
Itl 0x01 (lb: 0x1) updated id=2 ("c1 03"),
Itl 0x02 (lb: 0x2) updated id=1 ("c1 02").
If we look the TX v$lock printout ("ID1 ID2" in test_pkg.prt_tx_locks, not showed in this Blog), we can match both Xid
(0x007f.005.00013a91 = 127.5.80529, 0x0075.010.00011cca=117.16.72906).
block_row_dump section shows that both rows have txt = 'B' ("col 1: [ 1] 42").
Itl Xid Uba Flag Lck Scn/Fsc
0x01 0x007f.005.00013a91 0x00c026bf.2019.0f --U- 1 fsc 0x0000.5dcf3755
0x02 0x0075.010.00011cca 0x00c01798.1e21.21 --U- 1 fsc 0x0000.5dcf375a
===============
block_row_dump:
tab 0, row 0, @0x1f90
tl: 8 fb: --H-FL-- lb: 0x2 cc: 2
col 0: [ 2] c1 02 -- 1
col 1: [ 1] 42 -- 'B'
tab 0, row 1, @0x1f88
tl: 8 fb: --H-FL-- lb: 0x1 cc: 2
col 0: [ 2] c1 03 -- 2
col 1: [ 1] 42 -- 'B'
kflag
[0] CMPCOL
cmpp (2) c1 02 -- 1
[1] CMPCOL UPDCOL
cmpp (1) 41 -- 'A'
updp (1) 42 -- 'B'
updrow: CR error table 0 - rowid: 002fa5d6.000c9786.0 code 20
We got code=20 in "pass=1" ( "phase=NOT LOCKED") for id=2 ("rid=002fa5d6.000c9786.1"),
and got code=20 in "pass=3" ( "phase=ALL LOCKED") for id=1 ("rid=002fa5d6.000c9786.0")
dmlsrvRetryLogDump: seq:code:error:pass:hash:rowcol:piececol:currentLength:currentFlags:CRLength:CRFlags:rid:scn
dmlsrvRetryLogDump: 0:20:0:1:2139311695:1:1:1:0:1:0:002fa5d6.000c9786.1:0x000009185dcf3734
dmlsrvRetryLogDump: 1:20:0:3:2139311695:1:1:1:0:1:0:002fa5d6.000c9786.0:0x000009185dcf3757
At 16:14:07 update id=1 from A to B, and commit
because it is between SID-2 16:14:02 ("phase=LOCK") and 16:14:12 ("phase=NOT LOCKED").
Probably that is the code path which caused ORA-00600.
In the above test, if we remove this second update in SID-1@T3 as follows, and there is no more ORA-00600 because no second re-start is triggered.
--========== 3. SID-1@T3 ==========--
begin
dbms_output.put_line('At '||localtimestamp ||': wait id=2 update for 30 seconds');
test_pkg.prt_tx_locks;
dbms_lock.sleep(30);
commit;
end;
/
ORA-00600: internal error code, arguments: [13030], [20], [], [], [], [], [], [], [], [], [], []
*** 2022-04-06T16:14:22.450668+02:00
----- Current SQL Statement for this session (sql_id=6jabvd6xa3vfh) -----
UPDATE TEST_TAB SET TXT = 'B' WHERE TXT = 'A' AND TEST_PKG.NON_DETERMINISTIC_FUN(ID, 10) > 0
----- Call Stack Trace -----
FRAME [13] (ksesic1()+185 -> kgesiv())
FRAME [14] (updrow()+5781 -> ksesic1())
FRAME [15] (qerupUpdRow()+671 -> updrow())
FRAME [16] (qerupRopRowsets()+259 -> qerupUpdRow())
FRAME [17] (qerstRowP()+737 -> qerupRopRowsets())
FRAME [18] (kdstf110110100001000km()+1884 -> qerstRowP())
FRAME [19] (kdsttgr()+2208 -> kdstf110110100001000km())
FRAME [20] (qertbFetch()+1090 -> kdsttgr())
FRAME [21] (qerstFetch()+449 -> qertbFetch())
FRAME [22] (qerupFetch()+520 -> qerstFetch())
FRAME [23] (qerstFetch()+910 -> qerupFetch())
FRAME [24] (updaul()+1416 -> qerstFetch())
FRAME [25] (updThreePhaseExe()+6101 -> updaul())
FRAME [26] (updexe()+443 -> updThreePhaseExe())
FRAME [27] (opiexe()+11799 -> updexe())
FRAME [28] (opipls()+2427 -> opiexe())
for SID-1@T1, we update "id = 1" instead of "id = 2"
for SID-1@T3, we update "id = 2" instead of "id = 1"
(in SID-2, no rows updated, no Itl entry, no transaction created):
*** 17:44:51
updThreePhaseExe: objn=3122646 phase=NOT LOCKED
updaul: phase is NOT LOCKED snap oldsnap env:
*** 17:45:01
WAIT #140344716597752: nam='PL/SQL lock timer' ela= 10000544 duration=0 p2=0 p3=0 obj#=-1 tim=13376295440067
updrow: objn=3122646 phase=NOT LOCKED
*** 17:45:56
WAIT #140344716597752: nam='enq: TX - row lock contention' ela= 54748944 name|mode=1415053318 usn<<16 | slot=7602177 sequence=77639 obj#=3122646 tim=13376350189277
dmlTrace:file:line (kdu.c:3505) cmpf 20 rowcol 1 piececol 1
updrow: kauupd objn:3122646 table:0 rowMigrated:FALSE rowid 002fa5d6.000c9786.0 code 20
updThreePhaseExe: objn=3122646 phase=LOCK
updaul: phase is LOCK snap oldsnap env:
*** 17:46:06
WAIT #140344716597752: nam='PL/SQL lock timer' ela= 10000260 duration=0 p2=0 p3=0 obj#=-1 tim=13376360190078
updrow: objn=3122646 phase=LOCK
dmlTrace:file:line (kdd.c:3642) cmpf 17 rowcol 1 piececol 1
updrow: kddlkr objn 3122646 table 0 rowid 002fa5d6.000c9786.1 code 17
updThreePhaseExe:objn=3122646 pass=1 stat=2 err=17
updThreePhaseExe:began locking pass 2
updaul: phase is LOCK snap oldsnap env:
updThreePhaseExe: objn=3122646 phase=ALL LOCKED
updaul: phase is ALL LOCKED snap oldsnap env:
3. Related Work
Oracle MOS Ora-00600 [13030], [20] During Update Statement Using V$ tables (Doc ID 1400439.1) wrote:
For updates we use a 3 pass algorithm which relies on consistent read. If the first pass does not succeed then we use a CR scan and lock the rows returned, then reset the row source and use a further CR scan at the same snapshot SCN to update those locked rows. The V$ view in the WHERE clause does not support CR and so each scan using the same snapshot SCN may see different data depending on the content of V$SESSION at the scan time which completely breaks the update algorithm. The errors you see (ORA-600 [13030]) indicate: [1] - the row to be updated has changed values in comparison columns [2] - the row to be updated does not exist These are the sorts of error you can get if the separate scans at the same snapshot SCN return different data, as can occur with a V$ view involved.Book: Expert Oracle Database Architecture (Thomas Kyte, Darl Kuhn, 3rd Edition) explained update restart and demonstrated it with triggers.
Page 270 wrote:
But to continue on with the "but what happens if..." train of thought, what happens if, after restarting the update and going into SELECT FOR UPDATE mode (which has the same read-consistent and read current block gets going on as an update does), a row that was Y=5 when you started the SELECT FOR UPDATE is found to be Y=11 when you go to get the current version of it? That SELECT FOR UDPDATE will restart and the cycle begins again.This seems talking about a second restart after first restart. The above test showed ORA-00600: [13030], [20] in such second restart, and "cycle begins again" abnormally terminated (session is not disconnected).
So it is not clear if "but what happens if..." has ever been exercised.
For the update statement in the second session of Book Page 271, if we add a MONITOR hint and make a Sql trace:
(see Video: Oracle SQL Monitoring and Write Consistency Demo (Tanel Poder))
alter session set events '10046 trace name context forever, level 12';
-- with /*+ MONITOR */
update /*+ MONITOR */ t set x = x+1 where x > 0;
alter session set events '10046 trace name context off';
select sys.dbms_sqltune.report_sql_monitor('canctsv349dww', report_level=>'all' , type=>'TEXT') from dual;
------------------------------
update /*+ MONITOR */ t set x = x+1 where x > 0
SQL Plan Monitoring Details (Plan Hash Value=931696821)
=============================================================================================================================================
| Id | Operation | Name | Rows | Cost | Time | Start | Execs | Rows | Activity | Activity Detail |
| | | | (Estim) | | Active(s) | Active | | (Actual) | (%) | (# samples) |
=============================================================================================================================================
| 0 | UPDATE STATEMENT | | | | 1 | +13 | 3 | 0 | | |
| 1 | UPDATE | T | | | 14 | +0 | 3 | 0 | 100.00 | enq: TX - row lock contention (13) |
| 2 | TABLE ACCESS FULL | T | 4 | 2 | 11 | +3 | 3 | 3 | | |
=============================================================================================================================================
********************************************************************************
SQL ID: canctsv349dww Plan Hash: 931696821
update /*+ MONITOR */ t set x = x+1 where x > 0
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 1 0 0
Execute 1 0.00 12.61 0 21 13 1
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.00 12.61 0 22 13 1
Rows Row Source Operation
---- ---------------------------------------------------
0 UPDATE T (cr=21 pr=0 pw=0 time=12612642 us starts=3)
3 TABLE ACCESS FULL T (cr=20 pr=0 pw=0 time=222 us starts=3 cost=2 size=104 card=4)
********************************************************************************
and xplan shows that "TABLE ACCESS FULL" has Rows=3 and starts=3,
although only one single row is updated (without update restart, all above numbers are 1).
All those number 3 exactly signify "updThreePhaseExe".
By the way, an erratum of Foreign Key on Nested Table (maybe the only real one) was reported for 1st Edition of Book: Book Expert Oracle Database Architecture. It was once accepted and published, but now it cannot find any more. In Oracle 19.13, repeated the same test from Blog: Foreign Key on Nested Table Foreign Key on Nested Table can still successfully created (in Oracle 19.13, type has to be created as NONEDITIONABLE). But in Page 410 of 3rd Edition, we can still read: This will simply not work. Nested tables do not support referential integrity constraints, as they cannot reference any other tableóeven themselves. So, weíll just skip that requirement for this demonstration (something you cannot do in real life!). And error message (Page 409) seems disapproved: ORA-30730: referential constraint not allowed on nested table columnBlog: Oracle write consistency bug and multi-thread de-queuing (Franck Pachot) showed an update restart bug with nested subquery and used flashback version query to list all versions of the rows. It also mentioned hint RETRY_ON_ROW_CHANGE, which has no effect on the test of this Blog.
Oracle MOS Bug 33470254 - UPDATE FAILS WITH ORA-00600 [13030], [20] (Doc ID 33470254.8) provided a Workaround:
"_fix_control"= '30681521:0' (Versions affected, 19.11, 19.13, 19.14)
which seems related to subqueries (see V$SYSTEM_FIX_CONTROL.DESCRIPTION).
Our 19.13 test DB is set with this _fix_control, but it has no effect.
select bugno, value, description from v$system_fix_control where bugno=30681521;
BUGNO VALUE DESCRIPTION
-------- ----- ----------------------------------------------------------------
30681521 0 enable unnesting of subqueries in set clause of update statement
In the demo, SQL Monitoring also shows that Actual Rows with restart is at least double than without restart. So Actual Rows (V$SQL_PLAN_MONITOR.OUTPUT_ROWS) could be also an indicator of update restart besides V$SQL_PLAN_MONITOR.STARTS (str). The demo contains two tests, one at Wed Sep 5, 2018 10:42:47 AM, another at Wed Sep 5, 2018 3:51:30 PM.
First test involved 9 rows (9 + 8 + 8 = 25 rows in all ThreePhase),
second touched 10 rows (10 + 9 + 9 = 28 rows in all ThreePhase)
Blog: Write consistency and DML restart (Mahmoud Hatem) explored DML UTS (Unified Tracing Service) tracing to investigate update restart, which revealed the very details of updThreePhaseExe. (In its test, without update of Session 2, trace file shows str=3 instead of str=4).
A series of 3 Blogs:
That Old Restart Problem Strikes Back: Setting the Stage
That Old Restart Problem Strikes Back: Getting What You Pay for
That Old Restart Problem Strikes Back: Triggers to the Rescue
demonstrated the single session update restart without any other interfering sessions. It also uses:
alter session set events 'trace[dml]:sql_trace wait=true';
The first Blog shows that such update restart is only observed in non-partitioned table due to "updrowFastPath".
The second Blog points out that there is such update restart in partitioned table due to "updrow".
The third Blog shows that such update restart disappears in non-partitioned table when there is a after trigger due to "updrow".
Blog: Update restarts reveals various Oracle stats in update restart.
