Sunday, November 22, 2020

OracleJVM integer Array Size Limit and Out of Memory Error

Java provides 4 Primitive Data Types (byte, short, int, long) to represent integer numbers. In this Blog, we will look their array size limits in relation to two OracleJVM errors: ORA-29532 OutOfMemoryError and ORA-27102: out of memory.

Note: Tested in Oracle 19c on Linux.


1. ORA-29532 java.lang.OutOfMemoryError


Nenad's Blog: Troubleshooting java.lang.OutOfMemoryError in the Oracle Database made a deep investigation of ORA-29532 OutOfMemoryError, and found the internal hard-coded maximum total size in bytes: 536870895 It shows that for int[] array size of 134217723 (0x7FFFFFB, about 128MB Java int), there is no memory error. However, adding just one additional element will cause OutOfMemoryError (By default, Java int data type is a 32-bit signed).

We will explore further ORA-29532 OutOfMemoryError and list the 4 hard-coded integer array size limits on 4 respective Java integer Primitive Data Types.

At first, we copy Nenad's test code and add one method for byte[].

drop java source "Demo";

create or replace and compile java source named "Demo" as
public class Demo {
    public static void defineIntArray(int p_size) throws Exception {
      //Test of ORA-29532: Java call terminated by uncaught Java exception: java.lang.OutOfMemoryError
      //copy from https://nenadnoveljic.com/blog/troubleshooting-java-lang-outofmemoryerror-in-the-oracle-database/
      int[] v = new int[p_size];
      System.out.println("OracleJvm int[].length: " + v.length);
    }

    public static void defineByteArray(int p_size) throws Exception {
      byte[] v = new byte[p_size];
      System.out.println("OracleJvm byte[].length: " + v.length);
    }
}     
/

create Or replace procedure p_define_int_array (p_size number)
as language java name 'Demo.defineIntArray(int)' ;
/

create Or replace procedure p_define_byte_array (p_size number)
as language java name 'Demo.defineByteArray(int)' ;
/
Run the same test to demonstrate OracleJVM java.lang.OutOfMemoryError exactly at 134217724:

SQL > exec p_define_int_array(134217723);

  OracleJvm int[].length: 134217723


SQL > exec p_define_int_array(134217724);

  Exception in thread "Root Thread" java.lang.OutOfMemoryError
          at Demo.defineIntArray(Demo:29)
  BEGIN p_define_int_array(134217724); END;
  
  *
  ERROR at line 1:
  ORA-29532: Java call terminated by uncaught Java exception: java.lang.OutOfMemoryError
  ORA-06512: at "K.P_DEFINE_INT_ARRAY", line 1
  ORA-06512: at line 1
Following Blog's guidelines: switch off JIT compiler to obtain descriptive call stack, we disable OracleJVM Just-in-Time (JIT):

  alter system set java_jit_enabled=false;
and (gdb) disassemble joe_make_primitive_array:

# --------------------------- long, max: 0x3fffffd ---------------------------
  <+107>:   cmp    %r13d,%eax
  <+110>:   jl     0x583c639 <joe_make_primitive_array+121>
  <+112>:   cmp    $0x3fffffd,%rdx
  <+119>:   jbe    0x583c64b <joe_make_primitive_array+139>
  <+121>:   lea    0x11b9ed78(%rip),%rax        # 0x173db3b8 <ioa_ko_j_l_out_of_memory_error>
  <+128>:   mov    %r15,%rdi
  <+131>:   mov    (%rax),%rsi
  <+134>:   callq  0x58459f0 <joe_blow>
  <+139>:   mov    0x1f1(%r15),%r9
# --------------------------- int, max: 0x7fffffb ---------------------------    
  <+299>:   cmp    %r13d,%eax
  <+302>:   jl     0x583c6f9 <joe_make_primitive_array+313>
  <+304>:   cmp    $0x7fffffb,%rdx
  <+311>:   jbe    0x583c70b <joe_make_primitive_array+331>
  <+313>:   lea    0x11b9ecb8(%rip),%rax        # 0x173db3b8 <ioa_ko_j_l_out_of_memory_error>
  <+320>:   mov    %r15,%rdi
  <+323>:   mov    (%rax),%rsi
  <+326>:   callq  0x58459f0 <joe_blow>
  <+331>:   mov    0x1f1(%r15),%r9
# --------------------------- short, max: 0xffffff7 ---------------------------  
  <+491>:   cmp    %r13d,%eax
  <+494>:   jl     0x583c7b9 <joe_make_primitive_array+505>
  <+496>:   cmp    $0xffffff7,%rdx
  <+503>:   jbe    0x583c7cb <joe_make_primitive_array+523>
  <+505>:   lea    0x11b9ebf8(%rip),%rax        # 0x173db3b8 <ioa_ko_j_l_out_of_memory_error>
  <+512>:   mov    %r15,%rdi
  <+515>:   mov    (%rax),%rsi
  <+518>:   callq  0x58459f0 <joe_blow>
  <+523>:   mov    0x1f1(%r15),%r9
# --------------------------- byte, max: 0x1fffffef ---------------------------  
  <+676>:   cmp    %r13d,%eax
  <+679>:   jl     0x583c872 <joe_make_primitive_array+690>
  <+681>:   cmp    $0x1fffffef,%rdx
  <+688>:   jbe    0x583c884 <joe_make_primitive_array+708>
  <+690>:   lea    0x11b9eb3f(%rip),%rax        # 0x173db3b8 <ioa_ko_j_l_out_of_memory_error>
  <+697>:   mov    %r15,%rdi
  <+700>:   mov    (%rax),%rsi
  <+703>:   callq  0x58459f0 <joe_blow>
  <+708>:   mov    0x1f1(%r15),%r9
Copy 4 hex constants from above 4 cmp instructions and map to 4 integer Primitive Data Types:

  long  (8 bytes, 0x3fffffd =67108861 )
  int   (4 bytes, 0x7fffffb =134217723) 
  short (2 bytes, 0xffffff7 =268435447)
  byte  (1 byte,  0x1fffffef=536870895)
Above assemble code shows that each integer type is handled individually with different hard-coded limit, but total memory is capped below 512MB.

For example, for data type int, the input parameter array size (register rdx, passed as arg2 to joe_make_primitive_array) is checked against fixed constant 0x7fffffb (134217723, a hard-coded value). According to cmp status flags, create array if rdx below or equal to 0x7fffffb (%rdx - $0x7fffffb, CF=1 or ZF=1); otherwise continue to "ioa_ko_j_l_out_of_memory_error".

  <+304>:   cmp    $0x7fffffb,%rdx
  <+311>:   jbe    0x583c70b <joe_make_primitive_array+331>
  <+313>:   lea    0x11b9ecb8(%rip),%rax        # 0x173db3b8 <ioa_ko_j_l_out_of_memory_error>
We can also see that there is another memory pre-check before each integer type check. If the memory limit in eax is less than input parameter array size in r13d (%r13d > %eax), then jump to "ioa_ko_j_l_out_of_memory_error" (Note: maximum rax seems 0x20000000=536870912=512MB, probably default Heap Size since 11.2, see later appended MOS Doc ID 2526642.1).

  <+299>:   cmp    %r13d,%eax
  <+302>:   jl     0x583c6f9 <joe_make_primitive_array+313>
Now we can verify the limit of byte integer type exactly at 536870896:

SQL > exec p_define_byte_array(536870895);
  OracleJvm byte[].length: 536870895

SQL > exec p_define_byte_array(536870896);
  Exception in thread "Root Thread" java.lang.OutOfMemoryError
          at Demo.defineByteArray(Demo:31)
  BEGIN p_define_byte_array(536870896); END;
  
  *
  ERROR at line 1:
  ORA-29532: Java call terminated by uncaught Java exception: java.lang.OutOfMemoryError
  ORA-06512: at "K.P_DEFINE_BYTE_ARRAY", line 1
  ORA-06512: at line 1
Oracle MOS: Java Stored Procedure suddenly fails with java.lang.OutOfMemoryError (Doc ID 2526642.1) wrote:
Symptoms
  A database routine implemented as a Java Stored procedure receives the following error.
  ORA-29532: Java call terminated by uncaught Java exception: java.lang.OutOfMemoryError
  This routine may have worked previously or it may be brand new development.
  
Cause
  The DB JVM does not have enough session Heap Memory. This error occurs when a Java Stored Procedure 
  (ie. a PL/SQL routine where the body is implemented in Java ) does not have enough Heap space 
  to work with the amount of data being processed. If this were a client-side java program 
  using the Java Runtime Engine (JRE) (ie. java.exe), one would use the -Xmx parameter to configure the Heap Memory.  
  However, as the Oracle DB JVM is running in the process space of the Oracle executable, 
  there is no way to use the -Xmx switch.  The JVM has a default Heap Size (512MB since 11.2) 
  but it is also configurable using a method in the "Java Runtime" class called "oracle.aurora.vm.OracleRuntime".  
  Along with other "java runtime" related switches, this class contains a couple methods 
  that can be used to manage the Java Heap Size.  Therefore, if you encounter the OutOfMemoryError 
  and need to increase from either the default or a previous configured amount, 
  you can use oracle.aurora.vm.OracleRuntime.setMaxMemorySize to allocate more memory for the Java Heap.
The MOS Note described that "Oracle DB JVM is running in the process space of the Oracle executable" and had one hint about 512MB: "The JVM has a default Heap Size (512MB since 11.2)". As one Solution, MOS Note provided following workaround.

create or replace package Java_Runtime is
  function getHeapSize return number;
  function setHeapSize(num number) return number;
end Java_Runtime;
/

create or replace package body Java_Runtime is
  function getHeapSize return number is
    language java name 'oracle.aurora.vm.OracleRuntime.getMaxMemorySize() returns long';
  function setHeapSize(num number) return number is
    language java name 'oracle.aurora.vm.OracleRuntime.setMaxMemorySize(long) returns long';
end Java_Runtime;
/

declare
   heap_return_val NUMBER;
begin
   -- MOS code has a typo, setMaxMemorySize should be setHeapSize
   -- heap_return_val := Java_Runtime.setMaxMemorySize(1024*1024*1024);
   
   dbms_output.put_line('HeapSize Before Set: '||Java_Runtime.getHeapSize);
   heap_return_val := Java_Runtime.setHeapSize(1024*1024*1024);
   dbms_output.put_line('HeapSize After Set: '||Java_Runtime.getHeapSize);
   
   -- MOS code
   -- MY_JAVA_STORED_PROC(...);
   
   p_define_int_array(134217724);
end;
/

