Oracle Global Temporary Table ORA-01555 and XML Data Size

(1)-Oracle Global Temporary Table ORA-01555 and Undo Retention       (2)-Oracle Global Temporary Table ORA-01555 and XML Data Size      

---

Contrary to common belief that ORA-01555 is caused by long running query or small UNDO Tablespace size, we will look two cases of Global Temporary Table (GTT) ORA-01555 in two Blogs. The test shows that the behavours are changed following different Oracle releases.

In previous Blog, we showed that GTT ORA-01555 is irrelevant to Undo Retention (undo_retention), but depends on Maximum Allowed Number of CR buffers per dba (_db_block_max_cr_dba). The same test throws ORA-01555 only in Oracle 19c and 18c, but not in 12c.

In this blog, we will make two tests to demonstrate that ORA-01555 on GTT with XMLTYPE column depends on XML Data size. The first test reads XML data from an XML file, the second reads from memory. The same test throws ORA-01555 only in Oracle 19c (regression), but not in 18c and 12c.

Note 1: ORA-01555 observed in 19.13/19.10/19.7, but not in 18.9 and 12.1.

Note 2: Test DB settings:

  temp_undo_enabled    TRUE
  undo_management      AUTO
  undo_retention       3600

1. Test Setup

Create a GTT table, a helper table, and two Plsql procedures.
The first procedure writes an XML file under the given directory.
The second procedure reads twice XML file into GTT. The first read is OK, but the second read fails with ORA-01555.

truncate table test_gtt_xml;
drop table test_gtt_xml cascade constraints;
create global temporary table test_gtt_xml (xml_data sys.xmltype) on commit preserve rows nocache;

drop table test_tab_aux;
create table test_tab_aux as select 123 x from dual;

create or replace directory TEST_DB_DIR as '/tmp';

-- Write an XML file under one given directory
create or replace procedure test_create_file_xml (p_cnt number, p_file_name varchar2 := 'MYTEST.XML') as 
  l_xml             xmltype;
  l_clob            clob;
  l_xml_len         number;
begin

  select xmlelement ("Document",
           xmlagg (
             xmlelement ("Product",
               xmlforest (lpad (x.no, 8, 'A') as "Name"))))    -- about 40 byte per Entry
    into l_xml
    from (select level no from dual connect by level <= p_cnt) x;
  
  l_clob := l_xml.getClobVal();
  l_xml_len := dbms_lob.getlength(l_clob);
  dbms_output.put_line('--==>> Create XML File with CLOB Len = '||l_xml_len||' ('||(ceil(l_xml_len/1024))||' KB), Row Count = '||p_cnt);
  
  dbms_xslprocessor.clob2file(l_clob, 'TEST_DB_DIR', p_file_name, nls_charset_id('UTF8'));
end;
/

-- Read XML file into GTT, create a table by inserting all XML rows, then delele GTT.
-- When reading XML file into GTT again, it raises ORA-01555
create or replace procedure test_file_xml_ora1555 (p_cnt number, p_file_name varchar2 := 'MYTEST.XML') as
  l_cnt number;
begin
  test_create_file_xml(p_cnt, p_file_name);             -- Write XML file with dbms_xslprocessor
  --test_create_file_xml_utl_file(p_cnt, p_file_name);  -- Write XML file with utl_file (see Appendix)
  
  delete test_gtt_xml;
  insert /*+ first GTT CTAS */ into test_gtt_xml (xml_data) 
    select xmltype(bfilename('TEST_DB_DIR', p_file_name), nls_charset_id('UTF8')) from dual;
    
  -- Using dbms_xslprocessor.read2clob hits UTL_FILE ORA-29284 for big XML data.
  --dbms_xslprocessor.read2clob('TEST_DB_DIR', p_file_name, nls_charset_id('UTF8'))

  execute immediate q'[
    create table test_xml_tab as
      select  xmltab.name                       
      from
        (select xml_data
         from   test_gtt_xml) xt
         ,xmltable('/Document/Product'
              passing xt.xml_data
              columns
                name   varchar2(11) path 'Name'
          ) xmltab]';
  
  execute immediate q'[select count(*) from test_xml_tab]' into l_cnt;
  dbms_output.put_line('--==>> Create table test_xml_tab with Row Countt='||l_cnt);
  delete test_gtt_xml;
  execute immediate 'drop table test_xml_tab cascade constraints';
  
  insert into test_tab_aux values (123);
  
  -- Note: if we add a "commit" here, there is no more ORA-01555
  --commit;

  --When reading XML file into GTT again, it raises ORA-01555
  insert /*+ second GTT CTAS */ into test_gtt_xml (xml_data) 
    select xmltype(bfilename('TEST_DB_DIR', p_file_name), nls_charset_id('UTF8')) from dual;

  rollback;
end;
/

2. Test Run With XML File

Run following test (file size: 7813 KB), the output shows ORA-01555 in the second reading of XML file:

SQL > exec test_file_xml_ora1555(50000*4);

  --==>> Create XML File with CLOB Len = 8000021 (7813 KB), Row Count = 200000
  --==>> Create table test_xml_tab with Row Countt=200000
  BEGIN test_file_xml_ora1555(50000*4); END;
  
  *
  ERROR at line 1:
  ORA-01555: snapshot too old: rollback segment number 127 with name "$TEMPUNDOSEG" too small
  ORA-06512: at "TEST_FILE_XML_ORA1555", line 37
  ORA-06512: at line 1

However, if we run with a small XML (file size: 1954 KB), the output does not report any ORA-01555 (successfully completed):

SQL > exec test_file_xml_ora1555(50000);

  --==>> Create XML File with CLOB Len = 2000021 (1954 KB), Row Count = 50000
  --==>> Create table test_xml_tab with Row Countt=50000
  
  PL/SQL procedure successfully completed.

We can wrap above test with 1555 errorstack trace and 10046 trace, and then look the trace file:

alter system set max_dump_file_size = UNLIMITED;

alter session set events='1555 trace name errorstack level 3: 10046 trace name context forever, level 1' 
                  tracefile_identifier='1555_trc_2';
      
exec test_file_xml_ora1555(50000*4);          

alter session set events='1555 trace name errorstack off: 10046 trace name context off'; 

DB alert.log shows the ORA-01555 of the second GTT CTAS with "SQL ID: 4cd8xanmu7byw, Query Duration=0 sec".

2022-08-07T07:51:29.464005+02:00
ORA-01555 caused by SQL statement below (SQL ID: 4cd8xanmu7byw, Query Duration=0 sec, SCN: 0x00000b7111df7084):
2022-08-07T07:51:29.464084+02:00
INSERT /*+ second GTT CTAS */ INTO TEST_GTT_XML (XML_DATA) SELECT XMLTYPE(BFILENAME('TEST_DB_DIR', :B1 ), NLS_CHARSET_ID('UTF8')) FROM DUAL
2022-08-07T07:51:29.464276+02:00
Errors in file /orabin/app/oracle/admin/testdb/diag/rdbms/testdb/testdb/trace/testdb_ora_5083_1555_trc_2.trc:
ORA-01555: snapshot too old: rollback segment number 116 with name "$TEMPUNDOSEG" too small

In trace file, we can see that first GTT insert (SQL ID: 2m4ysxb0sakrt) is successful with 1 row inserted,
whereas the second GTT insert (SQL ID: 4cd8xanmu7byw) failed with 0 row inserted.

********************************************************************************

SQL ID: 2m4ysxb0sakrt Plan Hash: 1388734953

INSERT /*+ first GTT CTAS */ INTO TEST_GTT_XML (XML_DATA) SELECT 
  XMLTYPE(BFILENAME('TEST_DB_DIR', :B1 ), NLS_CHARSET_ID('UTF8')) FROM DUAL

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.30       0.41         42       1357       5644           1
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      0.30       0.41         42       1357       5644           1

Rows (1st) Row Source Operation
---------- ---------------------------------------------------
         0 LOAD TABLE CONVENTIONAL  TEST_GTT_XML (cr=1357 pr=42 pw=387 time=411911 us starts=1)
         1  FAST DUAL  (cr=0 pr=0 pw=0 time=1 us starts=1 cost=2 size=0 card=1)

********************************************************************************

SQL ID: 4cd8xanmu7byw Plan Hash: 1388734953

INSERT /*+ second GTT CTAS */ INTO TEST_GTT_XML (XML_DATA) SELECT 
  XMLTYPE(BFILENAME('TEST_DB_DIR', :B1 ), NLS_CHARSET_ID('UTF8')) FROM DUAL

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      2.84       3.79          1        198       3650           0
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      2.84       3.79          1        198       3650           0

Rows (1st) Row Source Operation
---------- ---------------------------------------------------
         0 LOAD TABLE CONVENTIONAL  TEST_GTT_XML (cr=0 pr=0 pw=0 time=11 us starts=1)
         1  FAST DUAL  (cr=0 pr=0 pw=0 time=1 us starts=1 cost=2 size=0 card=1)

********************************************************************************

ORA-01555 Call Stack shows that error raised at Frame[17] ktussto (kernel transaction undo snapshot too old).

----- Error Stack Dump -----
ORA-01555: snapshot too old: rollback segment number 116 with name "$TEMPUNDOSEG" too small
----- Current SQL Statement for this session (sql_id=4cd8xanmu7byw) -----
INSERT /*+ second GTT CTAS */ INTO TEST_GTT_XML (XML_DATA) SELECT XMLTYPE(BFILENAME('TEST_DB_DIR', :B1 ), NLS_CHARSET_ID('UTF8')) FROM DUAL

--------------------- Binary Stack Dump ---------------------

[15] (kgeselv()+89 -> kgeade())
[16] (ksesec2()+205 -> kgeselv())
[17] (ktussto()+2152 -> ksesec2())
[18] (kturCRBackoutOneChg()+2433 -> ktussto())
[19] (ktrgcm()+10148 -> kturCRBackoutOneChg())
[20] (ktrgtc2()+1308 -> ktrgcm())
[21] (kdiixs1()+1371 -> ktrgtc2())
[22] (kdlgkd()+5247 -> kdiixs1())
[23] (kdl_write1()+1809 -> kdlgkd())
[24] (kdlf_write()+245 -> kdl_write1())
[25] (koklCopyWrite()+190 -> kdlf_write())
[26] (koklCopyCnv()+1889 -> koklCopyWrite())
[27] (koklCopyInt()+2581 -> koklCopyCnv())
[28] (kokliclo()+623 -> koklCopyInt())
[29] (koklcre()+872 -> kokliclo())
[30] (kokleva()+1219 -> koklcre())
[31] (evaopn2()+747 -> kokleva())
[32] (qesltcEvalOutofLineCols()+289 -> evaopn2())
[33] (qesltcBeforeRowProcessing()+1214 -> qesltcEvalOutofLineCols())
[34] (qerltcKdtBufferedInsRowCBK()+237 -> qesltcBeforeRowProcessing())
[35] (qerltcLoadStateMachine()+232 -> qerltcKdtBufferedInsRowCBK())
[36] (qerltcInsertSelectRop()+241 -> qerltcLoadStateMachine())
[37] (qerstRowP()+737 -> qerltcInsertSelectRop())
[38] (qerstRowP()+737 -> qerstRowP())
[39] (qerfiFetch()+143 -> qerstRowP())
[40] (qerstFetch()+449 -> qerfiFetch())
[41] (rwsfcd()+113 -> qerstFetch())
[42] (qerstFetch()+449 -> rwsfcd())
[43] (qerltcFetch()+1058 -> qerstFetch())
[44] (qerstFetch()+449 -> qerltcFetch())
[45] (insexe()+733 -> qerstFetch())
[46] (opiexe()+6773 -> insexe())
[47] (opipls()+2427 -> opiexe())
[48] (opiodr()+1202 -> opipls())
[49] (rpidrus()+198 -> opiodr())
[50] (skgmstack()+65 -> rpidrus())
[51] (rpidru()+132 -> skgmstack())
[52] (rpiswu2()+543 -> rpidru())
[53] (rpidrv()+1266 -> rpiswu2())
[54] (psddr0()+467 -> rpidrv())
[55] (psdnal()+624 -> psddr0())
[56] (pevm_EXECC()+306 -> psdnal())
[57] (pfrinstr_EXECC()+56 -> pevm_EXECC())
[58] (pfrrun_no_tool()+60 -> pfrinstr_EXECC())
[59] (pfrrun()+902 -> pfrrun_no_tool())
[60] (plsql_run()+752 -> pfrrun())

