Sunday, August 7, 2022

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)

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