HeapSize Before Set: 536870912
HeapSize After Set: 1073741824
declare
*
ERROR at line 1:
ORA-29532: Java call terminated by uncaught Java exception: java.lang.OutOfMemoryError
ORA-06512: at "K.P_DEFINE_INT_ARRAY", line 1
ORA-06512: at line 14
We made the test in Oracle 12c and 19c and still got ORA-29532 OutOfMemoryError (for the reason of the hard-coded limit discovered by Nenad's Blog).


2. ORA-27102: out of memory


Blog: Oracle JVM Java OutOfMemoryError and lazy GC was trying to bring up some discussions on OracleJVM OutOfMemoryError in connection with lazy GC.

The first test in the Blog is to allocate 511MB byte array:

SQL > exec createBuffer512(1024*1024*511);
  PL/SQL procedure successfully completed
succeeded without Error.

but the second test with 512MB:

SQL > exec createBuffer512(1024*1024*512);
  
  ERROR at line 1:
  ORA-29532: Java call terminated by uncaught Java exception: java.lang.OutOfMemoryError
  ORA-06512: at "K.CREATEBUFFER512", line 1
  ORA-06512: at line 1
hit the general Java error: ORA-29532 java.lang.OutOfMemoryError, which probably indicates that the JVM is limited by 512MB for one single object instance, in this test, it is "new byte[bufferSize]".

We can see that above hard-coded byte[] limit of 536870895 (0x1fffffef) is between 511MB and 512MB.

   1024*1024*512=536870912 > 536870895 > 535822336=1024*1024*511.
Run a third test case, which gradually allocates memory from 1MB to 511MB, each time increases 1MB per call.

SQL > exec createBuffer512_loop(511, 1, 1);

  Step -- 1 --, Buffer Size (MB) = 1
  Step -- 2 --, Buffer Size (MB) = 2
  Step -- 3 --, Buffer Size (MB) = 3
  ...
  Step -- 202 --, Buffer Size (MB) = 202
  Step -- 203 --, Buffer Size (MB) = 203

  ERROR at line 1:
  ORA-27102: out of memory
  Linux-x86_64 Error: 12: Cannot allocate memory
  Additional information: 12394
  Additional information: 218103808
  ORA-06512: at "K.CREATEBUFFER512", line 1
  ORA-06512: at "K.CREATEBUFFER512_LOOP", line 8
  ORA-06512: at line 1
It reveals that out of memory can be generated even under above discussed hard-coded limit (203MB < 512MB), but the error code is ORA-27102 (in 12c, we saw ORA-29532). The test shows that above 4 integer array size limits for respective 4 integer Primitive Data Types are sufficient, but not necessary conditions for out of memory.

Make a 27102 trace:

  alter session set max_dump_file_size = unlimited;
  alter session set tracefile_identifier='ORA27102_trc3'; 
  alter session set events '27102 trace name errorstack level 3'; 
  exec createBuffer512_loop(511, 1, 1);
Here the extracted error message, call stack, and session wait event from trace file:

----- Error Stack Dump -----
Linux-x86_64 Error: 12: Cannot allocate memory
Additional information: 12394
Additional information: 218103808

BEGIN createBuffer512_loop(511, 1, 1); END;
----- PL/SQL Call Stack -----
  object      line  object
  handle    number  name
0x91948d30         1  procedure K.CREATEBUFFER512
0x8ef98db0         8  procedure K.CREATEBUFFER512_LOOP
0x8ca47e38         1  anonymous block

----- Call Stack Trace -----
FRAME [12] (dbgePostErrorKGE()+1066 -> dbkdChkEventRdbmsErr())
FRAME [13] (dbkePostKGE_kgsf()+71 -> dbgePostErrorKGE())
FRAME [14] (kgerscl()+546 -> dbkePostKGE_kgsf())
FRAME [15] (kgecss()+69 -> kgerscl())
FRAME [16] (ksmrf_init_alloc()+821 -> kgecss())
  CALL TYPE: call   ERROR SIGNALED: yes   COMPONENT: KSM
FRAME [17] (ksmapg()+521 -> ksmrf_init_alloc())
FRAME [18] (kgh_invoke_alloc_cb()+162 -> ksmapg())
  RDI 000000000D000000 RSI 00007F4D777511E0 RDX 000000000CE2D8B0 
FRAME [19] (kghgex()+2713 -> kgh_invoke_alloc_cb())
FRAME [20] (kghfnd()+376 -> kghgex())
FRAME [21] (kghalo()+4908 -> kghfnd())
FRAME [22] (kghgex()+593 -> kghalo())
FRAME [23] (kghfnd()+376 -> kghgex())
FRAME [24] (kghalo()+4908 -> kghfnd())
FRAME [25] (kghgex()+593 -> kghalo())
FRAME [26] (kghalf()+617 -> kghgex())
FRAME [27] (ioc_allocate0()+1094 -> kghalf())
FRAME [28] (iocbf_allocate0()+53 -> ioc_allocate0())
FRAME [29] (ioc_do_call()+1297 -> iocbf_allocate0())
FRAME [30] (joet_switched_env_callback()+376 -> ioc_do_call())
FRAME [31] (ioct_allocate0()+79 -> joet_switched_env_callback())
FRAME [32] (eoa_new_mman_segment()+368 -> ioct_allocate0())
FRAME [33] (eoa_new_mswmem_chunk()+66 -> eoa_new_mman_segment())
FRAME [34] (eomsw_allocate_block()+229 -> eoa_new_mswmem_chunk())
FRAME [35] (eoa_alloc_mswmem_object_no_gc()+2037 -> eomsw_allocate_block())
FRAME [36] (eoa_alloc_mswmem_object()+48 -> eoa_alloc_mswmem_object_no_gc())
FRAME [37] (eoa_new_ool_alloc()+508 -> eoa_alloc_mswmem_object())
FRAME [38] (joe_make_primitive_array()+828 -> eoa_new_ool_alloc())
FRAME [39] (joe_run_vm()+15736 -> joe_make_primitive_array())
FRAME [40] (joe_run()+608 -> joe_run_vm())
FRAME [41] (joe_invoke()+1156 -> joe_run())
FRAME [42] (joet_aux_thread_main()+1674 -> joe_invoke())
FRAME [43] (seoa_note_stack_outside()+34 -> joet_aux_thread_main())
FRAME [44] (joet_thread_main()+64 -> seoa_note_stack_outside())
FRAME [45] (sjontlo_initialize()+178 -> joet_thread_main())
FRAME [46] (joe_enter_vm()+1197 -> sjontlo_initialize())
FRAME [47] (ioei_call_java()+4716 -> joe_enter_vm())
FRAME [48] (ioesub_CALL_JAVA()+569 -> ioei_call_java())
FRAME [49] (seoa_note_stack_outside()+34 -> ioesub_CALL_JAVA())
FRAME [50] (ioe_call_java()+292 -> seoa_note_stack_outside())
FRAME [51] (jox_invoke_java_()+4133 -> ioe_call_java())
FRAME [52] (kkxmjexe()+1493 -> jox_invoke_java_())

    Session Wait History:
     0: waited for 'PGA memory operation'
        =0xd000000, =0x2, =0x0
"Error: 12" is ENOMEM defined in /usr/include/asm-generic/errno-base.h.
"Additional information: 12394" is not clear.
"Additional information: 218103808" points out P1 parameter in Event "PGA memory operation" (12.2 new introduced), which also appears in "RDI 000000000D000000" of kgh_invoke_alloc_cb call (0xd000000 = 218103808).

In the above call stack, there is a subroutine "FRAME [35] (eoa_alloc_mswmem_object_no_gc()", with suffix "no_gc".

"FRAME [38] (joe_make_primitive_array()+828 -> eoa_new_ool_alloc())" shows that "joe_make_primitive_array" already passed line <+708> of byte array size check (see above disassembled code), and is calling "eoa_new_ool_alloc".

Occasionally, session is terminated:

SQL > exec createBuffer512_loop(511, 1, 1);
  ERROR:
  ORA-03114: not connected to ORACLE
  ORA-03113: end-of-file on communication channel
  Process ID: 14461
  Session ID: 907 Serial number: 50430
and Linux dmesg shows:

  Out of memory: Kill process 14461 (oracle_14461_c0) score 781 or sacrifice child
  Killed process 14461 (oracle_14461_c0) total-vm:23745148kB, anon-rss:18595960kB, file-rss:132kB, shmem-rss:538232kB


3. Out of Memory Error Application Handling


If PL/SQL applications hit out of Memory Error even under the discussed hard-coded limit, one possible workaround is try to catch the error, invoke dbms_java.endsession to release memory, and then re-try the application as follows:

set serveroutput on size 50000;
exec dbms_java.set_output(50000);

declare
  java_oom_29532    exception;
  pragma            exception_init(java_oom_29532, -29532);
  l_es_ret          varchar2(100);
begin
  p_define_int_array(134217724);   -- only illustrative demo, real application should use size below the limit
  exception 
    when java_oom_29532 then
      dbms_output.put_line('------ int[134217724] hit ORA-29532: java.lang.OutOfMemoryError ------');
      l_es_ret  := dbms_java.endsession;
      p_define_int_array(134217723);
      dbms_output.put_line('------ int[134217723] Succeed ------');
    when others then
      raise;
end;
/

Exception in thread "Root Thread" java.lang.OutOfMemoryError
        at Demo.defineIntArray(Demo:5)
------ int[134217724] hit ORA-29532: java.lang.OutOfMemoryError ------
OracleJvm int[].length: 134217723
------ int[134217723] Succeed ------

set serveroutput on size 50000;
exec dbms_java.set_output(50000);

declare
  java_oom_27102    exception;
  pragma            exception_init(java_oom_27102, -27102);
  l_es_ret          varchar2(100);
begin
  createBuffer512_loop(511, 1, 1); 
  exception 
    when java_oom_27102 then
      dbms_output.put_line('------ createBuffer512_loop hit ORA-27102: out of memory ------');
      l_es_ret  := dbms_java.endsession;
      createBuffer512_loop(3, 1, 1);
      dbms_output.put_line('------ createBuffer512_loop(3, 1, 1) Succeed ------');
    when others then
      raise;
end;
/

Step -- 284 --, Buffer Size (MB) = 284
Step -- 285 --, Buffer Size (MB) = 285
------ createBuffer512_loop hit ORA-27102: out of memory ------
Step -- 1 --, Buffer Size (MB) = 1
Step -- 2 --, Buffer Size (MB) = 2
Step -- 3 --, Buffer Size (MB) = 3
------ createBuffer512_loop(3, 1, 1) Succeed ------   

Sunday, November 15, 2020

Oracle LOB Chunksize and Buffersize

In this Blog, we first show Oracle LOB chunksize in SQL and Plsql, then look chunksize and buffersize of LOB objects in Java from database and OracleJvm.

Note: Tested in Oracle 12c, 19c on Linux, Solaris, AIX with DB_BLOCK_SIZE=8192 and tablespace BLOCK_SIZE=8192.


1. SQL LOB Chunksize


First we create a table containing CLOB and BLOB columns with different chunk values, and insert one row:

drop table tab_lob cascade constraints;

create table tab_lob(
  id           number,
  clob_8k       clob,
  blob_8k       blob,
  clob_16k      clob,
  blob_16k      blob,
  clob_32k      clob,
  blob_32k      blob
)
lob (clob_8k) store as basicfile (
  enable       storage in row
  chunk        8192)
lob (blob_8k) store as basicfile (
  enable       storage in row
  chunk        8192)
lob (clob_16k) store as basicfile (
  enable       storage in row
  chunk        16384)
lob (blob_16k) store as basicfile (
  enable       storage in row
  chunk        16384)
lob (clob_32k) store as basicfile (
  enable       storage in row
  chunk        32768)
lob (blob_32k) store as basicfile (
  enable       storage in row
  chunk        32768);
  
insert into tab_lob values (1, empty_clob(), empty_blob(), empty_clob(), empty_blob(), empty_clob(), empty_blob());

commit;
List all chunksize with query:

select id, 
      dbms_lob.getchunksize(clob_8k)  clob_8k, 
      dbms_lob.getchunksize(blob_8k)  blob_8k, 
      dbms_lob.getchunksize(clob_16k) clob_16k, 
      dbms_lob.getchunksize(blob_16k) blob_16k,
      dbms_lob.getchunksize(clob_32k) clob_32k, 
      dbms_lob.getchunksize(blob_32k) blob_32k
from tab_lob;               


   ID   CLOB_8K   BLOB_8K   CLOB_16K   BLOB_16K   CLOB_32K   BLOB_32K
  --- --------- --------- ---------- ---------- ---------- ----------
    1      8132      8132      16264      16264      32528      32528
We can see that for chunking factor: 8192, chunksize is 8132, an overhead of 60 (8192-8132) bytes, only 8132 is used to store LOB value. All chunksize are multiple of 8132 instead of 8192 (DB_BLOCK_SIZE).

Here Oracle Docu on DBMS_LOB.GETCHUNKSIZE (19c):
DBMS_LOB.GETCHUNKSIZE Functions 
  When creating the table, you can specify the chunking factor, a multiple of tablespace blocks in bytes. 
  This corresponds to the chunk size used by the LOB data layer when accessing or modifying the LOB value. 
  Part of the chunk is used to store system-related information, and the rest stores the LOB value. 
  This function returns the amount of space used in the LOB chunk to store the LOB value.
The maximum CHUNK value is 32768 (32K), which is the largest Oracle Database block size allowed as documented in 19c LOB Storage with Applications :
LOB Storage CHUNK 
  If the tablespace block size is the same as the database block size, 
  then CHUNK is also a multiple of the database block size. 
  The default CHUNK size is equal to the size of one tablespace block, and the maximum value is 32K. 


2. Plsql and Java LOB Chunksize and BufferSize


We will look two sources of Java LOB objects, one is created in DB and passed to OracleJVM, another is directly created in OracleJVM. Besides chunksize similar to above SQL, Java LOB object has a bufferSize.

Here the test code:

drop java source "LobChunkBufferSize";

create or replace and compile java source named "LobChunkBufferSize" as
import java.sql.Connection;
import java.io.IOException;
import java.sql.SQLException;
import oracle.jdbc.OracleDriver;
import oracle.sql.CLOB;
import oracle.sql.BLOB;

public class LobChunkBufferSize {
    public static void printSizeFromDB(CLOB clob, BLOB blob) throws Exception {
        System.out.println("Java  CLOB ChunkSize: " + clob.getChunkSize() + ", BufferSize: " + clob.getBufferSize());
        System.out.println("Java  BLOB ChunkSize: " + blob.getChunkSize() + ", BufferSize: " + blob.getBufferSize());
    }
    
    public static void printSizeFromOracleJvm() throws Exception {
      Connection conn = new OracleDriver().defaultConnection();
      CLOB clob = CLOB.createTemporary(conn, false, CLOB.DURATION_SESSION);
      System.out.println("OracleJvm CLOB ChunkSize: " + clob.getChunkSize() + ", BufferSize: " + clob.getBufferSize());
      
      BLOB blob = BLOB.createTemporary(conn, false, BLOB.DURATION_SESSION);
      System.out.println("OracleJvm BLOB ChunkSize: " + blob.getChunkSize() + ", BufferSize: " + blob.getBufferSize());
    }
}     
/

create Or replace procedure printSizeFromDB (p_clob clob, p_blob blob) 
as language java name 'LobChunkBufferSize.printSizeFromDB(oracle.sql.CLOB, oracle.sql.BLOB)';
/

create Or replace procedure printSizeFromOracleJvm
as language java name 'LobChunkBufferSize.printSizeFromOracleJvm()' ;
/
First we display Plsql Chunksize, then pass LOB to OracleJVM and display their Chunksize and Buffersize:

set serveroutput on size 50000;
exec dbms_java.set_output(50000);

declare
  l_clob  clob;
  l_blob  blob;
  procedure print (l_name varchar2, l_clob clob, l_blob blob) as
    begin
      dbms_output.put_line(l_name);
      dbms_output.put_line('Plsql CLOB ChunkSize: '||dbms_lob.getchunksize(l_clob));
      dbms_output.put_line('Plsql BLOB ChunkSize: '||dbms_lob.getchunksize(l_blob)); 
      printSizeFromDB(l_clob, l_blob);        
    end;
begin
    select clob_8k, blob_8k into l_clob, l_blob from tab_lob where id = 1;
    print('------- 1. DB Lob 8k -------', l_clob, l_blob);
    
    select clob_16k, blob_16k into l_clob, l_blob from tab_lob where id = 1;
    print('------- 2. DB Lob 16k -------', l_clob, l_blob);
    
    select clob_32k, blob_32k into l_clob, l_blob from tab_lob where id = 1;
    print('------- 3. DB Lob 32k -------', l_clob, l_blob);
    
    dbms_lob.createtemporary(l_clob, TRUE);
    dbms_lob.createtemporary(l_blob, TRUE);        
    print('------- 4. Temporary Lob empty -------', l_clob, l_blob);
    
    l_clob := 'ABCabc123';
    l_blob := utl_raw.cast_to_raw(l_clob);
    print('------- 5. Temporary Lob small -------', l_clob, l_blob);
    dbms_output.put_line('----------**** CLOB length: '||dbms_lob.getlength(l_clob));
    
    l_clob := lpad('ABCabc123', 32767, 'A');
    l_blob := utl_raw.cast_to_raw(l_clob);
    print('------- 6. Temporary Lob big -------', l_clob, l_blob);
    dbms_output.put_line('----------****  CLOB length: '||dbms_lob.getlength(l_clob));
end;
/
Here the result:

  ------- 1. DB Lob 8k -------
  Plsql CLOB ChunkSize: 8132
  Plsql BLOB ChunkSize: 8132
  Java  CLOB ChunkSize: 8132, BufferSize: 32528
  Java  BLOB ChunkSize: 8132, BufferSize: 32528
  ------- 2. DB Lob 16k -------
  Plsql CLOB ChunkSize: 16264
  Plsql BLOB ChunkSize: 16264
  Java  CLOB ChunkSize: 16264, BufferSize: 32528
  Java  BLOB ChunkSize: 16264, BufferSize: 32528
  ------- 3. DB Lob 32k -------
  Plsql CLOB ChunkSize: 32528
  Plsql BLOB ChunkSize: 32528
  Java  CLOB ChunkSize: 32528, BufferSize: 32528
  Java  BLOB ChunkSize: 32528, BufferSize: 32528
  ------- 4. Temporary Lob empty -------
  Plsql CLOB ChunkSize: 8132
  Plsql BLOB ChunkSize: 8132
  Java  CLOB ChunkSize: 8132, BufferSize: 32528
  Java  BLOB ChunkSize: 8132, BufferSize: 32528
  ------- 5. Temporary Lob small -------
  Plsql CLOB ChunkSize: 4000
  Plsql BLOB ChunkSize: 4000
  Java  CLOB ChunkSize: 4000, BufferSize: 32000
  Java  BLOB ChunkSize: 4000, BufferSize: 32000
  ----------**** CLOB length: 9
  ------- 6. Temporary Lob big -------
  Plsql CLOB ChunkSize: 4000
  Plsql BLOB ChunkSize: 4000
  Java  CLOB ChunkSize: 4000, BufferSize: 32000
  Java  BLOB ChunkSize: 4000, BufferSize: 32000
  ----------****  CLOB length: 32767
We can see that Plsql and Java ChunkSize are the same as SQL for 8k, 16k, and 32k, and their BufferSize are always 32528. But Temporary Lob is special. In case of empty, ChunkSize is 8132, when assigned a value, it is decreased to 4000, in which CHUNK seems no more a multiple of the database block size as described in above "LOB Storage CHUNK". Their BufferSize are respectively 32528, 32000.

Now we look ChunkSize and BufferSize for LOB created in OracleJVM:

SQL > exec printSizeFromOracleJvm;

  OracleJvm CLOB ChunkSize: 8132, BufferSize: 32528
  OracleJvm BLOB ChunkSize: 8132, BufferSize: 32528
They are the same as the above case of 8k.

If we open Java class BLOB, we can see that getBufferSize is computed based on getChunkSize (all calculations are Java integer arithmetic), for example, if ChunkSize is 8132, BufferSize is 32528 (4*8132). Its maximum value is hard-coded as 32768 (probably the same limit as largest allowed Oracle Database block size).

public class BLOB extends DatumWithConnection implements Blob {
    public int getBufferSize() throws SQLException {
        ...

        int size = getChunkSize();
        int ret = size;

        if ((size >= 32768) || (size <= 0)) {
            ret = 32768;
        } else {
            ret = 32768 / size * size;
        }
        ...
        
        return ret;
    }
SQL*Plus Release 12.2.0.1.0 New Feature:

SET LOBPREFETCH {0 | n} 
sets the amount of LOB data (in bytes) that SQL*Plus will prefetch from the database at one time (one "roundtrips to/from client"), which has a maximum value of 32767. Each LOB value fetch requires one roundtrip.

One case of dbms_alert.signal deadlock

In this Blog, we present one case of DBMS_ALERT_INFO update deadlock when two sessions calling dbms_alert.signal.

At first, setup test by:

begin
       dbms_alert.register('test_alert_1');
       dbms_alert.register('test_alert_2');
end;
/
Then open 2 Sqlplus Sessions: S1, and S2, run following steps one after another:

---======== S1@T1:  send 'test_alert_1' ========---
exec dbms_alert.signal('test_alert_1', 'alert_msg_1');

---======== S2@T2:  send 'test_alert_2' ========---
exec dbms_alert.signal('test_alert_2', 'alert_msg_2');

---======== S1@T3:  send 'test_alert_2' ========---
exec dbms_alert.signal('test_alert_2', 'alert_msg_2');

---======== S2@T4:  send 'test_alert_1' ========---
exec dbms_alert.signal('test_alert_1', 'alert_msg_1');
After about 3 seconds, S1 (first starting session) hit a deadlock.
  
ERROR at line 1:
ORA-00060: deadlock detected while waiting for resource
ORA-06512: at "SYS.DBMS_ALERT", line 431
ORA-06512: at line 1
The trace file contains the Deadlock graph and Error Stack. It looks like a conventional case of deadlock generated in application of dbms_alert.signal.

Deadlock graph:
                                          ------------Blocker(s)-----------  ------------Waiter(s)------------
Resource Name                             process session holds waits serial  process session holds waits serial
TX-000F0014-00030A6B-00000000-00000000          8     374     X        16904      47     914           X  60788
TX-00020013-00043AF0-00000000-00000000         47     914     X        60788       8     374           X  16904
 
----- Information for waiting sessions -----
Session 374:
  sid: 374 ser: 16904 audsid: 50061287 user: 0/SYS
    flags: (0x8100041) USR/- flags2: (0x40009) -/-/INC
    flags_idl: (0x1) status: BSY/-/-/- kill: -/-/-/-
  pid: 8 O/S info: user: oracle, term: UNKNOWN, ospid: 6207
    image: oracle@testdb
  client details:
    O/S info: user: ksun, term: TESTPC, ospid: 20744:22464
    machine: SYS\TESTPC program: sqlplus.exe
    application name: SQL*Plus, hash value=3669949024
  current SQL:
  UPDATE DBMS_ALERT_INFO SET CHANGED = 'Y', MESSAGE = :B2 WHERE NAME = UPPER(:B1 )
 
Session 914:
  sid: 914 ser: 60788 audsid: 50061288 user: 0/SYS
    flags: (0x8100041) USR/- flags2: (0x40009) -/-/INC
    flags_idl: (0x1) status: BSY/-/-/- kill: -/-/-/-
  pid: 47 O/S info: user: oracle, term: UNKNOWN, ospid: 6325
    image: oracle@testdb
  client details:
    O/S info: user: ksun, term: TESTPC, ospid: 21236:22040
    machine: SYS\TESTPC program: sqlplus.exe
    application name: SQL*Plus, hash value=3669949024
  current SQL:
  UPDATE DBMS_ALERT_INFO SET CHANGED = 'Y', MESSAGE = :B2 WHERE NAME = UPPER(:B1 )
 
----- End of information for waiting sessions -----
 
*** 2020-11-08T14:53:34.649821+01:00
dbkedDefDump(): Starting a non-incident diagnostic dump (flags=0x0, level=1, mask=0x0)
----- Error Stack Dump -----
 at 0x7ffef6442228 placed updexe.c@2062
 at 0x7ffef6443050 placed updexe.c@4637
----- Current SQL Statement for this session (sql_id=6tmkh8j0d3w0p) -----
UPDATE DBMS_ALERT_INFO SET CHANGED = 'Y', MESSAGE = :B2 WHERE NAME = UPPER(:B1 )
----- PL/SQL Stack -----
----- PL/SQL Call Stack -----
  object      line  object
  handle    number  name
0x9ce97888       431  package body SYS.DBMS_ALERT.SIGNAL
0x7294ec28         1  anonymous block
In AskTOM: dbms_alert_info - Ask TOM - Oracle, there is also one case of dbms_alert deadlock.

Sunday, September 13, 2020

The Second Test of ORA-600 [4156] Rolling Back To Savepoint

In the previous Blog: ORA-600 [4156] SAVEPOINT and PL/SQL Exception Handling, we followed Oracle MOS Note:
     Bug 9471070 : ORA-600 [4156] GENERATED WITH EXECUTE IMMEDIATE AND SAVEPOINT
and presented 5 reproducible test codes (one original from MOS plus 4 variants).

In this Second Test, we extend the previous test by including Global Temporary Table (GTT), and run the test with trace and dumps to get further understanding of the error.

The original MOS Note: Bug 9471070 cannot be found any more. As a substitute, we found a new published MOS Note:
     ORA-00600: [4156] when Rolling Back to a Savepoint (Doc ID 2242249.1)
which provides a possible workaround:
     Set the TEMP_UNDO_ENABLED back to the default setting of FALSE.
We will repeat the same tests with this workaround and watch the outcome.

Note: Tested in Oracle 19.6


1. Test Setup


The test includes a normal table and a GTT table. GTT table is created analogue to SYS.ATEMPTAB$. We also list their object_id for later dump file reference.

drop table test_tab purge;
create table test_tab(id number);

drop table test_atemptab purge;
create global temporary table test_atemptab (id number) on commit delete rows nocache;
create index test_atempind on test_atemptab(id);

select object_name, object_id from dba_objects where object_name in ('TEST_TAB', 'TEST_ATEMPTAB', 'TEST_ATEMPIND');
  OBJECT_NAME    OBJECT_ID
  -------------  ---------
  TEST_TAB         3333415
  TEST_ATEMPTAB    3333416
  TEST_ATEMPIND    3333417     
By the way, SYS.ATEMPTAB$ (and its index SYS.ATEMPIND$) has the smallest object_id in dba_objects with TEMPORARY='Y', possibly the earliest Oracle temporary object. If ORA-00600: [4156] points to some SYS object like this one, it probably signifies an Oracle internal error since applications do not have privilege to directly perform DML on it.


2. ORA-600 [4156] Error Message


At first, we perform all the tests with TEMP_UNDO_ENABLED= TRUE. Later we will test the workaround of FALSE (default) provided by MOS (Doc ID 2242249.1).

Open a Sqplus window, run following code snippet (similar to VARIANT-3 in Blog: ORA-600 [4156] SAVEPOINT and PL/SQL Exception Handling).

savepoint sp_a;
insert into test_tab values(1);
insert into test_atemptab values(11);
savepoint sp_b; 
begin
  rollback to savepoint sp_a;
  insert into test_atemptab values(12);
  rollback to savepoint sp_b;
end;
/
The session is terminated with ORA-00600, and an incident file is generated:

ORA-00603: ORACLE server session terminated by fatal error
ORA-00600: internal error code, arguments: [4156], [], [], [], [], [], [], [],
[], [], [], []
ORA-01086: savepoint 'SP_B' never established in this session or is invalid
ORA-06512: at line 4
Process ID: 25417
Session ID: 902 Serial number: 20826
Opening incident file, it shows:

kturRollbackToSavepoint temp undokturRollbackToSavepoint savepoint uba: 0x00406a82.0000.02 xid: 0x005f.016.00007623
kturRollbackToSavepoint current call savepoint: ksucaspt num: 342  uba: 0x00c060ad.15fe.11
uba: 0x00406a82.0000.02 xid: 0x005f.016.00007623
 xid: 0x0386.000.00000001           <<< 0x0386 is Session ID: 902 (0x0386)
The first line indicates that the session is trying to rollback to a target savepoint by using temp undo (uba: 0x00406a82.0000.02) in transaction (xid: 0x005f.016.00007623).

The second and third line contain the info at the moment of crash, probably caused the error, which are savepoint (num: 342), permanent undo (uba: 0x00c060ad.15fe.11), temporary undo (uba: 0x00406a82.0000.02), transaction (xid: 0x005f.016.00007623).

The fourth line (xid: 0x0386.000.00000001) is not clear. As all the tests suggested, the first hexadecimal number is Session ID, for example, above 0x0386 is Session ID: 902. The second and third hexadecimal numbers are always 000.00000001.


3. Test with Trace and Dumps


To further explore the error, we can add some trace code to the test.

First we create a helper Plsql procedure to write out transaction and permanent/temporary undo info.

create or replace procedure write_info (p_step varchar2, p_sleep number := 5) as
  l_dst       binary_integer := 1;
  l_sid       number;
  l_trx       varchar2(100);
  l_temp_undo varchar2(100);
begin
  select sid into l_sid from v$mystat where rownum=1;
  
  select 'SID:'||s.sid||', XID:('||xidusn||'.'||xidslot||'.'||xidsqn||', '||flag||
         '), UNDO:('||ubafil||', '||ubablk||', '||ubasqn||', '||ubarec||')'
  into l_trx
  from v$transaction t, v$session s 
  where t.addr(+) = s.taddr and s.sid = l_sid;
  
  select 'TEMP_UNDO_HEADER:('||segrfno#||', '||segblk#||', '||segfile#||')' 
  into l_temp_undo
  from v$tempseg_usage t, v$session s 
  where t.segtype(+) = 'TEMP_UNDO' and t.session_addr(+) = s.saddr and s.sid = l_sid;
  
  sys.dbms_system.ksdwrt(l_dst, p_step||l_trx||', '||l_temp_undo);
  dbms_session.sleep(p_sleep);
end;
/
Each output line is composed of three tuples (all numbers in decimal):

  Step sid, XID:(xidusn.xidslot.xidsqn, flag), 
            UNDO:(ubafil, ubablk, ubasqn, ubarec), 
            TEMP_UNDO_HEADER:(segrfno#, segblk#, segfile#)
In the above test code, we add write_info after each code line. Step1 to Step5 make a default pause of 5 seconds. At Step6, we sleep 300 seconds, so that we have time to make dumps.

Open a Sqlplus window, run code below:

alter session set max_dump_file_size = unlimited;

alter session set tracefile_identifier = "Test_f";  

savepoint sp_a;
  exec write_info('Step1_');   
insert into test_tab values(1);
  exec write_info('Step2_');
insert into test_atemptab values(11);
savepoint sp_b; 
  exec write_info('Step3_');
begin
       write_info('Step4_');
  rollback to savepoint sp_a;
       write_info('Step5_');
  insert into test_atemptab values(12);
       write_info('Step6_', 300);
  rollback to savepoint sp_b;
       write_info('Step7_');
end;
/
And monitor the trace file "Test_f", once it reaches Step6 as follows:

Oracle process number: 38
Unix process pid: 16147, image: oracle@testdb
*** SESSION ID:(370.53180) 2020-09-13T15:21:48.003188+02:00

*** 2020-09-13T15:21:53.118636+02:00
Step2_SID:370, XID:(89.15.51190, 7683), UNDO:(3, 2476, 6688, 3), TEMP_UNDO_HEADER:(, , )

*** 2020-09-13T15:21:58.165769+02:00
Step3_SID:370, XID:(89.15.51190, 7683), UNDO:(3, 2476, 6688, 3), TEMP_UNDO_HEADER:(1, 19328, 3073)

*** 2020-09-13T15:22:03.263868+02:00
Step4_SID:370, XID:(89.15.51190, 7683), UNDO:(3, 2476, 6688, 3), TEMP_UNDO_HEADER:(1, 19328, 3073)

*** 2020-09-13T15:22:08.352391+02:00
Step5_SID:370, XID:(89.15.51190, 5635), UNDO:(0, 0, 0, 0), TEMP_UNDO_HEADER:(1, 19328, 3073)

*** 2020-09-13T15:22:13.553650+02:00
Step6_SID:370, XID:(89.15.51190, 5635), UNDO:(0, 0, 0, 0), TEMP_UNDO_HEADER:(1, 19328, 3073)
we pick the three tuples from Step4 line:

Step4_SID:370, XID:(89.15.51190, 7683), UNDO:(3, 2476, 6688, 3), TEMP_UNDO_HEADER:(1, 19328, 3073)
and make the both permanent and temporary undo dump (19328 is temp undo header block, we make 4 more blocks dump to include undo data block):

oradebug setmypid;
alter system flush buffer_cache;
alter system checkpoint;

oradebug settracefileid undo_f;
alter system dump datafile 3 block min 2476 block max 2476; 

oradebug settracefileid temp_undo_f;
alter system dump tempfile 1 block min 19328 block max 19332;	
and additionally make a processstate dump (38 is Oracle PID of test session):

oradebug setorapid 38;
oradebug settracefileid proc_f;
oradebug dump processstate 10;
After about 6 minutes, the session terminated with fatal error:

ORA-00603: ORACLE server session terminated by fatal error
ORA-00600: internal error code, arguments: [4156], [], [], [], [], [], [], [], [], [], [], []
ORA-01086: savepoint 'SP_B' never established in this session or is invalid
ORA-06512: at line 7
Process ID: 16147
Session ID: 370 Serial number: 53180
and incident file looks like:

========= Dump for incident 73594 (ORA 600 [4156]) ========
*** SESSION ID:(370.53180) 2020-09-13T15:27:13.752430+02:00

kturRollbackToSavepoint temp undokturRollbackToSavepoint savepoint uba: 0x00404b82.0000.02 xid: 0x0059.00f.0000c7f6
kturRollbackToSavepoint current call savepoint: ksucaspt num: 394  uba: 0x00c009ac.1a20.03
uba: 0x00404b82.0000.02 xid: 0x0059.00f.0000c7f6
 xid: 0x0172.000.00000001         <<< 0x0172 is Session ID: 370 (0x0172)
Now we go through all three dumps (only related lines are extracted).


3.1. Permanent Undo


We inserted one row into test_tab. "Rec #0x3" is the only undo record (first and last), noted with "rdba: 0x00000000" and "rci 0x00". It is "uba: 0x00c009ac.1a20.03" (rdba: 3/2476, seq: 6688, rec: 3) in above incident file.

========= undo_f ========
Start dump data blocks tsn: 2 file#:3 minblk 2476 maxblk 2476
Block dump from cache:
Dump of buffer cache at level 3 for pdb=0 tsn=2 rdba=12585388
BH (0x140f569e8) file#: 3 rdba: 0x00c009ac (3/2476) class: 194 ba: 0x1400c6000
...
UNDO BLK:  
 xid: 0x0059.00f.0000c7f6  seq: 0x1a20 cnt: 0x3   irb: 0x3   icl: 0x0   flg: 0x0000
 
 Rec Offset      Rec Offset      Rec Offset      Rec Offset      Rec Offset
---------------------------------------------------------------------------
0x01 0x1f78     0x02 0x1ec4     0x03 0x1e3c     
...
*-----------------------------
* Rec #0x3  slt: 0x0f  objn: 3333415(0x0032dd27)  objd: 3333415  tblspc: 2300(0x000008fc)
*       Layer:  11 (Row)   opc: 1   rci 0x00   
Undo type:  Regular undo    Begin trans    Last buffer split:  No 
Temp Object:  No 
rdba: 0x00000000Ext idx: 0
flg2: 0
*-----------------------------
uba: 0x00c009ac.1a20.02 ctl max scn: 0x000008d5bc68c586 prv tx scn: 0x000008d5bc68c589
txn start scn: scn: 0x000008d5bc68ccc8 logon user: 49
 prev brb: 12585365 prev bcl: 0


3.2. Temp Undo


At first, we look temp undo header block (rdba: 0x00404b80 (1/19328) class: 33. File number: 3073, Relative file number: 1).

========= temp_undo_f (undo header block) ========
Dump of buffer cache at level 3 for pdb=0 tsn=3 rdba=4213632
BH (0x108fe8de8) file#: 3073 rdba: 0x00404b80 (1/19328) class: 33 ba: 0x108dc6000
...
  TRN CTL:: seq: 0x0000 chd: 0x0001 ctl: 0x0061 inc: 0x00000000 nfb: 0x0000
            mgc: 0x8002 xts: 0x0068 flg: 0x0001 opt: 2147483647 (0x7fffffff)
            uba: 0x00404b82.0000.01 scn: 0x0000000000000000 
  TRN TBL::
  index  state cflags  wrap#    uel         scn            dba            parent-xid    nub     stmt_num
  ------------------------------------------------------------------------------------------------
   0x00   10    0x80  0x0001  0x0000  0x000008d5bc68cd00  0x00404b82   0x0000.000.00000000  0x00000001   0x00000000   0
   0x01    9    0x00  0x0000  0x0002  0x0000000000000000  0x00000000   0x0000.000.00000000  0x00000000   0x00000000   0
...
   0x61    9    0x00  0x0000  0xffff  0x0000000000000000  0x00000000   0x0000.000.00000000  0x00000000   0x00000000   0
There is one active slot 0x00 flagged with state 10, which is our transaction with starting uba: 0x00404b82.0000.01, and current dba 0x00404b82.

Here we can also see that temp undo header (class: 33) TRN TBL has 98 entries (0x00 to 0x61), whereas normal permanent undo header has 34 entries (0x00 to 0x21).

Then look temp undo data block (rdba: 0x00404b82 (1/19330) class: 34).

========= temp_undo_f (undo data block) ========
Dump of buffer cache at level 3 for pdb=0 tsn=3 rdba=4213634
BH (0x109fe2308) file#: 3073 rdba: 0x00404b82 (1/19330) class: 34 ba: 0x109d2e000
...
UNDO BLK:  
 xid: 0x0059.00f.0000c7f6  seq: 0x0   cnt: 0x4   irb: 0x4   icl: 0x0   flg: 0x0000
 
 Rec Offset      Rec Offset      Rec Offset      Rec Offset      Rec Offset
---------------------------------------------------------------------------
0x01 0x1f6c     0x02 0x1efc     0x03 0x1eb0     0x04 0x1e40     
...
*-----------------------------
* Rec #0x1  slt: 0x00  objn: 3333416(0x0032dd28)  objd: 4222336  tblspc: 3(0x00000003)
*       Layer:  11 (Row)   opc: 1   rci 0x00   
Undo type:  Regular undo    Begin trans    Last buffer split:  No 
Temp Object:  Yes 
rdba: 0x00000000Ext idx: 4
*-----------------------------
uba: 0x00000000.0000.00 ctl max scn: 0x0000000000000000 prv tx scn: 0x0000000000000000
txn start scn: scn: 0x000008d5bc68cd00 logon user: 49
 prev brb: 0 prev bcl: 0
*-----------------------------
* Rec #0x2  slt: 0x00  objn: 3333417(0x0032dd29)  objd: 4221568  tblspc: 3(0x00000003)
*       Layer:  10 (Index)   opc: 22   rci 0x01   
rdba: 0x00000000Ext idx: 5
*-----------------------------
(kdxlpu): purge leaf row
key :(10):  02 c1 0c 06 00 40 6d 81 00 00
*-----------------------------
* Rec #0x3  slt: 0x00  objn: 3333416(0x0032dd28)  objd: 4221568  tblspc: 3(0x00000003)
*       Layer:  11 (Row)   opc: 1   rci 0x00   
rdba: 0x00000000Ext idx: 4
*-----------------------------
* Rec #0x4  slt: 0x00  objn: 3333417(0x0032dd29)  objd: 4222336  tblspc: 3(0x00000003)
*       Layer:  10 (Index)   opc: 22   rci 0x03   
rdba: 0x00000000Ext idx: 5
*-----------------------------
(kdxlpu): purge leaf row
key :(10):  02 c1 0d 06 00 40 6a 81 00 00
Here we can see two temp table inserted rows:

  02 c1 0c 06 00 40 6d 81 00 00    <<< "c1 0c": 02 bytes for number 11, followed by 06 bytes
  02 c1 0d 06 00 40 6a 81 00 00    <<< "c1 0d": 02 bytes for number 12, followed by 06 bytes
both are marked with "purge leaf row", that represents undo of insert (reverse of insert).

In the above dump, there are 4 undo records. The last one is "Rec #0x4", whose "rci 0x03" indicates that its previous undo record is "Rec #0x3" (all undo records in the test with "rdba: 0x00000000"). Whereas "Rec #0x3" has "rci 0x00", which means that it is a first undo record and does not have any previous undo record, since in our test, immediately after "Step4", we rollback to a savepoint by:

  rollback to savepoint sp_a;
The incident file shows that "uba: 0x00404b82.0000.02" (Rec #0x2) is the target savepoint uba (undokturRollbackToSavepoint), and it is also the current temp undo record at the moment of crash (instead of Rec #0x4).

Since there is no link from ("Rec #0x4" -> "Rec #0x3") to ("Rec #0x2" -> "Rec #0x1"), "rollback to savepoint sp_b" failed, and hence ORA-600 [4156] Rolling Back To Savepoint.

By the way, if we remove this rollback, "Rec #0x3" will point to previous undo record "rci 0x02" as follows:

* Rec #0x3  slt: 0x00  objn: 3333416(0x0032dd28)  objd: 4221568  tblspc: 3(0x00000003)
*       Layer:  11 (Row)   opc: 1   rci 0x02  


3.3. Processstate


We only list Savepoint related lines.

========= proc_f ========
Flags=[0000] SavepointNum=1a7 Time=09/13/2020 15:22:13 
  LibraryHandle:  Address=0x8b61ad18 Hash=4ac26de7 LockMode=N PinMode=0 LoadLockMode=0 Status=VALD 
  ObjectName:  Name=INSERT INTO TEST_ATEMPTAB VALUES(12) 
    
Flags=CNB/[0001] SavepointNum=18a Time=09/13/2020 15:22:03 
  LibraryHandle:  Address=0x8b5e1558 Hash=a2b60837 LockMode=N PinMode=0 LoadLockMode=0 Status=VALD 
  ObjectName:  Name=begin
                           write_info('Step4_');
                      rollback to savepoint sp_a;
                           write_info('Step5_');
                      insert into test_atemptab values(12);
                           write_info('Step6_', 300);
                      rollback to savepoint sp_b;
                           write_info('Step7_');
                    end;

Flags=CNB/[0001] SavepointNum=164 Time=09/13/2020 15:21:57 
  LibraryHandle:  Address=0xa39d5d68 Hash=65d67994 LockMode=N PinMode=0 LoadLockMode=0 Status=VALD 
  ObjectName:  Name=insert into test_atemptab values(11) 
    
Flags=CNB/[0001] SavepointNum=14f Time=09/13/2020 15:21:52 
  LibraryHandle:  Address=0x96c1c530 Hash=9abe37a2 LockMode=N PinMode=0 LoadLockMode=0 Status=VALD 
  ObjectName:  Name=insert into test_tab values(1) 
We can see the three executed DML insert statements, one Plsql anonymous block, and their corresponding Savepoint numbers, timestamp, ordered reversely by execution sequence:

  INSERT INTO TEST_ATEMPTAB VALUES(12)  >>> SavepointNum=1a7  Time=09/13/2020 15:22:13 
  begin ... end                         >>> SavepointNum=18a  Time=09/13/2020 15:22:03
  insert into test_atemptab values(11)  >>> SavepointNum=164  Time=09/13/2020 15:21:57 
  insert into test_tab values(1)        >>> SavepointNum=14f  Time=09/13/2020 15:21:52
SavepointNum=18a is placed directly before we submit Plsql anonymous block.

Searching "0x18a" in Processstate dump, we found:

svpt(xcb:0xad719320 sptn:0x18a uba: 0x00c009ac.1a20.03 uba: 0x00404b82.0000.02)
xctsp name:ˆb¬‹
      svpt(xcb:0x8bac6310 sptn:0x6013cfa0 uba: 0x00000000.0000.00 uba: 0x00000000.0000.00)
      status:INVALID next:(nil)
Referring back to above incident file, "current call savepoint: ksucaspt num: 394" is exactly "sptn:0x18a". Its cryptic name "ˆb¬‹" (extended ascii: 88 62 AC 8B) suggested that it is an implicit savepoint created by Oracle in order to maintain the atomicity (eventually rollback when error happens). The "status:INVALID" probably hints the cause of ORA-00600: [4156].
(Note: occasionally cryptic name is empty, or "status:VALID", but same ORA-00600: [4156]).

In above trace file "Test_f", Step5 and Step6 are marked with a valid XID, but UNDO tuple contains 4 zeros:

Step5_SID:370, XID:(89.15.51190, 5635), UNDO:(0, 0, 0, 0), TEMP_UNDO_HEADER:(1, 19328, 3073)
It means that there exists an active transaction having XID, but no undo record. If we dump permanent undo header block, it also shows dba as "0x00000000" for the active (state 10) TRN TBL slot. By the way, in Blog: TM lock and No Transaction Commit, TX & TM Locks and No Transaction Visible , we showed one case where there exist TX and TM Locks, but no Transaction Visible (TX & TM Locks and No Transaction Visible).

gv$transaction is defined as:

select 
    ...
    ktcxbflg                                             flag     ,                                            
    decode (bitand (ktcxbflg, 16), 0, 'NO', 'YES')       space    ,      
    decode (bitand (ktcxbflg, 32), 0, 'NO', 'YES')       recursive,      
    decode (bitand (ktcxbflg, 64), 0, 'NO', 'YES')       noundo   ,      
    decode (bitand (ktcxbflg, 8388608), 0, 'NO', 'YES')  ptx      , 
    ...
  from x$ktcxb 
 where bitand (ksspaflg, 1) != 0 and bitand (ktcxbflg, 2) != 0
It contains a column: NOUNDO, computed by bitand (ktcxbflg, 64), which is YES for no undo transaction. In above test, the exported flag is either 5635 (1 0110 0000 0011) or 7683 (1 1110 0000 0011). Both has bit-7 not set (0100 0000=64), i.e., NOUNDO = 'NO'.

In above Step5, we have UNDO:(0, 0, 0, 0), but NOUNDO = 'NO'. It is not clear how this flag is set up.

We also tried to put a DML insert before "savepoint sp_a" to keep UNDO filled with non zeors, but it generates the same error.

insert into test_tab values(0);
savepoint sp_a;
insert into test_tab values(1);
insert into test_atemptab values(11);
savepoint sp_b; 
begin
  rollback to savepoint sp_a;
  insert into test_atemptab values(12);
  rollback to savepoint sp_b;
end;
/
(Note: If TEMP_UNDO_ENABLED = FALSE, the above code snippet with this added first insert statement does not throw "ORA-00600: [4156]", the error is "ORA-01086: savepoint 'SP_B' never established in this session or is invalid")

In above investigation, we looked different traces and dumps to understand the error. In real operations, when such an error occurs, an incident file is generated. We can go through the incident file to find similar information (if dump file size is unlimited).

In the incident file, we can see the redo dump commands like:

Dump redo command(s):
 ALTER SYSTEM DUMP REDO DBA MIN 3073 19328 DBA MAX 3073 19328 TIME MIN 1050591433 TIME MAX 1050593293
 ALTER SYSTEM DUMP REDO DBA MIN 3073 19330 DBA MAX 3073 19330 TIME MIN 1050591451 TIME MAX 1050593311
which are brought out by call stack:

  kcra_dump_redo_tsn_rdba <- kturDiskRbkToSvpt <- kturRbkToSvpt <- ktcrsp1_new 
  <- ktcrsp1 <- ksudlc <- kss_del_cb <- kssdel <- ksupop


4. TEMP_UNDO_ENABLED = FALSE Workaround Test


Here the Oracle Workaround MOS Note (copy here to archive a persistent reference):
ORA-00600: [4156] when Rolling Back to a Savepoint (Doc ID 2242249.1)

Applies to:
    Oracle Database - Standard Edition - Version 12.1.0.2 and later
Symptoms
    You are running a procedure that utilizes savepoints, however, 
    when attempting to rollback to a savepoint, you experience the following error:
The stack trace will show similar stack:
    ksedst1 <- ksedst <- dbkedDefDump <- ksedmp <- ksfdmp <- dbgexPhaseII <- dbgexExplicitEndInc 
    <- dbgeEndDDEInvocatio <- nImpl <- dbgeEndDDEInvocatio <- kturDiskRbkToSvpt <- kturRbkToSvpt 
    <- ktcrsp1 <- xctrsp <- roldrv <- kksExecuteCommand
Cause
    This is due to a product defect. This is being investigated in unpublished
    Bug 25393735 - SR18.1TEMPUNDO - TRC - KTURDISKRBKTOSVPT - ORA-600 [4156]
    This issue occurs when we have temp undo and the logical standby performs eager apply.
Solution
    Possible workaround is:
      Set the TEMP_UNDO_ENABLED back to the default setting of FALSE.
    TEMP_UNDO_ENABLED determines whether transactions within a particular session can have a temporary undo log.
    The default choice for database transactions has been to have a single undo log per transaction. 
    This parameter, at the session level / system level scope, lets a transaction split its undo log into 
    temporary undo log (for changes on temporary objects) and permanent undo log (for changes on persistent objects).
    
    Modifiable: ALTER SESSION, ALTER SYSTEM
Now we try to test the Workaround with the same code:

ALTER SESSION set TEMP_UNDO_ENABLED=FALSE;
-- ALTER SYSTEM set TEMP_UNDO_ENABLED= FALSE; is also tested. Same outcome

savepoint sp_a;
insert into test_tab values(1);
insert into test_atemptab values(11);
savepoint sp_b; 
begin
  rollback to savepoint sp_a;
  insert into test_atemptab values(12);
  rollback to savepoint sp_b;
end;
/

ORA-00603: ORACLE server session terminated by fatal error
ORA-00600: internal error code, arguments: [4156], [], [], [], [], [], [], [],
[], [], [], []
ORA-01086: savepoint 'SP_B' never established in this session or is invalid
ORA-06512: at line 4
Process ID: 24328
Session ID: 370 Serial number: 32536
The session terminated by the same fatal error, and incident file shows:

kturRollbackToSavepoint perm undokturRollbackToSavepoint savepoint uba: 0x00c038d7.1a1c.0b xid: 0x0059.01f.0000c7f4
kturRollbackToSavepoint current call savepoint: ksucaspt num: 362  uba: 0x00c038d7.1a1c.0b
uba: 0x00000000.0000.00 xid: 0x0059.01f.0000c7f4
 xid: 0x0000.000.00000000
Compared to the case of TEMP_UNDO_ENABLED=TRUE, no more temp undo is recorded. If we also make a processstate dump, we can see the similar savepoint info.

In fact, we re-run all 5 test codes from previous Blog: ORA-600 [4156] SAVEPOINT and PL/SQL Exception Handling in the same DB (Oracle 19.6), once with default TEMP_UNDO_ENABLED=FALSE, and once with TEMP_UNDO_ENABLED=TRUE. They all generated ORA-600 [4156]. As above tests showed, it is not clear in which case the abvoe MOS Note Workaround can be applied.

Friday, August 21, 2020

Row Cache Object and Row Cache Mutex Case Study

12cR2 introduced "row cache mutex" to replace previous "latch: row cache objects". In this Blog, we will choose 'dc_props' and 'dc_cdbprops' to test "row cache mutex". Both have a fixed number of objects, a fixed pattern to use mutex for each object access, so that test can be repeated, and results are identical for each run.

First we run queries and make dumps to expose row cache data structure and content. Then we perform 10222 event trace and gdb script to understand row cache data access and row cache mutex usage. Finally we make a few discussions on the test result.

Note: Tested in Oracle 19c on Linux.

Acknowledgement: This work results from the help and discussions with a longtime Oracle specialist.


1. Row Cache: 'dc_props' and 'dc_cdbprops'


Following query shows that dc_props has 85 objects, and dc_cdbprops has 6.

select cache#, type, subordinate#, parameter, count, usage, fixed, gets, fastgets 
from v$rowcache where parameter in ('dc_props', 'dc_cdbprops');

  CACHE# TYPE   SUBORDINATE# PARAMETER   COUNT USAGE FIXED    GETS FASTGETS
  ------ ------ ------------ ----------- ----- ----- ----- ------- --------
      15 PARENT              dc_props       85    85     0 1162164        0
      60 PARENT              dc_cdbprops     6     6     0    1127        0
One query on nls_database_parameters requires 88 row cache Gets. (GETS_DELTA should be 85, the difference of 3 is due to v$rowcache query. dc_props is the backbone of nls_database_parameters. See Blog: nls_database_parameters, dc_props, latch: row cache objects )

column gets new_value gets_old;
column fastgets new_value gets_oldf;
select sum(gets) gets, sum(fastgets) fastgets from v$rowcache where parameter = 'dc_props';

select value from nls_database_parameters where parameter = 'NLS_CHARACTERSET';

select (sum(gets)-&gets_old) gets_delta, (sum(fastgets)-&gets_oldf) gets_deltaf, sum(gets) gets, sum(fastgets) fastgets from v$rowcache where parameter = 'dc_props';

  GETS_DELTA  GETS_DELTAF        GETS    FASTGETS
  ----------  -----------  ----------  ----------
          88            0      138749           0    
By the way, Oracle has a hidden parameter to turn on FASTGETS when TRUE, and 19c changed the default value from FALSE to TRUE.
    _kqr_optimistic_reads
Description: optimistic reading of row cache objects
Default: FALSE (Oracle 12.1); TRUE (Oracle 19.6)
Change: alter system set "_kqr_optimistic_reads"=false; (require DB restart)
One more query reveals that 85 'dc_props' objects are distributed into 5 hash buckets with size varied from 1 to 6 (no hash_bucket_size 5). Most of objects are hashed into bucket size of 1 or 2. Later we will see the same hash mapping in row_cache dump.

select Hash_Bucket_Size, count(*) Number_of_Buckets, (Hash_Bucket_Size * count(*)) Number_of_RowCache_Objects from 
  (select (hash+1) Hash_Bucket, count(*) Hash_Bucket_Size from v$rowcache_parent where cache_name = 'dc_props' group by hash)
group by Hash_Bucket_Size order by 2 desc;

  HASH_BUCKET_SIZE NUMBER_OF_BUCKETS NUMBER_OF_ROWCACHE_OBJECTS
  ---------------- ----------------- --------------------------
                 1                22                         22
                 2                13                         26
                 3                 5                         15
                 4                 4                         16
                 6                 1                          6
Here the similar query for 6 'dc_cdbprops' objects:

select Hash_Bucket_Size, count(*) Number_of_Buckets, (Hash_Bucket_Size * count(*)) Number_of_RowCache_Objects from 
  (select (hash+1) Hash_Bucket, count(*) Hash_Bucket_Size from v$rowcache_parent where cache_name = 'dc_cdbprops' group by hash)
group by Hash_Bucket_Size order by 2 desc;

  HASH_BUCKET_SIZE NUMBER_OF_BUCKETS NUMBER_OF_ROWCACHE_OBJECTS
  ---------------- ----------------- --------------------------
                 2                 2                          4
                 1                 2                          2      
With following helper function and query, we can reveal the exact name of each 'dc_props' row cache object (See Blog: Oracle ROWCACHE Views and Contents)

----helper function----
create or replace function dump_hex2str (dump_hex varchar2) return varchar2 is
  l_str varchar2(100);
begin
  with sq_pos as (select level pos from dual connect by level <= 1000)
      ,sq_chr as (select pos, chr(to_number(substr(dump_hex, (pos-1)*2+1, 2), 'XX')) ch
                  from sq_pos where pos <= length(dump_hex)/2)
  select listagg(ch, '') within group (order by pos) word
    into l_str
  from sq_chr;
  return l_str;
end;
/
     
select dump_hex2str(rtrim(key, '0')) dc_prop_name, v.* 
from v$rowcache_parent v 
where cache_name in ('dc_props') 
order by key; 

  DC_PROP_NAME         INDX HASH ADDRESS          CACHE# CACHE_NAME EXISTENT
  -------------------- ---- ---- ---------------- ------ ---------- --------
  COMMON_DATA_MA       8840    1 0000000094E51558     15 dc_props   N
  MAX_PDB_SNAPSHOTS    8838    0 0000000093638360     15 dc_props   Y
  NLS_SPECIAL_CHARS    8842    2 000000009F55FB18     15 dc_props   N
  NLS_TIMESTAMP_FORMAT 8841    2 000000008C2726C8     15 dc_props   Y
  PDB_AUTO_UPGRADE     8839    0 0000000095BCE218     15 dc_props   N
  ...
  85 rows selected.              


2. Row Cache Data Dump


With following command, we can dump 'dc_props'. (See MOS Bug 19354335 - Diagnostic enhancement for rowcache data dumps (Doc ID 19354335.8))

alter session set tracefile_identifier = 'dc_props_dump';
-- dump level 0xf2b: f is cache id 15 ('dc_props'), 2 is single cacheiddump, b is level of 11
alter session set events 'immediate trace name row_cache level 0xf2b';
alter session set events 'immediate trace name row_cache off';
The dump consists of 3 sections, the first is about all ROW CACHE STATISTICS, the second is ROW CACHE HASH TABLE for our specified 'dc_props' (same as above query output about HASH_BUCKET), the third is about each BUCKET and its grouped rows. For example, 4 rows are hashed to BUCKET 50. After BUCKET 50 is BUCKET 52, there is no BUCKET 51.

We will pick BUCKET 50 and its last row cache parent object "addr=0x8d7bc858" in our later discussion.

ROW CACHE STATISTICS:
cache                          size     gets  misses  hit ratio  
--------------------------  -------  -------  ------  ---------  
dc_tablespaces                  560    94329    3277      0.966  
dc_free_extents                 336        0       0      0.000  
dc_segments                     416     9751    3050      0.762  
dc_rollback_segments            496   769333     367      1.000  
...

ROW CACHE HASH TABLE: cid=15 ht=0xa709f910 size=64
  Hash Chain Size     Number of Buckets
  ---------------     -----------------
  0                    0
  1                   22
  2                   13
  3                    5
  4                    4
  5                    0    <<< HASH_BUCKET_SIZE 5 has 0 Buckets. Same as previous query
  6                    1               
           
BUCKET 50:
  row cache parent object: addr=0x8d776c38 cid=15(dc_props) conid=0 conuid=0
  hash=641d81f1 typ=21 transaction=(nil) flags=00000001 inc=1, pdbinc=1
  own=0x8d776d08[0x8d776d08,0x8d776d08] wat=0x8d776d18[0x8d776d18,0x8d776d18] mode=N req=N
  status=EMPTY/-/-/-/-/-/-/-/-  KGH unpinned
  data=
  
  row cache parent object: addr=0x8e8c5b10 cid=15(dc_props) conid=0 conuid=0
  hash=534cbb1 typ=21 transaction=(nil) flags=00000002 inc=1, pdbinc=1
  own=0x8e8c5be0[0x8e8c5be0,0x8e8c5be0] wat=0x8e8c5bf0[0x8e8c5bf0,0x8e8c5bf0] mode=N req=N
  status=VALID/-/-/-/-/-/-/-/-  KGH unpinned
  
  row cache parent object: addr=0x8e8e5be0 cid=15(dc_props) conid=0 conuid=0
  hash=3cf1dc71 typ=21 transaction=(nil) flags=00000002 inc=1, pdbinc=1
  own=0x8e8e5cb0[0x8e8e5cb0,0x8e8e5cb0] wat=0x8e8e5cc0[0x8e8e5cc0,0x8e8e5cc0] mode=N req=N
  status=VALID/-/-/-/-/-/-/-/-  KGH unpinned
  
  row cache parent object: addr=0x8d7bc858 cid=15(dc_props) conid=0 conuid=0
  hash=819e131 typ=21 transaction=(nil) flags=00000002 inc=1, pdbinc=1
  own=0x8d7bc928[0x8d7bc928,0x8d7bc928] wat=0x8d7bc938[0x8d7bc938,0x8d7bc938] mode=N req=N
  status=VALID/-/-/-/-/-/-/-/-  KGH unpinned
  data=
  
  BUCKET 50 total object count=4
BUCKET 52:
  row cache parent object: addr=0x8d76c148 cid=15(dc_props) conid=0 conuid=0


3. Processstate Dump


Additionally, we make a Processstate Dump, which contains "call: 0xb74520f0", and can be mapped to later 10222 trace "pso=0xb74520f0", and gdb "kqrpre1 pso (SOC): b74520f0".

alter session set tracefile_identifier = 'proc_state';
alter session set events 'immediate trace name PROCESSSTATE level 10'; 
alter session set events 'immediate trace name PROCESSSTATE off'; 
Each SO (State Object) seems having one SOC (State Object Call (or Copy) as current instance)

PROCESS STATE
-------------
Process global information:
     process: 0xb84202a0, call: 0xb74520f0, xact: (nil), curses: 0xb898ecc8, usrses: 0xb898ecc8
     in_exception_handler: no
  ----------------------------------------
  SO: 0xb8eeb9a8, type: process (2), map: 0xb84202a0
      state: LIVE (0x4532), flags: 0x1
      owner: (nil), proc: 0xb8eeb9a8
      link: 0xb8eeb9c8[0xb8eeb9c8, 0xb8eeb9c8]
      child list count: 6, link: 0xb8eeba18[0xb8f060c8, 0xa6fe8208]
      pg: 0
  SOC: 0xb84202a0, type: process (2), map: 0xb8eeb9a8
       state: LIVE (0x99fc), flags: INIT (0x1)
  (process) Oracle pid:55, ser:96, calls cur/top: 0xb74520f0/0xb74520f0
...
    ----------------------------------------
    SO: 0xb8f226a8, type: call (3), map: 0xb74520f0
        state: LIVE (0x4532), flags: 0x1
        owner: 0xb8eeb9a8, proc: 0xb8eeb9a8
        link: 0xb8f226c8[0xa6fe8208, 0xb4ed1eb0]
        child list count: 0, link: 0xb8f22718[0xb8f22718, 0xb8f22718]
        pg: 0
    SOC: 0xb74520f0, type: call (3), map: 0xb8f226a8
         state: LIVE (0x99fc), flags: INIT (0x1)
    (call) sess: cur b898ecc8, rec 0, usr b898ecc8; flg:20 fl2:1; depth:0
    svpt(xcb:(nil) sptn:0x13f uba: 0x00000000.0000.00 uba: 0x00000000.0000.00)


4. Row Cache Event 10222


Make one 10222 trace: (See Blog: Oracle row cache objects Event: 10222, Dtrace Scripts (I))

alter session set tracefile_identifier = 'dc_props_10222';
alter session set events '10222 trace name context forever, level 4294967295';  
select value from nls_database_parameters where parameter = 'NLS_CHARACTERSET';
alter session set events '10222 trace name context off';
The trace file contains Function Calls and Call Stack, for example, Parent Object po=0x8d7bc858 has hash=819e131, pso=0xb74520f0. The same information can be found in the output of next gdb Script.

kqrpre: start hash=819e131 mode=S keyIndex=0 dur=CALL opt=FALSE
kqrpre: found cached object po=0x8d7bc858 flg=2
kqrmpin : kqrpre: found po Pin po 0x8d7bc858 cid=15 flg=2 hash=819e131
time=978904531
kqrpre: pinned po=0x8d7bc858 flg=2 pso=0xb74520f0
pinned stack po=0x8d7bc858 cid=15: ----- Abridged Call Stack Trace -----
ksedsts()+426<-kqrpre2 code="" kkdlpexecsql="" kkdlpexecsqlcbk="" kkdlpget="" kqrpre1="">


5. gdb Script


In Oracle session, we run again query on nls_database_parameters, and at the same time, trace the process with Blog appended Script: gdb_cmd_script2 in a UNIX window, write the trace output into file mutex-test2.log.

$ > gdb -x gdb_cmd_script2 -p 18158

SQL > select value from nls_database_parameters where parameter = 'NLS_CHARACTERSET';
Excerpted from mutex-test2.log, here the access pattern for row cache row with addr=0x8d7bc858.

Breakpoint 334, 0x00000000126e3930 in kqrpre1 ()
<<<==================== (1) kqrpre1 pso (SOC): b74520f0 ====================>>>
Breakpoint 124, 0x00000000126dd4e0 in kqrpre2 ()
Breakpoint 125, 0x00000000126df840 in kqrhsh ()
Breakpoint 335, 0x00000000126df8ad in kqrhsh ()
     (1) kqrhsh retq hash (rax): hash=819e131
Breakpoint 135, 0x00000000126e33f0 in kqrGetHashMutexInt ()
Breakpoint 336, 0x00000000129da970 in kgxExclusive ()
     (1-1) ---> kgxExclusive Mutex addr (rsi): a70a01a8
Breakpoint 146, 0x00000000126e5fd0 in kqrGetPOMutex ()
Breakpoint 336, 0x00000000129da970 in kgxExclusive ()
     (1-2) ---> kgxExclusive Mutex addr (rsi): 8d7bc960
Breakpoint 137, 0x00000000126e38c0 in kqrIncarnationMismatch ()
Breakpoint 132, 0x00000000126e2170 in kqrCacheHit ()
Breakpoint 338, 0x00000000126e2980 in kqrmpin ()
     (1) kqrmpin v$rowcache_parent.address (rdi): addr=8d7bc858 cid=15
Breakpoint 131, 0x00000000126e1fa0 in kqrFreeHashMutex ()
Breakpoint 337, 0x00000000129db980 in kgxRelease ()
     (1-1) <--- kgxRelease Mutex addr (*rsi): a70a01a8
Breakpoint 127, 0x00000000126dfd30 in kqrLockPo ()
Breakpoint 128, 0x00000000126e0180 in kqrAllocateEnqueue ()
Breakpoint 129, 0x00000000126e0790 in kqrget ()
Breakpoint 137, 0x00000000126e38c0 in kqrIncarnationMismatch ()
Breakpoint 137, 0x00000000126e38c0 in kqrIncarnationMismatch ()
Breakpoint 126, 0x00000000126dfc40 in kqrFreePOMutex ()
Breakpoint 337, 0x00000000129db980 in kgxRelease ()
     (1-2) <--- kgxRelease Mutex addr (*rsi): 8d7bc960
Breakpoint 139, 0x00000000126e3980 in kqrprl ()
Breakpoint 140, 0x00000000126e3ed0 in kqreqd ()
Breakpoint 146, 0x00000000126e5fd0 in kqrGetPOMutex ()
Breakpoint 336, 0x00000000129da970 in kgxExclusive ()
     (1-3) ---> kgxExclusive Mutex addr (rsi): 8d7bc960
Breakpoint 141, 0x00000000126e4d40 in kqrReleaseLock ()
Breakpoint 143, 0x00000000126e5910 in kqrmupin ()
Breakpoint 142, 0x00000000126e4ff0 in kqrpspr ()
Breakpoint 337, 0x00000000129db980 in kgxRelease ()
     (1-3) <--- kgxRelease Mutex addr (*rsi): 8d7bc960
Breakpoint 144, 0x00000000126e5e30 in kqrFreeEnqueue ()


6. Discussions

  1. gdb output mutex-test2.log contains 95 kqrpre1 Calls, each for one 'dc_props' / 'dc_cdbprops' object
    (total 85+6=91, 4 are fetched twice).

  2. For each row cache access, first compute a hash value (hash=819e131) and then access object (addr=8d7bc858).

  3. Each RowCache Object Get triggers three kgxExclusive Mutex Gets,
    one from kqrGetHashMutexInt (Mutex addr (rsi): a70a01a8),
    two from kqrGetPOMutex (Mutex addr (rsi): 8d7bc960).

  4. Mutex a70a01a8 is used in kqrGetHashMutexInt to protect hash BUCKET, hence BUCKET mutex.
    In above example, BUCKET 50 contains 4 row cache objects, so there are 4 occurrences in mutex-test2.log.

    Mutex 8d7bc960 is used in kqrGetPOMutex to protect individual row cache object, hence OBJECT mutex.
    So each row cache object has its own mutex.

  5. kqrGetHashMutexInt Mutex is released after first kqrGetPOMutex Get (interleaved).
    So at certain instant, one session can hold two Mutexes at the same time (same as latch).

    For latch, there is MOS Note: ORA-600 [504] "Trying to obtain a latch which is already held" (Doc ID 28104.1), which said:
    "This ORA-600 triggers when a latch request violates the ordering rules for obtaining latches and granting the latch would potentially result in a deadlock." (See Blog: ORA-600 [504] LATCH HIERARCHY ERROR Deadlock)

    For Mutex, it is not clear if there could exist such similar deadlock.

  6. The first Mutex Get is from kqrGetHashMutexInt, called by kqrpre, and released only after the second Mutex Get (the first of kqrGetPOMutex mutex Get). So kqrpre can hold two Mutexes and keep the first Mutex longer (till kqrFreeHashMutex).

    kqreqd makes one Mutex Get.

    In case of Latch (Oracle 12c), there are three Latch Gets with 3 different Locations:
    (see Blog: Oracle row cache objects Event: 10222, Dtrace Scripts (I) )
           Where=>4441(0x1159): kqrpre: find obj -> kslgetl()  -- latch Get at 1st Location
           Where=>4464(0x1170): kqreqd           -> kslgetl()  -- latch Get at 2nd Location
           Where=>4465(0x1171): kqreqd: reget    -> kslgetl()  -- latch Get at 3rd Location
    
    They are probably mapped to three kgxExclusive Mutex Gets as discussed in above Point (c).

  7. If one session, which held a mutex, but abnormally terminated, CLMN wrote a log about its cleanup and recovery of the mutex (0xa70a01a8).
           KGX cleanup...
           KGX Atomic Operation Log 0x928ad480
            Mutex 0xa70a01a8(14, 0) idn f00003c oper EXCL(6)
            Row Cache uid 14 efd 6 whr 19 slp 0
            oper=0 pt1=(nil) pt2=(nil) pt3=(nil)
            pt4=(nil) pt5=(nil) ub4=15 flg=0x8
           KQR UOL Recovery lc 928ad480 options = 1
    


7. kqrMutexLocations[] array


For all kqrMutexLocations in kqr.c, we can try to list them with following command. They often appear in AWR section "Mutex Sleep Summary" for Mutex Type: "Row Cache" (or V$MUTEX_SLEEP / V$MUTEX_SLEEP_HISTORY.location).
   
// uname -srm 
//      Linux 3.10.0-957.5.1.el7.x86_64 x86_64  cast (uint64_t *) optional
//      Linux 4.18.0-372.9.1.el8.x86_64 x86_64  requires cast (uint64_t *)
#Define Command to kqrMutexLocations      
define PrintkqrMutexLocations
  set $i = 0
  while $i < $arg0
    x /s *((uint64_t *)&kqrMutexLocations + $i)
    set $i = $i + 1
  end
end

(gdb) PrintkqrMutexLocations 51
0x14c21f40:     "[01] kqrHashTableInsert"
0x14c21f58:     "[02] kqrHashTableRemove"
0x14c21f70:     "[03] kqrUpdateHashTable"
0x14c21f88:     "[04] kqrshu"
0x14c21f94:     "[05] kqrWaitForObjectLoad"
0x14c21fb0:     "[06] kqrGetClusterLock"
0x14c21fc8:     "[07] kqrBackgroundInvalidate"
0x14c21fe8:     "[08] kqrget"
0x14c21ff4:     "[09] kqrReleaseLock"
0x14c22008:     "[10] kqreqd"
0x14c22014:     "[11] kqrfpo"
0x14c22020:     "[12] kqrpad"
0x14c2202c:     "[13] kqrsad"
0x14c22038:     "[14] kqrScan"
0x14c22048:     "[15] kqrCacheHit"
0x14c2205c:     "[16] kqrReadFromDB"
0x14c22070:     "[17] kqrCreateUsingSecondaryKey"
0x14c22090:     "[18] kqrCreateNewVersion"
0x14c220ac:     "[19] kqrpre"
0x14c220b8:     "[20] kqrpla"
0x14c220c4:     "[21] kqrpScanAndInvalidateLocal"
0x14c220e4:     "[22] kqrpScan"
0x14c220f4:     "[23] kqrpsiv"
0x14c22104:     "[24] kqrpsci"
0x14c22114:     "[25] kqrpup"
0x14c22120:     "[26] kqrpfu"
0x14c2212c:     "[27] kqrpdl"
0x14c22138:     "[28] kqrLocalInvalidateByHash"
0x14c22158:     "[29] kqrpiv"
0x14c22164:     "[30] kqrpsf"
0x14c22170:     "[31] kqrcmt"
0x14c2217c:     "[32] kqrsfd"
0x14c22188:     "[33] kqrsrd"
0x14c22194:     "[34] kqrssc"
0x14c221a0:     "[35] kqrisi"
0x14c221ac:     "[36] kqrsup"
0x14c221b8:     "[37] kqrsfu"
0x14c221c4:     "[38] kqrsdl"
0x14c221d0:     "[39] kqrsiv"
0x14c221dc:     "[40] kqrfrpo"
0x14c221ec:     "[41] kqrfrso"
0x14c221fc:     "[42] kqrdfc"
0x14c22208:     "[43] kqrlfc"
0x14c22214:     "[44] kqrdpc"
0x14c22220:     "[45] kqrdhst"
0x14c22230:     "[46] kqrMutexCleanup"
0x14c22248:     "[47] kqrftr"
0x14c22254:     "[48] kqrhngc"
0x14c22264:     "[49] kqrcic"
0x14c22270:     "[50] kqrpspr"
0x14c22280:     "[51] kqrglblkrs"


8. gdb script: gdb_cmd_script2


Before running the script, the breakpoint number and address have to be adjusted.

### ----================ gdb script: gdb -x gdb_cmd_script2 -p 18158 ================----
set pagination off
set logging file /temp/mutex-test2.log
set logging overwrite on
set logging on
set $k = 0
set $g = 0
set $r = 0
set $spacex = ' '

rbreak ^kqr.*
rbreak ^kgx.*

command 1-333                               
continue
end

#kqrmpin 
delete 133 
#kqrpre1   
delete 138 
#kgxExclusive   
delete 326 
#kgxRelease                               
delete 331   

#10222 trc pso, processstate dump SOC (State Object Call): $r8
break *kqrpre1
command 
printf "<<<==================== (%i) kqrpre1 pso (SOC): %x ====================>>>\n", ++$k, $r8
set $g = 0 
set $r = 0              
continue
end

#kqrhsh+109 retq, output hash value in "oradebug dump row_cache 0xf2b" (0xf2b is for "dc_props") 
break *0x00000000126df8ad     
command
printf "%5c(%i) kqrhsh retq hash (rax): hash=%x\n", $spacex, $k, $rax 
continue
end

break *kgxExclusive
command 
printf "%5c(%i-%i) ---> kgxExclusive Mutex addr (rsi): %x\n", $spacex, $k, ++$g, $rsi             
continue
end

break *kgxRelease
command
printf "%5c(%i-%i) <--- kgxRelease Mutex addr (*rsi): %x\n", $spacex, $k, ++$r, *((int *)$rsi)   
continue
end

#output v$rowcache_parent.address for row cache object
break *kqrmpin     
command
printf "%5c(%i) kqrmpin v$rowcache_parent.address (rdi): addr=%x cid=%i\n", $spacex, $k, $rdi, $r11
continue
end

Tuesday, May 26, 2020

12cR2 Index Usage Tracking Manual Flushing

Oracle 12.2 introduced index usage tracking to replace the previous index monitoring. Instead of only telling if an index is used (DBA_OBJECT_USAGE.USED), usage tracking provides a quantified index usage stats, such as number of accesses, number of rows returned per access.

There are two views and 3 hidden parameters to report and control index usage tracking:
V$INDEX_USAGE_INFO 
  keeps track of index usage since the last flush. A flush occurs every 15 minutes. 
  After each flush, ACTIVE_ELEM_COUNT is reset to 0 and LAST_FLUSH_TIME is updated to the current time.
  
DBA_INDEX_USAGE 
  displays object-level index usage once it has been flushed to disk.
  
Hidden Parameters
  NAME                       DESCRIPTION                               DEFAULT
  -------------------------  ----------------------------------------  -------
  _iut_enable                Control Index usage tracking              TRUE
  _iut_max_entries           Maximum Index entries to be tracked       30000
  _iut_stat_collection_type  Specify Index usage stat collection type  SAMPLED
By default, index usage tracking is enable ("_iut_enable" = TRUE). To get an accurate result, switch collection type to ALL:

ALTER SYSTEM SET "_iut_stat_collection_type" = ALL;
This new feature is documented in Oracle MOS Docu and Oracle Blogs:
   -.  Index Monitoring in Oracle 12.2 (Doc ID 2302110.1)
   -. 12cR2 new index usage tracking
   -. Index Usage Tracking (DBA_INDEX_USAGE, V$INDEX_USAGE_INFO) in Oracle Database 12c Release 2 (12.2)

In this Blog, we first show how to manually flush usage data instead of waiting 15 minutes so that we can make a realtime index usage evaluation and more precisely locate index access.

Then we look how usage data are recorded by Oracle MMON Slave Process.

Note: Tested in Oracle 19c.


1. Test Setup


At first, create a table and a primary key index (TEST_IUT_PK) with 14 rows.

drop table test_iut purge;

create table test_iut(x, constraint TEST_IUT_PK primary key (x)) 
          as select level from dual connect by level <= 14;


2. Manual Flush


Open one Sqlplus session: SQL1, login as SYSDBA. Pick one MMON slave. for example, M001, attach oradebug on it.

$ > sqlplus / as sysdba

SQL1 > 
     select s.program, s.module, s.action, s.sid, p.pid, p.spid
     from v$session s, v$process p 
     where s.paddr=p.addr and s.program like '%(M0%' 
     order by s.program;

       PROGRAM                 MODULE      ACTION                         SID  PID  SPID
       ----------------------  ----------  -----------------------------  ---  ---  -----
       oracle@testdb (M001)  MMON_SLAVE  Intensive AutoTask Dispatcher  186   49  20894
       oracle@testdb (M002)  MMON_SLAVE  KDILM background CLeaNup       912   35  2097
       oracle@testdb (M003)  MMON_SLAVE  KDILM background CLeaNup       371    8  13060
       oracle@testdb (M004)  MMON_SLAVE  KDILM background EXEcution     722   34  27905
       oracle@testdb (M005)  MMON_SLAVE  Intensive AutoTask Dispatcher  370   56  29674

SQL1 > oradebug setorapid 49
         Oracle pid: 49, Unix process pid: 20894, image: oracle@testdb (M001)
Open second Sqlplus session as a test session.

Change collection type to "ALL" so that statistics are collected for each sql execution that has index access (Note "alter SESSION" is the same as "alter SYSTEM" for this hidden parameter).

Run a query using index "TEST_IUT_PK", v$index_usage_info is not flushed immediately, hence dba_index_usage returns no rows about this index.

SQL2 > alter session set "_iut_stat_collection_type"=all;

SQL2 > select sysdate, x from test_iut where x= 3;

  SYSDATE                       X
  -------------------- ----------
  2020*MAY*23 15:22:46          3

SQL2 > select sysdate, index_stats_enabled, index_stats_collection_type, active_elem_count, last_flush_time
       from v$index_usage_info;

  SYSDATE              INDEX_STATS_ENABLED INDEX_STATS_COLLECTION_TYPE ACTIVE_ELEM_COUNT LAST_FLUSH_TIME
  -------------------- ------------------- --------------------------- ----------------- --------------------
  2020*MAY*23 15:23:55                   1                           0                 1 2020*MAY*23 15:21:34

SQL2 > select sysdate, total_access_count,total_exec_count,total_rows_returned,last_used
       from dba_index_usage where name = 'TEST_IUT_PK';

  no rows selected
Go back to SQL1, make a function call to flush usage stats:

SQL1 > oradebug call keiut_flush_all
         Function returned 60089650
We can see the usage stats are updated immediately (instead of waiting 15 minutes for one of MMON slaves to perform it).

SQL2 > select sysdate, index_stats_enabled, index_stats_collection_type, active_elem_count, last_flush_time
       from v$index_usage_info;
      
  SYSDATE              INDEX_STATS_ENABLED INDEX_STATS_COLLECTION_TYPE ACTIVE_ELEM_COUNT LAST_FLUSH_TIME
  -------------------- ------------------- --------------------------- ----------------- --------------------
  2020*MAY*23 15:24:57                   1                           0                 1 2020*MAY*23 15:24:46
                  
SQL2 > select sysdate, total_access_count,total_exec_count,total_rows_returned,last_used
       from dba_index_usage where name = 'TEST_IUT_PK';
      
  SYSDATE              TOTAL_ACCESS_COUNT TOTAL_EXEC_COUNT TOTAL_ROWS_RETURNED LAST_USED
  -------------------- ------------------ ---------------- ------------------- --------------------
  2020*MAY*23 15:25:17                  1                1                   1 2020*MAY*23 15:24:46      
Repeat the same steps after gather table and index stats, usage data are also flushed immediately.

SQL2 > exec dbms_stats.gather_table_stats(user, 'TEST_IUT', cascade=> TRUE);

SQL1 > oradebug call keiut_flush_all
         Function returned 60089650

SQL2 > select sysdate, index_stats_enabled, index_stats_collection_type, active_elem_count, last_flush_time
       from v$index_usage_info;
 
  SYSDATE              INDEX_STATS_ENABLED INDEX_STATS_COLLECTION_TYPE ACTIVE_ELEM_COUNT LAST_FLUSH_TIME
  -------------------- ------------------- --------------------------- ----------------- --------------------
  2020*MAY*23 15:26:03                   1                           0                 1 2020*MAY*23 15:25:55

SQL2 > select sysdate, total_access_count,total_exec_count,total_rows_returned,last_used
       from dba_index_usage where name = 'TEST_IUT_PK';
 
  SYSDATE              TOTAL_ACCESS_COUNT TOTAL_EXEC_COUNT TOTAL_ROWS_RETURNED LAST_USED
  -------------------- ------------------ ---------------- ------------------- --------------------
  2020*MAY*23 15:26:35                  2                2                  15 2020*MAY*23 15:25:55
In fact, index stats is gathered by a query as follows:

-- SQL_ID:   b1xgfyhj1c1yn

SELECT /*+ opt_param('_optimizer_use_auto_indexes' 'on')   no_parallel_index(t, "TEST_IUT_PK")  dbms_stats 
           cursor_sharing_exact use_weak_name_resl dynamic_sampling(0) no_monitoring xmlindex_sel_idx_tbl 
           opt_param('optimizer_inmemory_aware' 'false') no_substrb_pad  no_expand index(t,"TEST_IUT_PK") */
       COUNT (*)                                                AS nrw,
       COUNT (DISTINCT sys_op_lbid (3309518, 'L', t.ROWID))     AS nlb,
       NULL                                                     AS ndk,
       sys_op_countchg (SUBSTRB (t.ROWID, 1, 15), 1)            AS clf
  FROM "K"."TEST_IUT" t
 WHERE "X" IS NOT NULL

Plan hash value: 3307217019
 
--------------------------------------------------------------------------------
| Id  | Operation        | Name        | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------------
|   0 | SELECT STATEMENT |             |     1 |     3 |     1   (0)| 00:00:01 |
|   1 |  SORT GROUP BY   |             |     1 |     3 |            |          |
|   2 |   INDEX FULL SCAN| TEST_IUT_PK |    14 |    42 |     1   (0)| 00:00:01 |
--------------------------------------------------------------------------------

Hint Report (identified by operation id / Query Block Name / Object Alias):
Total hints for statement: 12 (U - Unused (1))
---------------------------------------------------------------------------
   0 -  STATEMENT
           -  opt_param('_optimizer_use_auto_indexes' 'on')
           -  opt_param('optimizer_inmemory_aware' 'false')
   1 -  SEL$1
           -  dynamic_sampling(0)
           -  no_expand
   2 -  SEL$1 / T@SEL$1
         U -  no_parallel_index(t, "TEST_IUT_PK")
           -  index(t,"TEST_IUT_PK")
Since it is a "INDEX FULL SCAN", 14 rows are returned, which is reflected in dba_index_usage columns:
  BUCKET_11_100_ACCESS_COUNT 
  BUCKET_11_100_ROWS_RETURNED
Here the output formatted vertically. Two accesses, the first returns 1 row, the second returns 14 rows, both are classified into two different histogram buckets.

select sysdate, total_access_count,total_exec_count,total_rows_returned,last_used,
       bucket_0_access_count, bucket_1_access_count,bucket_11_100_access_count,bucket_11_100_rows_returned
   from dba_index_usage where name = 'TEST_IUT_PK';

  SYSDATE                       : 23-may-2020 15:26:59
  TOTAL_ACCESS_COUNT            : 2
  TOTAL_EXEC_COUNT              : 2
  TOTAL_ROWS_RETURNED           : 15
  LAST_USED                     : 23-may-2020 15:25:55
  BUCKET_0_ACCESS_COUNT         : 0
  BUCKET_1_ACCESS_COUNT         : 1
  BUCKET_11_100_ACCESS_COUNT    : 1
  BUCKET_11_100_ROWS_RETURNED   : 14


3. Usage Statistics Update


Static Data Dictionary View DBA_INDEX_USAGE is based on table SYS.WRI$_INDEX_USAGE. In normal operation, each 15 minutes, one MMON slave is triggered to update WRI$_INDEX_USAGE with a merge statement looping over each index object as follows:

--- 5cu0x10yu88sw

MERGE INTO sys.wri$_index_usage iu
     USING DUAL
        ON (iu.obj# = :objn)
WHEN MATCHED
THEN
    UPDATE SET
        iu.total_access_count = iu.total_access_count + :ns,
        iu.total_rows_returned = iu.total_rows_returned + :rr,
        iu.total_exec_count = iu.total_exec_count + :ne,
        iu.bucket_0_access_count = iu.bucket_0_access_count + :nsh0,
        iu.bucket_1_access_count = iu.bucket_1_access_count + :nsh1,
        iu.bucket_2_10_access_count = iu.bucket_2_10_access_count + :nsh2_10,
        iu.bucket_2_10_rows_returned =
            iu.bucket_2_10_rows_returned + :nrh2_10,
        iu.bucket_11_100_access_count =
            iu.bucket_11_100_access_count + :nsh11_100,
        iu.bucket_11_100_rows_returned =
            iu.bucket_11_100_rows_returned + :nrh11_100,
        iu.bucket_101_1000_access_count =
            iu.bucket_101_1000_access_count + :nsh101_1000,
        iu.bucket_101_1000_rows_returned =
            iu.bucket_101_1000_rows_returned + :nrh101_1000,
        iu.bucket_1000_plus_access_count =
            iu.bucket_1000_plus_access_count + :nsh1000plus,
        iu.bucket_1000_plus_rows_returned =
            iu.bucket_1000_plus_rows_returned + :nrh1000plus,
        last_used = SYSDATE
WHEN NOT MATCHED
THEN
    INSERT     (iu.obj#,
                iu.total_access_count,
                iu.total_rows_returned,
                iu.total_exec_count,
                iu.bucket_0_access_count,
                iu.bucket_1_access_count,
                iu.bucket_2_10_access_count,
                iu.bucket_2_10_rows_returned,
                iu.bucket_11_100_access_count,
                iu.bucket_11_100_rows_returned,
                iu.bucket_101_1000_access_count,
                iu.bucket_101_1000_rows_returned,
                iu.bucket_1000_plus_access_count,
                iu.bucket_1000_plus_rows_returned,
                iu.last_used)
        VALUES ( :objn,
                :ns,
                :rr,
                :ne,
                :nsh0,
                :nsh1,
                :nsh2_10,
                :nrh2_10,
                :nsh11_100,
                :nrh11_100,
                :nsh101_1000,
                :nrh101_1000,
                :nsh1000plus,
                :nrh1000plus,
                SYSDATE)

--------------------------------------------------------------------------------------------------------
| Id  | Operation                       | Name                | E-Rows |E-Bytes| Cost (%CPU)| E-Time   |
--------------------------------------------------------------------------------------------------------
|   0 | MERGE STATEMENT                 |                     |        |       |     3 (100)|          |
|   1 |  MERGE                          | WRI$_INDEX_USAGE    |        |       |            |          |
|   2 |   VIEW                          |                     |        |       |            |          |
|   3 |    NESTED LOOPS OUTER           |                     |      1 |   287 |     3   (0)| 00:00:01 |
|   4 |     TABLE ACCESS FULL           | DUAL                |      1 |     2 |     2   (0)| 00:00:01 |
|   5 |     VIEW                        | VW_LAT_A18161FF     |      1 |   285 |     1   (0)| 00:00:01 |
|   6 |      TABLE ACCESS BY INDEX ROWID| WRI$_INDEX_USAGE    |      1 |    48 |     1   (0)| 00:00:01 |
|*  7 |       INDEX UNIQUE SCAN         | WRI$_INDEX_USAGE_PK |      1 |       |     1   (0)| 00:00:01 |
--------------------------------------------------------------------------------------------------------
We can see that merge statement is using index: WRI$_INDEX_USAGE_PK, but there is no usage stats on it (probably usage stats of SYS indexes are not tracked).

SQL2 > select total_access_count,total_exec_count,total_rows_returned,last_used
       from dba_index_usage where name = 'WRI$_INDEX_USAGE_PK';

  no rows selected
To flush usage stats, one active MMON slave starts a run of ACTION named: [Index usage tracking statistics flush]. If runtime exceeded 180 seconds, time limit violation (MMON slave action policy violation) is detected, an ORA-12751 is raised.
  12751, 00000, "cpu time or run time policy violation"
  // *Document: NO
  // *Cause: A piece of code ran longer than it is supposed to
  // *Action: If this error persists, contact Oracle Support Services.
As some future enhancement, this technique can be further extended if we can specify tracking index name, time interval, user sessions.

By the way, Oracle is continuously augmenting performance usage stats by including more tracking areas controlled by hidden parameters:
  NAME                         DESCRIPTION                                 DEFAULT
  ---------------------------  ------------------------------------------  -------
  _iut_enable                  Control Index usage tracking                TRUE
  _optimizer_track_hint_usage  enable tracking of optimizer hint usage     TRUE     
  _db_hot_block_tracking       track hot blocks for hash latch contention  FALSE
For example, in above Oracle generated gather index statement (SQL_ID b1xgfyhj1c1yn), Xplan is extended with one Hint Report introduced in Oracle 19.3.3. It can be disabled by:

alter session set "_optimizer_track_hint_usage" = false;