With following procedure, we can find the exact file size (or number of rows) which hits ORA-01555:

create or replace procedure test_file_xml_ora1555_finder (p_loops number, p_loop_base number := 74890) as 
  l_cnt  number;
begin
  for i in 1..p_loops loop
    l_cnt := p_loop_base + i-1;
    dbms_output.put_line('******************************************');
    dbms_output.put_line('--==>> Test with CNT = '||l_cnt);
    test_file_xml_ora1555(l_cnt);
  end loop;
  exception when others then
    dbms_output.put_line('--==>> Error when CNT = '||l_cnt);
    raise;
end;
/

The test output shows that ORA-01555 occurs only when number of rows reaches 74895 (file size: 2926 KB):

SQL> exec test_file_xml_ora1555_finder(10, 74893);

  ******************************************
  --==>> Test with CNT = 74893
  --==>> Create XML File with CLOB Len = 2995741 (2926 KB), Row Count = 74893
  --==>> Create table test_xml_tab with Row Countt=74893
  ******************************************
  --==>> Test with CNT = 74894
  --==>> Create XML File with CLOB Len = 2995781 (2926 KB), Row Count = 74894
  --==>> Create table test_xml_tab with Row Countt=74894
  ******************************************
  --==>> Test with CNT = 74895
  --==>> Create XML File with CLOB Len = 2995821 (2926 KB), Row Count = 74895
  --==>> Create table test_xml_tab with Row Countt=74895
  --==>> Error when CNT = 74895
  BEGIN test_file_xml_ora1555_finder(10, 74893); END;
  
  *
  ERROR at line 1:
  ORA-01555: snapshot too old: rollback segment number 109 with name "$TEMPUNDOSEG" too small
  ORA-06512: at "TEST_FILE_XML_ORA1555_FINDER", line 12
  ORA-06512: at "TEST_FILE_XML_ORA1555", line 37
  ORA-06512: at "TEST_FILE_XML_ORA1555_FINDER", line 8
  ORA-06512: at line 1

By the way, in procedure test_xml_ora1555, if adding one "commit" immediately before the second GTT insert,
there is no more ORA-01555 (see test_xml_ora1555 code).

3. Test Run With Memory XML

We can also reproduce ORA-01555 with memory XML data.

In a Plsql procedure, we first compose a memory XML data, then insert it into GTT table.
When inserting again by reading the same row, it hits ORA-01555.

create or replace procedure test_create_memory_xml(p_cnt number) as 
  l_xml             xmltype;
  l_clob            clob;
  l_xml_len         number;
  l_cnt             number;
begin
  execute immediate 'truncate table test_gtt_xml';
  
  -- Create memory XML data
  select xmlelement ("Document",
           xmlagg (
             xmlelement ("Person",
               xmlforest (lpad (x.no, 10, '0') as "Number",
                          lpad (x.no, 10, 'X') as "Name",
                          lpad (x.no, 14, 'A') as "Address"))))   -- about 100 byte per Entry
    into l_xml
    from (select level no from dual connect by level <= p_cnt) x;
  
  l_clob := l_xml.getClobVal();
  l_xml_len := dbms_lob.getlength(l_clob);
  dbms_output.put_line('--==>>> XML CLOB Len = '||l_xml_len||' ('||(ceil(l_xml_len/1024))||' KB), Row Count = '||p_cnt);
  
  -- incert into GTT
  insert into test_gtt_xml (xml_data) select l_xml from dual;
  select count(*) into l_cnt from test_gtt_xml;
  dbms_output.put_line('first row CNT='||l_cnt);
  
  commit;   -- above insert trx committed
  
  -- Double GTT table by reading own session committed data hits ORA_01555
  insert into test_gtt_xml (xml_data) select * from test_gtt_xml;
  select count(*) into l_cnt from test_gtt_xml;
  dbms_output.put_line('second row CNT='||l_cnt);
end;
/

When testing with 10,000 rows (XML with 977 KB), we receive ORA-01555:

SQL> exec test_create_memory_xml(1000*10);

  --==>>> XML CLOB Len = 1000021 (977 KB), Row Count = 10000
  first row CNT=1
  BEGIN test_create_memory_xml(1000*10); END;
  
  *
  ERROR at line 1:
  ORA-01555: snapshot too old: rollback segment number  with name "" too small
  ORA-22924: snapshot too old
  ORA-06512: at "TEST_CREATE_MEMORY_XML", line 31
  ORA-06512: at line 1

However when testing with 1,000 rows (XML with 98 KB), there is no ORA-01555:

SQL> exec test_create_memory_xml(1000);         

  --==>>> XML CLOB Len = 100021 (98 KB), Row Count = 1000
  first row CNT=1
  second row CNT=2

PL/SQL procedure successfully completed.

Similar to above test, we can create a procedure to find the exact size which hits ORA-01555:

create or replace procedure test_create_memory_xml_finder (p_loops number, p_loop_base number := 1000) as 
  l_step number;
  l_cnt  number;
begin
  for i in 1..p_loops loop
    l_cnt := p_loop_base + i-1;
    dbms_output.put_line('--==>>  Test with CNT = '||l_cnt);
    test_create_memory_xml(l_cnt);
  end loop;
  exception when others then
    dbms_output.put_line('--==>>  Error when CNT = '||l_cnt);
    raise;
end;
/

The test output shows that ORA-01555 occurs only when number of row reaches 2032 (file size: 199 KB):

SQL> exec test_create_memory_xml_finder(10, 2030);

  --==>>  Test with CNT = 2030
  --==>>> XML CLOB Len = 203021 (199 KB), Row Count = 2030
  first row CNT=1
  second row CNT=2
  --==>>  Test with CNT = 2031
  --==>>> XML CLOB Len = 203121 (199 KB), Row Count = 2031
  first row CNT=1
  second row CNT=2
  --==>>  Test with CNT = 2032
  --==>>> XML CLOB Len = 203221 (199 KB), Row Count = 2032
  first row CNT=1
  --==>>  Error when CNT = 2032
  BEGIN test_create_memory_xml_finder(10, 2030); END;
  
  *
  ERROR at line 1:
  ORA-01555: snapshot too old: rollback segment number  with name "" too small
  ORA-06512: at "TEST_CREATE_MEMORY_XML_FINDER", line 12
  ORA-22924: snapshot too old
  ORA-06512: at "TEST_CREATE_MEMORY_XML", line 31
  ORA-06512: at "TEST_CREATE_MEMORY_XML_FINDER", line 8
  ORA-06512: at line 1

In the above test, xmltype is stored as BLOB (Binary XML storage) in an automatically created hidden_column:

select table_name, column_name, data_type, data_type_owner, data_length, hidden_column, virtual_column
  from dba_tab_cols t where table_name = 'TEST_GTT_XML';

  TABLE_NAME    COLUMN_NAME   DATA_TYPE  DATA_TYPE_OWNER DATA_LENGTH HIDDEN_COLUMN   VIRTUAL_COLUMN
  ------------- ------------- ---------- --------------- ----------- --------------- ---------------
  TEST_GTT_XML  XML_DATA      XMLTYPE    SYS                    2000 NO              YES
  TEST_GTT_XML  SYS_NC00002$  BLOB                              4000 YES             NO

If we use 12.1 deprecated CLOB storage clause, there is no more ORA-01555:
(Note: Starting with Oracle Database 12c Release 1 (12.1.0.1), the unstructured (CLOB) storage model for XMLType is deprecated. Use binary XML storage instead).

truncate table test_gtt_xml;
drop table test_gtt_xml cascade constraints;

-- a hidden CLOB column is automatically created to store the XML data.
create global temporary table test_gtt_xml (xml_data sys.xmltype) on commit preserve rows nocache
                                            xmltype column xml_data store as clob;
  
select table_name, column_name, data_type, data_type_owner, data_length, hidden_column, virtual_column
  from dba_tab_cols t where table_name = 'TEST_GTT_XML';
                                              
  TABLE_NAME    COLUMN_NAME   DATA_TYPE  DATA_TYPE_OWNER DATA_LENGTH HIDDEN_COLUMN   VIRTUAL_COLUMN
  ------------- ------------- ---------- --------------- ----------- --------------- ---------------
  TEST_GTT_XML  XML_DATA      XMLTYPE    SYS                    2000 NO              YES
  TEST_GTT_XML  SYS_NC00002$  CLOB                              4000 YES             NO


-- Test and output
SQL> exec test_create_memory_xml(1000*10);

  --==>>> XML CLOB Len = 1000021 (977 KB), Row Count = 10000
  first row CNT=1
  second row CNT=2

Further test shows that CLOB storage only eliminates ORA-01555 for Memory XML reading, but we still get ORA-01555 for above XML File reading.

4. Appendix: Create XML File with utl_file

create or replace procedure test_create_file_xml_utl_file (p_cnt number, p_file_name varchar2 := 'MYTEST.XML')  as 
  l_file      utl_file.file_type;
  l_str       varchar2(4000);
begin
  l_str := 'AAAAAAA1AAAAAAA2';

  l_file := utl_file.fopen('TEST_DB_DIR', p_file_name, 'w', 32767);
  utl_file.put_line(l_file, '');
    
  for i in 1..p_cnt loop
    l_str := ''||lpad (i, 8, 'A') ||'';
    utl_file.put_line(l_file, l_str);
  end loop;
  utl_file.put_line(l_file, '');
  utl_file.fflush(l_file);
  
  -- Close the file.
  utl_file.fclose(l_file);
  exception when others then
    if utl_file.is_open(l_file) then
      utl_file.fclose(l_file);
    end if;
    raise;
end;
/

-- exec test_create_file_xml_utl_file(50000*4);

Oracle Global Temporary Table ORA-01555 and Undo Retention

(1)-Oracle Global Temporary Table ORA-01555 and Undo Retention       (2)-Oracle Global Temporary Table ORA-01555 and XML Data Size      

---

Contrary to common belief that ORA-01555 is caused by long running query or small UNDO Tablespace size, we will look two cases of Global Temporary Table (GTT) ORA-01555 in two Blogs. The test shows that the behavours are changed following different Oracle releases.

In this Blog, we will show that GTT ORA-01555 is irrelevant to Undo Retention (undo_retention), but depends on Maximum Allowed Number of CR buffers per dba (_db_block_max_cr_dba). The same test throws ORA-01555 only in Oracle 19c and 18c, but not in 12c.

In next blog, we will make two tests to demonstrate that ORA-01555 on GTT with XMLTYPE column depends on XML Data size. The first test reads XML data from an XML file, the second reads from memory. The same test throws ORA-01555 only in Oracle 19c (regression), but not in 18c and 12c.

Note 1. ORA-01555 observed in 19.13/19.10/19.7 and 18.9, but not in 12.1.

Note 2: Test DB settings:

  temp_undo_enabled    TRUE
  undo_management      AUTO
  undo_retention       3600

1. GTT ORA-01555 Test

According to Oracle:

  Temp undo is not managed like normal undo, doesn't have undo retention to avoid undo overwritten,
  one session sticks to one temp segment to store temp undo, so it is easier to be overwritten than normal undo.
  
  Example:
  if cursor is opened for table and and in a loop same table is updated and sometimes committed.
  So, cursor needs to read before image of these update/commit,
  and when required undo block to rollback change is overwritten, it raises ORA-1555.

We can construct the following test code.

Running it, in one second, we receive ORA-01555:

