Oracle ORA-01426: numeric overflow and PL/SQL Runtime MCODE

Oracle PLS_INTEGER data type stores signed integers in the range -2,147,483,648 through 2,147,483,647, represented in 32 bits.

ORA-01426: numeric overflow

declare                                            
  p_pint1    pls_integer := 2147483645;            
  p_pint2    pls_integer := 13;                    
  p_pint3    pls_integer := 9;                     
  p_char     varchar2(4) := 'ABC';                 
  p_num_ret  number;                               
begin                                              
  p_num_ret := mod((p_pint1+p_pint2), p_pint3);    
end;                                               
/                                                  

ERROR at line 1:
ORA-01426: numeric overflow
ORA-06512: at line 8

PL/SQL Runtime MCODE

----- PL/SQL Runtime State -----
ANONYMOUS BLOCK:
library unit=9849d118 line=8 opcode=8(ADDI) static link=0 scope=0
----- Begin Dump of MCODE -----
Entry #0
00000: BREAK          
Entry #1
00002: ENTER            DS[0]+136 <"__anonymous_block",ept=1,sz=208,lvl=0,prm=0>
    Static Address Registers                              
    #0000005 HS+0                                 |================ MCODE Mnemonics ==============        
    #0000006 HS+24                                |    MOVI:  Move Integer                                
    #0000007 HS+48                                |    MOVC:  Move Character                                                          
    #0000008 HS+72                                |    ADDI:  Add Integer (operand and return are Integer. Interpreted as Subroutine: pfrrexc_record_excp())             
00008: INFR             DS[0]+184                 |    RASIX: Raise Exception                                          
  Frame Desc Version = 2                          |===========================================================================================                         
    slot# = 0 start offset = 16                   | Comment                                | Test Code                                                           
    # of locals = 5                               |-------------------------------------   |---------------------------------------------------    
    TC_SSCALARi: #0, FP+16, d=FP+24               | #0 <= 2147483645                       |                                                                 
    TC_SSCALARi: #1, FP+48, d=FP+56               | #1 <= 13                               |  declare                                                        
    TC_SSCALARi: #2, FP+80, d=FP+88               | #2 <=  9                               |    p_pint1    pls_integer := 2147483645;                        
    TC_VCHARi: #3, FP+112, d=FP+136, mxl=4 cha    | #3 <= 'ABC'                            |    p_pint2    pls_integer := 13;                                
    TC_SSCALARi: #4, FP+176, d=FP+184             |                                        |    p_pint3    pls_integer := 9;                                 
00014: MOVI             #6, #0                    | #6 <= #0 (2147483645)                  |    p_char     varchar2(4) := 'ABC';                             
00020: MOVI             #7, #1                    | #7 <= #1 (13        )                  |    p_num_ret  number;                                           
00026: MOVI             #5, #2                    | #5 <= #2 (9         )                  |  begin                                                          
00032: MOVC             #8, #3                    | #8 <= #3 ('ABC      )                  |    p_num_ret := mod((p_pint1+p_pint2), p_pint3);              
00038: ADDI             #6, #7, #4                | #6 + #7 => #4 (2147483645 + 13 => #4)  |  end;                                                                
00046: RASIX            6501                      | #Throw Exception                       |  /                                                              
----- End Dump of MCODE -----  
                                                                          
