Monday, July 18, 2022

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], [], [], [], [], [], [], [], [], [], []

Sunday, June 26, 2022

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

Tuesday, May 24, 2022

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

Monday, April 11, 2022

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())';

Oracle Write Consistency and ORA-00600: [13030], [20]

(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.

This Blog will make one test to demonstrate Write Consistency and error ORA-00600: [13030], [20].
Next Blog will show Write Consistency and ORA-30926: "unable to get a stable set of rows in the source tables".

We will show that error message depends on column declaration:
  for column "not null", it is ORA-00600: [13030], [20]
  for column "null",     it is ORA-30926: "unable to get a stable set of rows in the source tables"
Note: Tested in Oracle 19.13, 19.7, 18.9, 12.1


1. Test Setup


We create a simple table with two columns, and insert two rows:

drop table test_tab;

create table test_tab (id number, txt varchar2(1) not null, constraint test_tab_pk primary key (id));     
  -- ORA-30926: unable to get a stable set of rows
  --create table test_tab (id number, txt varchar2(1), constraint test_tab_pk primary key (id));     

insert into test_tab values (1, 'A');
insert into test_tab values (2, 'A');
commit;

SQL> select * from test_tab;

     ID   TXT
    ---  ----
      1    A
      2    A
Then create a non deterministic function (non_deterministic_fun) in a Plsql package. The function toggles its return value as 0 or 1 in successive call for the given input after sleeping the specified seconds.

create or replace package test_pkg as
  b_1_cnt    number := 0;
  b_2_cnt    number := 0;
  
  function  non_deterministic_fun(p_id number, p_sleep number := 10) return number;
  procedure set_cnt (p_1_cnt number, p_2_cnt number);
  procedure prt_tx_locks;
end;
/

create or replace package body test_pkg as
  function non_deterministic_fun(p_id number, p_sleep number := 10) return number as
    l_ret     number;
    l_cnt_str varchar2(20);
  begin
    case p_id
      when 1 then 
        b_1_cnt   := b_1_cnt + 1;
        l_ret     := mod(b_1_cnt, 2);  
        l_cnt_str := ': b_1_cnt='||b_1_cnt;
      when 2 then
        b_2_cnt   := b_2_cnt + 1;
        l_cnt_str := ': b_2_cnt='||b_2_cnt;
        l_ret     := mod(b_2_cnt, 2);
    end case;

    dbms_lock.sleep(p_sleep);  --dbms_session.sleep(p_sleep);    -- Oracle 19c 
    dbms_output.put_line('At '||localtimestamp ||l_cnt_str||', non_deterministic_fun('||p_id||', '||p_sleep||')='||l_ret);  -- print after 10 seconds sleep
    prt_tx_locks;              -- Print TX locks 
    return l_ret;
  end;
  
  procedure set_cnt (p_1_cnt number, p_2_cnt number) as
  begin
    b_1_cnt := p_1_cnt;
    b_2_cnt := p_2_cnt;
    dbms_output.put_line('At '||localtimestamp ||': Reset Package Variables: b_1_cnt='||b_1_cnt||', b_2_cnt='||b_2_cnt);
    dbms_output.put_line('');
  end;
  
  procedure prt_tx_locks as
    l_spaces varchar2(6) := '      ';
  begin
    dbms_output.put_line('');
    dbms_output.put_line(l_spaces||'|------------------------------------------------------|');
    dbms_output.put_line(l_spaces||'|SID        ID1     ID2   LMODE REQUEST   CTIME   BLOCK|');
    dbms_output.put_line(l_spaces||'|------ ------- ------- ------- ------- ------- -------|');
    for c in (select * from v$lock where type='TX' order by sid, type) 
    loop
      dbms_output.put_line(l_spaces||'|'||rpad(c.SID, 6)||lpad(c.ID1, 8)||lpad(c.ID2, 8)||lpad(c.LMODE, 8)||
                                      lpad(c.REQUEST, 8)||lpad(c.CTIME, 8)||lpad(c.BLOCK, 8)||'|');
    end loop;
    dbms_output.put_line(l_spaces||'|------------------------------------------------------|');
    dbms_output.put_line('');
  end;
end;
/


2. Test Run


We open two Sqlplus sessions: SID-1 and SID-2.

At T1, SID-1 updates txt from 'A' to 'B' for id=2.

--========== 1. SID-1@T1 ==========--
                 
begin
  update test_tab set txt = 'A'; 
  commit;                        
   
  -- block id=2 update                              
  update test_tab                
     set txt = 'B'               
   where txt = 'A'               
     and id  = 2;
  dbms_output.put_line('At '||localtimestamp ||': update id=2 from A to B');                
end;
/        

---- Output ----
At 16:12:11: update id=2 from A to B
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.

We also use DML UTS (Unified Tracing Service) described in Blog: Write consistency and DML restart (Mahmoud Hatem) to monitor Oracle three phases of update restart.

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

alter session set tracefile_identifier = 'NotNull_Error_1';
alter session set events 'trace[DML]   disk=high ';       
exec dbms_monitor.session_trace_enable;

--ALTER SESSION SET "_fix_control"='30681521:0';

begin
  test_pkg.set_cnt(0, 0);   -- reset package state
  
  update test_tab           -- update /*+ RETRY_ON_ROW_CHANGE */ test_tab -- hint has no effect
     set txt = 'B'
   where txt = 'A'
     and test_pkg.non_deterministic_fun(id, 10) > 0;
end;
/

---- Output ----
At 16:12:50: Reset Package Variables: b_1_cnt=0, b_2_cnt=0
At 16:13:00: b_1_cnt=1, non_deterministic_fun(1, 10)=1     -- where test started at 16:12:50
At 16:13:10: b_2_cnt=1, non_deterministic_fun(2, 10)=1     -- where test started at 16:13:00
At 16:14:12: b_1_cnt=2, non_deterministic_fun(1, 10)=0     -- where test started at 16:14:02
At 16:14:22: b_1_cnt=3, non_deterministic_fun(1, 10)=1     -- where test started at 16:14:12

ORA-00600: internal error code, arguments: [13030], [20], [], [], [], [], [], [], [], [], [], []
      Elapsed: 00:01:45.30
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 16:13:32: wait id=2 update for 30 seconds
At 16:14:02: commit id=2 update. Then wait 5 seconds
At 16:14:07: update id=1 from A to B, and commit
      Elapsed: 00:00:35.04
From test output, we can see the update sequence:

At 16:12:11: SID-1 update id=2 from A to B.
At 16:12:50: SID-2 start running. get into "phase=NOT LOCKED". sleep 10 seconds. 
At 16:13:00: SID-2 update id=1 because non_deterministic_fun(1, 10)=1. sleep 10 seconds.
At 16:13:10: SID-2 update id=2, but SID-1 does not commit "id=2 update", it is blocked by "TX" lock for 52 seconds (ela= 52217121).
At 16:14:02: SID-1 commit "id=2 update". SID-2 is unlocked.
             SID-2 restart update, get into "phase=LOCK" with "SELECT FOR UPDATE". sleep 10 seconds.
At 16:14:07: SID-1 update id=1 from A to B, and commit.
At 16:14:12: SID-2 get into "phase=NOT LOCKED". id=1 check non_deterministic_fun(1, 10)=0. sleep 10 seconds. 
At 16:14:22: SID-2 id=1 check non_deterministic_fun(1, 10)=1.
             SID-2 raise ORA-00600: internal error code, arguments: [13030], [20]
Here SID-2 DML UTS tracing file (only related lines extracted).

===================== *** 16:12:50
PARSING IN CURSOR tim=12445563522721 hv=3131174352 ad='c080e660' sqlid='6jabvd6xa3vfh'
UPDATE TEST_TAB SET TXT = 'B' WHERE TXT = 'A' AND TEST_PKG.NON_DETERMINISTIC_FUN(ID, 10) > 0

updThreePhaseExe: objn=3122646 phase=NOT LOCKED
updaul: phase is NOT LOCKED snap oldsnap env: (scn: 0x000009185dcf3734  xid: 0x0000.000.00000000  uba: 
===================== *** 16:13:00
WAIT: nam='PL/SQL lock timer' ela= 10000786  tim=12445573526055
updrow: objn=3122646 phase=NOT LOCKED
updrow: kauupd objn:3122646  rowid 002fa5d6.000c9786.0 code 0
===================== *** 16:13:10
WAIT: nam='PL/SQL lock timer' ela= 10000287  tim=12445583549063
updrow: objn=3122646 phase=NOT LOCKED
===================== *** 16:14:02
WAIT: nam='enq: TX - row lock contention' ela= 52217121 name|mode=1415053318 usn<<16 | slot=8323077 sequence=80529 obj#=3122646 tim=12445635782319
dmlTrace:file:line (kdu.c:3505) cmpf 20 rowcol 1 piececol 1
updrow: kauupd objn:3122646  rowid 002fa5d6.000c9786.1 code 20
updThreePhaseExe: objn=3122646 phase=LOCK
===================== *** 16:14:12
WAIT: nam='PL/SQL lock timer' ela= 10000133  tim=12445645783076
updThreePhaseExe: objn=3122646 phase=ALL LOCKED
===================== *** 16:14:22
WAIT: nam='PL/SQL lock timer' ela= 10000583  tim=12445655800069
updrow: objn=3122646 phase=ALL LOCKED

Block header dump:  0x000c9786
 Itl           Xid                  Uba         Flag  Lck        Scn/Fsc
0x01   0x007f.005.00013a91  0x00c026bf.2019.0f  --U-    1  fsc 0x0000.5dcf3755      
0x02   0x0075.010.00011cca  0x00c01798.1e21.21  --U-    1  fsc 0x0000.5dcf375a      
===============
block_row_dump:
tab 0, row 0, @0x1f90
tl: 8 fb: --H-FL-- lb: 0x2  cc: 2
col  0: [ 2]  c1 02
col  1: [ 1]  42
tab 0, row 1, @0x1f88
tl: 8 fb: --H-FL-- lb: 0x1  cc: 2
col  0: [ 2]  c1 03
col  1: [ 1]  42

  kflag
   [0] CMPCOL
   cmpp (2) c1 02
   [1] CMPCOL UPDCOL
   cmpp (1) 41
   updp (1) 42
   
updrow: CR error table 0 - rowid: 002fa5d6.000c9786.0 code 20

dmlsrvRetryLogDump: seq:code:error:pass:hash:rowcol:piececol:currentLength:currentFlags:CRLength:CRFlags:rid:scn
dmlsrvRetryLogDump: 0:20:0:1:2139311695:1:1:1:0:1:0:002fa5d6.000c9786.1:0x000009185dcf3734
dmlsrvRetryLogDump: 1:20:0:3:2139311695:1:1:1:0:1:0:002fa5d6.000c9786.0:0x000009185dcf3757
=====================
ORA-00600: internal error code, arguments: [13030], [20], [], [], [], [], [], [], [], [], [], []
Above trace file records all the details of ThreePhase updates:

===================== *** 16:12:50
  updThreePhaseExe: objn=3122646 phase=NOT LOCKED
===================== *** 16:14:02
  updThreePhaseExe: objn=3122646 phase=LOCK
===================== *** 16:14:12
  updThreePhaseExe: objn=3122646 phase=ALL LOCKED
At 16:14:02, SID-1 committed the updated of id=2 (rowid 002fa5d6.000c9786.1),
SID-2 finished "TX" wait after 52 seconds (ela= 52217121).
dmlTrace shows code 20 error: "rowid 002fa5d6.000c9786.1 code 20".
(maybe "line (kdu.c:3505) cmpf 20" is interpreted as "code 20" or [20] in error message).
"phase=LOCK" signifies the update restart.

===================== *** 16:14:02
WAIT: nam='enq: TX - row lock contention' ela= 52217121 name|mode=1415053318 usn<<16 | slot=8323077 sequence=80529 obj#=3122646 tim=12445635782319
dmlTrace:file:line (kdu.c:3505) cmpf 20 rowcol 1 piececol 1
updrow: kauupd objn:3122646  rowid 002fa5d6.000c9786.1 code 20
updThreePhaseExe: objn=3122646 phase=LOCK
At 16:14:22, Itl section list two "fast commit" entries.
   Itl 0x01 (lb: 0x1) updated id=2 ("c1 03"),
   Itl 0x02 (lb: 0x2) updated id=1 ("c1 02").
If we look the TX v$lock printout ("ID1 ID2" in test_pkg.prt_tx_locks, not showed in this Blog), we can match both Xid
(0x007f.005.00013a91 = 127.5.80529, 0x0075.010.00011cca=117.16.72906).

block_row_dump section shows that both rows have txt = 'B' ("col 1: [ 1] 42").

 Itl           Xid                  Uba         Flag  Lck        Scn/Fsc
0x01   0x007f.005.00013a91  0x00c026bf.2019.0f  --U-    1  fsc 0x0000.5dcf3755      
0x02   0x0075.010.00011cca  0x00c01798.1e21.21  --U-    1  fsc 0x0000.5dcf375a      
===============
block_row_dump:
tab 0, row 0, @0x1f90
tl: 8 fb: --H-FL-- lb: 0x2  cc: 2
col  0: [ 2]  c1 02                   -- 1
col  1: [ 1]  42                      -- 'B'
tab 0, row 1, @0x1f88
tl: 8 fb: --H-FL-- lb: 0x1  cc: 2
col  0: [ 2]  c1 03                   -- 2
col  1: [ 1]  42                      -- 'B'
kflag section shows that we want to update id = 1 ("c1 02") from 'A' ("cmpp (1) 41") to 'B' ("updp (1) 42") for "rowid: 002fa5d6.000c9786.0" (row 0), but failed with "code 20".

  kflag
   [0] CMPCOL
   cmpp (2) c1 02          -- 1
   [1] CMPCOL UPDCOL
   cmpp (1) 41             -- 'A'
   updp (1) 42             -- 'B'
   
updrow: CR error table 0 - rowid: 002fa5d6.000c9786.0 code 20
dmlsrvRetryLogDump section shows two errors with code=20.
We got code=20 in "pass=1" ( "phase=NOT LOCKED") for id=2 ("rid=002fa5d6.000c9786.1"),
and got code=20 in "pass=3" ( "phase=ALL LOCKED") for id=1 ("rid=002fa5d6.000c9786.0")

dmlsrvRetryLogDump: seq:code:error:pass:hash:rowcol:piececol:currentLength:currentFlags:CRLength:CRFlags:rid:scn
dmlsrvRetryLogDump: 0:20:0:1:2139311695:1:1:1:0:1:0:002fa5d6.000c9786.1:0x000009185dcf3734
dmlsrvRetryLogDump: 1:20:0:3:2139311695:1:1:1:0:1:0:002fa5d6.000c9786.0:0x000009185dcf3757
In the above update sequence, SID-1 makes a second update:

  At 16:14:07 update id=1 from A to B, and commit
It is not clear if SID-2 has to perform a second re-start
because it is between SID-2 16:14:02 ("phase=LOCK") and 16:14:12 ("phase=NOT LOCKED").
Probably that is the code path which caused ORA-00600.

In the above test, if we remove this second update in SID-1@T3 as follows, and there is no more ORA-00600 because no second re-start is triggered.

--========== 3. SID-1@T3 ==========--

begin
  dbms_output.put_line('At '||localtimestamp ||': wait id=2 update for 30 seconds');
  test_pkg.prt_tx_locks;
  dbms_lock.sleep(30);
  commit;
end;
/
Here the incident file, which shows the Call Stack (only partially extracted):

  ORA-00600: internal error code, arguments: [13030], [20], [], [], [], [], [], [], [], [], [], []

  *** 2022-04-06T16:14:22.450668+02:00
  ----- Current SQL Statement for this session (sql_id=6jabvd6xa3vfh) -----
  UPDATE TEST_TAB SET TXT = 'B' WHERE TXT = 'A' AND TEST_PKG.NON_DETERMINISTIC_FUN(ID, 10) > 0
  
  ----- Call Stack Trace -----
  FRAME [13] (ksesic1()+185 -> kgesiv())
  FRAME [14] (updrow()+5781 -> ksesic1())
  FRAME [15] (qerupUpdRow()+671 -> updrow())
  FRAME [16] (qerupRopRowsets()+259 -> qerupUpdRow())
  FRAME [17] (qerstRowP()+737 -> qerupRopRowsets())
  FRAME [18] (kdstf110110100001000km()+1884 -> qerstRowP())
  FRAME [19] (kdsttgr()+2208 -> kdstf110110100001000km())
  FRAME [20] (qertbFetch()+1090 -> kdsttgr())
  FRAME [21] (qerstFetch()+449 -> qertbFetch())
  FRAME [22] (qerupFetch()+520 -> qerstFetch())
  FRAME [23] (qerstFetch()+910 -> qerupFetch())
  FRAME [24] (updaul()+1416 -> qerstFetch())
  FRAME [25] (updThreePhaseExe()+6101 -> updaul())
  FRAME [26] (updexe()+443 -> updThreePhaseExe())
  FRAME [27] (opiexe()+11799 -> updexe())
  FRAME [28] (opipls()+2427 -> opiexe())
In the above test, if we change row update sequence as follows:
       for SID-1@T1, we update "id  = 1" instead of "id  = 2"
       for SID-1@T3, we update "id  = 2" instead of "id  = 1"
there is no more error, and SID-2 DML UTS tracing file (only related lines extracted) looks like
(in SID-2, no rows updated, no Itl entry, no transaction created):

*** 17:44:51
updThreePhaseExe: objn=3122646 phase=NOT LOCKED
updaul: phase is NOT LOCKED snap oldsnap env: 

*** 17:45:01
WAIT #140344716597752: nam='PL/SQL lock timer' ela= 10000544 duration=0 p2=0 p3=0 obj#=-1 tim=13376295440067
updrow: objn=3122646 phase=NOT LOCKED

*** 17:45:56
WAIT #140344716597752: nam='enq: TX - row lock contention' ela= 54748944 name|mode=1415053318 usn<<16 | slot=7602177 sequence=77639 obj#=3122646 tim=13376350189277
dmlTrace:file:line (kdu.c:3505) cmpf 20 rowcol 1 piececol 1
updrow: kauupd objn:3122646 table:0 rowMigrated:FALSE  rowid 002fa5d6.000c9786.0 code 20
updThreePhaseExe: objn=3122646 phase=LOCK
updaul: phase is LOCK snap oldsnap env: 

*** 17:46:06
WAIT #140344716597752: nam='PL/SQL lock timer' ela= 10000260 duration=0 p2=0 p3=0 obj#=-1 tim=13376360190078
updrow: objn=3122646 phase=LOCK
dmlTrace:file:line (kdd.c:3642) cmpf 17 rowcol 1 piececol 1
updrow: kddlkr objn 3122646 table 0  rowid 002fa5d6.000c9786.1 code 17
updThreePhaseExe:objn=3122646 pass=1 stat=2 err=17
updThreePhaseExe:began locking pass 2
updaul: phase is LOCK snap oldsnap env: 
updThreePhaseExe: objn=3122646 phase=ALL LOCKED
updaul: phase is ALL LOCKED snap oldsnap env: 


3. Related Work


Oracle MOS Ora-00600 [13030], [20] During Update Statement Using V$ tables (Doc ID 1400439.1) wrote:
  For updates we use a 3 pass algorithm which relies on consistent read. If the first pass does not succeed 
  then we use a CR scan and lock the rows returned, then reset the row source and use a further CR scan at the same snapshot SCN 
  to update those locked rows. The V$ view in the WHERE clause does not support CR and so each scan using the same snapshot SCN 
  may see different data depending on the content of V$SESSION at the scan time which completely breaks the update algorithm. 
  The errors you see (ORA-600 [13030]) indicate:
  [1] - the row to be updated has changed values in comparison columns
  [2] - the row to be updated does not exist
  These are the sorts of error you can get if the separate scans at the same snapshot SCN return different data, as can occur with a V$ view involved.
Book: Expert Oracle Database Architecture (Thomas Kyte, Darl Kuhn, 3rd Edition) explained update restart and demonstrated it with triggers.
Page 270 wrote:
  But to continue on with the "but what happens if..." train of thought, what happens if, after
  restarting the update and going into SELECT FOR UPDATE mode (which has the same read-consistent and
  read current block gets going on as an update does), a row that was Y=5 when you started the SELECT FOR
  UPDATE is found to be Y=11 when you go to get the current version of it? That SELECT FOR UDPDATE will
  restart and the cycle begins again.
This seems talking about a second restart after first restart. The above test showed ORA-00600: [13030], [20] in such second restart, and "cycle begins again" abnormally terminated (session is not disconnected).

So it is not clear if "but what happens if..." has ever been exercised.

For the update statement in the second session of Book Page 271, if we add a MONITOR hint and make a Sql trace:
(see Video: Oracle SQL Monitoring and Write Consistency Demo (Tanel Poder))

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

-- with  /*+ MONITOR */
update /*+ MONITOR */ t set x = x+1 where x > 0;

alter session set events '10046 trace name context off';
Here MONITOR report and Sql trace:

select sys.dbms_sqltune.report_sql_monitor('canctsv349dww', report_level=>'all' , type=>'TEXT') from dual;

------------------------------
update /*+ MONITOR */ t set x = x+1 where x > 0

SQL Plan Monitoring Details (Plan Hash Value=931696821)
=============================================================================================================================================
| Id |      Operation       | Name |  Rows   | Cost |   Time    | Start  | Execs |   Rows   | Activity |          Activity Detail           |
|    |                      |      | (Estim) |      | Active(s) | Active |       | (Actual) |   (%)    |            (# samples)             |
=============================================================================================================================================
|  0 | UPDATE STATEMENT     |      |         |      |         1 |    +13 |     3 |        0 |          |                                    |
|  1 |   UPDATE             | T    |         |      |        14 |     +0 |     3 |        0 |   100.00 | enq: TX - row lock contention (13) |
|  2 |    TABLE ACCESS FULL | T    |       4 |    2 |        11 |     +3 |     3 |        3 |          |                                    |
=============================================================================================================================================

********************************************************************************
SQL ID: canctsv349dww Plan Hash: 931696821

update /*+ MONITOR */ t set x = x+1 where x > 0

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          1          0           0
Execute      1      0.00      12.61          0         21         13           1
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      0.00      12.61          0         22         13           1

Rows  Row Source Operation
----  ---------------------------------------------------
   0  UPDATE  T (cr=21 pr=0 pw=0 time=12612642 us starts=3)
   3   TABLE ACCESS FULL T (cr=20 pr=0 pw=0 time=222 us starts=3 cost=2 size=104 card=4)
********************************************************************************
MONITOR report shows that "TABLE ACCESS FULL" has Execs=3 and Rows=3
and xplan shows that "TABLE ACCESS FULL" has Rows=3 and starts=3,
although only one single row is updated (without update restart, all above numbers are 1).
All those number 3 exactly signify "updThreePhaseExe".
  By the way, an erratum of Foreign Key on Nested Table (maybe the only real one) was reported for 1st Edition of
  Book: Book Expert Oracle Database Architecture. 
  It was once accepted and published, but now it cannot find any more.
  
  In Oracle 19.13, repeated the same test from Blog: Foreign Key on Nested Table
  Foreign Key on Nested Table can still successfully created (in Oracle 19.13, type has to be created as NONEDITIONABLE).
  But in Page 410 of 3rd Edition, we can still read:
  
      This will simply not work. Nested tables do not support referential integrity constraints, as they
      cannot reference any other tableóeven themselves. So, weíll just skip that requirement for this
      demonstration (something you cannot do in real life!).

  And error message (Page 409) seems disapproved: 
    ORA-30730: referential constraint not allowed on nested table column
Blog: Oracle write consistency bug and multi-thread de-queuing (Franck Pachot) showed an update restart bug with nested subquery and used flashback version query to list all versions of the rows. It also mentioned hint RETRY_ON_ROW_CHANGE, which has no effect on the test of this Blog.

Oracle MOS Bug 33470254 - UPDATE FAILS WITH ORA-00600 [13030], [20] (Doc ID 33470254.8) provided a Workaround:
     "_fix_control"= '30681521:0'      (Versions affected, 19.11, 19.13, 19.14)
which seems related to subqueries (see V$SYSTEM_FIX_CONTROL.DESCRIPTION).

Our 19.13 test DB is set with this _fix_control, but it has no effect.

select bugno, value, description from v$system_fix_control where bugno=30681521;

     BUGNO VALUE DESCRIPTION
  -------- ----- ----------------------------------------------------------------
  30681521     0 enable unnesting of subqueries in set clause of update statement
Video: Oracle SQL Monitoring and Write Consistency Demo (Tanel Poder) demonstrated restart by a big table update on Oracle 18.3, and detected them by V$SQL_PLAN_MONITOR.STARTS and Sql Trace.

In the demo, SQL Monitoring also shows that Actual Rows with restart is at least double than without restart. So Actual Rows (V$SQL_PLAN_MONITOR.OUTPUT_ROWS) could be also an indicator of update restart besides V$SQL_PLAN_MONITOR.STARTS (str). The demo contains two tests, one at Wed Sep 5, 2018 10:42:47 AM, another at Wed Sep 5, 2018 3:51:30 PM.
First test involved 9 rows (9 + 8 + 8 = 25 rows in all ThreePhase),
second touched 10 rows (10 + 9 + 9 = 28 rows in all ThreePhase)

Blog: Write consistency and DML restart (Mahmoud Hatem) explored DML UTS (Unified Tracing Service) tracing to investigate update restart, which revealed the very details of updThreePhaseExe. (In its test, without update of Session 2, trace file shows str=3 instead of str=4).

A series of 3 Blogs:
     That Old Restart Problem Strikes Back: Setting the Stage
     That Old Restart Problem Strikes Back: Getting What You Pay for
     That Old Restart Problem Strikes Back: Triggers to the Rescue
demonstrated the single session update restart without any other interfering sessions. It also uses:

   alter session set events 'trace[dml]:sql_trace wait=true';
to reveal internal handled error ORA-01551.
The first Blog shows that such update restart is only observed in non-partitioned table due to "updrowFastPath".
The second Blog points out that there is such update restart in partitioned table due to "updrow".
The third Blog shows that such update restart disappears in non-partitioned table when there is a after trigger due to "updrow".

Blog: Update restarts reveals various Oracle stats in update restart.