truncate table gtt_tab_1;
drop table gtt_tab_1 cascade constraints;
create global temporary table gtt_tab_1 (x number, y number) on commit preserve rows nocache;

insert into gtt_tab_1 select level, level from dual connect by level <= 3;
commit;

select count(*) from gtt_tab_1;

declare
  l_x          number;
  l_y          number;    
  l_update_cnt number := 10;   --hit ORA-1555 when l_update_cnt >= 6
  cursor c_gtt_cur is select /*+ GATHER_PLAN_STATISTICS MONITOR */ * from gtt_tab_1;
begin
  open c_gtt_cur;
  
  for i in 1..l_update_cnt loop
    update gtt_tab_1 set y = -i where x = 2;
    commit;
  end loop;
  
  loop
    fetch c_gtt_cur into l_x, l_y;
    exit when c_gtt_cur%notfound;
    dbms_output.put_line(l_x ||', '||l_y);
  end loop;
  close c_gtt_cur;
  
  rollback;
end;
/

Here the output:

ERROR at line 1:
ORA-01555:: snapshot too old: rollback segment number 5 with name "$TEMPUNDOSEG" too small
ORA-06512: at line 15

The test shows that GTT ORA-01555 is irrelevant to undo_retention (3600).

DB alert.log says "SQL ID: 4ancgbsm0js82, Query Duration=0 sec".

2022-08-05T17:04:30.326414+02:00
ORA-01555 caused by SQL statement below (SQL ID: 4ancgbsm0js82, Query Duration=0 sec, SCN: 0x00000b7111de659f):
2022-08-05T17:04:30.326471+02:00
SELECT /*+ GATHER_PLAN_STATISTICS MONITOR */ * FROM GTT_TAB_1

In above test, if we change l_update_cnt <= 5, there is no more ORA-01555.
Probably due to:

   _db_block_max_cr_dba	
       Maximum Allowed Number of CR buffers per dba
       default 6 (5 CR buffers and 1 Current buffer)

In fact, increasing "_db_block_max_cr_dba" to 20:

  alter system set "_db_block_max_cr_dba" = 20 scope=spfile;
     -- alter system reset "_db_block_max_cr_dba";
  startup force

ORA-01555 only occurs when l_update_cnt >= 20, but not when l_update_cnt <= 19.

2. ORA-01555 Errorstack Trace Event

We can wrap above test with 1555 errorstack trace and 10046 trace, and then look the trace file:

alter system set max_dump_file_size = UNLIMITED;

alter session set events='1555 trace name errorstack level 3: 10046 trace name context forever, level 1' 
                  tracefile_identifier='1555_trc_1';
      
-- above GTT ORA-01555 Test            

alter session set events='1555 trace name errorstack off: 10046 trace name context off'; 

In trace file (or MONITOR report), we can see 4 CR Buffer (query) Gets. Probably the 5th CR Get hits ORA_01555.

********************************************************************************
SQL ID: 4ancgbsm0js82 Plan Hash: 1581058644

SELECT /*+ GATHER_PLAN_STATISTICS MONITOR */ * 
FROM
 GTT_TAB_1

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          1          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        1      1.60       1.60          0          4          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        3      1.60       1.60          0          5          0           0

Rows (1st) Row Source Operation
---------- ---------------------------------------------------
         0 TABLE ACCESS FULL GTT_TAB_1 (cr=0 pr=0 pw=0 time=5 us starts=1 cost=30 size=212368 card=8168)
         
********************************************************************************

ORA-01555 Call Stack shows that error is raised at Frame[17] ktussto (kernel transaction undo snapshot too old).

----- Error Stack Dump -----
ORA-01555: snapshot too old: rollback segment number 2 with name "$TEMPUNDOSEG" too small
----- Current SQL Statement for this session (sql_id=4ancgbsm0js82) -----
SELECT /*+ GATHER_PLAN_STATISTICS MONITOR */ * FROM GTT_TAB_1

--------------------- Binary Stack Dump ---------------------

[15] (kgeselv()+89 -> kgeade())
[16] (ksesec2()+205 -> kgeselv())
[17] (ktussto()+2152 -> ksesec2())
[18] (kturCRBackoutOneChg()+2433 -> ktussto())
[19] (ktrgcm()+10148 -> kturCRBackoutOneChg())
[20] (ktrget2()+971 -> ktrgcm())
[21] (kdst_fetch0()+711 -> ktrget2())
[22] (kdstf000010100000000km()+7386 -> kdst_fetch0())
[23] (kdsttgr()+2154 -> kdstf000010100000000km())
[24] (qertbFetch()+1090 -> kdsttgr())
[25] (qerstFetch()+449 -> qertbFetch())
[26] (opifch2()+3211 -> qerstFetch())
[27] (opifch()+61 -> opifch2())
[28] (opipls()+7744 -> opifch())
[29] (opiodr()+1202 -> opipls())
[30] (rpidrus()+198 -> opiodr())
[31] (skgmstack()+65 -> rpidrus())
[32] (rpidru()+132 -> skgmstack())
[33] (rpiswu2()+543 -> rpidru())
[34] (rpidrv()+1266 -> rpiswu2())
[35] (psddr0()+467 -> rpidrv())
[36] (psdnal()+624 -> psddr0())
[37] (pevm_BFTCHC()+314 -> psdnal())
[38] (pfrinstr_FTCHC()+135 -> pevm_BFTCHC())
[39] (pfrrun_no_tool()+60 -> pfrinstr_FTCHC())
[40] (pfrrun()+902 -> pfrrun_no_tool())
[41] (plsql_run()+752 -> pfrrun())

SQL Monitoring Report

SQL > select SYS.DBMS_SQLTUNE.REPORT_SQL_MONITOR('4ancgbsm0js82', report_level=>'all' , type=>'TEXT') from dual;

SQL Text
------------------------------
SELECT /*+ GATHER_PLAN_STATISTICS MONITOR */ * FROM GTT_TAB_1

Error: ORA-1555
------------------------------
ORA-01555: snapshot too old: rollback segment number 2 with name "$TEMPUNDOSEG" too small

Global Information
------------------------------
 Status              :  DONE (ERROR)        
 SQL ID              :  4ancgbsm0js82       
 SQL Execution ID    :  16777219            
 Duration            :  2s                  
 Program             :  sqlplus.exe         
 Fetch Calls         :  1                   

Global Stats
=================================================
| Elapsed |   Cpu   |  Other   | Fetch | Buffer |
| Time(s) | Time(s) | Waits(s) | Calls |  Gets  |
=================================================
|    1.60 |    1.60 |     0.00 |     1 |      4 |
=================================================