FP=0x7f8432ae69c8 PC=0x628c39be Page=0 AP=(nil) ST=0x7f8432ae6a98            |                              
DL0=0x7f84319bac20 GF=0x7f84319bac68 DL1=0x7f84319bac38 DPF=0x7f84319bac58   | 
HS=0x628c3bd0 AR=0x7f84319babb8 DS=0x628c3b70                                | 
PB_PC=(nil) SV_PC=0x628c39c6                                                 | 
DS pkg desc :                                                                | 
0628C3A30                   02920314 00000040          [....@...]            | 
0628C3A40 00020003 00000000 00000000 00000001  [................]            | 
0628C3A50 00D80000 0000000A 01200000 00000204  [.......... .....]            | 
0628C3A60 00000000 00000000 00000000 00000000  [................]            | 
0628C3A70 00000000 00000000                    [........]                    | 
AR :                                                                         | 
7F84319BABB0                   32AE69D8 00007F84          [.i.2....]         | 
7F84319BABC0 32AE69F8                             [.i.2]                     | 
FP :                                                                         | 
7F8432AE69C0                   00000000 00000000          [........]         | 
7F8432AE69D0 32AE69F0 00007F84 32AE69E0 00007F84  [.i.2.....i.2....]         | 
7F8432AE69E0 32AE69F0 00007F84 00080000 00000000  [.i.2............]         | 
7F8432AE69F0 7FFFFFFD 00007F84 32AE6A00 00007F84  [.........j.2....]         | TC_SSCALARi: #0, FP+16: 7FFFFFFD = p_pint1    pls_integer := 2147483645; 
7F8432AE6A00 32AE6A10 00007F84 00080000 00000000  [.j.2............]         | 
7F8432AE6A10 0000000D 00007F84 32AE6A20 00007F84  [........ j.2....]         | TC_SSCALARi: #1, FP+48: 0000000D = p_pint2    pls_integer := 13;
7F8432AE6A20 32AE6A30 00007F84 00080000 00000000  [0j.2............]         | 
7F8432AE6A30 00000009 00000000 32AE6A50 00007F84  [........Pj.2....]         | TC_SSCALARi: #2, FP+80: 00000009 = p_pint3    pls_integer := 9;
7F8432AE6A40 01040009 00010369 00000010 00000000  [....i...........]         | 
7F8432AE6A50 32AE6A60 00007F84 00280003 00000000  [`j.2......(.....]         | TC_VCHARi: #3, FP+112:  p_char     varchar2(4) := 'ABC';
7F8432AE6A60 7F434241 00000003 00060009 00460001  [ABC...........F.]         |                         434241 = CBA             
7F8432AE6A70 00000000 00000000 32AE6A80 00007F84  [.........j.2....]         | 
7F8432AE6A80 32AE6A90 00007F84 000A0000 7FFFFFFF  [.j.2............]         | 
7F8432AE6A90 7FFFFF80 00800010                    [........]                 | TC_SSCALARi: #4, FP+176

Oracle SQL MEMBER vs. IN Comparison Condition Performance - Part1

---

(I)-Oracle SQL MEMBER vs. IN Comparison Condition Performance - Part1       (II)-Oracle SQL MEMBER vs. IN Comparison Condition Performance - Part2

---

In this Blog, we will demonstrate the performance difference of MEMBER and IN Comparison Conditions, and explore their complexity.

In next Blog: (II)-Oracle SQL MEMBER vs. IN Comparison Condition Performance - Part2, we will demonstrate the performance difference of MEMBER and IN Comparison Conditions for nested table column.

Note: Tested in Oracle 19.27

1. MEMBER vs. IN Performance Difference

We create two nested tables of number, and run query on them with MEMBER and IN Conditions respectively:

---------------- test Number MEMBER vs. IN Comparison Conditions Performance ----------------

drop type t_num_tab;

create or replace noneditionable type t_num_tab is table of number;
/

create or replace procedure test_NUM_MEMBER_vs_IN_Conditions (p_size_1 number, p_size_2 number, p_sel varchar2 := 'A') as
  l_t_num_tab_1    t_num_tab := t_num_tab();
  l_t_num_tab_2    t_num_tab := t_num_tab();
  l_start_time     number;
  l_ret_cnt        number;
begin
  select level bulk collect into l_t_num_tab_1 from dual connect by level <= p_size_1;
  select level bulk collect into l_t_num_tab_2 from dual connect by level <= p_size_2;
 
  dbms_output.put_line('l_t_num_tab_1.count   = '||cardinality(l_t_num_tab_1));
  dbms_output.put_line('l_t_num_tab_2.count   = '||l_t_num_tab_2.count);
   
  if p_sel in ('A', 'M') then
        --================= MEMBER Comparison =================
        l_start_time := dbms_utility.get_time;
       
        select /*+ Test_NUM_MEMBER */ count(*) into l_ret_cnt
          from table(cast (l_t_num_tab_1 as t_num_tab)) t1
         where t1.column_value member of cast(l_t_num_tab_2 as t_num_tab);
        
        dbms_output.put_line('=============== MEMBER Condition ===============');
        dbms_output.put_line('Elapsed(centi)        = '||(dbms_utility.get_time - l_start_time));
        dbms_output.put_line('l_ret_cnt             = '||l_ret_cnt);
  end if;
 
  if p_sel in ('A', 'I') then
        --================= IN Comparison =================
        l_start_time := dbms_utility.get_time;
       
        select /*+ Test_NUM_IN */ count(*) into l_ret_cnt
          from table(cast (l_t_num_tab_1 as t_num_tab)) t1
         where t1.column_value in (select column_value from table(cast(l_t_num_tab_2 as t_num_tab)));
       
        dbms_output.put_line('=============== IN Condition ===============');
        dbms_output.put_line('Elapsed(centi)        = '||(dbms_utility.get_time - l_start_time));
        dbms_output.put_line('l_ret_cnt             = '||l_ret_cnt);
      end if;
end;
/

The test result shows that the elapsed time for MEMBER is about 100 times greater than for IN.

SQL > exec test_NUM_MEMBER_vs_IN_Conditions(100000, 1000);

      l_t_num_tab_1.count   = 100000
      l_t_num_tab_2.count   = 1000
      =============== MEMBER Condition ===============
      Elapsed(centi)        = 226
      l_ret_cnt             = 1000
      =============== IN Condition ===============
      Elapsed(centi)        = 2
      l_ret_cnt             = 1000

Here both xplan:

SELECT /*+ Test_NUM_MEMBER */ COUNT(*) FROM TABLE(CAST (:B1 AS T_NUM_TAB)) T1 WHERE T1.COLUMN_VALUE MEMBER OF CAST(:B2 AS T_NUM_TAB);
  SQL_ID  9v3d6bbpjs0x2, child number 0  Plan hash value: 3309076612
  -------------------------------------------------------------------------------------------
  | Id  | Operation                          | Name | Rows  | Bytes | Cost (%CPU)| Time     |
  -------------------------------------------------------------------------------------------
  |   0 | SELECT STATEMENT                   |      |       |       |    30 (100)|          |
  |   1 |  SORT AGGREGATE                    |      |     1 |     2 |            |          |
  |*  2 |   COLLECTION ITERATOR PICKLER FETCH|      |    50 |   100 |    30   (0)| 00:00:01 |
  -------------------------------------------------------------------------------------------
  Predicate Information (identified by operation id):
  ---------------------------------------------------
     2 - filter(VALUE(KOKBF$)MEMBER OFCAST(:B2 AS "T_NUM_TAB") )
    

SELECT /*+ Test_NUM_IN */ COUNT(*) FROM TABLE(CAST (:B1 AS T_NUM_TAB)) T1 WHERE T1.COLUMN_VALUE IN (SELECT COLUMN_VALUE FROM TABLE(CAST(:B2 AS T_NUM_TAB)));
  SQL_ID  2z2buk4wrs0gs, child number 0  Plan hash value: 4146508332
  --------------------------------------------------------------------------------------------
  | Id  | Operation                           | Name | Rows  | Bytes | Cost (%CPU)| Time     |
  --------------------------------------------------------------------------------------------
  |   0 | SELECT STATEMENT                    |      |       |       |    60 (100)|          |
  |   1 |  SORT AGGREGATE                     |      |     1 |     4 |            |          |
  |*  2 |   HASH JOIN RIGHT SEMI              |      |    10 |    40 |    60   (0)| 00:00:01 |
  |   3 |    COLLECTION ITERATOR PICKLER FETCH|      |   300 |   600 |    30   (0)| 00:00:01 |
  |   4 |    COLLECTION ITERATOR PICKLER FETCH|      |  1000 |  2000 |    30   (0)| 00:00:01 |
  --------------------------------------------------------------------------------------------
  Predicate Information (identified by operation id):
  ---------------------------------------------------
     2 - access(VALUE(KOKBF$)=VALUE(KOKBF$))
     

Here bpftrace on kopi2csaccess for both MEMBER and IN Comparison.
For MEMBER, count() = 10,094,950 is about (l_t_obj_tab_1.count * l_t_obj_tab_2.count), which is quadratic performance.
For IN, count() = 100,102 is about (l_t_obj_tab_1.count + l_t_obj_tab_2.count), which is linear performance.

--------------------- MEMBER Comparison ---------------------- 
SQL > exec test_NUM_MEMBE,R_vs_IN_Conditions(100000, 100, 'M');
        l_t_num_tab_1.count   = 100000
        l_t_num_tab_2.count   = 100
        =============== MEMBER Condition ===============
        Elapsed(centi)        = 1199
        l_ret_cnt             = 100
 
$ > bpftrace -e 'uprobe:/orabin/app/oracle/product/19.27.0.0.250415-212/bin/oracle:kopi2csaccess+2 /pid == 1129837/ {@[ustack(2)] = count();}'
      @[
          kopi2csaccess+2
          qerocFetch+201
      ]: 100001
      @[
          kopi2csaccess+2
          expeal+59
      ]: 10094950
 
 
--------------------- IN Comparison --------------------------
SQL > exec test_NUM_MEMBER_vs_IN_Conditions(100000, 100, 'I');
        l_t_num_tab_1.count   = 100000
        l_t_num_tab_2.count   = 100
        =============== IN Condition ===============
        Elapsed(centi)        = 13
        l_ret_cnt             = 100
 
$ > bpftrace -e 'uprobe:/orabin/app/oracle/product/19.27.0.0.250415-212/bin/oracle:kopi2csaccess+2 /pid == 1129837/ {@[ustack(2)] = count();}'
      @[
          kopi2csaccess+2
          qerocFetch+201
      ]: 100102
      

2. MEMBER vs. IN complexity

We create nested table of objects with map member function to record number of Comparisons in MEMBER and IN queries in order to evaluate the complexity of applied algorithm, similar to the approaches of previous Blog:
     Performance of Oracle Object Collection Comparisons - Part1
     Performance of Oracle Object Collection Comparisons - Part2

---------------- test Object MEMBER vs. IN Comparison Conditions Performance ----------------

create or replace package cmp_counter as
  p_cnt number := 0;
end;
/

create or replace package body helper as
  procedure format(p_name varchar2, p_value number) as
  begin
    dbms_output.put_line(rpad(p_name, 40) ||' = '|| lpad(p_value, 10));
  end format;
end helper;
/

drop type t_obj_tab force;

drop type t_obj force;

create or replace type t_obj as object (
  p_num number,
  map member function comp return integer);
/

create or replace type body t_obj as
  map member function comp return integer is 
    begin 
      cmp_counter.p_cnt := cmp_counter.p_cnt + 1;
      return p_num;
    end; 
end;
/

create or replace type t_obj_tab as table of t_obj;
/

create or replace procedure test_OBJ_MEMBER_vs_IN_Conditions (p_size_1 number, p_size_2 number, p_sel varchar2 := 'A') as
  l_t_obj_tab_1     t_obj_tab := t_obj_tab();
  l_t_obj_tab_2     t_obj_tab := t_obj_tab();
  l_start_time     number;
  l_ret_cnt        number;
begin
  select cast(collect(t_obj(level)) as t_obj_tab) into l_t_obj_tab_1 from dual connect by level <= p_size_1; 
  select cast(collect(t_obj(level)) as t_obj_tab) into l_t_obj_tab_2 from dual connect by level <= p_size_2; 
  
  dbms_output.put_line('l_t_obj_tab_1.count   = '||cardinality(l_t_obj_tab_1));
  dbms_output.put_line('l_t_obj_tab_2.count   = '||l_t_obj_tab_2.count);
    
  if p_sel in ('A', 'M') then
    --================= MEMBER Comparison =================
    cmp_counter.p_cnt := 0;
    l_start_time := dbms_utility.get_time;
    
    select /*+ Test_OBJ_MEMBER */ count(*) into l_ret_cnt 
      from table(cast (l_t_obj_tab_1 as t_obj_tab)) t1 
     where t_obj(t1.p_num) member cast(l_t_obj_tab_2 as t_obj_tab);
     
    dbms_output.put_line('=============== MEMBER Condition ===============');
    dbms_output.put_line('Elapsed(centi)        = '||(dbms_utility.get_time - l_start_time));
    dbms_output.put_line('l_ret_cnt             = '||l_ret_cnt);
    dbms_output.put_line('Number of Comparisons = '||cmp_counter.p_cnt);
  end if;
       
  if p_sel in ('A', 'I') then
    --================= IN Operator =================
    cmp_counter.p_cnt := 0;
    l_start_time := dbms_utility.get_time;
    
    select /*+ Test_OBJ_IN */ count(*) into l_ret_cnt 
      from table(cast (l_t_obj_tab_1 as t_obj_tab)) t1 
     where t_obj(t1.p_num) in (select t_obj(t2.p_num) from table(cast(l_t_obj_tab_2 as t_obj_tab)) t2);
    
    dbms_output.put_line('=============== IN Condition ===============');
    dbms_output.put_line('Elapsed(centi)        = '||(dbms_utility.get_time - l_start_time));
    dbms_output.put_line('l_ret_cnt             = '||l_ret_cnt);
    dbms_output.put_line('Number of Comparisons = '||cmp_counter.p_cnt); 
  end if;
end;
/

We run the test:

SQL> exec test_OBJ_MEMBER_vs_IN_Conditions(10000, 1000);    

     l_t_obj_tab_1.count   = 10000
     l_t_obj_tab_2.count   = 1000
     =============== MEMBER Condition ===============
     Elapsed(centi)        = 4503
     l_ret_cnt             = 1000
     Number of Comparisons = 19001000
     =============== IN Condition ===============
     Elapsed(centi)        = 4
     l_ret_cnt             = 1000
     Number of Comparisons = 11000

The test result shows that the elapsed time for MEMBER is about 1000 times greater than for IN, and the number of Comparisons is more than 1000 times (elapsed time is proportional to number of Comparisons).

For MEMBER, the Number of Comparisons is about (product: l_t_obj_tab_1.count * l_t_obj_tab_2.count=19,001,000), which is quadratic performance.
For IN, the Number of Comparisons is about (addition: l_t_obj_tab_1.count + l_t_obj_tab_2.count=11,000), which is linear performance.

Here both xplan:

SELECT /*+ Test_NUM_MEMBER */ COUNT(*) FROM TABLE(CAST (:B1 AS T_NUM_TAB)) T1 WHERE T1.COLUMN_VALUE MEMBER OF CAST(:B2 AS T_NUM_TAB);
  SQL_ID  9v3d6bbpjs0x2, child number 0  Plan hash value: 3309076612
  -------------------------------------------------------------------------------------------
  | Id  | Operation                          | Name | Rows  | Bytes | Cost (%CPU)| Time     |
  -------------------------------------------------------------------------------------------
  |   0 | SELECT STATEMENT                   |      |       |       |    30 (100)|          |
  |   1 |  SORT AGGREGATE                    |      |     1 |     2 |            |          |
  |*  2 |   COLLECTION ITERATOR PICKLER FETCH|      |    50 |   100 |    30   (0)| 00:00:01 |
  -------------------------------------------------------------------------------------------
  Predicate Information (identified by operation id):
  ---------------------------------------------------
     2 - filter(VALUE(KOKBF$)MEMBER OFCAST(:B2 AS "T_NUM_TAB") )
    

SELECT /*+ Test_NUM_IN */ COUNT(*) FROM TABLE(CAST (:B1 AS T_NUM_TAB)) T1 WHERE T1.COLUMN_VALUE IN (SELECT COLUMN_VALUE FROM TABLE(CAST(:B2 AS T_NUM_TAB)));
  SQL_ID  2z2buk4wrs0gs, child number 0  Plan hash value: 4146508332
  --------------------------------------------------------------------------------------------
  | Id  | Operation                           | Name | Rows  | Bytes | Cost (%CPU)| Time     |
  --------------------------------------------------------------------------------------------
  |   0 | SELECT STATEMENT                    |      |       |       |    60 (100)|          |
  |   1 |  SORT AGGREGATE                     |      |     1 |     4 |            |          |
  |*  2 |   HASH JOIN RIGHT SEMI              |      |    10 |    40 |    60   (0)| 00:00:01 |
  |   3 |    COLLECTION ITERATOR PICKLER FETCH|      |   300 |   600 |    30   (0)| 00:00:01 |
  |   4 |    COLLECTION ITERATOR PICKLER FETCH|      |  1000 |  2000 |    30   (0)| 00:00:01 |
  --------------------------------------------------------------------------------------------
  Predicate Information (identified by operation id):
  ---------------------------------------------------
     2 - access(VALUE(KOKBF$)=VALUE(KOKBF$)) 
     

3. bpftrace on PICKLER FETCH Calls

The Oracle subroutine for PICKLER FETCH is implemented by "kodpunp" (kernel objects data manager (pickler) unpickle an image into an object). We can use bpftrace to count the number of such calls.

3.1 MEMBER Comparison

The bpftrace count on kodpunp (from kgmtimob): 19001000 matches Sqlplus(pid == 1128134) output: Number of Comparisons = 19001000.

SQL > exec test_OBJ_MEMBER_vs_IN_Conditions(10000, 1000, 'M');

        l_t_obj_tab_1.count   = 10000
        l_t_obj_tab_2.count   = 1000
        =============== MEMBER Condition ===============
        Elapsed(centi)        = 7526
        l_ret_cnt             = 1000
        Number of Comparisons = 19001000
        
        Elapsed: 00:01:15.28

$ > bpftrace -e 'uprobe:/orabin/app/oracle/product/19.27.0.0.250415-212/bin/oracle:kodpunp+2 /pid == 1128134/ {@[ustack(2)] = count();}'
      @[
          kodpunp+2
          kpcocaup+599
      ]: 2
      @[
          kodpunp+2
          kopp2uattr+7010
      ]: 11000
      @[
          kodpunp+2
          kgmtimob+1002
      ]: 19001000
      

3.2 IN Comparison

The bpftrace count on kodpunp (from kgmtimob): 11000 matches Sqlplus(pid == 1128134) output: Number of Comparisons = 11000.

SQL > exec test_OBJ_MEMBER_vs_IN_Conditions(10000, 1000, 'I');

        l_t_obj_tab_1.count   = 10000
        l_t_obj_tab_2.count   = 1000
        =============== IN Condition ===============
        Elapsed(centi)        = 5
        l_ret_cnt             = 1000
        Number of Comparisons = 11000
        
        Elapsed: 00:00:00.09

$ > bpftrace -e 'uprobe:/orabin/app/oracle/product/19.27.0.0.250415-212/bin/oracle:kodpunp+2 /pid == 1128134/ {@[ustack(2)] = count();}'
      @[
          kodpunp+2
          kpcocaup+599
      ]: 2
      @[
          kodpunp+2
          kgmtimob+1002
      ]: 11000
      @[
          kodpunp+2
          kopp2uattr+7010
      ]: 11000
      

Voila full Plsql callstack:

#0    kodpunp ()
#1    kokoupkl ()
#2    kpcocaup ()
#3    kprcdt ()
#4    kprccu ()
#5    opifcr ()
#6    qergsFetch ()
#7    opifch2 ()
#8    opiefn0 ()
#9    opipls ()
#10   opiodr ()
#11   rpidrus ()
#12   skgmstack ()
#13   rpidru ()
#14   rpiswu2 ()
#15   rpidrv ()
#16   psddr0 ()
#17   psdnal ()
#18   pevm_EXECC ()
#19   pfrinstr_EXECC ()
#20   pfrrun_no_tool ()
#21   pfrrun ()
#22   plsql_run ()

Oracle SQL MEMBER vs. IN Comparison Condition Performance - Part2

---

(I)-Oracle SQL MEMBER vs. IN Comparison Condition Performance - Part1      (II)-Oracle SQL MEMBER vs. IN Comparison Condition Performance - Part2

---

Continuing with last Blog: (I)-Oracle SQL MEMBER vs. IN Comparison Condition Performance - Part1,
in this Blog, we will first demonstrate the performance difference of MEMBER and IN Comparison Conditions for nested table column and varray table column, then run tests to show performance improvement by creating index on nested child table.

Note: Tested in Oracle 19.27

1. MEMBER vs. IN Performance Difference on Nested Table Column

We create a table containing one nested table column, and run tests with MEMBER vs. IN Conditions.

create or replace noneditionable type t_num_tab is table of number;
/

-- varray has the same behaviour as nested table if we replace t_num_tab by t_num_vary
create or replace noneditionable type t_num_vary as varray(100) of number;
/

drop table test_table;

create table test_table (id number, nt t_num_tab) nested table nt store as test_table_nt;

insert into test_table(id, nt) select level, t_num_tab(level, -level) from dual connect by level <= 1e5; 

commit; 

begin
   dbms_stats.gather_table_stats(user, 'TEST_TABLE',    cascade=>true);
   dbms_stats.gather_table_stats(user, 'TEST_TABLE_NT', cascade=>true);
end;
/

select table_name, num_rows, blocks, avg_row_len from dba_tables where table_name in ('TEST_TABLE', 'TEST_TABLE_NT');
  TABLE_NAME        NUM_ROWS     BLOCKS AVG_ROW_LEN
  --------------- ---------- ---------- -----------
  TEST_TABLE          100000        496          22
  TEST_TABLE_NT       200000        874          22
 
select table_name, index_name, uniqueness, leaf_blocks, num_rows, distinct_keys from dba_indexes where table_name in ('TEST_TABLE', 'TEST_TABLE_NT');
  TABLE_NAME      INDEX_NAME                UNIQUENESS   LEAF_BLOCKS   NUM_ROWS DISTINCT_KEYS
  --------------- ------------------------- ------------ ----------- ---------- -------------
  TEST_TABLE      SYS_C00144532             UNIQUE               338     100000        100000
  TEST_TABLE_NT   SYS_FK0005992996N00002$   NONUNIQUE            702     200000        102008
 
select segment_name, bytes, blocks from dba_segments where segment_name in ('TEST_TABLE', 'TEST_TABLE_NT', 'SYS_C00142541', 'SYS_FK0005992996N00002$');
  SEGMENT_NAME                   BYTES     BLOCKS
  ------------------------- ---------- ----------
  TEST_TABLE                   4194304        512
  TEST_TABLE_NT                7340032        896
  SYS_C00144532                3145728        384
  SYS_FK0005992996N00002$      6291456        768

create or replace procedure test_TAB_MEMBER_vs_IN_Conditions (p_size number) as
  l_num_tab        t_num_tab := t_num_tab();
  l_start_time     number;
  l_ret_cnt        number;
begin
  select level bulk collect into l_num_tab from dual connect by level <= p_size;
  
  --================= MEMBER Comparison =================
  l_start_time := dbms_utility.get_time;
  
  select /*+ Test_TAB_MEMBER */ count(c.column_value) into l_ret_cnt 
    from test_table t, table(t.nt) c 
   where c.column_value member of cast(l_num_tab as t_num_tab);
   
  dbms_output.put_line('=============== MEMBER Condition ===============');
  dbms_output.put_line('Elapsed(centi)        = '||(dbms_utility.get_time - l_start_time));
  dbms_output.put_line('l_ret_cnt             = '||l_ret_cnt);

  --================= IN Comparison =================
  l_start_time := dbms_utility.get_time;
  
  select /*+ Test_TAB_IN */ count(c.column_value) into l_ret_cnt 
    from test_table t, table(t.nt) c 
   where c.column_value in (select column_value from table(cast(l_num_tab as t_num_tab)));
  
  dbms_output.put_line('=============== IN Condition ===============');
  dbms_output.put_line('Elapsed(centi)        = '||(dbms_utility.get_time - l_start_time));
  dbms_output.put_line('l_ret_cnt             = '||l_ret_cnt);
end;
/

The test result shows that the elapsed time for MEMBER is about 100 times longer than for IN.

SQL > exec test_TAB_MEMBER_vs_IN_Conditions(1000);

  =============== MEMBER Condition ===============
  Elapsed(centi)        = 449
  l_ret_cnt             = 1000
  =============== IN Condition ===============
  Elapsed(centi)        = 3
  l_ret_cnt             = 1000

2. MEMBER vs. IN Performance Difference on Lookup

Blog: MEMBER OF comparison of PL/SQL and SQL (Kim Berg Hansen June 23, 2014) shows the performance difference of single row select in PL/SQL and SQL, and demonstrate SQL performance improvement by creating index on nested child table.

Based on it, we will make tests to show the Performance Difference of lookup on nested table column with and without index on it by MEMBER or IN Comparison Conditions.

Note that this is not applicable to varray array column because database stores varray column as a single objest (raw value or LOB) and it has no storage_table clause, whereas nested table column has storage_table clause to store it as a normal heap table.

2.1 Single Key Lookup

First we make tests by single key lookup:

alter session set tracefile_identifier = 'nt_single';
alter session set events '10046 trace name context forever, level 12'; 
 				
VARIABLE lookup_key NUMBER;
exec :lookup_key := 999;

------------- No Index ------------
drop index test_table_nt_indx;

select /*+ Test_TAB_MEMBER_LOOKUP_Single_NO_INDX */ count(t.id) from test_table t where :lookup_key member of cast(t.nt as t_num_tab);
select /*+ Test_TAB_IN_LOOKUP_Single_NO_INDX */ count(t.id) from test_table t, table(t.nt) c where c.column_value = :lookup_key;

------------- Index on column_value ------------
drop index test_table_nt_indx;
create index test_table_nt_indx on test_table_nt(column_value);

begin
   dbms_stats.gather_table_stats(user, 'TEST_TABLE',    cascade=>true);
   dbms_stats.gather_table_stats(user, 'TEST_TABLE_NT', cascade=>true);
end;
/

--MEMBER Comparison does not use INDEX 
select /*+ Test_TAB_MEMBER_LOOKUP_Single_INDX_Col_1 */ count(t.id) from test_table t where :lookup_key member of cast(t.nt as t_num_tab);
select /*+ Test_TAB_IN_LOOKUP_Single_INDX_Col_1 */ count(t.id) from test_table t, table(t.nt) c where c.column_value = :lookup_key;

------------- Index on (column_value, nested_table_id) ------------
drop index test_table_nt_indx;
create index test_table_nt_indx on test_table_nt(column_value, nested_table_id);

begin
   dbms_stats.gather_table_stats(user, 'TEST_TABLE',    cascade=>true);
   dbms_stats.gather_table_stats(user, 'TEST_TABLE_NT', cascade=>true);
end;
/

select /*+ Test_TAB_IN_LOOKUP_Single_INDX_Col_2 */ count(t.id) from test_table t, table(t.nt) c where c.column_value = :lookup_key;

alter session set events '10046 trace name context off';

Here the SQL Trace (10046) output:

********************************************************************************
SQL ID: f90kvg63f33fr Plan Hash: 440919791

select /*+ Test_TAB_MEMBER_LOOKUP_Single_NO_INDX */ count(t.id) 
from test_table t where :lookup_key member of cast(t.nt as t_num_tab)

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        2      0.35       0.35          0     212122          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      0.36       0.36          0     212122          0           1

Rows (1st) Row Source Operation
---------- ---------------------------------------------------
         1 SORT AGGREGATE (cr=212122 pr=0 pw=0 time=359533 us starts=1)
         1  FILTER  (cr=212122 pr=0 pw=0 time=359523 us starts=1)
    100000   TABLE ACCESS FULL TEST_TABLE (cr=394 pr=0 pw=0 time=7314 us starts=1 cost=143 size=2200000 card=100000)
    200000   TABLE ACCESS BY INDEX ROWID BATCHED TEST_TABLE_NT (cr=211728 pr=0 pw=0 time=179841 us starts=100000 cost=2 size=44 card=2)
    200000    INDEX RANGE SCAN SYS_FK0005992996N00002$ (cr=111678 pr=0 pw=0 time=100304 us starts=100000 cost=2 size=0 card=2)(object id 5992998)

********************************************************************************
SQL ID: 3b57pxgx3ka1r Plan Hash: 299443699

select /*+ Test_TAB_IN_LOOKUP_Single_NO_INDX */ count(t.id) 
from test_table t, table(t.nt) c where c.column_value = :lookup_key

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        2      0.00       0.00          0        792          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      0.00       0.00          0        792          0           1

Rows (1st) Row Source Operation
---------- ---------------------------------------------------
         1 SORT AGGREGATE (cr=792 pr=0 pw=0 time=4927 us starts=1)
         1  NESTED LOOPS  (cr=792 pr=0 pw=0 time=4919 us starts=1 cost=252 size=44 card=1)
         1   NESTED LOOPS  (cr=791 pr=0 pw=0 time=4910 us starts=1 cost=252 size=44 card=1)
         1    TABLE ACCESS FULL TEST_TABLE_NT (cr=789 pr=0 pw=0 time=4900 us starts=1 cost=251 size=22 card=1)
         1    INDEX UNIQUE SCAN SYS_C00144532 (cr=2 pr=0 pw=0 time=7 us starts=1 cost=1 size=0 card=1)(object id 5992999)
         1   TABLE ACCESS BY INDEX ROWID TEST_TABLE (cr=1 pr=0 pw=0 time=8 us starts=1 cost=1 size=22 card=1)
********************************************************************************

SQL ID: 5pyx85dkay5fz Plan Hash: 440919791

select /*+ Test_TAB_MEMBER_LOOKUP_Single_INDX_Col_1 */ count(t.id) 
from test_table t where :lookup_key member of cast(t.nt as t_num_tab)

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        2      0.35       0.35          0     212122          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      0.35       0.35          0     212122          0           1

Rows (1st) Row Source Operation
---------- ---------------------------------------------------
         1 SORT AGGREGATE (cr=212122 pr=0 pw=0 time=357398 us starts=1)
         1  FILTER  (cr=212122 pr=0 pw=0 time=357388 us starts=1)
    100000   TABLE ACCESS FULL TEST_TABLE (cr=394 pr=0 pw=0 time=8078 us starts=1 cost=143 size=2200000 card=100000)
    200000   TABLE ACCESS BY INDEX ROWID BATCHED TEST_TABLE_NT (cr=211728 pr=0 pw=0 time=178477 us starts=100000 cost=2 size=44 card=2)
    200000    INDEX RANGE SCAN SYS_FK0005992996N00002$ (cr=111678 pr=0 pw=0 time=98691 us starts=100000 cost=2 size=0 card=2)(object id 5992998)
    
********************************************************************************

SQL ID: 77x73ayp09c9p Plan Hash: 1013981520

select /*+ Test_TAB_IN_LOOKUP_Single_INDX_Col_1 */ count(t.id) 
from test_table t, table(t.nt) c where c.column_value = :lookup_key

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        2      0.00       0.00          0          6          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      0.00       0.00          0          6          0           1

Rows (1st) Row Source Operation
---------- ---------------------------------------------------
         1 SORT AGGREGATE (cr=6 pr=0 pw=0 time=40 us starts=1)
         1  NESTED LOOPS  (cr=6 pr=0 pw=0 time=33 us starts=1 cost=2 size=44 card=1)
         1   NESTED LOOPS  (cr=5 pr=0 pw=0 time=26 us starts=1 cost=2 size=44 card=1)
         1    TABLE ACCESS BY INDEX ROWID BATCHED TEST_TABLE_NT (cr=3 pr=0 pw=0 time=18 us starts=1 cost=1 size=22 card=1)
         1     INDEX RANGE SCAN TEST_TABLE_NT_INDX (cr=2 pr=0 pw=0 time=14 us starts=1 cost=1 size=0 card=1)(object id 5993191)
         1    INDEX UNIQUE SCAN SYS_C00144532 (cr=2 pr=0 pw=0 time=6 us starts=1 cost=1 size=0 card=1)(object id 5992999)
         1   TABLE ACCESS BY INDEX ROWID TEST_TABLE (cr=1 pr=0 pw=0 time=5 us starts=1 cost=1 size=22 card=1)
         
********************************************************************************

SQL ID: 535h2a2yb77z0 Plan Hash: 2041402069

select /*+ Test_TAB_IN_LOOKUP_Single_INDX_Col_2 */ count(t.id) 
from test_table t, table(t.nt) c where c.column_value = :lookup_key

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        2      0.00       0.00          0          6          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      0.00       0.00          0          6          0           1

Rows (1st) Row Source Operation
---------- ---------------------------------------------------
         1 SORT AGGREGATE (cr=6 pr=0 pw=0 time=32 us starts=1)
         1  NESTED LOOPS  (cr=6 pr=0 pw=0 time=25 us starts=1 cost=3 size=44 card=1)
         1   NESTED LOOPS  (cr=5 pr=0 pw=0 time=18 us starts=1 cost=3 size=44 card=1)
         1    INDEX RANGE SCAN TEST_TABLE_NT_INDX (cr=3 pr=0 pw=0 time=12 us starts=1 cost=2 size=22 card=1)(object id 5993192)
         1    INDEX UNIQUE SCAN SYS_C00144532 (cr=2 pr=0 pw=0 time=5 us starts=1 cost=1 size=0 card=1)(object id 5992999)
         1   TABLE ACCESS BY INDEX ROWID TEST_TABLE (cr=1 pr=0 pw=0 time=6 us starts=1 cost=1 size=22 card=1)    
         

Above test output shows the MEMBER Comparisons make 212,122 block gets (query=212122), mostly on TEST_TABLE_NT and its foreign key index: SYS_FK0005992996N00002$ although both together has only about 1,600 blocks.

Whereas IN Comparisons has query=792 when no index, and query=6 when there is the index on nested table column.

2.2 Multi Key Lookup

Now we run tests of lookup with multiple keys:

alter session set tracefile_identifier = 'nt_multi';
alter session set events '10046 trace name context forever, level 12'; 
 				
drop table test_keys; 
create table test_keys as select level k from dual connect by level <= 100; 
begin
   dbms_stats.gather_table_stats(user, 'TEST_KEYS',    cascade=>true);
end;
/

------------- No Index ------------
drop index test_table_nt_indx;

select /*+ Test_TAB_MEMBER_LOOKUP_Multi_NO_INDX */ count(t.id) from test_table t, test_keys l where l.k member of cast(t.nt as t_num_tab);
select /*+ Test_TAB_IN_LOOKUP_Multi_NO_INDX */ count(t.id) from test_table t, table(t.nt) c, test_keys l where c.column_value = l.k;

------------- Index on column_value ------------
drop index test_table_nt_indx;
create index test_table_nt_indx on test_table_nt(column_value);

begin
   dbms_stats.gather_table_stats(user, 'TEST_TABLE',    cascade=>true);
   dbms_stats.gather_table_stats(user, 'TEST_TABLE_NT', cascade=>true);
end;
/

--MEMBER Comparison does not use INDEX  
select /*+ Test_TAB_MEMBER_LOOKUP_Multi_INDX_Col_1 */ count(t.id) from test_table t, test_keys l where l.k member of cast(t.nt as t_num_tab);
select /*+ Test_TAB_IN_LOOKUP_Multi_INDX_Col_1 */ count(t.id) from test_table t, table(t.nt) c, test_keys l where c.column_value = l.k;

------------- Index on (column_value, nested_table_id) ------------
drop index test_table_nt_indx;
create index test_table_nt_indx on test_table_nt(column_value, nested_table_id);

begin
   dbms_stats.gather_table_stats(user, 'TEST_TABLE',    cascade=>true);
   dbms_stats.gather_table_stats(user, 'TEST_TABLE_NT', cascade=>true);
end;
/

select /*+ Test_TAB_IN_LOOKUP_Multi_INDX_Col_2 */ count(t.id) from test_table t, table(t.nt) c, test_keys l where c.column_value = l.k;

alter session set events '10046 trace name context off';

Here SQL Trace (10046) output:

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

SQL ID: a9wc0w7m86gr3 Plan Hash: 2034372327

select /*+ Test_TAB_MEMBER_LOOKUP_Multi_NO_INDX */ count(t.id) 
from test_table t, test_keys l where l.k member of cast(t.nt as t_num_tab)

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        2     36.91      37.14          0   21173295          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4     36.91      37.15          0   21173295          0           1

Rows (1st) Row Source Operation
---------- ---------------------------------------------------
         1 SORT AGGREGATE (cr=21173295 pr=0 pw=0 time=37148408 us starts=1)
       100  FILTER  (cr=21173295 pr=0 pw=0 time=36949905 us starts=1)
  10000000   MERGE JOIN CARTESIAN (cr=396 pr=0 pw=0 time=2089627 us starts=1 cost=14177 size=250000000 card=10000000)
       100    TABLE ACCESS FULL TEST_KEYS (cr=2 pr=0 pw=0 time=126 us starts=1 cost=3 size=300 card=100)
  10000000    BUFFER SORT (cr=394 pr=0 pw=0 time=1116011 us starts=100 cost=14174 size=2200000 card=100000)
    100000     TABLE ACCESS FULL TEST_TABLE (cr=394 pr=0 pw=0 time=8323 us starts=1 cost=142 size=2200000 card=100000)
  20000000   TABLE ACCESS BY INDEX ROWID BATCHED TEST_TABLE_NT (cr=21172899 pr=0 pw=0 time=18230528 us starts=10000000 cost=2 size=44 card=2)
  20000000    INDEX RANGE SCAN SYS_FK0005992996N00002$ (cr=11167899 pr=0 pw=0 time=10198247 us starts=10000000 cost=2 size=0 card=2)(object id 5992998)
********************************************************************************

SQL ID: ftr39jncgyj2r Plan Hash: 768666713

select /*+ Test_TAB_IN_LOOKUP_Multi_NO_INDX */ count(t.id) 
from test_table t, table(t.nt) c, test_keys l where c.column_value = l.k

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        2      0.02       0.02          0        900          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      0.02       0.02          0        900          0           1

Rows (1st) Row Source Operation
---------- ---------------------------------------------------
         1 SORT AGGREGATE (cr=900 pr=0 pw=0 time=20282 us starts=1)
       100  NESTED LOOPS  (cr=900 pr=0 pw=0 time=787 us starts=1 cost=304 size=4700 card=100)
       100   NESTED LOOPS  (cr=800 pr=0 pw=0 time=583 us starts=1 cost=304 size=4700 card=100)
       100    HASH JOIN  (cr=791 pr=0 pw=0 time=375 us starts=1 cost=254 size=2500 card=100)
       100     TABLE ACCESS FULL TEST_KEYS (cr=2 pr=0 pw=0 time=45 us starts=1 cost=3 size=300 card=100)
    200000     TABLE ACCESS FULL TEST_TABLE_NT (cr=789 pr=0 pw=0 time=23571 us starts=1 cost=251 size=4400000 card=200000)
       100    INDEX UNIQUE SCAN SYS_C00144532 (cr=9 pr=0 pw=0 time=47 us starts=100 cost=1 size=0 card=1)(object id 5992999)
       100   TABLE ACCESS BY INDEX ROWID TEST_TABLE (cr=100 pr=0 pw=0 time=50 us starts=100 cost=1 size=22 card=1)
********************************************************************************

SQL ID: gqxbmzjcrt5p1 Plan Hash: 2034372327

select /*+ Test_TAB_MEMBER_LOOKUP_Multi_INDX_Col_1 */ count(t.id) 
from test_table t, test_keys l where l.k member of cast(t.nt as t_num_tab)

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        2     36.68      36.92          0   21173295          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4     36.69      36.92          0   21173295          0           1

Rows (1st) Row Source Operation
---------- ---------------------------------------------------
         1 SORT AGGREGATE (cr=21173295 pr=0 pw=0 time=36926973 us starts=1)
       100  FILTER  (cr=21173295 pr=0 pw=0 time=35871619 us starts=1)
  10000000   MERGE JOIN CARTESIAN (cr=396 pr=0 pw=0 time=2062528 us starts=1 cost=14177 size=250000000 card=10000000)
       100    TABLE ACCESS FULL TEST_KEYS (cr=2 pr=0 pw=0 time=130 us starts=1 cost=3 size=300 card=100)
  10000000    BUFFER SORT (cr=394 pr=0 pw=0 time=1081777 us starts=100 cost=14174 size=2200000 card=100000)
    100000     TABLE ACCESS FULL TEST_TABLE (cr=394 pr=0 pw=0 time=7557 us starts=1 cost=142 size=2200000 card=100000)
  20000000   TABLE ACCESS BY INDEX ROWID BATCHED TEST_TABLE_NT (cr=21172899 pr=0 pw=0 time=18120678 us starts=10000000 cost=2 size=44 card=2)
  20000000    INDEX RANGE SCAN SYS_FK0005992996N00002$ (cr=11167899 pr=0 pw=0 time=10102918 us starts=10000000 cost=2 size=0 card=2)(object id 5992998)
********************************************************************************

SQL ID: 3hww8x82t497g Plan Hash: 3838096326

select /*+ Test_TAB_IN_LOOKUP_Multi_INDX_Col_1 */ count(t.id) 
from test_table t, table(t.nt) c, test_keys l where c.column_value = l.k

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        2      0.00       0.00          0        120          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      0.00       0.00          0        120          0           1

Rows (1st) Row Source Operation
---------- ---------------------------------------------------
         1 SORT AGGREGATE (cr=120 pr=0 pw=0 time=336 us starts=1)
       100  NESTED LOOPS  (cr=120 pr=0 pw=0 time=1052 us starts=1 cost=103 size=4700 card=100)
       100   NESTED LOOPS  (cr=20 pr=0 pw=0 time=849 us starts=1 cost=103 size=4700 card=100)
       100    NESTED LOOPS  (cr=11 pr=0 pw=0 time=544 us starts=1 cost=53 size=2500 card=100)
       100     TABLE ACCESS FULL TEST_KEYS (cr=2 pr=0 pw=0 time=132 us starts=1 cost=3 size=300 card=100)
       100     TABLE ACCESS BY INDEX ROWID BATCHED TEST_TABLE_NT (cr=9 pr=0 pw=0 time=115 us starts=100 cost=1 size=22 card=1)
       100      INDEX RANGE SCAN TEST_TABLE_NT_INDX (cr=8 pr=0 pw=0 time=74 us starts=100 cost=1 size=0 card=1)(object id 5993194)
       100    INDEX UNIQUE SCAN SYS_C00144532 (cr=9 pr=0 pw=0 time=46 us starts=100 cost=1 size=0 card=1)(object id 5992999)
       100   TABLE ACCESS BY INDEX ROWID TEST_TABLE (cr=100 pr=0 pw=0 time=48 us starts=100 cost=1 size=22 card=1)
********************************************************************************

SQL ID: 5ghun4988xh7w Plan Hash: 2752258125

select /*+ Test_TAB_IN_LOOKUP_Multi_INDX_Col_2 */ count(t.id) 
from test_table t, table(t.nt) c, test_keys l where c.column_value = l.k

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        2      0.00       0.00          0        136          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      0.00       0.00          0        136          0           1

Rows (1st) Row Source Operation
---------- ---------------------------------------------------
         1 SORT AGGREGATE (cr=136 pr=0 pw=0 time=275 us starts=1)
       100  NESTED LOOPS  (cr=136 pr=0 pw=0 time=837 us starts=1 cost=103 size=4700 card=100)
       100   NESTED LOOPS  (cr=36 pr=0 pw=0 time=831 us starts=1 cost=103 size=4700 card=100)
       100    NESTED LOOPS  (cr=27 pr=0 pw=0 time=528 us starts=1 cost=53 size=2500 card=100)
       100     TABLE ACCESS FULL TEST_KEYS (cr=2 pr=0 pw=0 time=121 us starts=1 cost=3 size=300 card=100)
       100     INDEX RANGE SCAN TEST_TABLE_NT_INDX (cr=25 pr=0 pw=0 time=83 us starts=100 cost=1 size=22 card=1)(object id 5993195)
       100    INDEX UNIQUE SCAN SYS_C00144532 (cr=9 pr=0 pw=0 time=44 us starts=100 cost=1 size=0 card=1)(object id 5992999)
       100   TABLE ACCESS BY INDEX ROWID TEST_TABLE (cr=100 pr=0 pw=0 time=47 us starts=100 cost=1 size=22 card=1)
       

Above test output shows for 100 keys, the MEMBER Comparisons make 21,173,295 block gets (query=21173295), mostly on TEST_TABLE_NT and its foreign key index: SYS_FK0005992996N00002$, which is about 100 times of single key lookup (query=212,122)

Whereas IN Comparisons has query=900 when no index, and query=120/136 when there is the index on nested table column, which are linear to number of lookup keys.

Sqltraces shows that for MEMBER Comparison, it is much slower than IN Comparison (37.15 vs. 0.02 seconds)
because there are much higher block gets (query = 21173295 vs. 900), and index on nested table column is not used.

When there are Index on (column_value) or (column_value, nested_table_id), the performance is further improved (query = 900 vs. 120/136).

For Index on (column_value), index TEST_TABLE_NT_INDX and SYS_C00144532 are used, but still need TABLE ACCESS BY INDEX ROWID BATCHED on TEST_TABLE_NT.

For Index on (column_value, nested_table_id), index TEST_TABLE_NT_INDX and SYS_C00144532 are used, no more TEST_TABLE_NT access.

Here xplan with Predicate Information:

--======================= No Index MEMBER Comparison =======================--
drop index test_table_nt_indx;

select /*+ Test_TAB_MEMBER_LOOKUP_Multi_NO_INDX */ count(t.id) 
from test_table t, test_keys l where l.k member of cast(t.nt as t_num_tab);

Plan hash value: 2034372327
-----------------------------------------------------------------------------------------------------------------
| Id  | Operation                             | Name                    | Rows  | Bytes | Cost (%CPU)| Time     |
-----------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                      |                         |     1 |    25 | 14179   (1)| 00:00:01 |
|   1 |  SORT AGGREGATE                       |                         |     1 |    25 |            |          |
|*  2 |   FILTER                              |                         |       |       |            |          |
|   3 |    MERGE JOIN CARTESIAN               |                         |    10M|   238M| 14177   (1)| 00:00:01 |
|   4 |     TABLE ACCESS FULL                 | TEST_KEYS               |   100 |   300 |     3   (0)| 00:00:01 |
|   5 |     BUFFER SORT                       |                         |   100K|  2148K| 14174   (1)| 00:00:01 |
|   6 |      TABLE ACCESS FULL                | TEST_TABLE              |   100K|  2148K|   142   (0)| 00:00:01 |
|   7 |    TABLE ACCESS BY INDEX ROWID BATCHED| TEST_TABLE_NT           |     2 |    44 |     2   (0)| 00:00:01 |
|*  8 |     INDEX RANGE SCAN                  | SYS_FK0005992996N00002$ |     2 |       |     2   (0)| 00:00:01 |
-----------------------------------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
   2 - filter("L"."K"MEMBER OFCAST("T"."NT" AS "T_NUM_TAB") )
   8 - access("NESTED_TABLE_ID"=:B1)

--======================= No Index IN Comparison =======================--
select /*+ Test_TAB_IN_LOOKUP_Multi_NO_INDX */ count(t.id) 
from test_table t, table(t.nt) c, test_keys l where c.column_value = l.k;

Plan hash value: 768666713
-----------------------------------------------------------------------------------------------
| Id  | Operation                     | Name          | Rows  | Bytes | Cost (%CPU)| Time     |
-----------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT              |               |     1 |    47 |   304   (0)| 00:00:01 |
|   1 |  SORT AGGREGATE               |               |     1 |    47 |            |          |
|   2 |   NESTED LOOPS                |               |   100 |  4700 |   304   (0)| 00:00:01 |
|   3 |    NESTED LOOPS               |               |   100 |  4700 |   304   (0)| 00:00:01 |
|*  4 |     HASH JOIN                 |               |   100 |  2500 |   254   (0)| 00:00:01 |
|   5 |      TABLE ACCESS FULL        | TEST_KEYS     |   100 |   300 |     3   (0)| 00:00:01 |
|   6 |      TABLE ACCESS FULL        | TEST_TABLE_NT |   200K|  4296K|   251   (0)| 00:00:01 |
|*  7 |     INDEX UNIQUE SCAN         | SYS_C00144532 |     1 |       |     1   (0)| 00:00:01 |
|   8 |    TABLE ACCESS BY INDEX ROWID| TEST_TABLE    |     1 |    22 |     1   (0)| 00:00:01 |
-----------------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
   4 - access("C"."COLUMN_VALUE"="L"."K")
   7 - access("C"."NESTED_TABLE_ID"="T"."SYS_NC0000200003$")
   
--======================= Index on (column_value), MEMBER Comparison =======================--
drop index test_table_nt_indx;
create index test_table_nt_indx on test_table_nt(column_value);

begin
   dbms_stats.gather_table_stats(user, 'TEST_TABLE',    cascade=>true);
   dbms_stats.gather_table_stats(user, 'TEST_TABLE_NT', cascade=>true);
end;
/

select /*+ Test_TAB_MEMBER_LOOKUP_Multi_INDX_Col_1 */ count(t.id) 
from test_table t, test_keys l where l.k member of cast(t.nt as t_num_tab);

Plan hash value: 2034372327
-----------------------------------------------------------------------------------------------------------------
| Id  | Operation                             | Name                    | Rows  | Bytes | Cost (%CPU)| Time     |
-----------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                      |                         |     1 |    25 | 14179   (1)| 00:00:01 |
|   1 |  SORT AGGREGATE                       |                         |     1 |    25 |            |          |
|*  2 |   FILTER                              |                         |       |       |            |          |
|   3 |    MERGE JOIN CARTESIAN               |                         |    10M|   238M| 14177   (1)| 00:00:01 |
|   4 |     TABLE ACCESS FULL                 | TEST_KEYS               |   100 |   300 |     3   (0)| 00:00:01 |
|   5 |     BUFFER SORT                       |                         |   100K|  2148K| 14174   (1)| 00:00:01 |
|   6 |      TABLE ACCESS FULL                | TEST_TABLE              |   100K|  2148K|   142   (0)| 00:00:01 |
|   7 |    TABLE ACCESS BY INDEX ROWID BATCHED| TEST_TABLE_NT           |     2 |    44 |     2   (0)| 00:00:01 |
|*  8 |     INDEX RANGE SCAN                  | SYS_FK0005992996N00002$ |     2 |       |     2   (0)| 00:00:01 |
-----------------------------------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
   2 - filter("L"."K"MEMBER OFCAST("T"."NT" AS "T_NUM_TAB") )
   8 - access("NESTED_TABLE_ID"=:B1)

--======================= Index on (column_value), IN Comparison =======================--
select /*+ Test_TAB_IN_LOOKUP_Multi_INDX_Col_1 */ count(t.id) 
from test_table t, table(t.nt) c, test_keys l where c.column_value = l.k;

Plan hash value: 3838096326
--------------------------------------------------------------------------------------------------------------
| Id  | Operation                               | Name               | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                        |                    |     1 |    47 |   103   (0)| 00:00:01 |
|   1 |  SORT AGGREGATE                         |                    |     1 |    47 |            |          |
|   2 |   NESTED LOOPS                          |                    |   100 |  4700 |   103   (0)| 00:00:01 |
|   3 |    NESTED LOOPS                         |                    |   100 |  4700 |   103   (0)| 00:00:01 |
|   4 |     NESTED LOOPS                        |                    |   100 |  2500 |    53   (0)| 00:00:01 |
|   5 |      TABLE ACCESS FULL                  | TEST_KEYS          |   100 |   300 |     3   (0)| 00:00:01 |
|   6 |      TABLE ACCESS BY INDEX ROWID BATCHED| TEST_TABLE_NT      |     1 |    22 |     1   (0)| 00:00:01 |
|*  7 |       INDEX RANGE SCAN                  | TEST_TABLE_NT_INDX |     1 |       |     1   (0)| 00:00:01 |
|*  8 |     INDEX UNIQUE SCAN                   | SYS_C00144532      |     1 |       |     1   (0)| 00:00:01 |
|   9 |    TABLE ACCESS BY INDEX ROWID          | TEST_TABLE         |     1 |    22 |     1   (0)| 00:00:01 |
--------------------------------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
   7 - access("C"."COLUMN_VALUE"="L"."K")
   8 - access("C"."NESTED_TABLE_ID"="T"."SYS_NC0000200003$")

--======================= Index on (column_value, nested_table_id), IN Comparison =======================--
drop index test_table_nt_indx;
create index test_table_nt_indx on test_table_nt(column_value, nested_table_id);

begin
   dbms_stats.gather_table_stats(user, 'TEST_TABLE',    cascade=>true);
   dbms_stats.gather_table_stats(user, 'TEST_TABLE_NT', cascade=>true);
end;
/

select /*+ Test_TAB_IN_LOOKUP_Multi_INDX_Col_2 */ count(t.id) 
from test_table t, table(t.nt) c, test_keys l where c.column_value = l.k;

Plan hash value: 2752258125
----------------------------------------------------------------------------------------------------
| Id  | Operation                     | Name               | Rows  | Bytes | Cost (%CPU)| Time     |
----------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT              |                    |     1 |    47 |   103   (0)| 00:00:01 |
|   1 |  SORT AGGREGATE               |                    |     1 |    47 |            |          |
|   2 |   NESTED LOOPS                |                    |   100 |  4700 |   103   (0)| 00:00:01 |
|   3 |    NESTED LOOPS               |                    |   100 |  4700 |   103   (0)| 00:00:01 |
|   4 |     NESTED LOOPS              |                    |   100 |  2500 |    53   (0)| 00:00:01 |
|   5 |      TABLE ACCESS FULL        | TEST_KEYS          |   100 |   300 |     3   (0)| 00:00:01 |
|*  6 |      INDEX RANGE SCAN         | TEST_TABLE_NT_INDX |     1 |    22 |     1   (0)| 00:00:01 |
|*  7 |     INDEX UNIQUE SCAN         | SYS_C00144532      |     1 |       |     1   (0)| 00:00:01 |
|   8 |    TABLE ACCESS BY INDEX ROWID| TEST_TABLE         |     1 |    22 |     1   (0)| 00:00:01 |
----------------------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
   6 - access("C"."COLUMN_VALUE"="L"."K")
   7 - access("C"."NESTED_TABLE_ID"="T"."SYS_NC0000200003$")
   

3. Nested Table Internals

Referring to early Blog: Foreign Key on Nested Table, we can cross check with Oracle internal table and index DDL:

select o.object_name table_name, c.name column_name, c.type# column_type
  from   dba_objects o, sys.col$ c
 where c.obj# = o.object_id
   and o.object_name in ('TEST_TABLE', 'TEST_TABLE_NT')
 order by o.object_name, c.name;
 
   TABLE_NAME      COLUMN_NAME          COLUMN_TYPE
  --------------- -------------------- -----------
  TEST_TABLE      ID                             2
  TEST_TABLE      NT                           122
  TEST_TABLE      SYS_NC0000200003$             23
  TEST_TABLE_NT   COLUMN_VALUE                   2
  TEST_TABLE_NT   NESTED_TABLE_ID               23

select index_name, table_name, column_name 
  from  dba_ind_columns 
 where table_name in ('TEST_TABLE', 'TEST_TABLE_NT');

  INDEX_NAME                TABLE_NAME      COLUMN_NAME
  ------------------------- --------------- --------------------
  SYS_C00144532             TEST_TABLE      NT
  TEST_TABLE_NT_INDX        TEST_TABLE_NT   COLUMN_VALUE
  TEST_TABLE_NT_INDX        TEST_TABLE_NT   NESTED_TABLE_ID
  SYS_FK0005992996N00002$   TEST_TABLE_NT   NESTED_TABLE_ID

Above xplan shows that for MEMBER Comparison, foreign key index SYS_FK0005992996N00002$ on TEST_TABLE_NT is used, and index on nested table column is not used.

For IN Comparison, when no index on nested table column, TABLE ACCESS FULL on TEST_TABLE_NT is used with table index SYS_C00144532.

When there is Index on (column_value), index TEST_TABLE_NT_INDX and SYS_C00144532 are used, but still need TABLE ACCESS BY INDEX ROWID BATCHED on TEST_TABLE_NT.

When there is Index on (column_value, nested_table_id), index TEST_TABLE_NT_INDX and SYS_C00144532 are used, no more TEST_TABLE_NT access.

"Disk file operations I/O" with (FileOperation: 8, fileno: 0, filetype: 8) Test

In this blog, we will make a test to demonstrate Oracle Wait Event "Disk file operations I/O" with
(P1/FileOperation: 8, P2/fileno: 0, P3/filetype: 8).

Note: Tested in Oracle 19.27

1. Test Setup

The database auditing is configured as follows:

NAME                      TYPE        VALUE
------------------------- ----------- --------------------------------
audit_file_dest           string      /home/oracle/suk/slow_dir3/adump
audit_sys_operations      boolean     TRUE
audit_trail               string      OS

audit_file_dest is mounted on a slow file system with 5000 ms read/write delay.
(See Blog: Oracle Database Stuck on DB Writer Wait Event: "oradebug request completion" ).

2. Wait Event Tracing

2.1 10046 Trace

We start system-wide 10046 trace by:

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

2.2 strace

Find TNS listener process and strace it:

oracle@db3audit:db3audit > ps -efl |grep tns
  0 S oracle    728055       1  0  80   0 - 40462 do_epo Sep27 ?        00:00:15 /orabin/app/oracle/product/19.27.0.0./bin/tnslsnr LISTENER_oradb3audit             

oracle@db3audit:db3audit >  strace -ttTfy -p 728055 -o strace_output_2.txt

2.3 Sqlplus Session

Now we open a Sqlplus session by

SQL > sqlplus k/k@db3audit

2.4 10046 Trace Output

Trace file /orabin/app/oracle/admin/db3audit/diag/rdbms/db3audit/db3audit/trace/db3audit_ora_1072963.trc
Build label:    RDBMS_19.27.0.0.0DBRU_LINUX.X64_250331
Oracle process number: 57
Unix process pid: 1072963, image: oracle@db3audit
*** MODULE NAME:(sqlplus.exe) 2025-12-23T10:11:56.689481+01:00

*** 2025-12-23T10:12:01.847101+01:00
WAIT #0: nam='Disk file operations I/O' ela= 5100597 FileOperation=8 fileno=0 filetype=8 obj#=-1 tim=18667193313139

It shows "ela= 5100597" microseconds with "FileOperation=8 fileno=0 filetype=8".
So we can say that in this case, "FileOperation=8" is file open, and "filetype=8" is OS Audit file.

After test, stop 10046 trace by (otherwise too many trace files):

  alter system set events '10046 trace name context off';

2.5 strace Output

We can see that Sqlplus Process 1072963 was spawned by TNS Process 728055:

oracle@db3audit:db3audit > strace -ttTfy -p 728055 -o strace_output_3.txt
./strace: Process 728055 attached
./strace: Process 1072962 attached
./strace: Process 1072963 attached

Open strace_output_2.txt, it shows:

1072963 10:11:56.746551 openat(AT_FDCWD, "/home/oracle/suk/slow_dir3/adump/db3audit_ora_1072963_20251223101156746537740094.aud", O_RDWR|O_CREAT|O_EXCL, 0640) = 10
                                 <5.098572>
1072963 10:12:01.845204 write(10, "Audit file ", 11) = 11 <0.000058>
1072963 10:12:01.845315 write(10, "/home/oracle/suk/slow_dir3/adump"..., 84) = 84 <0.000023>
1072963 10:12:01.845372 write(10, "\n", 1) = 1 <0.000022>
1072963 10:12:01.845433 write(10, "Oracle Database 19c Enterprise E"..., 90) = 90 <0.000021>
1072963 10:12:01.845482 write(10, "\n", 1) = 1 <0.000020>
1072963 10:12:01.845533 write(10, "Build label:    RDBMS_19.27.0.0."..., 54) = 54 <0.000020>
1072963 10:12:01.845582 write(10, "\n", 1) = 1 <0.000020>
1072963 10:12:01.845639 write(10, "ORACLE_HOME:    /orabin/app/orac"..., 64) = 64 <0.000020>
1072963 10:12:01.845689 write(10, "System name:\tLinux\n", 19) = 19 <0.000020>
1072963 10:12:01.845738 write(10, "Node name:\tdb3audit\n", 20) = 20 <0.000021>
1072963 10:12:01.845796 write(10, "Release:\t4.18.0-372.9.1.el8.x86_"..., 35) = 35 <0.000020>
1072963 10:12:01.845845 write(10, "Version:\t#1 SMP Fri Apr 15 22:12"..., 45) = 45 <0.000021>
1072963 10:12:01.845895 write(10, "Machine:\tx86_64\n", 16) = 16 <0.000021>
1072963 10:12:01.845953 write(10, "CLID:\tP\n", 8) = 8 <0.000021>
1072963 10:12:01.846010 write(10, "Instance name: db3audit\n", 24) = 24 <0.000062>
1072963 10:12:01.846105 write(10, "Instance number: 1\n", 19) = 19 <0.000020>
1072963 10:12:01.846161 write(10, "Database name: db3audit ", 24) = 24 <0.000023>
1072963 10:12:01.846215 write(10, "\n", 1) = 1 <0.000020>
1072963 10:12:01.846264 write(10, "Database unique name: db3audit ", 31) = 31 <0.000020>
1072963 10:12:01.846313 write(10, "\n", 1) = 1 <0.000020>
1072963 10:12:01.846388 write(10, "Database id: 1059538969\n", 24) = 24 <0.000021>
1072963 10:12:01.846442 write(10, "Database role: PRIMARY\n", 23) = 23 <0.000020>
1072963 10:12:01.846491 write(10, "Redo thread mounted by this inst"..., 40) = 40 <0.000020>
1072963 10:12:01.846541 write(10, "Oracle process number: 57\n", 26) = 26 <0.000021>
1072963 10:12:01.846592 write(10, "Unix process pid: 1072963, image"..., 49) = 49 <0.000019>
1072963 10:12:01.846640 write(10, "\n", 1) = 1 <0.000020>
1072963 10:12:01.846689 write(10, "\n", 1) = 1 <0.000020>
1072963 10:12:01.846762 write(10, "Tue Dec 23 10:12:01 2025 +01:00\n", 32) = 32 <0.000021>
1072963 10:12:01.846812 write(10, "LENGTH: \"408\"", 13) = 13 <0.000021>
1072963 10:12:01.846860 write(10, "\n", 1) = 1 <0.000020>
1072963 10:12:01.846909 write(10, "SESSIONID:[9] \"102147891\" ENTRYI"..., 406) = 406 <0.000030>
1072963 10:12:01.846973 write(10, "\n", 1) = 1 <0.000020>
1072963 10:12:01.847023 write(10, "\n", 1) = 1 <0.000021>

The above output shows that openat "/home/oracle/suk/slow_dir3/adump/db3audit_ora_1072963_20251223101156746537740094.aud" returns FD = 10,
and it takes 5.098572 seconds from 10:11:56 to 10:12:01.

Look OS audit file, its name is composed by DB SID: db3audit, Unix process pid: 1072963, and creating timestamp: 20251223101156, which is 2025-12-23 10:11:56.
In the OS audit file, the first timestamp "10:12:01" is recorded for session LOGON, which has about 5 seconds delay (from 10:11:56 to 10:12:01),
and the second timestamp "10:28:44" is for session LOGOFF. Here the full audit file:

oracle@db3audit:db3audit > cat /home/oracle/suk/slow_dir3/adump/db3audit_ora_1072963_20251223101156746537740094.aud
Audit file /home/oracle/suk/slow_dir3/adump/db3audit_ora_1072963_20251223101156746537740094.aud
Oracle Database 19c Enterprise Edition Release 19.0.0.0.0 - Production
Version 19.27.0.0.0
Build label:    RDBMS_19.27.0.0.0DBRU_LINUX.X64_250331
ORACLE_HOME:    /orabin/app/oracle/product/19.27.0.0.
System name:	Linux
Node name:	db3audit
Release:	4.18.0-372.9.1.el8.x86_64
Version:	#1 SMP Fri Apr 15 22:12:19 EDT 2022
Machine:	x86_64
CLID:	P
Instance name: db3audit
Instance number: 1
Database name: db3audit 
Database unique name: db3audit 
Database id: 1059538969
Database role: PRIMARY
Redo thread mounted by this instance: 1
Oracle process number: 57
Unix process pid: 1072963, image: oracle@db3audit

Tue Dec 23 10:12:01 2025 +01:00
LENGTH: "408"
SESSIONID:[9] "102147891" ENTRYID:[1] "1" STATEMENT:[1] "1" USERID:[1] "K" USERHOST:[16] "SYS\MACHINE12345" TERMINAL:[12] "MACHINE12345" ACTION:[3] "100" RETURNCODE:[1] "0" COMMENT$TEXT:[126] "Authenticated by: DATABASE;AUTHENTICATED IDENTITY: K; Client address: (ADDRESS=(PROTOCOL=tcp)(HOST=10.44.105.100)(PORT=50160))" OS$USERID:[7] "KS00383" DBID:[10] "1059538969" PRIV$USED:[1] "5" CURRENT_USER:[1] "K"

Thu Dec 23 10:28:44 2025 +01:00
LENGTH: "231"
SESSIONID:[9] "102147891" ENTRYID:[1] "1" USERID:[1] "K" ACTION:[3] "101" RETURNCODE:[1] "0" LOGOFF$PREAD:[5] "35037" LOGOFF$LREAD:[6] "166495" LOGOFF$LWRITE:[1] "4" LOGOFF$DEAD:[1] "0" DBID:[10] "1059538969" SESSIONCPU:[3] "258"

Here the process lsof output showing FD 10u for audit file:

oracle@db3audit:db3audit > lsof -p 1072963 |grep aud
  COMMAND       PID   USER   FD      TYPE             DEVICE    SIZE/OFF       NODE NAME
  oracle_10 1072963 oracle   10u      REG             253,2         1167         77 /home/oracle/suk/slow_dir3/adump/db3audit_ora_1072963_20251223101156746537740094.aud

2.6 v$active_session_history and Oracle Performance Views

select sample_time, program, event, p1, p2, p3, p1text, p2text, p3text
  from v$active_session_history t 
 where event = 'Disk file operations I/O' and p1=8 and p2=0 and p3=8 
   and sample_time >= timestamp '2025-12-28 10:31:22.549'
 order by t.sample_time;
 
 
  SAMPLE_TIME         PROGRAM      EVENT                     P1  P2  P3  P1TEXT         P2TEXT  P3TEXT
  ------------------- ------------ ------------------------ --- --- --- --------------- ------- --------
  2025-12-22 10:11:57 sqlplus.exe  Disk file operations I/O   8   0   8  FileOperation  fileno  filetype
  2025-12-22 10:11:58 sqlplus.exe  Disk file operations I/O   8   0   8  FileOperation  fileno  filetype
  2025-12-22 10:11:59 sqlplus.exe  Disk file operations I/O   8   0   8  FileOperation  fileno  filetype
  2025-12-22 10:12:00 sqlplus.exe  Disk file operations I/O   8   0   8  FileOperation  fileno  filetype
  2025-12-22 10:12:01 sqlplus.exe  Disk file operations I/O   8   0   8  FileOperation  fileno  filetype


select filetype_id, filetype_name, function_id, function_name, sum(small_read_reqs), sum(small_write_reqs), sum(number_of_waits), sum(wait_time) 
from  v$iostat_function_detail 
where filetype_id = 8
group by filetype_id, filetype_name, function_id, function_name
order by filetype_id, function_id;

  FILETYPE_ID FILETYPE FUNCTION_ID FUNCTION_NAME        SUM(SMALL_READ_REQS) SUM(SMALL_WRITE_REQS) SUM(NUMBER_OF_WAITS) SUM(WAIT_TIME)
  ----------- -------- ----------- -------------------- -------------------- --------------------- -------------------- --------------
            8 Other              2 LGWR                                    0                     0               136398          50459
            8 Other              7 Recovery                                0                     0                    1              0
            8 Other              8 Buffer Cache Reads                      0                     0                  245            283
            8 Other             13 Others                                  0                     0               273272         120046


-- also in v$session_event, dba_hist_system_event
select event, total_waits, time_waited, time_waited_micro, event_id, wait_class_id, wait_class#, wait_class from v$system_event 
 where event = 'Disk file operations I/O';

  EVENT                     TOTAL_WAITS TIME_WAITED TIME_WAITED_MICRO   EVENT_ID WAIT_CLASS_ID WAIT_CLASS# WAIT_CLASS
  ------------------------- ----------- ----------- ----------------- ---------- ------------- ----------- ----------
  Disk file operations I/O        67226       28853         288534923  166678035    1740759767           8 User I/O

-- no rows in v$iostat_file
select * from v$iostat_file where filetype_id = 8;
	no rows selected

2.7 AWR and ASH

TOP Wait Event "Disk file operations I/O" in AWR and ASH looks like:

Top 10 Foreground Events by Total Wait Time

Event	Waits	Total Wait Time (sec)	Avg Wait	% DB time	Wait Class
Disk file operations I/O	2,706	11.4	4.20ms	35.4	User I/O

Top Event P1/P2/P3 Values

Event	% Event	P1, P2, P3 Values	% Activity	Parameter 1	Parameter 2	Parameter 3
Disk file operations I/O	45.45	"8","0","8"	45.45	FileOperation	fileno	filetype

3. bpftrace

Start following bpftrace script and then open a Sqlplus session.

The script output shows file open (sys_enter_openat) "Duration (us): 5089844", and its Oracle CallStack.

BPFTRACE_STRLEN=128 bpftrace -e 'tracepoint:syscalls:sys_enter_openat /strncmp("oracle", comm, 6) == 0 && strncmp("/home/oracle/suk/slow_dir3", str(args->filename), 26) == 0 / {
               time("%H:%M:%S "); @start[tid] = nsecs;
               printf("comm: %s, pid: %d, tid: %d, __syscall_nr: %d, dfd: %d, flags: %d, mode: %d \n============== filename: %s =======\n", 
                       comm, pid, tid, args->__syscall_nr, args->dfd, args->flags, args->mode, str(args->filename)); }
             tracepoint:syscalls:sys_exit_openat  /strncmp("oracle", comm, 6) == 0 && @start[tid] / {
               time("%H:%M:%S "); @fd = (uint64)args->ret; $duration_us = ( nsecs - @start[tid] ) / 1000; 
               printf("===================== File Descriptor: %d, Duration (us): %d ===================== \n", @fd, $duration_us); 
               printf("CallStack: %s\n", ustack(30));
               delete(@start[tid]); }
             tracepoint:syscalls:sys_enter_write /strncmp("oracle", comm, 6) == 0 && @fd == args->fd / {
               time("%H:%M:%S "); $length = args->count; $line = str(args->buf);
               printf("[pid: %d, fd: %d, length: %3d] %s \n", pid, args->fd, $length, $line); }'

13:12:01 comm: oracle_1086521_, pid: 1086521, tid: 1086521, __syscall_nr: 257, dfd: -100, flags: 194, mode: 416
============== filename: /home/oracle/suk/slow_dir3/adump/db3audit_ora_1086521_20251228131201036719868850.aud =======
13:12:06 ===================== File Descriptor: 8, Duration (us): 5089844 =====================
CallStack:
        __open+79
        szaudinit+506
        szaud+1416
        szaud_mkrec+1774
        audios+2936
        audins+13805
        audlon0+1983
        audlon+526
        auddft_internal+2853
        audStatement+1168
        kpolnb+4729
        kpoauth+1917
        opiodr+1264
        ttcpip+1219
        opitsk+1925
        opiino+939
        opiodr+1264
        opidrv+1094
        sou2o+165
        opimai_real+422
        ssthrdmain+417
        main+256
        __libc_start_main+243
        0x5541f689495641d7
        
13:12:06 [pid: 1086521, fd: 8, length:  11] Audit file
13:12:06 [pid: 1086521, fd: 8, length:  84] /home/oracle/suk/slow_dir3/adump/db3audit_ora_1086521_20251228131201036719868850.aud
13:12:06 [pid: 1086521, fd: 8, length:  90] Oracle Database 19c Enterprise Edition Release 19.0.0.0.0 - Production
Version 19.27.0.0.0
......
13:12:06 [pid: 1086521, fd: 8, length: 406] SESSIONID:[9] "102148556" ENTRYID:[1] "1" STATEMENT:[1] "1" USERID:[1] "K" USERHOST:[16] "SYS\MACHINE12345" TERMINAL:[12] "MACH

In above test, Audit Parameter: audit_syslog_level is not set, and audit files (and audit info) are created under directory audit_file_dest.
If we set "audit_syslog_level='LOCAL0.INFO'" and re-start DB, audit info is written into /var/log/messages (configured in /etc/rsyslog.conf).

alter system set audit_syslog_level='LOCAL0.INFO' scope=spfile;
--DB re-start

-- reset by alter system reset audit_syslog_level scope=spfile;

$ cat /etc/rsyslog.conf
 
  # Log anything (except mail) of level info or higher.
  # Don't log private authentication messages!
  *.info;mail.none;authpriv.none;cron.none                /var/log/messages

If /etc/rsyslog.conf is configured with two lines with “info” as follows, then same Oracle messages are written into both files simultaneously.

local0.info;mail.none;authpriv.none;cron.none           /var/log/messagesl0
*.info;mail.none;authpriv.none;cron.none                /var/log/messages

If /etc/rsyslog.conf is configured with a higher severity. e.g, "warn", rsyslog will capture everything at the warning level plus all severities above it (Errors, Critical events, Alerts, and Emergencies).

*.warn;mail.none;authpriv.none;cron.none                /var/log/messages

4. Related Work

Blog: Disk file operations I/O (July 17, 2024 Dinesh Bandelkar) shows one case of "Disk file operations I/O" with (FileOperation: 8, fileno: 0, filetype: 8) when Oracle Redaction is OS audited.

Blog: Disk file operations I/O (December 21, 2020) shows ASH snapper to monitor such wait event.

Three Oracle cursor error Tests

In this Blog, we will test 3 Oracle cursor errors:

  ORA-01001: invalid cursor
  ORA-06511: PL/SQL: cursor already open
  ORA-21780: Maximum number of object durations exceeded

Note: Tested in Oracle 19.28

1. Test Setup

drop table test_tab;

create table test_tab as select level id, 'Name_'||level name from dual connect by level <= 10;

create or replace package test_cursor_errors is
  cursor p_curs(p_id number) is select * from test_tab where id = p_id;
  p_ORA_21780_Maximum number := 0;
  procedure test_ORA_01001(p_id number, p_recur_depth number);
  procedure test_ORA_06511(p_id number);
  procedure test_ORA_21780(p_id number, p_recur_depth number);
end;
/

create or replace package body test_cursor_errors is
  procedure prt(p_recur_depth number, text varchar2) is
  begin
    dbms_output.put_line(rpad(chr(32), 4*p_recur_depth, chr(32))||text);
  end;
  
  --ORA-01001: invalid cursor
  procedure test_ORA_01001(p_id number, p_recur_depth number) is
    l_name varchar2(1000);
    l_chg  integer := 1;  
  begin
    prt(p_recur_depth, '1-1 Start --- p_id = '||p_id||', recur_depth = '||p_recur_depth||', curs%isopen = '||bool_to_char(p_curs%isopen));

    if p_curs%isopen then
      prt(p_recur_depth, '2-1 Close p_curs  --- p_id = '||p_id||', curs%isopen = '||bool_to_char(p_curs%isopen));
      close p_curs;   --Close previous Implicit Cursor
      prt(p_recur_depth, '2-2 p_curs Closed --- p_id = '||p_id||', curs%isopen = '||bool_to_char(p_curs%isopen));
    end if;
    
    for c in p_curs(p_id) loop
      l_name :=c.name;
      prt(p_recur_depth, '3-1 Recur Entry --- p_id = '||p_id||', Implicit Cursor Opened'||', curs%isopen = '||bool_to_char(p_curs%isopen));
      test_ORA_01001(p_id - l_chg, p_recur_depth + 1);
      prt(p_recur_depth, '3-2 Recur Exit  --- p_id = '||p_id||', Close  Implicit Cursor'||', curs%isopen = '||bool_to_char(p_curs%isopen));
    end loop;

    if p_curs%isopen then
      prt(p_recur_depth, '4-1 Close p_curs --- p_id = '||p_id||', curs%isopen = '||bool_to_char(p_curs%isopen));
      close p_curs;
      prt(p_recur_depth, '4-2 p_curs Closed  --- p_id = '||p_id||', curs%isopen = '||bool_to_char(p_curs%isopen));
    end if;
   
    prt(p_recur_depth, '1-2 End --- p_id = '||p_id||', recur_depth = '||p_recur_depth||', curs%isopen = '||bool_to_char(p_curs%isopen));
  end;

  --ORA-06511: PL/SQL: cursor already open
  procedure test_ORA_06511 (p_id number) is
    l_name varchar2(1000);
  begin
    for c in p_curs(p_id) loop
      dbms_output.put_line('1. Loop p_id = '||p_id||', curs%isopen = '||bool_to_char(p_curs%isopen));
      l_name :=c.name;
      for c in p_curs(p_id -1) loop
        dbms_output.put_line('2. Loop p_id = '||p_id||', curs%isopen = '||bool_to_char(p_curs%isopen));
        l_name :=c.name;
      end loop;
    end loop;
  end;
  
  --ORA-21780: Maximum number of object durations exceeded. ORA_21780_Maximum = 65325 (Oracle 19.28), ORA_21780_Maximum = 65318 (Oracle 19.10)
  procedure test_ORA_21780 (p_id number, p_recur_depth number) is
    l_name varchar2(1000);
    l_chg  integer := 0;  
  begin
    if p_curs%isopen then
      close p_curs;   --Close previous Implicit Cursor
    end if;
    
    for c in p_curs(p_id) loop
      begin
	      l_name := c.name;
	      p_ORA_21780_Maximum := greatest(p_ORA_21780_Maximum, p_recur_depth + 1);
	      test_ORA_21780(p_id - l_chg, p_recur_depth + 1);
	    end;
    end loop;

    if p_curs%isopen then
      close p_curs;
    end if;
  end;
end;
/

2. Test Run

exec test_cursor_errors.test_ORA_01001(2, 1);

exec test_cursor_errors.test_ORA_06511(2);

begin
  test_cursor_errors.p_ORA_21780_Maximum := 0;
  test_cursor_errors.test_ORA_21780(2, 1);
  exception when others then
    dbms_output.put_line('ORA_21780_Maximum = '||test_cursor_errors.p_ORA_21780_Maximum);
    raise;
end;
/

3. Test Outcome

3.1. ORA-01001: invalid cursor

Here the indentation print of recursive calls:

SQL > exec test_cursor_errors.test_ORA_01001(2, 1);

    1-1 Start --- p_id = 2, recur_depth = 1, curs%isopen = false
    3-1 Recur Entry --- p_id = 2, Implicit Cursor Opened, curs%isopen = true
        1-1 Start --- p_id = 1, recur_depth = 2, curs%isopen = true
        2-1 Close p_curs  --- p_id = 1, curs%isopen = true
        2-2 p_curs Closed --- p_id = 1, curs%isopen = false
        3-1 Recur Entry --- p_id = 1, Implicit Cursor Opened, curs%isopen = true
            1-1 Start --- p_id = 0, recur_depth = 3, curs%isopen = true
            2-1 Close p_curs  --- p_id = 0, curs%isopen = true
            2-2 p_curs Closed --- p_id = 0, curs%isopen = false
            1-2 End --- p_id = 0, recur_depth = 3, curs%isopen = false
        3-2 Recur Exit  --- p_id = 1, Close  Implicit Cursor, curs%isopen = false
BEGIN test_cursor_errors.test_ORA_01001(2, 1); END;

*
ERROR at line 1:
ORA-01001: invalid cursor
ORA-06512: at "K.TEST_CURSOR_ERRORS", line 20
ORA-01001: invalid cursor
ORA-06512: at "K.TEST_CURSOR_ERRORS", line 20
ORA-01001: invalid cursor
ORA-06512: at "K.TEST_CURSOR_ERRORS", line 20
ORA-06512: at "K.TEST_CURSOR_ERRORS", line 20
ORA-06512: at "K.TEST_CURSOR_ERRORS", line 23
ORA-06512: at "K.TEST_CURSOR_ERRORS", line 23
ORA-06512: at line 1
Elapsed: 00:00:00.00

In Oracle. cursor for loop starts with one implicit cursor open and finishes with one implicit cursor close.
In above test, we have closed cursor in Step 2, and in Step 3-2 of cursor for loop Exit,
Oracle wants to close the implicit cursor again, and throws "ORA-01001: invalid cursor".
("invalid cursor" signifies error when closing an already closed cursor).

Here 10046 trace file with "err=1001" and 'SQL*Net break/reset to client':

alter session set events '10046 trace name context forever, level 12';  
exec test_cursor_errors.test_ORA_01001(2, 1);
alter session set events '10046 trace name context off';


=====================
PARSING IN CURSOR #140151808236992 len=52 dep=0 uid=49 oct=47 lid=49 tim=6880035008376 hv=4277818309 ad='9d4835d0' sqlid='7g4pxwzzgnny5'
BEGIN test_cursor_errors.test_ORA_01001(2, 1); END;

END OF STMT
PARSE #140151808236992:c=15,e=15,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=0,tim=6880035008375
=====================
PARSING IN CURSOR #140151808572984 len=38 dep=1 uid=49 oct=3 lid=49 tim=6880035009339 hv=1133886660 ad='77b15960' sqlid='c8b161d1tbg64'
SELECT * FROM TEST_TAB WHERE ID = :B1 
END OF STMT
PARSE #140151808572984:c=558,e=848,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=1,plh=0,tim=6880035009339
BINDS #140151808572984:

 Bind#0
  oacdty=02 mxl=22(21) mxlc=00 mal=00 scl=00 pre=00
  oacflg=03 fl2=1206001 frm=00 csi=00 siz=24 off=0
  kxsbbbfp=7f77a2c284c0  bln=22  avl=02  flg=05
  value=2
EXEC #140151808572984:c=932,e=1170,p=0,cr=1,cu=0,mis=0,r=0,dep=1,og=1,plh=3962208483,tim=6880035010574
FETCH #140151808572984:c=65,e=65,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=1,plh=3962208483,tim=6880035010672
STAT #140151808572984 id=1 cnt=1 pid=0 pos=1 obj=5983275 op='TABLE ACCESS FULL TEST_TAB (cr=3 pr=0 pw=0 str=1 time=58 us cost=3 size=315 card=3)'
CLOSE #140151808572984:c=0,e=0,dep=1,type=3,tim=6880035010802
BINDS #140151808572984:

 Bind#0
  oacdty=02 mxl=22(21) mxlc=00 mal=00 scl=00 pre=00
  oacflg=03 fl2=1206001 frm=00 csi=00 siz=24 off=0
  kxsbbbfp=7f77a2c284c0  bln=22  avl=02  flg=05
  value=1
EXEC #140151808572984:c=55,e=55,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=3962208483,tim=6880035010880
FETCH #140151808572984:c=18,e=18,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=1,plh=3962208483,tim=6880035010927
CLOSE #140151808572984:c=0,e=0,dep=1,type=3,tim=6880035010963
BINDS #140151808572984:

 Bind#0
  oacdty=02 mxl=22(21) mxlc=00 mal=00 scl=00 pre=00
  oacflg=03 fl2=1206001 frm=00 csi=00 siz=24 off=0
  kxsbbbfp=7f77a2d11a98  bln=22  avl=01  flg=05
  value=0
EXEC #140151808572984:c=62,e=62,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=3962208483,tim=6880035011043
FETCH #140151808572984:c=13,e=13,p=0,cr=3,cu=0,mis=0,r=0,dep=1,og=1,plh=3962208483,tim=6880035011068
CLOSE #140151808572984:c=0,e=0,dep=1,type=3,tim=6880035011100
EXEC #140151808236992:c=2237,e=2765,p=0,cr=10,cu=0,mis=0,r=0,dep=0,og=1,plh=0,tim=6880035011182
ERROR #140151808236992:err=1001 tim=6880035011196
WAIT #140151808236992: nam='SQL*Net break/reset to client' ela= 3 driver id=1413697536 break?=1 p3=0 obj#=528 tim=6880035011230
WAIT #140151808236992: nam='SQL*Net break/reset to client' ela= 5553 driver id=1413697536 break?=0 p3=0 obj#=528 tim=6880035016797
WAIT #140151808236992: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=528 tim=6880035016842
WAIT #140151808236992: nam='SQL*Net message from client' ela= 711 driver id=1413697536 #bytes=1 p3=0 obj#=528 tim=6880035017582

3.2 ORA-06511: PL/SQL: cursor already open

In this test, the same cursor opened twice, hence "ORA-06511: PL/SQL: cursor already open".

SQL > exec test_cursor_errors.test_ORA_06511(2);

1. Loop p_id = 2, curs%isopen = true
BEGIN test_cursor_errors.test_ORA_06511(2); END;

*
ERROR at line 1:
ORA-06511: PL/SQL: cursor already open
ORA-06512: at "K.TEST_CURSOR_ERRORS", line 2
ORA-06512: at "K.TEST_CURSOR_ERRORS", line 43
ORA-06512: at "K.TEST_CURSOR_ERRORS", line 43
ORA-06512: at line 1

Here 10046 trace file with "err=6511" and 'SQL*Net break/reset to client':

alter session set events '10046 trace name context forever, level 12';  
exec test_cursor_errors.test_ORA_06511(2);
alter session set events '10046 trace name context off';


=====================
PARSING IN CURSOR #140498746628816 len=49 dep=0 uid=49 oct=47 lid=49 tim=6880557312015 hv=243630832 ad='72f8ab68' sqlid='1cu3xcc78b0rh'
BEGIN test_cursor_errors.test_ORA_06511(2); END;

END OF STMT
PARSE #140498746628816:c=50,e=51,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=0,tim=6880557312014
=====================
PARSING IN CURSOR #140498750073448 len=38 dep=1 uid=49 oct=3 lid=49 tim=6880557312222 hv=1133886660 ad='77b15960' sqlid='c8b161d1tbg64'
SELECT * FROM TEST_TAB WHERE ID = :B1 
END OF STMT
PARSE #140498750073448:c=77,e=77,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=3962208483,tim=6880557312222
BINDS #140498750073448:

 Bind#0
  oacdty=02 mxl=22(21) mxlc=00 mal=00 scl=00 pre=00
  oacflg=03 fl2=1206001 frm=00 csi=00 siz=24 off=0
  kxsbbbfp=7fc869ff9388  bln=22  avl=02  flg=05
  value=2
EXEC #140498750073448:c=52,e=52,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=3962208483,tim=6880557312308
FETCH #140498750073448:c=62,e=62,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=1,plh=3962208483,tim=6880557312393
STAT #140498750073448 id=1 cnt=1 pid=0 pos=1 obj=5983275 op='TABLE ACCESS FULL TEST_TAB (cr=3 pr=0 pw=0 str=1 time=58 us cost=3 size=315 card=3)'
CLOSE #140498750073448:c=0,e=1,dep=1,type=3,tim=6880557312532
EXEC #140498746628816:c=512,e=513,p=0,cr=3,cu=0,mis=0,r=0,dep=0,og=1,plh=0,tim=6880557312562
ERROR #140498746628816:err=6511 tim=6880557312573
WAIT #140498746628816: nam='SQL*Net break/reset to client' ela= 2 driver id=1413697536 break?=1 p3=0 obj#=528 tim=6880557312605
WAIT #140498746628816: nam='SQL*Net break/reset to client' ela= 696 driver id=1413697536 break?=0 p3=0 obj#=528 tim=6880557313324
WAIT #140498746628816: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=528 tim=6880557313347
WAIT #140498746628816: nam='SQL*Net message from client' ela= 5220 driver id=1413697536 #bytes=1 p3=0 obj#=528 tim=6880557318586

3.3 ORA-21780: Maximum number of object durations exceeded

In this test, we make an infinitive recursive calls, in each call, open the same cursor,
then hit "ORA-21780: Maximum number of object durations exceeded".
(The only difference of this test to "ORA-01001" code is that "l_chg = 0" instead of "l_chg = 1").

The test shows that the maximum value is around 65339.

SQL > begin
        test_cursor_errors.p_ORA_21780_Maximum := 0;
        test_cursor_errors.test_ORA_21780(2, 1);
        exception when others then
          dbms_output.put_line('ORA_21780_Maximum = '||test_cursor_errors.p_ORA_21780_Maximum);
          raise;
      end;
      /
            
ORA_21780_Maximum = 65339
begin
*
ERROR at line 1:
ORA-01001: invalid cursor
ORA-06512: at "K.TEST_CURSOR_ERRORS", line 59
ORA-01001: invalid cursor
ORA-06512: at "K.TEST_CURSOR_ERRORS", line 59
ORA-01001: invalid cursor
ORA-06512: at "K.TEST_CURSOR_ERRORS", line 59
ORA-01001: invalid cursor
ORA-06512: at "K.TEST_CURSOR_ERRORS", line 59
ORA-01001: invalid cursor
ORA-06512: at "K.TEST_CURSOR_ERRORS", line 59
ORA-01001: invalid cursor
ORA-06512: at "K.TEST_CURSOR_ERRORS", line 59
ORA-01001: invalid cursor
ORA-06512: at "K.TEST_CURSOR_ERRORS", line 59
ORA-21780: Maximum number of object durations exceeded.
ORA-06512: at "K.TEST_CURSOR_ERRORS", line 51
ORA-06512: at "K.TEST_CURSOR_ERRORS", line 63

Elapsed: 00:00:03.00

4. Pass Cursor as Integer Input

In one application, client program wants to receive cursor input represented by an integer.
Here is one implementation:

create or replace package test_cursor_number as 
  --p_recordset     sys_refcursor;  -- PLS-00994: Cursor Variables cannot be declared as part of a package
  function get_id_cur (p_id in test_tab.id%type) return integer;
end;
/

create or replace package body test_cursor_number as 
  function get_id_cur (p_id in test_tab.id%type) return integer as
    l_cursor_number   integer;
  begin
    l_cursor_number := dbms_sql.open_cursor;
    dbms_sql.parse (l_cursor_number, 'SELECT id, name from test_tab where id <= '||p_id, dbms_sql.NATIVE);
    return l_cursor_number;
  end;
end;
/

declare
  l_cursor_number   integer;
  l_return          integer;
  l_cursor          sys_refcursor;
  l_id              test_tab.id%type;
  l_name            test_tab.name%type;
begin
  l_cursor_number := test_cursor_number.get_id_cur(p_id => 3);
  dbms_output.put_line('cursor_number = '||l_cursor_number);
  
  l_return := dbms_sql.execute (l_cursor_number);
  dbms_output.put_line('execute return = '||l_return);
  
  l_cursor := dbms_sql.to_refcursor (l_cursor_number);
  --dbms_output.put_line('l_cursor = '||l_cursor);      
  loop
    fetch l_cursor
    into l_id, l_name;

    exit when l_cursor%notfound;
    dbms_output.PUT_LINE (l_id || ' | ' || l_name);
  end loop;

  close l_cursor;
end;
/

-- Test Output
cursor_number = 357706397
execute return = 0
1 | Name_1
2 | Name_2
3 | Name_3

By the way, Oracle Magazine On Connection Pools, Cursor Differentiation, and Optimal Ordering (By Tom Kyte May/June 2012) discussed the regular cursor vs. ref cursor, and showed the performance difference.