Bug 9471070 : ORA-600 [4156] GENERATED WITH EXECUTE IMMEDIATE AND SAVEPOINT
and presented 5 reproducible test codes (one original from MOS plus 4 variants).
In this Second Test, we extend the previous test by including Global Temporary Table (GTT), and run the test with trace and dumps to get further understanding of the error.
The original MOS Note: Bug 9471070 cannot be found any more. As a substitute, we found a new published MOS Note:
ORA-00600: [4156] when Rolling Back to a Savepoint (Doc ID 2242249.1)
which provides a possible workaround:
Set the TEMP_UNDO_ENABLED back to the default setting of FALSE.
We will repeat the same tests with this workaround and watch the outcome.
Note: Tested in Oracle 19.6
1. Test Setup
The test includes a normal table and a GTT table. GTT table is created analogue to SYS.ATEMPTAB$. We also list their object_id for later dump file reference.
drop table test_tab purge;
create table test_tab(id number);
drop table test_atemptab purge;
create global temporary table test_atemptab (id number) on commit delete rows nocache;
create index test_atempind on test_atemptab(id);
select object_name, object_id from dba_objects where object_name in ('TEST_TAB', 'TEST_ATEMPTAB', 'TEST_ATEMPIND');
OBJECT_NAME OBJECT_ID
------------- ---------
TEST_TAB 3333415
TEST_ATEMPTAB 3333416
TEST_ATEMPIND 3333417
2. ORA-600 [4156] Error Message
At first, we perform all the tests with TEMP_UNDO_ENABLED= TRUE. Later we will test the workaround of FALSE (default) provided by MOS (Doc ID 2242249.1).
Open a Sqplus window, run following code snippet (similar to VARIANT-3 in Blog: ORA-600 [4156] SAVEPOINT and PL/SQL Exception Handling).
savepoint sp_a;
insert into test_tab values(1);
insert into test_atemptab values(11);
savepoint sp_b;
begin
rollback to savepoint sp_a;
insert into test_atemptab values(12);
rollback to savepoint sp_b;
end;
/
ORA-00603: ORACLE server session terminated by fatal error
ORA-00600: internal error code, arguments: [4156], [], [], [], [], [], [], [],
[], [], [], []
ORA-01086: savepoint 'SP_B' never established in this session or is invalid
ORA-06512: at line 4
Process ID: 25417
Session ID: 902 Serial number: 20826
kturRollbackToSavepoint temp undokturRollbackToSavepoint savepoint uba: 0x00406a82.0000.02 xid: 0x005f.016.00007623
kturRollbackToSavepoint current call savepoint: ksucaspt num: 342 uba: 0x00c060ad.15fe.11
uba: 0x00406a82.0000.02 xid: 0x005f.016.00007623
xid: 0x0386.000.00000001 <<< 0x0386 is Session ID: 902 (0x0386)
The second and third line contain the info at the moment of crash, probably caused the error, which are savepoint (num: 342), permanent undo (uba: 0x00c060ad.15fe.11), temporary undo (uba: 0x00406a82.0000.02), transaction (xid: 0x005f.016.00007623).
The fourth line (xid: 0x0386.000.00000001) is not clear. As all the tests suggested, the first hexadecimal number is Session ID, for example, above 0x0386 is Session ID: 902. The second and third hexadecimal numbers are always 000.00000001.
3. Test with Trace and Dumps
To further explore the error, we can add some trace code to the test.
First we create a helper Plsql procedure to write out transaction and permanent/temporary undo info.
create or replace procedure write_info (p_step varchar2, p_sleep number := 5) as
l_dst binary_integer := 1;
l_sid number;
l_trx varchar2(100);
l_temp_undo varchar2(100);
begin
select sid into l_sid from v$mystat where rownum=1;
select 'SID:'||s.sid||', XID:('||xidusn||'.'||xidslot||'.'||xidsqn||', '||flag||
'), UNDO:('||ubafil||', '||ubablk||', '||ubasqn||', '||ubarec||')'
into l_trx
from v$transaction t, v$session s
where t.addr(+) = s.taddr and s.sid = l_sid;
select 'TEMP_UNDO_HEADER:('||segrfno#||', '||segblk#||', '||segfile#||')'
into l_temp_undo
from v$tempseg_usage t, v$session s
where t.segtype(+) = 'TEMP_UNDO' and t.session_addr(+) = s.saddr and s.sid = l_sid;
sys.dbms_system.ksdwrt(l_dst, p_step||l_trx||', '||l_temp_undo);
dbms_session.sleep(p_sleep);
end;
/
Step sid, XID:(xidusn.xidslot.xidsqn, flag),
UNDO:(ubafil, ubablk, ubasqn, ubarec),
TEMP_UNDO_HEADER:(segrfno#, segblk#, segfile#)
Open a Sqlplus window, run code below:
alter session set max_dump_file_size = unlimited;
alter session set tracefile_identifier = "Test_f";
savepoint sp_a;
exec write_info('Step1_');
insert into test_tab values(1);
exec write_info('Step2_');
insert into test_atemptab values(11);
savepoint sp_b;
exec write_info('Step3_');
begin
write_info('Step4_');
rollback to savepoint sp_a;
write_info('Step5_');
insert into test_atemptab values(12);
write_info('Step6_', 300);
rollback to savepoint sp_b;
write_info('Step7_');
end;
/
Oracle process number: 38
Unix process pid: 16147, image: oracle@testdb
*** SESSION ID:(370.53180) 2020-09-13T15:21:48.003188+02:00
*** 2020-09-13T15:21:53.118636+02:00
Step2_SID:370, XID:(89.15.51190, 7683), UNDO:(3, 2476, 6688, 3), TEMP_UNDO_HEADER:(, , )
*** 2020-09-13T15:21:58.165769+02:00
Step3_SID:370, XID:(89.15.51190, 7683), UNDO:(3, 2476, 6688, 3), TEMP_UNDO_HEADER:(1, 19328, 3073)
*** 2020-09-13T15:22:03.263868+02:00
Step4_SID:370, XID:(89.15.51190, 7683), UNDO:(3, 2476, 6688, 3), TEMP_UNDO_HEADER:(1, 19328, 3073)
*** 2020-09-13T15:22:08.352391+02:00
Step5_SID:370, XID:(89.15.51190, 5635), UNDO:(0, 0, 0, 0), TEMP_UNDO_HEADER:(1, 19328, 3073)
*** 2020-09-13T15:22:13.553650+02:00
Step6_SID:370, XID:(89.15.51190, 5635), UNDO:(0, 0, 0, 0), TEMP_UNDO_HEADER:(1, 19328, 3073)
Step4_SID:370, XID:(89.15.51190, 7683), UNDO:(3, 2476, 6688, 3), TEMP_UNDO_HEADER:(1, 19328, 3073)
oradebug setmypid;
alter system flush buffer_cache;
alter system checkpoint;
oradebug settracefileid undo_f;
alter system dump datafile 3 block min 2476 block max 2476;
oradebug settracefileid temp_undo_f;
alter system dump tempfile 1 block min 19328 block max 19332;
oradebug setorapid 38;
oradebug settracefileid proc_f;
oradebug dump processstate 10;
ORA-00603: ORACLE server session terminated by fatal error
ORA-00600: internal error code, arguments: [4156], [], [], [], [], [], [], [], [], [], [], []
ORA-01086: savepoint 'SP_B' never established in this session or is invalid
ORA-06512: at line 7
Process ID: 16147
Session ID: 370 Serial number: 53180
========= Dump for incident 73594 (ORA 600 [4156]) ========
*** SESSION ID:(370.53180) 2020-09-13T15:27:13.752430+02:00
kturRollbackToSavepoint temp undokturRollbackToSavepoint savepoint uba: 0x00404b82.0000.02 xid: 0x0059.00f.0000c7f6
kturRollbackToSavepoint current call savepoint: ksucaspt num: 394 uba: 0x00c009ac.1a20.03
uba: 0x00404b82.0000.02 xid: 0x0059.00f.0000c7f6
xid: 0x0172.000.00000001 <<< 0x0172 is Session ID: 370 (0x0172)
3.1. Permanent Undo
We inserted one row into test_tab. "Rec #0x3" is the only undo record (first and last), noted with "rdba: 0x00000000" and "rci 0x00". It is "uba: 0x00c009ac.1a20.03" (rdba: 3/2476, seq: 6688, rec: 3) in above incident file.
========= undo_f ========
Start dump data blocks tsn: 2 file#:3 minblk 2476 maxblk 2476
Block dump from cache:
Dump of buffer cache at level 3 for pdb=0 tsn=2 rdba=12585388
BH (0x140f569e8) file#: 3 rdba: 0x00c009ac (3/2476) class: 194 ba: 0x1400c6000
...
UNDO BLK:
xid: 0x0059.00f.0000c7f6 seq: 0x1a20 cnt: 0x3 irb: 0x3 icl: 0x0 flg: 0x0000
Rec Offset Rec Offset Rec Offset Rec Offset Rec Offset
---------------------------------------------------------------------------
0x01 0x1f78 0x02 0x1ec4 0x03 0x1e3c
...
*-----------------------------
* Rec #0x3 slt: 0x0f objn: 3333415(0x0032dd27) objd: 3333415 tblspc: 2300(0x000008fc)
* Layer: 11 (Row) opc: 1 rci 0x00
Undo type: Regular undo Begin trans Last buffer split: No
Temp Object: No
rdba: 0x00000000Ext idx: 0
flg2: 0
*-----------------------------
uba: 0x00c009ac.1a20.02 ctl max scn: 0x000008d5bc68c586 prv tx scn: 0x000008d5bc68c589
txn start scn: scn: 0x000008d5bc68ccc8 logon user: 49
prev brb: 12585365 prev bcl: 0
3.2. Temp Undo
At first, we look temp undo header block (rdba: 0x00404b80 (1/19328) class: 33. File number: 3073, Relative file number: 1).
========= temp_undo_f (undo header block) ========
Dump of buffer cache at level 3 for pdb=0 tsn=3 rdba=4213632
BH (0x108fe8de8) file#: 3073 rdba: 0x00404b80 (1/19328) class: 33 ba: 0x108dc6000
...
TRN CTL:: seq: 0x0000 chd: 0x0001 ctl: 0x0061 inc: 0x00000000 nfb: 0x0000
mgc: 0x8002 xts: 0x0068 flg: 0x0001 opt: 2147483647 (0x7fffffff)
uba: 0x00404b82.0000.01 scn: 0x0000000000000000
TRN TBL::
index state cflags wrap# uel scn dba parent-xid nub stmt_num
------------------------------------------------------------------------------------------------
0x00 10 0x80 0x0001 0x0000 0x000008d5bc68cd00 0x00404b82 0x0000.000.00000000 0x00000001 0x00000000 0
0x01 9 0x00 0x0000 0x0002 0x0000000000000000 0x00000000 0x0000.000.00000000 0x00000000 0x00000000 0
...
0x61 9 0x00 0x0000 0xffff 0x0000000000000000 0x00000000 0x0000.000.00000000 0x00000000 0x00000000 0
Here we can also see that temp undo header (class: 33) TRN TBL has 98 entries (0x00 to 0x61), whereas normal permanent undo header has 34 entries (0x00 to 0x21).
Then look temp undo data block (rdba: 0x00404b82 (1/19330) class: 34).
========= temp_undo_f (undo data block) ========
Dump of buffer cache at level 3 for pdb=0 tsn=3 rdba=4213634
BH (0x109fe2308) file#: 3073 rdba: 0x00404b82 (1/19330) class: 34 ba: 0x109d2e000
...
UNDO BLK:
xid: 0x0059.00f.0000c7f6 seq: 0x0 cnt: 0x4 irb: 0x4 icl: 0x0 flg: 0x0000
Rec Offset Rec Offset Rec Offset Rec Offset Rec Offset
---------------------------------------------------------------------------
0x01 0x1f6c 0x02 0x1efc 0x03 0x1eb0 0x04 0x1e40
...
*-----------------------------
* Rec #0x1 slt: 0x00 objn: 3333416(0x0032dd28) objd: 4222336 tblspc: 3(0x00000003)
* Layer: 11 (Row) opc: 1 rci 0x00
Undo type: Regular undo Begin trans Last buffer split: No
Temp Object: Yes
rdba: 0x00000000Ext idx: 4
*-----------------------------
uba: 0x00000000.0000.00 ctl max scn: 0x0000000000000000 prv tx scn: 0x0000000000000000
txn start scn: scn: 0x000008d5bc68cd00 logon user: 49
prev brb: 0 prev bcl: 0
*-----------------------------
* Rec #0x2 slt: 0x00 objn: 3333417(0x0032dd29) objd: 4221568 tblspc: 3(0x00000003)
* Layer: 10 (Index) opc: 22 rci 0x01
rdba: 0x00000000Ext idx: 5
*-----------------------------
(kdxlpu): purge leaf row
key :(10): 02 c1 0c 06 00 40 6d 81 00 00
*-----------------------------
* Rec #0x3 slt: 0x00 objn: 3333416(0x0032dd28) objd: 4221568 tblspc: 3(0x00000003)
* Layer: 11 (Row) opc: 1 rci 0x00
rdba: 0x00000000Ext idx: 4
*-----------------------------
* Rec #0x4 slt: 0x00 objn: 3333417(0x0032dd29) objd: 4222336 tblspc: 3(0x00000003)
* Layer: 10 (Index) opc: 22 rci 0x03
rdba: 0x00000000Ext idx: 5
*-----------------------------
(kdxlpu): purge leaf row
key :(10): 02 c1 0d 06 00 40 6a 81 00 00
02 c1 0c 06 00 40 6d 81 00 00 <<< "c1 0c": 02 bytes for number 11, followed by 06 bytes
02 c1 0d 06 00 40 6a 81 00 00 <<< "c1 0d": 02 bytes for number 12, followed by 06 bytes
In the above dump, there are 4 undo records. The last one is "Rec #0x4", whose "rci 0x03" indicates that its previous undo record is "Rec #0x3" (all undo records in the test with "rdba: 0x00000000"). Whereas "Rec #0x3" has "rci 0x00", which means that it is a first undo record and does not have any previous undo record, since in our test, immediately after "Step4", we rollback to a savepoint by:
rollback to savepoint sp_a;
Since there is no link from ("Rec #0x4" -> "Rec #0x3") to ("Rec #0x2" -> "Rec #0x1"), "rollback to savepoint sp_b" failed, and hence ORA-600 [4156] Rolling Back To Savepoint.
By the way, if we remove this rollback, "Rec #0x3" will point to previous undo record "rci 0x02" as follows:
* Rec #0x3 slt: 0x00 objn: 3333416(0x0032dd28) objd: 4221568 tblspc: 3(0x00000003)
* Layer: 11 (Row) opc: 1 rci 0x02
3.3. Processstate
We only list Savepoint related lines.
========= proc_f ========
Flags=[0000] SavepointNum=1a7 Time=09/13/2020 15:22:13
LibraryHandle: Address=0x8b61ad18 Hash=4ac26de7 LockMode=N PinMode=0 LoadLockMode=0 Status=VALD
ObjectName: Name=INSERT INTO TEST_ATEMPTAB VALUES(12)
Flags=CNB/[0001] SavepointNum=18a Time=09/13/2020 15:22:03
LibraryHandle: Address=0x8b5e1558 Hash=a2b60837 LockMode=N PinMode=0 LoadLockMode=0 Status=VALD
ObjectName: Name=begin
write_info('Step4_');
rollback to savepoint sp_a;
write_info('Step5_');
insert into test_atemptab values(12);
write_info('Step6_', 300);
rollback to savepoint sp_b;
write_info('Step7_');
end;
Flags=CNB/[0001] SavepointNum=164 Time=09/13/2020 15:21:57
LibraryHandle: Address=0xa39d5d68 Hash=65d67994 LockMode=N PinMode=0 LoadLockMode=0 Status=VALD
ObjectName: Name=insert into test_atemptab values(11)
Flags=CNB/[0001] SavepointNum=14f Time=09/13/2020 15:21:52
LibraryHandle: Address=0x96c1c530 Hash=9abe37a2 LockMode=N PinMode=0 LoadLockMode=0 Status=VALD
ObjectName: Name=insert into test_tab values(1)
INSERT INTO TEST_ATEMPTAB VALUES(12) >>> SavepointNum=1a7 Time=09/13/2020 15:22:13
begin ... end >>> SavepointNum=18a Time=09/13/2020 15:22:03
insert into test_atemptab values(11) >>> SavepointNum=164 Time=09/13/2020 15:21:57
insert into test_tab values(1) >>> SavepointNum=14f Time=09/13/2020 15:21:52
Searching "0x18a" in Processstate dump, we found:
svpt(xcb:0xad719320 sptn:0x18a uba: 0x00c009ac.1a20.03 uba: 0x00404b82.0000.02)
xctsp name:ˆb¬‹
svpt(xcb:0x8bac6310 sptn:0x6013cfa0 uba: 0x00000000.0000.00 uba: 0x00000000.0000.00)
status:INVALID next:(nil)
(Note: occasionally cryptic name is empty, or "status:VALID", but same ORA-00600: [4156]).
In above trace file "Test_f", Step5 and Step6 are marked with a valid XID, but UNDO tuple contains 4 zeros:
Step5_SID:370, XID:(89.15.51190, 5635), UNDO:(0, 0, 0, 0), TEMP_UNDO_HEADER:(1, 19328, 3073)
gv$transaction is defined as:
select
...
ktcxbflg flag ,
decode (bitand (ktcxbflg, 16), 0, 'NO', 'YES') space ,
decode (bitand (ktcxbflg, 32), 0, 'NO', 'YES') recursive,
decode (bitand (ktcxbflg, 64), 0, 'NO', 'YES') noundo ,
decode (bitand (ktcxbflg, 8388608), 0, 'NO', 'YES') ptx ,
...
from x$ktcxb
where bitand (ksspaflg, 1) != 0 and bitand (ktcxbflg, 2) != 0
In above Step5, we have UNDO:(0, 0, 0, 0), but NOUNDO = 'NO'. It is not clear how this flag is set up.
We also tried to put a DML insert before "savepoint sp_a" to keep UNDO filled with non zeors, but it generates the same error.
insert into test_tab values(0);
savepoint sp_a;
insert into test_tab values(1);
insert into test_atemptab values(11);
savepoint sp_b;
begin
rollback to savepoint sp_a;
insert into test_atemptab values(12);
rollback to savepoint sp_b;
end;
/
In above investigation, we looked different traces and dumps to understand the error. In real operations, when such an error occurs, an incident file is generated. We can go through the incident file to find similar information (if dump file size is unlimited).
In the incident file, we can see the redo dump commands like:
Dump redo command(s):
ALTER SYSTEM DUMP REDO DBA MIN 3073 19328 DBA MAX 3073 19328 TIME MIN 1050591433 TIME MAX 1050593293
ALTER SYSTEM DUMP REDO DBA MIN 3073 19330 DBA MAX 3073 19330 TIME MIN 1050591451 TIME MAX 1050593311
kcra_dump_redo_tsn_rdba <- kturDiskRbkToSvpt <- kturRbkToSvpt <- ktcrsp1_new
<- ktcrsp1 <- ksudlc <- kss_del_cb <- kssdel <- ksupop
4. TEMP_UNDO_ENABLED = FALSE Workaround Test
Here the Oracle Workaround MOS Note (copy here to archive a persistent reference):
ORA-00600: [4156] when Rolling Back to a Savepoint (Doc ID 2242249.1)
Applies to:
Oracle Database - Standard Edition - Version 12.1.0.2 and later
Symptoms
You are running a procedure that utilizes savepoints, however,
when attempting to rollback to a savepoint, you experience the following error:
The stack trace will show similar stack:
ksedst1 <- ksedst <- dbkedDefDump <- ksedmp <- ksfdmp <- dbgexPhaseII <- dbgexExplicitEndInc
<- dbgeEndDDEInvocatio <- nImpl <- dbgeEndDDEInvocatio <- kturDiskRbkToSvpt <- kturRbkToSvpt
<- ktcrsp1 <- xctrsp <- roldrv <- kksExecuteCommand
Cause
This is due to a product defect. This is being investigated in unpublished
Bug 25393735 - SR18.1TEMPUNDO - TRC - KTURDISKRBKTOSVPT - ORA-600 [4156]
This issue occurs when we have temp undo and the logical standby performs eager apply.
Solution
Possible workaround is:
Set the TEMP_UNDO_ENABLED back to the default setting of FALSE.
TEMP_UNDO_ENABLED determines whether transactions within a particular session can have a temporary undo log.
The default choice for database transactions has been to have a single undo log per transaction.
This parameter, at the session level / system level scope, lets a transaction split its undo log into
temporary undo log (for changes on temporary objects) and permanent undo log (for changes on persistent objects).
Modifiable: ALTER SESSION, ALTER SYSTEM
Now we try to test the Workaround with the same code:
ALTER SESSION set TEMP_UNDO_ENABLED=FALSE;
-- ALTER SYSTEM set TEMP_UNDO_ENABLED= FALSE; is also tested. Same outcome
savepoint sp_a;
insert into test_tab values(1);
insert into test_atemptab values(11);
savepoint sp_b;
begin
rollback to savepoint sp_a;
insert into test_atemptab values(12);
rollback to savepoint sp_b;
end;
/
ORA-00603: ORACLE server session terminated by fatal error
ORA-00600: internal error code, arguments: [4156], [], [], [], [], [], [], [],
[], [], [], []
ORA-01086: savepoint 'SP_B' never established in this session or is invalid
ORA-06512: at line 4
Process ID: 24328
Session ID: 370 Serial number: 32536
kturRollbackToSavepoint perm undokturRollbackToSavepoint savepoint uba: 0x00c038d7.1a1c.0b xid: 0x0059.01f.0000c7f4
kturRollbackToSavepoint current call savepoint: ksucaspt num: 362 uba: 0x00c038d7.1a1c.0b
uba: 0x00000000.0000.00 xid: 0x0059.01f.0000c7f4
xid: 0x0000.000.00000000
In fact, we re-run all 5 test codes from previous Blog: ORA-600 [4156] SAVEPOINT and PL/SQL Exception Handling in the same DB (Oracle 19.6), once with default TEMP_UNDO_ENABLED=FALSE, and once with TEMP_UNDO_ENABLED=TRUE. They all generated ORA-600 [4156]. As above tests showed, it is not clear in which case the abvoe MOS Note Workaround can be applied.