SQL Plan Monitoring Details (Plan Hash Value=1581058644)
==============================================================================================================================
| Id |      Operation      |   Name    |  Rows   | Cost |   Time    | Start  | Execs |   Rows   | Activity | Activity Detail |
|    |                     |           | (Estim) |      | Active(s) | Active |       | (Actual) |   (%)    |   (# samples)   |
==============================================================================================================================
|  0 | SELECT STATEMENT    |           |         |      |           |        |     1 |          |          |                 |
|  1 |   TABLE ACCESS FULL | GTT_TAB_1 |    8168 |   30 |         2 |     +1 |     1 |        0 |   100.00 | Cpu (1)         |
==============================================================================================================================

DB alert.log

2022-08-07T08:57:07.444615+02:00
ORA-01555 caused by SQL statement below (SQL ID: 4ancgbsm0js82, Query Duration=0 sec, SCN: 0x00000b7111df77b8):
2022-08-07T08:57:07.444669+02:00
SELECT /*+ GATHER_PLAN_STATISTICS MONITOR */ * FROM GTT_TAB_1
2022-08-07T08:57:07.444798+02:00
Errors in file /orabin/app/oracle/admin/testdb/diag/rdbms/testdb/testdb/trace/testdb_ora_5083_1555_trc_1.trc:
ORA-01555: snapshot too old: rollback segment number 2 with name "$TEMPUNDOSEG" too small

3. GTT ORA-01555 Test of Implicit Cursor

We can also make a test of GTT ORA-01555 on implicit cursor for loops array fetch.

truncate table gtt_tab_1;
drop table gtt_tab_1 cascade constraints;
create global temporary table gtt_tab_1 (x number, y number) on commit preserve rows nocache;

create or replace function gtt_dml_test(p_rownum number) return number as
  l_cnt number := 0;
  pragma autonomous_transaction;
begin
  insert into gtt_tab_1 values(p_rownum, -p_rownum); 
  commit;
  dbms_output.put_line('DML SEQ = '|| p_rownum);
  return p_rownum;
end;
/

declare 
  l_cnt number := 0;
begin 
  execute immediate q'[truncate table gtt_tab_1]';
  insert into gtt_tab_1 select level, level from dual connect by level <= 1000; 
  commit; 

  select count(*) into l_cnt from gtt_tab_1;
  dbms_output.put_line('CNT-1 = '||l_cnt);
  
  l_cnt := 0;
  for c in (select x from gtt_tab_1 where gtt_dml_test(rownum) is not null)
  --for c in (select x from gtt_tab_1 order by gtt_dml_test(rownum))
  loop
    l_cnt := l_cnt + c.x/c.x;
  end loop;
  dbms_output.put_line('CNT-2 = '||l_cnt);
  
  select count(*) into l_cnt from gtt_tab_1;
  dbms_output.put_line('CNT-2 = '||l_cnt);
  
  exception when others then
    select count(*) into l_cnt from gtt_tab_1;
    dbms_output.put_line('CNT-3 = '||l_cnt);
    raise;
end;
/

Here the output:

CNT-1 = 1000
DML SEQ = 1
DML SEQ = 2
DML SEQ = 3
...
DML SEQ = 573
DML SEQ = 574
DML SEQ = 575
CNT-3 = 1575
declare
*
ERROR at line 1:
ORA-01555: snapshot too old: rollback segment number  with name "" too small
ORA-06512: at line 25
ORA-06512: at line 12
ORA-06512: at line 12

Since implicit cursor for loops array fetch 100 rows at a time by default, we hit ORA-01555 at 575th row in the 6th fetches (_db_block_max_cr_dba default 6). If we run above test with 1555 and 10046 traces:

alter system set max_dump_file_size = UNLIMITED;

alter session set events='1555 trace name errorstack level 3: 10046 trace name context forever, level 1' 
                  tracefile_identifier='1555_trc_2';
      
-- above GTT ORA-01555 Test of Implicit Cursor           

alter session set events='1555 trace name errorstack off: 10046 trace name context off'

The trace file shows that ORA-01555 occurs in 0 second (Query Length = 0) regardless of Undo Retention: 3600. Xplan shows 575rows fetched (table has 1000 rows).

SSOLD: SQL ID: 7rj7rptrm0vt1, Statement: 
SELECT X FROM GTT_TAB_1 WHERE GTT_DML_TEST(ROWNUM) IS NOT NULL

SSOLD: Query Length = 0 (sttm=1712430340, fchtm=1712430340, curtime=ts:1712430340)
SSOLD: Undo Retention (reactive): 3619, Max Query Length: 600, Best Possible Retention = 11418308
SSOLD: Parameter Undo Retention: 3600, Tuned Undo Retention: 3619, High threshold Undo Retention: 31536000, Autotune: 1
SSOLD: Parameter values: smu_debug = 0x0, undo_debug = 0x0txn_alert = 0x0

----- Abridged Call Stack Trace -----
ksedsts<-ktussto<-kturCRBackoutOneChg<-ktrgcm<-ktrget2<-kdst_fetch0<-kdstf000010100000000km<-kdsttgr
<-qertbFetch<-qerstFetch<-qerflFetchOutside<-qerstFetch<-qercoFetch<-qerstFetch<-opifch2<-opifch<-opipls

----- Error Stack Dump -----
ORA-01555: snapshot too old: rollback segment number 6 with name "$TEMPUNDOSEG" too small
----- Current SQL Statement for this session (sql_id=7rj7rptrm0vt1) -----
SELECT X FROM GTT_TAB_1 WHERE GTT_DML_TEST(ROWNUM) IS NOT NULL


********************************************************************************
SQL ID: 7rj7rptrm0vt1 Plan Hash: 1595833369

SELECT X FROM GTT_TAB_1 WHERE GTT_DML_TEST(ROWNUM) IS NOT NULL

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          2          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        6      2.02       3.56          0         10          0         575
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        8      2.02       3.56          0         12          0         575

Rows (1st)  Row Source Operation
----------  ---------------------------------------------------
       575  COUNT  (cr=607 pr=0 pw=0 time=99550 us starts=1)
       575   FILTER  (cr=607 pr=0 pw=0 time=99318 us starts=1)
       575    TABLE ACCESS FULL GTT_TAB_1 (cr=8 pr=0 pw=0 time=142 us starts=1 cost=30 size=106184 card=8168)

********************************************************************************

Plsql ORA-00600 by JDBC Call Exception Catch

When Plsql executions hit ORA-00600, the session can be disconnected or not disconnected. In this Blog, we will make tests to show both ORA-00600 cases can be caught and returned in JDBC Exception Catch.

Note: Tested in Oracle 19.13

1. Plsql Test Setup

1.1 ORA-00600 and Session Disconnected

For the first case, we take the same test code from Blog: ORA-600 [4156] SAVEPOINT and PL/SQL Exception Handling

drop table test_tab_disconnet;

create table test_tab_disconnet(id number, label varchar2(10));
insert into test_tab_disconnet(id, label) values(1, 'label');
commit;

create or replace procedure test_ora_600_disconnet as
begin
  savepoint sp;
  update test_tab_disconnet set label = label where id = 1;
  execute immediate '
    begin
      raise_application_error(-20000, ''error-sp'');
    exception
      when others then
        rollback to savepoint sp;
        update test_tab_disconnet set label = label where id = 1;
        raise;
    end;';
end;
/

-- Session disconnected when calling:
--   exec test_ora_600_disconnet;

--     ORA-00603: ORACLE server session terminated by fatal error
--     ORA-00600: internal error code, arguments: [4156], [], [], [], [], [], [], [], [], [], [], []
--     ORA-20000: error-sp
--     ORA-06512: at line 8
--     ORA-06512: at line 3
--     Process ID: 2496
--     Session ID: 193 Serial number: 5555

1.2 ORA-00600 and Session Not Disconnected

For the second case, we take the same test code from Blog: How volatile is ORA-00600 [qernsRowP] ?

drop type t_char100_varray50_test force;

create or replace noneditionable type t_char100_varray50_test as varray(50) of varchar2(100)
/

drop table test_tab_disconnet_no cascade constraints;

create table test_tab_disconnet_no as select level id, t_char100_varray50_test('a', 'b', 'c') vary
  from dual connect by level <= 1e4;

alter table test_tab_disconnet_no add constraint test_tab_disconnet_no#p primary key (id);

create or replace procedure test_ora_600_disconnet_no as
begin
  for c in (
    select /*+ parallel(4) index(t test_tab_disconnet_no#p) */ t.id, count(*)
      from test_tab_disconnet_no t, table(t.vary) v
    where rownum <= 3000
    group by t.id)
  loop
    null;
  end loop;
end;
/


-- Session not disconnected when calling:
--   exec test_ora_600_disconnet_no;

--     ORA-00600: internal error code, arguments: [qernsRowP], [1], [], [], [], [], [], [], [], [], [], []

1.3 Plsql Wait Helper

create or replace procedure test_wait_for_seconds (p_seconds number) as
begin
  dbms_application_info.set_client_info('Plsql Waiting '||p_seconds||' seconds for you to check Connection');
  dbms_session.sleep(p_seconds);
  dbms_application_info.set_client_info('Plsql Waiting '||p_seconds||' ended. JDBC Connection still alive');
end;
/

2 JDBC Test Setup

import java.sql.DriverManager;
import java.sql.Connection;
import java.sql.CallableStatement;
import java.sql.Struct;
import java.sql.Array;
import java.sql.SQLException;
import java.util.Vector;
import java.time.LocalDateTime; 
import oracle.jdbc.OracleTypes;
import oracle.jdbc.OracleConnection;

// Ora600JDBCTestV2       // 1: test_ora_600_disconnet;  2: test_ora_600_disconnet_no
// Ora600JDBCTestV2 "jdbc:oracle:thin:k/s@testDB:1522:testDB" 1
// Ora600JDBCTestV2 "jdbc:oracle:thin:k/s@testDB:1522:testDB" 2

public class Ora600JDBCTestV2 {
  static String TEST_PROC_DIS    = "begin test_ora_600_disconnet; end;";
  static String TEST_PROC_DIS_NO = "begin test_ora_600_disconnet_no; end;";
  static String WAIT_PROC        = "begin test_wait_for_seconds(30); end;";
  
  public static void main(String[] args) {
    String ret = ora600Call(args);
    // return caught outtput to show that ORA-00600 can be caught and returned.
    System.out.println("Ora600 JDBC calling return: " + ret);
  }
  
  static String ora600Call(String[] args) {
   String jdbcURL      = args[0];
   int    connCase     = Integer.parseInt(args[1]);
   CallableStatement cStmt;
   String exceptMessage = "No Exception";
   
   try {
     Class.forName("oracle.jdbc.driver.OracleDriver");
   } catch (ClassNotFoundException e) {
     System.out.println("Where is your Oracle JDBC Driver ?");
     e.printStackTrace();
     return "ClassNotFoundException return";
   }
   
   System.out.println(java.time.LocalDateTime.now()); 
   Connection conn = null;
   try {
       conn = DriverManager.getConnection(jdbcURL);
       System.out.println("You Connected");
       
       cStmt = conn.prepareCall(WAIT_PROC);
       System.out.println("Waiting 30 seconds .... for you to check Connection");
       cStmt.execute();
       cStmt.close();  
       
       System.out.println(java.time.LocalDateTime.now()); 
       if (connCase == 1) {
         System.out.println("test_ora_600_disconnet starting ....");
         cStmt = conn.prepareCall(TEST_PROC_DIS);
       } else {
         System.out.println("test_ora_600_disconnet_no starting ....");
         cStmt = conn.prepareCall(TEST_PROC_DIS_NO);
       }   
       
       cStmt.execute();
       cStmt.close();  
       
       System.out.println("You made it, Test End");
       return "Normal return";     
   } catch (Exception e) {
       System.out.println(java.time.LocalDateTime.now()); 
       exceptMessage = e.toString();
       System.err.println("You have Exception: " + e.getMessage());
       e.printStackTrace();
       return "Exception return:" + exceptMessage;
   } finally {
       System.out.println(java.time.LocalDateTime.now()); 
       // return Plsql Exception Message to JDBC caller for catching
       System.out.println("Return Plsql Exception to JDBC caller: " + exceptMessage);
       System.out.println("Waiting 30 seconds .... before FINALLY return");
       try {
           Thread.sleep(30*1000);  
       } catch (InterruptedException e) {
           System.out.println(e);
       }  
       System.out.println(java.time.LocalDateTime.now());   
       System.out.println("You FINALLY return.");
       return "FINALLY return:" + exceptMessage;
   }
  }
}

3. Test Run

Compile JDBC code and run two tests.

From output, we can see that ORA-00600 can be caught and returned in both cases.

3.1 ORA-00600 and Session Disconnected

$ > Ora600JDBCTestV2 "jdbc:oracle:thin:k/s@testDB:1522:testDB" 1     
                                                              
2022-07-17T08:16:54.514
You Connected
Waiting 30 seconds .... for you to check Connection
2022-07-17T08:17:25.042
test_ora_600_disconnet starting ....
2022-07-17T08:17:38.935
You have Exception: ORA-00603: ORACLE server session terminated by fatal error
ORA-00600: internal error code, arguments: [4156], [], [], [], [], [], [], [], [], [], [], []
ORA-20000: error-sp
ORA-06512: at line 8
ORA-06512: at line 3

java.sql.SQLRecoverableException: ORA-00603: ORACLE server session terminated by fatal error
ORA-00600: internal error code, arguments: [4156], [], [], [], [], [], [], [], [], [], [], []
ORA-20000: error-sp
ORA-06512: at line 8
ORA-06512: at line 3

        at oracle.jdbc.driver.T4CTTIoer11.processError(T4CTTIoer11.java:509)
        at oracle.jdbc.driver.T4CTTIoer11.processError(T4CTTIoer11.java:461)
        at oracle.jdbc.driver.T4C8Oall.processError(T4C8Oall.java:1104)
        at oracle.jdbc.driver.T4CTTIfun.receive(T4CTTIfun.java:553)
        at oracle.jdbc.driver.T4CTTIfun.doRPC(T4CTTIfun.java:269)
        at oracle.jdbc.driver.T4C8Oall.doOALL(T4C8Oall.java:655)
        at oracle.jdbc.driver.T4CCallableStatement.doOall8(T4CCallableStatement.java:265)
        at oracle.jdbc.driver.T4CCallableStatement.doOall8(T4CCallableStatement.java:86)
        at oracle.jdbc.driver.T4CCallableStatement.executeForRows(T4CCallableStatement.java:965)
        at oracle.jdbc.driver.OracleStatement.doExecuteWithTimeout(OracleStatement.java:1205)
        at oracle.jdbc.driver.OraclePreparedStatement.executeInternal(OraclePreparedStatement.java:3666)
        at oracle.jdbc.driver.T4CCallableStatement.executeInternal(T4CCallableStatement.java:1358)
        at oracle.jdbc.driver.OraclePreparedStatement.execute(OraclePreparedStatement.java:3778)
        at oracle.jdbc.driver.OracleCallableStatement.execute(OracleCallableStatement.java:4251)
        at oracle.jdbc.driver.OraclePreparedStatementWrapper.execute(OraclePreparedStatementWrapper.java:1081)
        at Ora600JDBCTestV2.ora600Call(Ora600JDBCTestV2.java:60)
        at Ora600JDBCTestV2.main(Ora600JDBCTestV2.java:22)
Caused by: Error : 603, Position : 0, Sql = begin test_ora_600_disconnet; end;, OriginalSql = begin test_ora_600_disconnet; end;, Error Msg = ORA-00603: ORACLE server session terminated by fatal error
ORA-00600: internal error code, arguments: [4156], [], [], [], [], [], [], [], [], [], [], []
ORA-20000: error-sp
ORA-06512: at line 8
ORA-06512: at line 3

        at oracle.jdbc.driver.T4CTTIoer11.processError(T4CTTIoer11.java:513)
        ... 16 more
2022-07-17T08:17:38.936
Return Plsql Exception to JDBC caller: java.sql.SQLRecoverableException: ORA-00603: ORACLE server session terminated by fatal error
ORA-00600: internal error code, arguments: [4156], [], [], [], [], [], [], [], [], [], [], []
ORA-20000: error-sp
ORA-06512: at line 8
ORA-06512: at line 3

Waiting 30 seconds .... before FINALLY return
2022-07-17T08:18:08.937
You FINALLY return.
Ora600 JDBC calling return: FINALLY return:java.sql.SQLRecoverableException: ORA-00603: ORACLE server session terminated by fatal error
ORA-00600: internal error code, arguments: [4156], [], [], [], [], [], [], [], [], [], [], []
ORA-20000: error-sp
ORA-06512: at line 8
ORA-06512: at line 3

3.2 ORA-00600 and Session Not Disconnected

$ > Ora600JDBCTestV2 "jdbc:oracle:thin:k/s@testDB:1522:testDB" 2     

2022-07-17T08:21:06.148
You Connected
Waiting 30 seconds .... for you to check Connection
2022-07-17T08:21:36.690
test_ora_600_disconnet_no starting ....
2022-07-17T08:21:37.750
You have Exception: ORA-00600: internal error code, arguments: [qernsRowP], [1], [], [], [], [], [], [], [], [], [], []

java.sql.SQLException: ORA-00600: internal error code, arguments: [qernsRowP], [1], [], [], [], [], [], [], [], [], [], []

        at oracle.jdbc.driver.T4CTTIoer11.processError(T4CTTIoer11.java:509)
        at oracle.jdbc.driver.T4CTTIoer11.processError(T4CTTIoer11.java:461)
        at oracle.jdbc.driver.T4C8Oall.processError(T4C8Oall.java:1104)
        at oracle.jdbc.driver.T4CTTIfun.receive(T4CTTIfun.java:553)
        at oracle.jdbc.driver.T4CTTIfun.doRPC(T4CTTIfun.java:269)
        at oracle.jdbc.driver.T4C8Oall.doOALL(T4C8Oall.java:655)
        at oracle.jdbc.driver.T4CCallableStatement.doOall8(T4CCallableStatement.java:265)
        at oracle.jdbc.driver.T4CCallableStatement.doOall8(T4CCallableStatement.java:86)
        at oracle.jdbc.driver.T4CCallableStatement.executeForRows(T4CCallableStatement.java:965)
        at oracle.jdbc.driver.OracleStatement.doExecuteWithTimeout(OracleStatement.java:1205)
        at oracle.jdbc.driver.OraclePreparedStatement.executeInternal(OraclePreparedStatement.java:3666)
        at oracle.jdbc.driver.T4CCallableStatement.executeInternal(T4CCallableStatement.java:1358)
        at oracle.jdbc.driver.OraclePreparedStatement.execute(OraclePreparedStatement.java:3778)
        at oracle.jdbc.driver.OracleCallableStatement.execute(OracleCallableStatement.java:4251)
        at oracle.jdbc.driver.OraclePreparedStatementWrapper.execute(OraclePreparedStatementWrapper.java:1081)
        at Ora600JDBCTestV2.ora600Call(Ora600JDBCTestV2.java:60)
        at Ora600JDBCTestV2.main(Ora600JDBCTestV2.java:22)
Caused by: Error : 600, Position : 0, Sql = begin test_ora_600_disconnet_no; end;, OriginalSql = begin test_ora_600_disconnet_no; end;, Error Msg = ORA-00600: internal error code, arguments: [qernsRowP], [1], [], [], [], [], [], [], [], [], [], []

        at oracle.jdbc.driver.T4CTTIoer11.processError(T4CTTIoer11.java:513)
        ... 16 more
2022-07-17T08:21:37.751
Return Plsql Exception to JDBC caller: java.sql.SQLException: ORA-00600: internal error code, arguments: [qernsRowP], [1], [], [], [], [], [], [], [], [], [], []

Waiting 30 seconds .... before FINALLY return
2022-07-17T08:22:07.752
You FINALLY return.
Ora600 JDBC calling return: FINALLY return:java.sql.SQLException: ORA-00600: internal error code, arguments: [qernsRowP], [1], [], [], [], [], [], [], [], [], [], []

Tests of Oracle ORA-01866: the datetime class is invalid

In this Blog, we will make a few tetss of Oracle ORA-01866 in Named and Offset Time_Zone (TZ).

Note 1: Tested in Oracle 19.13, 19.10, 18.9, 12.1
Note 2: The behaviour was first observed by other people in Oracle applications.

1. Test Setup

We create a test table with a column of data type "timestamp with local time zone" and insert two rows with value of "to_date(1,'J')" (4712-JAN-01 00:00:00 BC) in Named TZ and Offset TZ respectively.

drop table test_tab;

create table test_tab (id number, lts timestamp with local time zone);

alter session set time_zone = 'Europe/Paris';

-- row 1 inserted in Named TZ
insert into test_tab values (1,  to_date(1,'J'));

commit;

alter session set time_zone = '+02:00';

-- row 2 inserted in Offset TZ
insert into test_tab values (2,  to_date(1,'J'));

commit;

alter session set nls_date_format         ='YYYY*MON*DD HH24:MI:SS AD';    
alter session set nls_timestamp_format    ='YYYY*MON*DD HH24:MI:SS.FF3 AD';
alter session set nls_timestamp_tz_format ='YYYY-MON-DD HH24:MI:SS.FF3 TZR TZD AD';


select validate_conversion('0' as date, 'J', 'NLS_DATE_LANGUAGE = American') not_valid_date_0_return_0,
       validate_conversion('1' as date, 'J', 'NLS_DATE_LANGUAGE = American') valid_date_1_return_1,
       validate_conversion('2' as date, 'J', 'NLS_DATE_LANGUAGE = American') valid_date_2_return_1
  from dual;

  NOT_VALID_DATE_0_RETURN_0 VALID_DATE_1_RETURN_1 VALID_DATE_2_RETURN_1
  ------------------------- --------------------- ---------------------
                          0                     1                     1

select cast('0' as date default '2459808' on conversion error, 'J', 'NLS_DATE_LANGUAGE = American') not_valid_date_0_return_today,
       cast('1' as date default '2459808' on conversion error, 'J', 'NLS_DATE_LANGUAGE = American') valid_date_1_return,
       cast('2' as date default '2459808' on conversion error, 'J', 'NLS_DATE_LANGUAGE = American') valid_date_2_return
  from dual; 

  NOT_VALID_DATE_0_RETURN VALID_DATE_1_RETURN     VALID_DATE_2_RETURN
  ----------------------- ----------------------- -----------------------
  2022*JUN*26 00:00:00 AD 4712*JAN*01 00:00:00 BC 4712*JAN*02 00:00:00 BC

2. Test Run

We will make 4 tests for 4 combinations of Named and Offset TZ.
All commented test outputs are from Oracle 19.13 on Sqlplus running on Microsoft Windows remotely connecting to Unix DB.

2.1 Test in Named TZ for Row inserted in Named TZ

col id    for 999
col lts   for a40
col dtext for a40

alter session set time_zone = 'Europe/Paris';

select dbtimezone, sessiontimezone from dual;
  --  +01:00    Europe/Paris

select t.*, dump(lts) dtext from test_tab t where id = 1;
  --       1    7161*JAN*01 00:51:00.000 AD    Typ=231 Len=7: 53,88,1,1,1,52,1

select cast(lts as timestamp with local time zone) from test_tab where id = 1;
  --  7161*JAN*01 00:51:00.000 AD

select cast(lts as timestamp with time zone) from test_tab where id = 1;
  --  ORA-01866: the datetime class is invalid

select cast(lts as date) from test_tab where id = 1;
  --  ORA-01866: the datetime class is invalid

select sys_extract_utc("LTS") from test_tab where id = 1;
  --  ORA-01866: the datetime class is invalid

2.2 Test in Offset TZ for Row inserted in Named TZ

alter session set time_zone = '+02:00';

select dbtimezone, sessiontimezone from dual;
  --  +01:00    +02:00

select t.*, dump(lts) dtext from test_tab t where id = 1;
  --       1   7161*JAN*01 01:51:00.000 AD    Typ=231 Len=7: 53,88,1,1,1,52,1

select cast(lts as timestamp with local time zone) from test_tab where id = 1;
  --  7161*JAN*01 01:51:00.000 AD

select cast(lts as timestamp with time zone) from test_tab where id = 1;
  --  4712-JAN-02 01:51:00.000 +02:00  BC

select cast(lts as date) from test_tab where id = 1;
  --  4712*JAN*01 01:51:00 BC

select sys_extract_utc("LTS") from test_tab where id = 1;
  --  4712*JAN*01 23:51:00.000 BC

2.3 Test in Named TZ for Row inserted in Offset TZ

alter session set time_zone = 'Europe/Paris';

select dbtimezone, sessiontimezone from dual;
  --  +01:00    Europe/Paris

select t.*, dump(lts) dtext from test_tab t where id = 2;
  --  ORA-01877: string is too long for internal buffer

select cast(lts as timestamp with local time zone) from test_tab where id = 2;
  --  ORA-01877: string is too long for internal buffer

select cast(lts as timestamp with time zone) from test_tab where id = 2;
  --  ORA-01877: string is too long for internal buffer

select cast(lts as date) from test_tab where id = 2;
  --  ORA-01858: a non-numeric character was found where a numeric was expected

select sys_extract_utc("LTS") from test_tab where id = 2;
  --  ORA-01877: string is too long for internal buffer

2.4 Test in Offset TZ for Row inserted in Offset TZ

alter session set time_zone = '+02:00';

select dbtimezone, sessiontimezone from dual;
  --  +01:00    +02:00

select t.*, dump(lts) dtext from test_tab t where id = 2;
  --       2    2848*MAY*07 00:00:00.000 BC    Typ=231 Len=7: 71,152,151,127,24,1,1

select cast(lts as timestamp with local time zone) from test_tab where id = 2;
  --  2848*MAY*07 00:00:00.000 BC

select cast(lts as timestamp with time zone) from test_tab where id = 2;
  --  ORA-01877: string is too long for internal buffer

select cast(lts as date) from test_tab where id = 2;
  --  ORA-01866: the datetime class is invalid

select sys_extract_utc("LTS") from test_tab where id = 2;
  --  ORA-01866: the datetime class is invalid

3. Script to Find to_date(1,'J')

With following script, we can find all rows with column value: "to_date(1,'J')":

alter session set time_zone = '+02:00';
  -- alter session set time_zone = dbtimezone;
  -- alter session set time_zone = 'Europe/Paris';

declare 
  l_lts       timestamp with local time zone;
  l_lts_dump  varchar2(50);
begin
  for c in (select id from test_tab)
  loop
    begin
      select lts, dump(lts) into l_lts, l_lts_dump from test_tab where id = c.id;
      if l_lts_dump like 'Typ=231 Len=7: 53,88,1,1,%' or l_lts_dump like 'Typ=231 Len=7: 71,152,151,127,%' then
        dbms_output.put_line('ID='||c.id ||', '||l_lts||','||l_lts_dump||'===>4712-01-01 BC');    --write to a table
      else
        dbms_output.put_line('ID='||c.id ||', '||l_lts||','||l_lts_dump);
      end if;
    exception when others 
      then dbms_output.put_line('ID='||c.id||', '||SQLERRM);   --write to a table
    end;
  end loop;
end;
/

Here two rows found:

ID=1, 4712*JAN*01 01:51:00.000 BC,Typ=231 Len=7: 53,88,1,1,1,52,1===>4712-01-01 BC
ID=2, ORA-01891: Datetime/Interval internal error

Following tests show that we cannot find all such rows with simple queries:

alter session set time_zone = 'Europe/Paris';

select * from test_tab where lts = to_date(1,'J');
  --  1   7161*JAN*01 00:51:00.000 AD
  
alter session set time_zone = '+02:00';

select * from test_tab where lts = to_date(1,'J');
  --  no rows selected

4. Error Code and Date Format

Following tests demonstrate that Error Code varies with Date Format:

alter session set time_zone = 'Europe/Paris';

alter session set nls_date_format  ='DD-MON-YYYY';  

select cast(lts as date) from test_tab where id = 2;
  -- ORA-01801: date format is too long for internal buffer

alter session set nls_date_format  ='YYYY-MON-DD';  

select cast(lts as date) from test_tab where id = 2;
  -- ORA-01858: a non-numeric character was found where a numeric was expected

5. Oracle Releases and Used Tools

The output depends on Oracle Releases and used tools (Sqlplus local or remote Connections, TOAD, Sql Developer).

For example,

--=== Oracle 19.13 with remote Connection:

alter session set time_zone = 'Europe/Paris';

select cast(lts as timestamp with local time zone) from test_tab where id = 1;
  --  7161*JAN*01 00:51:00.000 AD
  
  
--=== Oracle 19.10, 18.9 and 12.1 with remote Connection:

alter session set time_zone = 'Europe/Paris';

select cast(lts as timestamp with local time zone) from test_tab where id = 1; 
  --  ORA-01866: the datetime class is invalid

Even strange is that if you run the same select twice, the output of first run and that of the second can be different.

6. 1866 Trace Event

Oracle MOS: "EM 12c: Error in the Enterprise Manager 12.1.0.4 Cloud Control Repository Database Alert Log: ORA-01866: the datetime class is invalid (Doc ID 1969582.1)" documented 1866 trace event as follows:

      Set the event:
       alter system set events '1866 trace name errorstack level 3';
      wait for the next ORA-1866
       alter system set events '1866 trace name errorstack off';

Once setting this event system wide, when ORA-1866 occurs, DB alert.log shows that trace file, which contains Current SQL Statement, call stack, and data block dump.
From them, we can locate the problem program, table, data block and table rows.

For example,

alter session set max_dump_file_size = UNLIMITED;
alter system set events '1866 trace name errorstack level 4';
 
alter session set time_zone = 'Europe/Paris';

declare 
  l_lts            timestamp with local time zone;
  l_lts_date       date;
  l_lts_dump       varchar2(50);
begin
  select cast(lts as date), dump(lts) into l_lts_date, l_lts_dump from test_tab where id = 1;
    -- ORA-01866: the datetime class is invalid
end;
/

alter system set events '1866 trace name errorstack off';

-- Output
  ERROR at line 1:
  ORA-01866: the datetime class is invalid
  ORA-06512: at line 6

Then DB alert.log shows:

2022-06-25T06:42:45.774336+02:00
Errors in file /orabin/app/oracle/admin/testdb/diag/rdbms/testdb/testdb/trace/testdb_ora_24592.trc:
ORA-01866: the datetime class is invalid

Open trace file "testdb_ora_24592.trc", we can see:

ORA-01866: the datetime class is invalid
----- Current SQL Statement for this session (sql_id=068wc1kt3fhhn) -----
SELECT CAST(LTS AS DATE), DUMP(LTS) FROM TEST_TAB WHERE ID = 1

----- PL/SQL Call Stack -----
  object      line  object
  handle    number  name
0x80bf09d8         6  anonymous block

----- Call Stack Trace -----
 [9] (dbgdProcessEventActions()+525 -> dbgdRunActions())
[10] (dbgdChkEventKgErr()+394 -> dbgdProcessEventActions())
[11] (dbkdChkEventRdbmsErr()+65 -> dbgdChkEventKgErr())
[12] (dbgePostErrorKGE()+1066 -> dbkdChkEventRdbmsErr())
[13] (dbkePostKGE_kgsf()+71 -> dbgePostErrorKGE())
[14] (kgeade()+392 -> dbkePostKGE_kgsf())
[15] (kgeselv()+89 -> kgeade())
[16] (kgesecl0()+145 -> kgeselv())
[17] (evadica()+565 -> kgesecl0())
[18] (evaopn2()+747 -> evadica())
[19] (evaopn2()+594 -> evaopn2())
[20] (evaopn2()+594 -> evaopn2())
[21] (opifcr()+524 -> evaopn2())
[22] (kdstf110010100000000km()+1015 -> opifcr())
[23] (kdsttgr()+2154 -> kdstf110010100000000km())
[24] (qertbFetch()+1090 -> kdsttgr())
[25] (opifch2()+3211 -> qertbFetch())
[26] (opiefn0()+490 -> opifch2())
[27] (opipls()+3142 -> opiefn0())
[28] (opiodr()+1202 -> opipls())
[29] (rpidrus()+198 -> opiodr())
[30] (skgmstack()+65 -> rpidrus())
[31] (rpidru()+132 -> skgmstack())
[32] (rpiswu2()+543 -> rpidru())
[33] (rpidrv()+1266 -> rpiswu2())
[34] (psddr0()+467 -> rpidrv())
[35] (psdnal()+624 -> psddr0())
[36] (pevm_EXECC()+306 -> psdnal())
[37] (pfrinstr_EXECC()+56 -> pevm_EXECC())
[38] (pfrrun_no_tool()+60 -> pfrinstr_EXECC())
[39] (pfrrun()+902 -> pfrrun_no_tool())
[40] (plsql_run()+752 -> pfrrun())

Trace file also contains data block dump (including rdba, obj, block_row_dump).
From above tests, we can see the dump of those special datetime:

select id, dump(lts, 16) from test_tab;

 ID   DUMP(LTS,16)
 ---- ---------------------------------
  1	  Typ=231 Len=7: 35,58,1,1,1,34,1
  2	  Typ=231 Len=7: 47,98,97,7f,18,1,1

Then searching string "35 58 01 01" and "47 98 97 7f" in data block dump, we can locate the exact problem rows:

BH (0x114f7b180) file#: 74 rdba: 0x001300ff (1024/1245439) class: 1 ba: 0x114404000
  set: 15 pool: 3 bsz: 8192 bsi: 0 sflg: 0 pwc: 0,25
  dbwrid: 0 obj: 4733309 objn: 4733309 tsn: [0/3315] afn: 74 hint: f
  
block_row_dump:
tab 0, row 0, @0x1f8a
tl: 14 fb: --H-FL-- lb: 0x1  cc: 2
col  0: [ 2]  c1 02
col  1: [ 7]  35 58 01 01 01 34 01
tab 0, row 1, @0x1f7c
tl: 14 fb: --H-FL-- lb: 0x2  cc: 2
col  0: [ 2]  c1 03
col  1: [ 7]  47 98 97 7f 18 01 01

7. Datatype Conversion

Look xplan:

select * from test_tab where lts = to_date(1,'J');

------------------------------------------------------------------------------
| Id  | Operation         | Name     | Rows  | Bytes | Cost (%CPU)| Time     |
------------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |          |     4 |   104 |     3   (0)| 00:00:01 |
|*  1 |  TABLE ACCESS FULL| TEST_TAB |     4 |   104 |     3   (0)| 00:00:01 |
------------------------------------------------------------------------------
 
Predicate Information (identified by operation id):
---------------------------------------------------
 
   1 - filter("LTS"=TO_DATE('-4712-01-01 00:00:00', 'syyyy-mm-dd hh24:mi:ss'))

Predicate Information shows that Oracle internally converts "to_date(1,'J')" to "TO_DATE('-4712-01-01 00:00:00', 'syyyy-mm-dd hh24:mi:ss')"
which is datatype "DATE", whereas LTS is datatype "TIMESTAMP WITH LOCAL TIME ZONE"
(such conversion can cause "ORA-01878: specified field not found in datetime or interval").

Oracle Datetime (1) - Concepts wrote:

When you compare date and timestamp values, Oracle Database converts the data to the more precise data type 
before doing the comparison. 
For example, if you compare data of TIMESTAMP WITH TIME ZONE data type with data of TIMESTAMP data type, 
Oracle Database converts the TIMESTAMP data to TIMESTAMP WITH TIME ZONE, using the session time zone.

The order of precedence for converting date and timestamp data is as follows:
    DATE
    TIMESTAMP
    TIMESTAMP WITH LOCAL TIME ZONE
    TIMESTAMP WITH TIME ZONE

For more discussions of Oracle datetime, see Blog: Oracle Datetime (1) - Concepts

How volatile is ORA-00600 [qernsRowP] ?

ORA-600 [qernsRowP] seems related to a parallel query when the execution plan includes SORT GROUP BY NOSORT.

This Blog will demonstrate ORA-00600 [qernsRowP] with one small test code (probably one shortest ORA-00600 test code).

Note: Tested in Oracle 19.13, 19.7, 18.9, 12.1

1. Test Setup

drop type t_char100_varray50 force;

create or replace noneditionable type t_char100_varray50 as varray(50) of varchar2(100)
/

drop table test_tab cascade constraints;

create table test_tab as select level id, t_char100_varray50('a', 'b', 'c') vary
  from dual connect by level <= 1e4;
  
-- No primary key, no error
alter table test_tab add constraint test_tab#p primary key (id);

2. Test Run

Run following query, it throws ORA-00600 [qernsRowP].

select /*+ parallel(4) index(t test_tab#p) */ t.id, count(*)
  from test_tab t, table(t.vary) v
where rownum <= 3000
group by t.id;

    ID   COUNT(*)
 ----- ----------
     1          3
     2          3
     3          3
  ...
  2602          3
  2603          3
  
  ERROR:
  ORA-00600: internal error code, arguments: [qernsRowP], [1], [], [], [], [], [], [], [], [], [], []

  615 rows selected.
  
  Note that sometime error occurs alternatively (not in first run, but in second run).

If we limit rownum to a small number, e.g. 100, no error occurs, but exact number is hard to find (varying with Oracle release, OS, and run sequence).

-- rownum <= 100, no error. Exact number is not fixed. 
select /*+ parallel(4) index(t test_tab#p) */ t.id, count(*)
  from test_tab t, table(t.vary) v
where rownum <= 100
group by t.id;

    ID   COUNT(*)
  ---- ----------
     1          3
     2          3
   ... 
    33          3
    34          1

  34 rows selected.

If we remove parallel hint, there is also no more errors.

--remove parallel hint, no error.
select /*+ index(t test_tab#p) */  t.id, count(*)
  from test_tab t, table(t.vary) v 
where rownum <= 1000
group by t.id; 

        ID   COUNT(*)
  ----- ----------
      1          3
      2          3
    ...  
    333          3
    334          1

  334 rows selected.

For ORA-00600 [qernsRowP] query, Plan Table is dumped in session trace and incident file.
The rowsource line 1 contains "SORT GROUP BY NOSORT".

Plan Table
--------------------------------------------------------------------+-----------------------------------+-------------------------+
| Id  | Operation                             | Name      | Rows  | Bytes | Cost  | Time      | ObjectId  |  TQ  |IN-OUT|PQ Distrib |
--------------------------------------------------------------------+-----------------------------------+-------------------------+
| 0   | SELECT STATEMENT                      |           |       |       |  6016 |           |           |      |      |           |
| 1   |  SORT GROUP BY NOSORT                 |           |  3000 | 5540K |  6016 |  06:26:57 |           |      |      |           |
| 2   |   COUNT STOPKEY                       |           |       |       |       |           |           |      |      |           |
| 3   |    NESTED LOOPS                       |           |   46M |   86G |  6016 |  06:26:57 |           |      |      |           |
| 4   |     PX COORDINATOR                    |           |       |       |       |           |           |      |      |           |
| 5   |      PX SEND QC (RANDOM)              | :TQ10001  |  5963 |   11M |    44 |  00:03:50 |           |:Q1001| P->S |QC (RANDOM)|
| 6   |       TABLE ACCESS BY INDEX ROWID     | TEST_TAB  |  5963 |   11M |    44 |  00:03:50 | 4683207   |:Q1001| PCWP |           |
| 7   |        BUFFER SORT                    |           |       |       |       |           |           |:Q1001| PCWC |           |
| 8   |         PX RECEIVE                    |           |  5963 |       |    11 |  00:00:43 |           |:Q1001| PCWP |           |
| 9   |          PX SEND HASH (BLOCK ADDRESS) | :TQ10000  |  5963 |       |    11 |  00:00:43 |           |      | S->P |HASH (BLOCK ADDRESS)|
| 10  |           INDEX FULL SCAN             | TEST_TAB#P|  5963 |       |    11 |  00:00:43 | 4683210   |      |      |           |
| 11  |     COLLECTION ITERATOR PICKLER FETCH |           |  8168 |       |     8 |  00:00:31 |           |      |      |           |
--------------------------------------------------------------------+-----------------------------------+-------------------------+

Predicate Information:
----------------------
2 - filter(ROWNUM<=3000)
 
Content of other_xml column
===========================
  dop_reason     : hint
  dop            : 4
  px_in_memory_imc: no
  px_in_memory   : no
  db_version     : 19.0.0.0
-----------------

  Hint Report:
    Query Block: SEL$F5BB74E1
      Table: ("T"@"SEL$1") index(t test_tab#p)
    Statement: parallel(4)

Call Stack in incident file looks like:

  --------------------- Binary Stack Dump ---------------------
  [1]  (ksedst1()+95 -> kgdsdst())
  [2]  (ksedst()+58 -> ksedst1())
  [3]  (dbkedDefDump()+23448 -> ksedst())
  [4]  (ksedmp()+577 -> dbkedDefDump())
  [5]  (dbgexPhaseII()+2092 -> ksedmp())
  [6]  (dbgexProcessError()+1871 -> dbgexPhaseII())
  [7]  (dbgePostErrorKGE()+1853 -> dbgexProcessError())
  [8]  (dbkePostKGE_kgsf()+71 -> dbgePostErrorKGE())
  [9]  (kgeadse()+447 -> dbkePostKGE_kgsf())
  [10] (kgerinv_internal()+44 -> kgeadse())
  [11] (kgerinv()+40 -> kgerinv_internal())
  [12] (kgesinv()+21 -> kgerinv())
  [13] (ksesin()+180 -> kgesinv())
  [14] (qernsRowP()+501 -> ksesin())          --ERROR SIGNALED: yes   COMPONENT: SQL_Execution
  [15] (qercoRop()+111 -> qernsRowP())
  [16] (qerocpFetch()+428 -> qercoRop())
  [17] (qerocFetch()+201 -> qerocpFetch())
  [18] (qerjotRowProc()+397 -> qerocFetch())
  [19] (qerpxFetch()+995 -> qerjotRowProc())
  [20] (qerjotFetch()+2094 -> qerpxFetch())
  [21] (qercoFetch()+299 -> qerjotFetch())
  [22] (qernsFetch()+424 -> qercoFetch())
  [23] (opifch2()+3211 -> qernsFetch())
  [24] (opifch()+61 -> opifch2())
  [25] (opiodr()+1202 -> opifch())
  [26] (ttcpip()+1246 -> opiodr())  

MOS provides a workaround, but test shows that it does not work.

     ORA-600 [qernsrowp] (Doc ID 285913.1)
     ORA-00600 [QERNSROWP] When Running a Parallel Query With Group By NOSORT Option (Doc ID 984955.1)

workarounds

  Alter session set events '10119 trace name context forever, level 12';
  alter session set events '10119 trace name context forever';

MOS: Receiving ORA-600 [qernsRowP] Internal Error When Saving Changes. (Doc ID 455139.1) provides solution:

  -- To implement the solution, please execute the following steps::
  Setting cursor_sharing=EXACT

But our test DB is already set "Setting cursor_sharing=EXACT"

  SQL > show parameter cursor_sharing
  
     NAME             TYPE    VALUE
     ---------------- ------- -----
     cursor_sharing   string  exact

One Case of ORA-00036: Maximum Number Of Recursive SQL Levels (50) Exceeded

ORA-00036 is documented as:

  00036, 00000, "maximum number of recursive SQL levels (%s) exceeded"
  // *Cause:  An attempt was made to go more than the specified number
  //          of recursive SQL levels.
  // *Action: Remove the recursive SQL, possibly a recursive trigger.

The most (possibly only) circulated test code is about recursive trigger
(see MOS: PL/SQL Trigger causes ORA-00036: Maximum Number Of Recursive SQL Levels (50) Exceeded (Doc ID 1478056.1)).

This Blog will demonstrate one most often occurred case of ORA-00036 in Oracle applications.

Note: Tested in Oracle 19.13, 19.7, 18.9, 12.1

1. Test Setup

We create a Plsql procedure, which makes dynamic recursive calls with execute immediate.

create or replace procedure recursive_dynamic (p_depth number) as 
begin
  dbms_output.put_line('Depth = '|| p_depth); 
  execute immediate q'[begin recursive_dynamic (:dep); end;]' using p_depth + 1;
end;
/

2. Dynamic Recursive Call

We run the test with "36 trace" and "10046 trace". (See MOS: OERR: ORA-36 "maximum number of recursive SQL levels (%s) exceeded" Reference Note (Doc ID 48793.1))

alter session set max_dump_file_size = UNLIMITED;
alter session set events='36 trace name errorstack level 3: 10046 trace name context forever, level 12' 
                  tracefile_identifier='recursive_trc';
            
begin      
  execute immediate q'[begin recursive_dynamic (:dep); end;]' using 1;
end;
/

alter session set events='36 trace name errorstack off: 10046 trace name context off';

After a few seconds, session throws ORA-00036 after 51 recursive calls:

Depth = 1
Depth = 2
Depth = 3
...
Depth = 49
Depth = 50
Depth = 51

ORA-00036: maximum number of recursive SQL levels (50) exceeded
ORA-06512: at "K.RECURSIVE_DYNAMIC", line 4
ORA-06512: at line 1

Elapsed: 00:00:02.92

Trace file shows 51 "PARSING IN CURSOR" with dep=1 to dep=51 and Bind#0 from value=1 to value=51:

PARSING IN CURSOR #140643820632152 dep=1 tim=142118502429 hv=3989675504 ad='8cbdaf18' sqlid='2s8jqqgqwv7gh'
begin recursive_dynamic (:dep); end;
END OF STMT
PARSE #140643820632152:c=238,e=238,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=1,plh=0,tim=142118502429
BINDS #140643820632152:

 Bind#0
  oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
  oacflg=03 fl2=1206001 frm=00 csi=00 siz=24 off=0
  kxsbbbfp=7fea315aff88  bln=22  avl=02  flg=05
  value=1
  
...
 
PARSING IN CURSOR #140643819871240 dep=51 tim=142118509346 hv=3989675504 ad='8cbdaf18' sqlid='2s8jqqgqwv7gh'
begin recursive_dynamic (:dep); end;
END OF STMT
PARSE #140643819871240:c=12,e=12,p=0,cr=0,cu=0,mis=0,r=0,dep=51,og=1,plh=0,tim=142118509346
BINDS #140643819871240:

 Bind#0
  oacdty=02 mxl=22(21) mxlc=00 mal=00 scl=00 pre=00
  oacflg=13 fl2=206001 frm=00 csi=00 siz=24 off=0
  kxsbbbfp=7fea30ebb770  bln=22  avl=02  flg=09
  value=51

Here the Call Stack:

----- Error Stack Dump -----
ORA-00036: maximum number of recursive SQL levels (50) exceeded
Current SQL information unavailable - no cursor.
----- PL/SQL Call Stack -----
  object      line  object
  handle    number  name
0x8cccbf90         4  procedure K.RECURSIVE_DYNAMIC
0x8cbcedf0         1  anonymous block
0x8cccbf90         4  procedure K.RECURSIVE_DYNAMIC
0x8cbcedf0         1  anonymous block
0x8cccbf90         4  procedure K.RECURSIVE_DYNAMIC
0x8cbcedf0         1  anonymous block
0x8cccbf90         4  procedure K.RECURSIVE_DYNAMIC  
  
--------------------- Binary Stack Dump ---------------------
[13] (dbkePostKGE_kgsf()+71 -> dbgePostErrorKGE()) 
[14] (kgeade()+392 -> dbkePostKGE_kgsf()) 
[15] (kgeselv()+89 -> kgeade()) 
[16] (ksesec1()+205 -> kgeselv()) 
[17] (ksuprc()+1629 -> ksesec1()) 
[18] (opiodr()+760 -> ksuprc()) 
[19] (rpidrus()+198 -> opiodr()) 
[20] (skgmstack()+65 -> rpidrus()) 
[21] (rpidru()+132 -> skgmstack()) 
[22] (rpiswu2()+543 -> rpidru()) 
[23] (rpidrv()+1266 -> rpiswu2()) 
[24] (psddr0()+467 -> rpidrv()) 
[25] (psdopn()+72 -> psddr0()) 
[26] (plcurOpen()+64 -> psdopn()) 
[27] (kgscGetCursor()+4842 -> plcurOpen()) 
[28] (pevm_I4EXIM()+601 -> kgscGetCursor()) 
[29] (pfrinstr_I4EXIM()+167 -> pevm_I4EXIM()) 
[30] (pfrrun_no_tool()+60 -> pfrinstr_I4EXIM()) 
[31] (pfrrun()+902 -> pfrrun_no_tool()) 
[32] (plsql_run()+752 -> pfrrun()) 

In Call Stack Trace, we can see that Oracle detected "recursion pattern":

----- Call Stack Trace -----

**** At frame 91 recursion pattern of size 17 found, for return address 
     rpiswu2()+543 suppressing  printing.
**** At frame 100 recursion pattern broken, last return was 
     plsql_run()
     
**** At frame 891 recursion pattern of size 17 found, for return address 
     rpidrv()+1266 suppressing  printing.
**** At frame 900 recursion pattern broken, last return was 
     peicnt()

The 51 recursive calls generated 51 Cursors from Cursor#7 to Cursor#57 with Bind#0 from value=1 to value=51:

----------------------------------------
Cursor#7(0x7fea318a0908) state=BOUND curiob=0x7fea30f7f858
 curflg=0xcd fl2=0x0 fl3=0x0 par=(nil) ses=0xb8c54908
----- Dump Cursor sql_id=2s8jqqgqwv7gh xsc=0x7fea30f7f858 cur=0x7fea318a0908 -----

LibraryHandle:  Address=0x8cbdaf18 Hash=edcd9df0 LockMode=N PinMode=0 LoadLockMode=0 Status=VALD 
  ObjectName:  Name=begin recursive_dynamic (:dep); end; 
  
----- Bind Info (kkscoacd) -----
 Bind#0
  oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
  oacflg=03 fl2=1206001 frm=00 csi=00 siz=24 off=0
  kxsbbbfp=7fea315aff88  bln=22  avl=02  flg=05
  value=1
  
...

----------------------------------------
Cursor#57(0x7fea318a2848) state=BOUND curiob=0x7fea30ec5c08
 curflg=0xc5 fl2=0x0 fl3=0x0 par=(nil) ses=0xb8c54908
----- Dump Cursor sql_id=2s8jqqgqwv7gh xsc=0x7fea30ec5c08 cur=0x7fea318a2848 -----

LibraryHandle:  Address=0x8cbdaf18 Hash=edcd9df0 LockMode=N PinMode=0 LoadLockMode=0 Status=VALD 
  ObjectName:  Name=begin recursive_dynamic (:dep); end; 

----- Bind Info (kkscoacd) -----
 Bind#0
  oacdty=02 mxl=22(21) mxlc=00 mal=00 scl=00 pre=00
  oacflg=13 fl2=206001 frm=00 csi=00 siz=24 off=0
  kxsbbbfp=7fea30ebb770  bln=22  avl=02  flg=09
  value=51

10046 SQL trace shows Parse and Execute with count=51:

SQL ID: 2s8jqqgqwv7gh Plan Hash: 0

begin recursive_dynamic (:dep); end;


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse       51      0.00       0.00          0          0          0           0
Execute     51      2.76       2.89          0          0          0           0
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total      102      2.76       2.89          0          0          0           0

Misses in library cache during parse: 1
Misses in library cache during execute: 2
Optimizer mode: ALL_ROWS
Parsing user id: 49     (recursive depth: 1)

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  PGA memory operation                            7        0.00          0.00

3. Static Recursive Call

In contrast to "execute immediate" dynamic calls, we can also test static recursive calls as follows.

create or replace procedure recursive_static (p_depth number) as 
begin
  recursive_static(p_depth + 1);
end;
/
   
alter session set max_dump_file_size = UNLIMITED;
alter session set events='36 trace name errorstack level 3: 10046 trace name context forever, level 12' 
                  tracefile_identifier='static_trc'; 
begin      
  execute immediate q'[begin recursive_static (:dep); end;]' using 1;
end;
/

alter session set events='36 trace name errorstack off: 10046 trace name context off';

If the machine has sufficient memory (more than 32 GB), after about one hour, session throws ORA-03114.

begin
  execute immediate q'[begin recursive_static (:dep); end;]' using 1;
end;
 /
 
ORA-03114: not connected to ORACLE

ERROR at line 1:
ORA-03113: end-of-file on communication channel
Process ID: 11285
Session ID: 564 Serial number: 15134

Elapsed: 00:59:46.25

In DB alert.log / Trace / Incident file, we can see ORA-04030: out of process memory due to PL/SQL STACK.

-- DB alert.log / Trace / Incident file
ORA-04030: out of process memory when trying to allocate 8216 bytes (PLS PGA hp,PL/SQL STACK)

82%   26 GB, 3421439 chunks: "PL/SQL STACK              "  PL/SQL
         PLS PGA hp      ds=7fffbdb2bd40  dsprt=7fffbdb831f0
17% 5436 MB, 349774 chunks: "pl/sql vc2                "  PL/SQL
         koh-kghu sessi  ds=7fffbbfa3050  dsprt=7fffbd8f96b8
 1%  200 MB, 12842 chunks: "pmucalm coll              "  PL/SQL
         koh-kghu sessi  ds=7fffbd749660  dsprt=7fffbd8f96b8

If the machine has not sufficient memory (less than 32 GB), session also hits ORA-03114.

begin
  execute immediate q'[begin recursive_static (:dep); end;]' using 1;
end;
/

ORA-03114: not connected to ORACLE

ERROR at line 1:
ORA-03113: end-of-file on communication channel
Process ID: 20417
Session ID: 14 Serial number: 53851

Elapsed: 00:01:27.51

But DB alert.log / Trace / Incident file reported ORA-6544:

ORA-6544 [pevm_peruws_callback-1] [27102] [] [] [] [] [] [] [] [] [] []

========= Dump for incident 28438 (ORA 6544 [pevm_peruws_callback-1]) ========

----- Current SQL Statement for this session (sql_id=g3u50dymhsuwn) -----
begin recursive_static (:dep); end;

----- PL/SQL Call Stack -----
  object      line  object
  handle    number  name
0x8cccb400         1  procedure K.RECURSIVE_STATIC
0x8cccb400         4  procedure K.RECURSIVE_STATIC
0x8cccb400         4  procedure K.RECURSIVE_STATIC
0x8cccb400         4  procedure K.RECURSIVE_STATIC
0x8cccb400         4  procedure K.RECURSIVE_STATIC
0x8cccb400         4  procedure K.RECURSIVE_STATIC

[8]  (dbgePostErrorDirect()+798 -> dbgePostErrorDirectVaList_int()) 
[9]  (pevm_peruws_callback()+1233 -> dbgePostErrorDirect()) 
[10] (kgepop()+438 -> pevm_peruws_callback()) 
[11] (kgersel()+256 -> kgepop()) 
[12] (ksmrf_init_alloc()+508 -> kgersel()) 
[13] (ksmapg()+539 -> ksmrf_init_alloc()) 
[14] (kgh_invoke_alloc_cb()+494 -> ksmapg()) 
[15] (kghgex()+2751 -> kgh_invoke_alloc_cb()) 
[16] (kghfnd()+1030 -> kghgex()) 
[17] (kghalo()+6631 -> kghfnd()) 
[18] (kghgex()+760 -> kghalo()) 
[19] (kghalf()+1607 -> kghgex()) 
[20] (pfrsgr()+246 -> kghalf()) 
[21] (pevm_ENTER()+3089 -> pfrsgr()) 
[22] (pfrinstr_ENTER()+59 -> pevm_ENTER()) 
[23] (pfrrun_no_tool()+60 -> pfrinstr_ENTER()) 
[24] (pfrrun()+902 -> pfrrun_no_tool()) 
[25] (plsql_run()+752 -> pfrrun()) 

In Oracle, ORA-6544 is documented as:

  06544, 00000, "PL/SQL: internal error, arguments: [%s], [%s], [%s], [%s], [%s], [%s], [%s], [%s]"
  // *Cause: A pl/sql internal error occurred.
  // *Action:Report as a bug; the first argument is the internal error nuber.

Note*: typo "nuber"

In such case, Linux dmesg shows that session process hits "Out of memory", so in-kernel, that is still something similar to ORA-04030.

[09:55:19] Out of memory: Kill process 20417 (oracle_20417_c0) score 784 or sacrifice child
[09:55:19] Killed process 20417 (oracle_20417_c0) total-vm:23949296kB, anon-rss:18819800kB, file-rss:2332kB, shmem-rss:375432kB

Oracle Write Consistency and ORA-30926: "unable to get a stable set of rows in the source tables"

(1)-Oracle Write Consistency and ORA-00600: [13030], [20]      (2)-Oracle Write Consistency and ORA-30926      

---

We will discuss Oracle Write Consistency and different error messages in two Blogs.

Following previous Blog: Oracle Write Consistency and ORA-00600: [13030], [20],
this 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"

Note: Tested in Oracle 19.13, 19.7, 18.9, 12.1

1. Test Setup

We use the same test code of previous Blog, but change column txt from "not null" to nullable:

alter table test_tab modify txt varchar2(1) null;

  --alter table test_tab modify (txt not null);

So its DDL looks like:

create table test_tab (id number, txt varchar2(1), constraint test_tab_pk primary key (id));          

2. Test Run

We run the same test as previous Blog:

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 18:52:20: update id=2 from A to B

At T2, SID-2 updates txt from 'A' to 'B' with filter condition: "test_pkg.non_deterministic_fun(id, 10) > 0", which sleeps 10 seconds before return. Its output toggles as 0 or 1 in successive call for the given id.

--========== 2. SID-2@T2 ==========--

alter session set nls_timestamp_format ='HH24:MI:SS.ff3';  

alter session set tracefile_identifier = 'Null_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 18:53:01: Reset Package Variables: b_1_cnt=0, b_2_cnt=0
At 18:53:11: b_1_cnt=1, non_deterministic_fun(1, 10)=1
At 18:53:21: b_2_cnt=1, non_deterministic_fun(2, 10)=1
At 18:54:28: b_1_cnt=2, non_deterministic_fun(1, 10)=0
At 18:54:38: b_1_cnt=3, non_deterministic_fun(1, 10)=1

ORA-30926: unable to get a stable set of rows in the source tables
ORA-06512: at line 4
      Elapsed: 00:01:37.37

At T3, SID-1 sleeps 30 seconds and commits its T1 update.
Sleeps another 5 seconds.
Then updates txt from 'A' to 'B' for id=1 and commit.

--========== 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 18:53:48: wait id=2 update for 30 seconds
At 18:54:18: commit id=2 update. Then wait 5 seconds
At 18:54:23: update id=1 from A to B, and commit
      Elapsed: 00:00:35.10

From test output, we can see the update sequence:

At 18:52:20: SID-1 update id=2 from A to B.
At 18:53:01: SID-2 start running. get into "phase=NOT LOCKED". sleep 10 seconds. 
At 18:53:11: SID-2 update id=1 because non_deterministic_fun(1, 10)=1. sleep 10 seconds.
At 18:53:21: 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 18:54:18: 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 18:54:23: SID-1 update id=1 from A to B, and commit.
At 18:54:28: SID-2 get into "phase=NOT LOCKED". id=1 check non_deterministic_fun(1, 10)=0. sleep 10 seconds. 
At 18:54:38: SID-2 id=1 check non_deterministic_fun(1, 10)=1.
             SID-2 raise ORA-30926: unable to get a stable set of rows in the source tables

Here SID-2 DML UTS tracing file (only related lines extracted).

  
===================== *** 18:53:01
PARSING IN CURSOR #140130541280008 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: 
===================== *** 18:53:11
WAIT #140130541280008: nam='PL/SQL lock timer' ela= 10000747 tim=12530784547085
===================== *** 18:53:21
WAIT #140130541280008: nam='PL/SQL lock timer' ela= 10000350 tim=12530794548111
===================== *** 18:54:18
WAIT #140130541280008: nam='enq: TX - row lock contention' ela= 57331903 name|mode=1415053318 usn<<16 | slot=7929886 sequence=75843 obj#=3122646 tim=12530851880410
dmlTrace:file:line (kdu.c:3505) cmpf 20 rowcol 1 piececol 1
updThreePhaseExe: objn=3122646 phase=LOCK
===================== *** 18:54:28
WAIT #140130541280008: nam='PL/SQL lock timer' ela= 10000913 tim=12530861882109
updThreePhaseExe: objn=3122646 phase=ALL LOCKED
===================== *** 18:54:38
WAIT #140130541280008: nam='PL/SQL lock timer' ela= 10000212 tim=12530871883059
Block header dump:  0x000c9786
 
 Itl           Xid                  Uba         Flag  Lck        Scn/Fsc
0x01   0x0079.01e.00012843  0x00c037cf.2339.04  --U-    1  fsc 0x0000.5dd736a1
0x02   0x007d.01e.00011c65  0x00c00edd.1dbf.0c  --U-    1  fsc 0x0000.5dd736ac
===============
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
updThreePhaseExe: Table 0 Code 20 Cannot update, all rows locked: 002fa5d6.000c9786.0

EXEC #140130541280008:c=126042,e=97365970,p=0,cr=23,cu=10,mis=0,r=0,dep=1,og=1,plh=1551061149,tim=12530871911513
ERROR #140130541280008:err=30926 tim=12530871911558

We can see that all the test output is almost identical to previous Blog: Write Consistency and error ORA-00600: [13030], [20]. but error messages are different.

  when column "txt not null", it is ORA-00600: [13030], [20]
  when column "txt null",     it is ORA-30926: "unable to get a stable set of rows in the source tables"

3. Related Work

Oracle MOS: How to Troubleshoot ORA-30926 Errors? (Doc ID 471956.1) wrote:

  Applies to:
    Oracle Database - Enterprise Edition - Version 8.1.7.4 to 11.2.0.4 [Release 8.1.7 to 11.2]

  ORA-30926 (formerly ORA-600 [13012]) 
  
  30926, 00000, "unable to get a stable set of rows in the source tables"  
  // *Cause:  A stable set of rows could not be got because of large dml
  //          activity or a non-deterministic where clause.
  // *Action: Remove any non-deterministic where clauses and reissue the dml.
  
  Troubleshooting Steps
    - If the error occurs in your SQLPLUS session, use:
    SQL> alter session set events '30926 trace name errorstack level 3';
            Run the failing script/procedure etc.
         This event can be disabled by ending the session or by using:
    SQL> alter session set events '30926 trace name errorstack off'; 

So ORA-30926 was formerly ORA-600 [13012] for column "null", similar to ORA-600 [13030] for column "not null".

We also tried with trace event 30926 in SID-2:

--========== 2. SID-2@T2 ==========--

alter session set max_dump_file_size = UNLIMITED;
alter session set tracefile_identifier = 'Null_Error_2';
alter session set events ë30926 trace name errorstack level 3í;

--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;
/

alter session set events ë30926 trace name errorstack offí; 

Here the trace file (only related lines extracted):

DML restarted sqlid : 6jabvd6xa3vfh
dmlTrace:file:line (kdu.c:3505) cmpf 20 rowcol 1 piececol 1

Block header dump:  0x000c9786
 Itl           Xid                  Uba         Flag  Lck        Scn/Fsc
0x01   0x007e.015.00011c86  0x00c02dbd.1ea0.03  --U-    1  fsc 0x0000.5df1e217
0x02   0x007f.01d.00013bad  0x00c01fbf.20ca.03  --U-    1  fsc 0x0000.5df1e212
data_block_dump,data header at 0x135a18064
===============
tab 0, row 0, @0x1f90
tl: 8 fb: --H-FL-- lb: 0x1  cc: 2
col  0: [ 2]  c1 02
col  1: [ 1]  42
tab 0, row 1, @0x1f88
tl: 8 fb: --H-FL-- lb: 0x2  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
updThreePhaseExe: Table 0 Code 20 Cannot update, all rows locked: 002fa5d6.000c9786.0

30926 trace name errorstack level 3
trace [RDBMS.DML] {callstack: fname dmlTrace} disk=high trace("DML restarted sqlid : %\n", sqlid())

It looks like DML UTS in Blog: Write consistency and DML restart (Mahmoud Hatem) and shows the same trace event to find update statement hitting the write consistency.

  alter system set events 'trace[DML] {callstack: fname dmlTrace} disk=high trace("DML restarted sqlid : %\n", sqlid())';