Monday, September 16, 2013

Execution Switching between "direct path read" and "db file scattered read"

Oracle’s locking principle: blocking is only eligible among writers. Reader never blocks writer, and writer never blocks reader.

    What happens when underlying table is changed during "direct path read" ?

As we know, "direct path read" bypasses Buffer Cache, and directly fetches data from disk files into session private PGA. When data is modified, the disk files can contain the new data which is later than the starting point of already running query. In order to read the consistent version of data, the query has to visit Buffer Cache to reconstruct them by applying UNDO. Thus it has to use a different accessing approach.

Continuing from the example of Blog: Impact of Direct Reads on Delayed Block Cleanouts, we add a few more steps to demonstrate that Oracle dynamically adjusts the access methods during query execution.

The test is performed on Oracle 11.2.0.3.0 with db_cache_size = 304M.

At first, start 3 Oracle Sessions:
    Session_1: monitor sesssion
  Session_2: select sesssion
  Session_3: delete sesssion


In Session_1, prepare test by:
 drop table t1;
 drop table t2;
 create table t1 (id number, pad varchar2(500)) ;
 insert into t1 select rownum, rpad('*', 500, '*') from dual connect by level <= 140000;
 commit;
 create table t2 as select rownum id from dual connect by level < = 100000;
 alter system flush buffer_cache;


In Session_2, run query:
   select /*+ leading(t2) use_nl(t1) */ count(*) from t1, t2;

Back to Session_1, run query:
  select event, p1text, p1, p2text, p2, p3text, p3, row_wait_obj#, sql_exec_id, seq#
   from v$session where sid = &sid_2;

 
We can see the event: "direct path read" on table T1.

To understand the internal implementation, run
 select file#, block#, class#
   from v$bh b, dba_objects d
  where object_name = 'T1' and objd = data_object_id and b.status = 'xcur' and class# != 1;


which lists the special blocks loaded in Buffer Cache:

  FILE#   BLOCK#  CLASS#
  -----  -------  ------
      6  1349410       4 ('segment header')
      6  1364513       7 ('extent map')

  
The reason of "direct path read" still reads these blocks into Buffer Cache is to let all sessions share them. And probably it is acting as a central synchronizing role.

If we make a block dump of above blocks, we can see all the extents, which equals to:
  select extents from dba_segments where segment_name = 'T1';

The dumps also include something like: objq, objaq, which are often mentioned in the discussion of "direct path read".

Run one more query:
   select dbms_rowid.rowid_block_number(rowid) from t1 where id = 600;

to get the block number of the row to be deleted in Session_3:
    1369733

Go to Session_3, delete one row:
  delete from t1 where id = 600;

Back again to Session_1, run query again:
  select event, p1text, p1, p2text, p2, p3text, p3, row_wait_obj#, sql_exec_id, seq#
   from v$session where sid = &sid_2;


now we see the event: "db file scattered read" or "db file sequential read" on table T1.

Run query:
 select event, p1, p2, p3, d.object_name, sql_exec_id, seq#
 from   v$active_session_history t, dba_objects d
 where  d.object_name in ('T1', 'T2')
     and t.current_obj# = d.data_object_id
     and session_id = &sid_2 and session_serial# = &serial_2
 group by d.object_name, sql_exec_id, seq#, event, p1, p2, p3
 order by min(sample_time);


we get:

 EVENT                   P1      P2 P3 OBJECT_NAME  SQL_EXEC_ID   SEQ#
 ---------------------- --- ------- -- ------------ ----------- ------
 direct path read         6 1369216 32 T1              16777216  39127
 db file scattered read   6 1369728 16 T1              16777216  49540


If we go back again to Session_3, make a commit or rollback, Session_2 will not switch back to "direct path read".

However, if we flush out all dirty buffers by:
    alter system flush buffer_cache;
 or
    alter system checkpoint;

Session_2 will switch back to "direct path read".

Query:
 select event, p1, p2, p3, d.object_name, sql_exec_id, seq#
 from   v$active_session_history t, dba_objects d
 where  d.object_name in ('T1', 'T2')
     and t.current_obj# = d.data_object_id
     and session_id = &sid and session_serial# = &serial
 group by d.object_name, sql_exec_id, seq#, event, p1, p2, p3
 order by min(sample_time);


confirms these dynamic changing:

 EVENT                   P1      P2 P3 OBJECT_NAME  SQL_EXEC_ID   SEQ#
 ---------------------- --- ------- -- ------------ ----------- ------
 direct path read         6 1369216 32 T1              16777216  39127
 db file scattered read   6 1369728 16 T1              16777216  49540
 direct path read         6 1349411 13 T1              16777216  63731
 

Now it raises an interesting question:

 How Oracle guarantees correct result when switching back to "direct path read" ?
 since the data file now contains fresh data which is not yet visible to the select session.

A 10046 dump trace will help us understand it:

  nam='direct path read' file number=6 first dba=1369216 block cnt=32 obj#=596657 tim=9813000274679
  nam='db file sequential read' file#=6 block#=1364873 blocks=1 obj#=596657 tim=9813012825308
    ......
  nam='db file scattered read' file#=6 block#=1369712 blocks=16 obj#=596657 tim=9813012877616
  nam='db file scattered read' file#=6 block#=1369728 blocks=16 obj#=596657 tim=9813012877787

           (read extent of deleted row)
  nam='db file sequential read' file#=3 block#=626 blocks=1 obj#=0 tim=9813012877868

           (read UNDO block)
  nam='db file sequential read' file#=6 block#=1349410 blocks=1 obj#=596657 tim=9813012877986

           (read segment header block)
  nam='direct path read' file number=6 first dba=1349411 block cnt=13 obj#=596657 tim=9813012878205


In the above dump,

1. obj#=596657 is Table T1.

2. line: 'db file scattered read' file#=6 block#=1369728 blocks=16
    is to read extent starting from block#=1369728, and having 16 blocks,
    which contains the block 1369733 of the above deleted row (id = 600)
    ( 1369728 <= 1369733 <= (1369728+16-1) ).

3. line: 'db file sequential read' file#=3 block#=626 blocks=1 obj#=0
    is to read UNDO block which contains the before image of the deleted row.

From the dump, we can see that immediately following "db file scattered read" (file#=6 block#=1369728) is an UNDO block read (file#=3 block#=626), and then, it is a "segment header" read of block#=1349410,afterwords, it continues with "direct path read".

So "direct path read" can also use UNDO to get the consistent version of modified blocks.

In above test, we only execute once a delete statement. If we loop over a DML update statement:

begin
  for i in 1..600 loop
    update t1 set pad = rpad('*', 400, '*'||i) where id = i*100;
    dbms_session.sleep(1);
    execute immediate 'alter system flush buffer_cache';
  end loop;
end;
/
Then in Session_1, run following query to observe Session_2 activity. We can observe the toggling between single block read and multi block read (parameter p3 is varied between 1 and 32 (or some other number > 1)). Among them, there are also some read of UNOD blocks.

select program, session_id, session_serial#, event, p1, p2, p3, p1text, p2text, p3text, v.* 
from   v$active_session_history v
where  session_id = &sid_2 and sample_time > sysdate - 10/1440
order by sample_time desc;  

Thursday, June 27, 2013

Oracle PL/SQL Collection Memory Reclaim

Oracle PL/SQL collection includes associative array, nested table and varray array, which are often used to store large amount of data. Consequently certain garbage collectors have to be developed in such applications to manually reclaim no longer used memory in order to reduce PGA memory consumption and eventually avoid:

    ORA-04030: out of process memory

In this Blog, we will demonstrate different approaches and their effects.

Test Code:


create or replace package mem_reclaim_test as
  procedure rpt(l_name varchar);
  procedure nullify;
  procedure empty;
  procedure empty_no_init;
  procedure empty_aa;
  procedure empty_aa_no_init;
  procedure delete;
  procedure copy;
  procedure copy_and_touch;
  procedure app_dealloc;
  procedure app_sparse;
end mem_reclaim_test;
/

create or replace package body mem_reclaim_test as
  type t_tab_type is table of char(1000);
  p_tab              t_tab_type := t_tab_type();  -- nested table
  p_tab_empty        t_tab_type := t_tab_type();
  p_sid              number     := sys.dbms_support.mysid;
 
  type t_tab_aa is table of char(1000) index by pls_integer;
  p_tab_aa           t_tab_aa;          -- associative array

  -------------------------------------------
 procedure rpt(l_name varchar) as
   l_v$process_mem            varchar2(4000);
    l_v$process_memory_mem     varchar2(4000);
 begin
  select 'Used/Alloc/Freeable/Max >>> '||
          round(pga_used_mem/1024/1024)    ||'/'||round(pga_alloc_mem/1024/1024)||'/'||
            round(pga_freeable_mem/1024/1024)||'/'||round(pga_max_mem/1024/1024)
      into l_v$process_mem
      from v$process where addr = (select paddr from v$session where sid = p_sid);
     
   select 'Category(Alloc/Used/Max) >>> '||
            listagg(Category||'('||round(allocated/1024/1024)||'/'||
                    round(used/1024/1024)||'/'||round(max_allocated/1024/1024)||') > ')
    within group (order by Category desc) name_usage_list
      into l_v$process_memory_mem
      from v$process_memory
      where pid = (select pid from v$process
                    where addr = (select paddr from v$session where sid = p_sid));
 
   dbms_output.put_line(rpad(l_name, 30)||' > '||rpad(l_v$process_mem, 50)||
                             ' --- '||l_v$process_memory_mem);
 end rpt;

 -------------------------------------------
 procedure allo(p_name varchar2) as
 begin
  rpt(p_name);
  select 'M' bulk collect into p_tab from dual connect by level <= 1000*1000;
  rpt('Allo');
 end allo;

 -------------------------------------------
 procedure allo_aa(p_name varchar2) as
 begin
  rpt(p_name);
  select 'M' bulk collect into p_tab_aa from dual connect by level <= 1000*1000;
  rpt('Allo');
 end allo_aa;

 -------------------------------------------
 procedure free as
 begin
  dbms_session.free_unused_user_memory;
  rpt('Free');
 end free;

 -------------------------------------------
 procedure nullify as
 begin
  allo('--- 1. Nullify');
  p_tab := null;               
  rpt('Nullify');
  free;                 
 end nullify;

 -------------------------------------------
 procedure empty as
  l_tab_temp      t_tab_type := t_tab_type();
 begin
  allo('--- 2_1. Empty_'||
     (case when l_tab_temp is null then 'null' else to_char(l_tab_temp.count) end));
  p_tab := l_tab_temp;
  rpt('Empty');
  free;                
 end empty;

 -------------------------------------------
 procedure empty_no_init as
  l_tab_temp      t_tab_type;
 begin
  allo('--- 2_2. Empty_no_init_'||
     (case when l_tab_temp is null then 'null' else to_char(l_tab_temp.count) end));
  p_tab := l_tab_temp;
  rpt('Empty_no_init');
  free;                
 end empty_no_init;

  -------------------------------------------
 procedure empty_aa as
  l_tab_temp      t_tab_aa;
 begin
  l_tab_temp(1) := 'Empty_aa';  -- init with one element

  l_tab_temp.delete(1);         -- delete it
  allo_aa('--- 2_3. Empty_aa_'||
   (case when l_tab_temp is null then 'null' else to_char(l_tab_temp.count) end));
  p_tab_aa := l_tab_temp;
  rpt('Empty_aa');
  free;                
 end empty_aa;

 -------------------------------------------
 procedure empty_aa_no_init as
  l_tab_temp      t_tab_aa;
 begin
  allo_aa('--- 2_4. Empty_aa_no_init_'||
   (case when l_tab_temp is null then 'null' else to_char(l_tab_temp.count) end));
  p_tab_aa := l_tab_temp;
  rpt('Empty_aa_no_init');
  free;                
 end empty_aa_no_init;

 -------------------------------------------
 procedure delete as
 begin
  allo('--- 3. Delete');
  p_tab.delete;
  rpt('Delete');
  free;                
 end delete;

 -------------------------------------------
 procedure copy as
  l_tab_temp      t_tab_type := t_tab_type();
 begin
  allo('--- 4. Copy');
  l_tab_temp := p_tab;
  rpt('Copy');
  free;                 
 end copy;

 -------------------------------------------
 procedure copy_and_touch as
  l_tab_temp      t_tab_type := t_tab_type();
    l_x             char(1000);
 begin
  allo('--- 5. Copy_and_Touch');
  l_tab_temp := p_tab;
  rpt('Copy');
  l_x := l_tab_temp(19);
  rpt('Touch');
  free;                      
 end copy_and_touch;

 -------------------------------------------
 procedure app_dealloc as
  l_tab_temp      t_tab_type := t_tab_type();
 begin
  allo('--- 6. App_dealloc');
  l_tab_temp := p_tab;
  rpt('Copy');
  p_tab     := p_tab_empty;
  rpt('Empty');
  p_tab     := l_tab_temp;
  rpt('Dealloc');
  free;                       
 end app_dealloc;

 -------------------------------------------
 procedure app_sparse as
  l_tab_temp      t_tab_type := t_tab_type();
 begin
  allo('--- 7. App_sparse');
  for i in 1..p_tab.count/4 loop
   p_tab.delete(i*4);
  end loop;
  rpt('New cnt='||p_tab.count);
  l_tab_temp := p_tab;
  rpt('Copy');
  p_tab     := p_tab_empty;
  rpt('Empty');
  p_tab     := l_tab_temp;
  rpt('Dealloc');
  free;                     
 end app_sparse;

end mem_reclaim_test;
/

set lines 200
exec dbms_session.reset_package;
set serveroutput on;
exec mem_reclaim_test.nullify;
exec mem_reclaim_test.rpt('--- End');
exec dbms_session.reset_package;

set serveroutput on;
exec mem_reclaim_test.empty;
exec mem_reclaim_test.rpt('--- End');
exec dbms_session.reset_package;
set serveroutput on;
exec mem_reclaim_test.empty_no_init;
exec mem_reclaim_test.rpt('--- End');
exec dbms_session.reset_package;

set serveroutput on;
exec mem_reclaim_test.empty_aa;
exec mem_reclaim_test.rpt('--- End');
exec dbms_session.reset_package;
set serveroutput on;
exec mem_reclaim_test.empty_aa_no_init;
exec mem_reclaim_test.rpt('--- End');
exec dbms_session.reset_package;

set serveroutput on;
exec mem_reclaim_test.delete;
exec mem_reclaim_test.rpt('--- End');
exec dbms_session.reset_package;
set serveroutput on;
exec mem_reclaim_test.copy;
exec mem_reclaim_test.rpt('--- End');
exec dbms_session.reset_package;
set serveroutput on;
exec mem_reclaim_test.copy_and_touch;
exec mem_reclaim_test.rpt('--- End');
exec dbms_session.reset_package;
set serveroutput on;
exec mem_reclaim_test.app_dealloc;
exec mem_reclaim_test.rpt('--- End');
exec dbms_session.reset_package;
set serveroutput on;
exec mem_reclaim_test.app_sparse;
exec mem_reclaim_test.rpt('--- End');



Output


SQL> exec mem_reclaim_test.nullify;
--- 1. Nullify       > Used/Alloc/Freeable/Max >>> 2/3/1/2296
Allo                 > Used/Alloc/Freeable/Max >>> 1179/1180/0/2296
Nullify              > Used/Alloc/Freeable/Max >>> 1179/1180/0/2296
Free                 > Used/Alloc/Freeable/Max >>> 1179/1180/0/2296
--- End              > Used/Alloc/Freeable/Max >>> 1179/1180/0/2296


SQL> exec mem_reclaim_test.empty;
--- 2_1. Empty_0     > Used/Alloc/Freeable/Max >>> 2/3/1/2296
Allo                 > Used/Alloc/Freeable/Max >>> 1179/1180/0/2296
Empty                > Used/Alloc/Freeable/Max >>> 1179/1180/0/2296
Free                 > Used/Alloc/Freeable/Max >>> 2/1180/1178/2296
--- End              > Used/Alloc/Freeable/Max >>> 2/3/1/2296


SQL> exec mem_reclaim_test.empty_no_init;
--- 2_2. Empty_no_init_null > Used/Alloc/Freeable/Max >>> 5/6/1/2297       
Allo                        > Used/Alloc/Freeable/Max >>> 1180/1181/0/2297 
Empty_no_init               > Used/Alloc/Freeable/Max >>> 1180/1181/0/2297 
Free                        > Used/Alloc/Freeable/Max >>> 1180/1181/0/2297 
--- End                     > Used/Alloc/Freeable/Max >>> 1180/1181/0/2297 


SQL> exec mem_reclaim_test.empty_aa;
--- 2_3. Empty_aa_0 > Used/Alloc/Freeable/Max >>> 5/6/1/2297
Allo                > Used/Alloc/Freeable/Max >>> 1180/1181/0/2297
Empty_aa            > Used/Alloc/Freeable/Max >>> 1180/1181/0/2297
Free                > Used/Alloc/Freeable/Max >>> 5/1181/1176/2297
--- End             > Used/Alloc/Freeable/Max >>> 5/6/1/2297


SQL> exec mem_reclaim_test.empty_aa_no_init;
--- 2_4. Empty_aa_no_init_0 > Used/Alloc/Freeable/Max >>> 5/6/1/2297
Allo                        > Used/Alloc/Freeable/Max >>> 1180/1181/0/2297
Empty_aa_no_init            > Used/Alloc/Freeable/Max >>> 1180/1181/0/2297
Free                        > Used/Alloc/Freeable/Max >>> 5/1181/1176/2297
--- End                     > Used/Alloc/Freeable/Max >>> 5/6/1/2297


SQL> exec mem_reclaim_test.delete;
--- 3. Delete        > Used/Alloc/Freeable/Max >>> 2/3/1/2296
Allo                 > Used/Alloc/Freeable/Max >>> 1179/1180/0/2296
Delete               > Used/Alloc/Freeable/Max >>> 1179/1180/0/2296
Free                 > Used/Alloc/Freeable/Max >>> 2/1180/1178/2296
--- End              > Used/Alloc/Freeable/Max >>> 2/3/1/2296


SQL> exec mem_reclaim_test.copy;
--- 4. Copy          > Used/Alloc/Freeable/Max >>> 2/3/1/2296
Allo                 > Used/Alloc/Freeable/Max >>> 1179/1180/0/2296
Copy                 > Used/Alloc/Freeable/Max >>> 1179/1180/0/2296
Free                 > Used/Alloc/Freeable/Max >>> 1179/1180/0/2296
--- End              > Used/Alloc/Freeable/Max >>> 1179/1180/0/2296


SQL> exec mem_reclaim_test.copy_and_touch;
--- 5. Copy_and_Touc > Used/Alloc/Freeable/Max >>> 2/3/1/2296
Allo                 > Used/Alloc/Freeable/Max >>> 1179/1180/0/2296
Copy                 > Used/Alloc/Freeable/Max >>> 2295/2296/0/2296
Touch                > Used/Alloc/Freeable/Max >>> 2295/2296/0/2296
Free                 > Used/Alloc/Freeable/Max >>> 2295/2296/0/2296
--- End              > Used/Alloc/Freeable/Max >>> 1179/1181/1/2296


SQL> exec mem_reclaim_test.app_dealloc;
--- 6. App_dealloc   > Used/Alloc/Freeable/Max >>> 2/3/1/2296
Allo                 > Used/Alloc/Freeable/Max >>> 1179/1180/0/2296
Copy                 > Used/Alloc/Freeable/Max >>> 2295/2296/0/2296
Empty                > Used/Alloc/Freeable/Max >>> 2295/2296/0/2296
Dealloc              > Used/Alloc/Freeable/Max >>> 2295/2296/0/2296
Free                 > Used/Alloc/Freeable/Max >>> 2295/2296/0/2296
--- End              > Used/Alloc/Freeable/Max >>> 1179/1181/1/2296


SQL> exec mem_reclaim_test.app_sparse;
--- 7. App_sparse    > Used/Alloc/Freeable/Max >>> 2/3/1/2296
Allo                 > Used/Alloc/Freeable/Max >>> 1179/1180/0/2296
New cnt=750000       > Used/Alloc/Freeable/Max >>> 1179/1180/0/2296
Copy                 > Used/Alloc/Freeable/Max >>> 2016/2017/0/2296
Empty                > Used/Alloc/Freeable/Max >>> 2016/2017/0/2296
Dealloc              > Used/Alloc/Freeable/Max >>> 2016/2017/0/2296
Free                 > Used/Alloc/Freeable/Max >>> 1722/2017/294/2296
--- End              > Used/Alloc/Freeable/Max >>> 885/886/1/2296


Analysis


Based on the above output, we can conclude:

 1. nullify:                   Memory not released.
 2. empty:                   In case of nested table, when making empty with an initialized nested table, memory released; 
                                   when making empty with a non-initialized nested table, memory not released;

                                   In case of associative array, memory always released, irrelevant of initialization,
                                   because associative array is always initialized with 0 element, even only declared without initialization.

                                   The difference is probably that nested table is an object, in OO paradigm, non-initialized variable is NULL.
                                   So making empty with a non-initialized nested table, is same as Nullify.
 3. delete:                   Memory released.
 4. copy:                     If not touched, memory stays same.
                   2013Sep05 Updated:
                          One Reader pointed out that this behavior is true when plsql_optimize_level >= 2(Default);

                          for 0 and 1, it is the same as copy_and_touch.
 5. copy_and_touch:  If touched, a real copy created, memory doubled.
                                  This is already noticed in Step: Touch, that means a forward allocation.
 6. app_dealloc:         Memory doubled.
 7. app_sparse:          Deleting 1/4 of entries (294=1179*(1/4)), the sparse nested table is 885=1179*(3/4) .
                                  Therefore, the total aloocated memory of 2017 is around the sum of two nested tables
                                  (p_tab=1179 plus l_tab_temp=885).

                                  At the end, the 1/4 deleted entries are garbage collected, and remaining 3/4 entries amounts to 885.

                                  That was shown by the line:
                                       Free  > Used/Alloc/Freeable/Max >>> 1722/2017/294/2296
                                  where (not very exact):
                                      1722(Used) = 2017(Alloc) - 294(Freeable)

One interesting result is the difference between testcase: copy and copy_and_touch. As long as the memory copy is not touched, the real memory is not allocated. This is probably the Copy-on-write optimization in PL/SQL.


Nested Table Operators



declare
  type      doubly_linked_list is table of number;
  l_dl_list doubly_linked_list := doubly_linked_list();
begin
  l_dl_list := new doubly_linked_list();
  l_dl_list.extend(4);
  l_dl_list(1) := -1;
  l_dl_list(2) := -2;
  l_dl_list(3) := -3;
  l_dl_list(4) := -4;

  dbms_output.put_line('start.count  = '||l_dl_list.count||', last = '||l_dl_list.last);
  l_dl_list.delete(4);  
  dbms_output.put_line('delete.count = '||l_dl_list.count||', last = '||l_dl_list.last);
  l_dl_list.extend;
  dbms_output.put_line('extend.count = '||l_dl_list.count||', last = '||l_dl_list.last);
  
  if l_dl_list.exists(5) then 
    if l_dl_list(5) is null then 
       dbms_output.put_line('  exists(5) true: '||'null');
    else
       dbms_output.put_line('  exists(5) true: '||l_dl_list(5));
    end if;
  else
    dbms_output.put_line('  exists(5) false ');
  end if;
  
  if l_dl_list.exists(4) then 
    if l_dl_list(4) is null then 
       dbms_output.put_line('  exists(4) true: '||'null');
    else
       dbms_output.put_line('  exists(4) true: '||l_dl_list(4));
    end if;
  else
    dbms_output.put_line('  exists(4) false ');
  end if;
  
  l_dl_list.trim;
  dbms_output.put_line('trim_1.count = '||l_dl_list.count||', last = '||l_dl_list.last);
  l_dl_list.trim;
  dbms_output.put_line('trim_2.count = '||l_dl_list.count||', last = '||l_dl_list.last);
  l_dl_list.trim;
  dbms_output.put_line('trim_3.count = '||l_dl_list.count||', last = '||l_dl_list.last);
  l_dl_list.delete;
  dbms_output.put_line('delall.count = '||l_dl_list.count||', last = '||l_dl_list.last);
  l_dl_list.extend;
  dbms_output.put_line('extend.count = '||l_dl_list.count||', last = '||l_dl_list.last);
end;
/  

start.count  = 4, last = 4
delete.count = 3, last = 3
extend.count = 4, last = 5  -- extend not use deleted index
  exists(5) true: null
  exists(4) false
trim_1.count = 3, last = 3  -- trim last
trim_2.count = 3, last = 3  -- trim deleted index
trim_3.count = 2, last = 2
delall.count = 0, last =    -- delete all, and trim to zero
extend.count = 1, last = 1


1. extend and trim are physical space operators.
2. assignment, delete, exists, first/last, count, prior/next are logical operators. They ignore deleted elements.
3. delete without parameters frees the entire memory allocated to the collection, and hence a physical space operator.

See Oracle 12c Collection Methods in PL/SQL Collections and Records of Database PL/SQL Language Reference.

Tuesday, June 4, 2013

dbms_alert lock hash collision

dbms_alert package calls dbms_lock to synchronize alert senders and receivers based on lockid generated by the name in dbms_alert_info table by a function call:

   dbms_utility.get_hash_value(name, 2000000000, 2048)

which can have a high hash collision probability, and hence occasionally false UL lock contention.

For example, both 'warning_1828' and 'alarm_1828' are hashed to the same value: 2000000389.

 select dbms_utility.get_hash_value(upper('warning_1828'), 2000000000, 2048) lockid_1,
        dbms_utility.get_hash_value(upper('alarm_1828'),   2000000000, 2048) lockid_2 
 from dual;



Here is a testcase.

At first create a helper function:

 create or replace procedure dbms_alert_lock_collision(p_name varchar2) as
   l_message varchar2(1800);
   l_status  pls_integer;
   l_name    varchar2(30);
 begin
   dbms_alert.register(p_name);
   dbms_alert.waitany(l_name, l_message, l_status);
   dbms_output.put_line('Received Name='||l_name||', Message='||l_message||', Status:='||to_char(l_status));
 end;


then open 4 Sqlplus sessions, perform the test steps as follows:

(1). Session-1 at T1
         exec dbms_alert_lock_collision('warning_1828');

(2). Session-2  at T2
         exec dbms_alert_lock_collision('alarm_1828');

(3). Session-3 at T3
         exec dbms_alert.signal('warning_1828', 'warning_1828_msg');

 Firing signal wakes up the waiter session, which changes its state from "pipe get" (wait_class Idle)
 to "enq: UL - contention" (wait_class Application).

(4). Session-4 at T4
         exec dbms_alert.signal('alarm_1828', 'alarm_1828_msg');

(5). Session-3 at T5, wait Session-4 returns (this can take up to 32 seconds), then:
          commit;

 even Session-3 committed, Session-1 is still blocked by 'UL'lock. You can see it by:

  select * from v$lock where type = 'UL';

  select * from v$wait_chains;


(6). Session-4 at T6

         commit;

 Session-4's commit de-locks both Session-1 and Session-2.


If Session-3 at T5 commits before Session-4 at T4 returns, the commit of Session-3 at T5 can probably de-lock Session-1. However the behavior is dependent on the UL lock time sequence.

When signal is sent by the signalling session, but before commit, dbms_alert.waitany requests a UL lock with a timeout: 1, 2, 4, 8, 16, 32 seconds for the first 6 times, and afterwards always with timeout: 32 seconds.

If Session-4 at T4 waits less than 32 seconds, it can be blocked by Session-1 at T1. In this case, Session-3 holds S_MODE(4) lock and blocks Session-1's SX_MODE(3) lock Request, and Session-1's SX_MODE(3) lock Request blocks Session-4's S_MODE(4) lock Request (Session-4 is queued after Session-1). When Session-1 renews its lock request after maximum 32 seconds, Session-4 got its S_MODE(4) lock. And then both Session-3 and Session-4 hold S_MODE(4) lock, whereas both Session-1 and Session-2 are waiting SX_MODE(3) lock. Therefore when Session-3 at T5 commits (and hence release its S_MODE(4) lock), Session-4 is still blocking Session-1 and Session-2.

Following query can help to detect the hash collision names:

  select lockid, count(*) cnt, listagg(name, '; ') within group (order by name)
    from (
      select name, dbms_utility.get_hash_value(upper(name), 2000000000, 2048) lockid
        from (select distinct name from sys.dbms_alert_info) v
    )
  group by lockid
  having count(*) > 1
  order by cnt desc; 


If there are more than 100 waiting sessions like Session-1 and Session-2, the system can be disturbed by the heavy UNDO activities. Here the query to monitor them:

 select n.name, s.sid, s.value
   from v$statname n, v$sesstat s
  where s.statistic# = n.statistic#
    and name in ('data blocks consistent reads - undo records applied'
                ,'rollback changes - undo records applied')


By the way, in 14 May 2013, a first rank result on twin prime conjecture was reported: "Bounded gaps between primes".

Friday, April 12, 2013

cursor: pin S wait on X

Oracle introduced mutex (replacing latch) to protect cursor and library cache, and consequently following wait events:

   cursor: mutex S
   cursor: mutex X

   cursor: pin S
   cursor: pin X
   cursor: pin S wait on X

   library cache: mutex S
   library cache: mutex X


Staring in perplexity, I wonder why Oracle conceived such an asymmetrical third wait event for "cursor: pin":

      cursor: pin S wait on X

but not for "cursor: mutex" and "library cache: mutex".

A recent session crash dump shed some light on this deliberate design.

Session Wait History shows that it is desperately waiting for 'cursor: pin S wait on X'.

  waited for 'cursor: pin S wait on X'                               
  idn=0xb9a7f11c, value=0x1fef00000000, where=0x500000000
  wait_id=26539 seq_num=26582 snap_id=1
  wait times: snap=0.010060 sec, exc=0.010060 sec, total=0.010060 sec
  wait times: max=infinite
  wait counts: calls=2 os=2
  occurred after 0.014483 sec of elapsed time


pick the idn value, and search further in the dump file, we find the waited object.

  LibraryHandle:  Address=70000521ff2b1e8 Hash=b9a7f11c LockMode=N PinMode=0 LoadLockMode=0 Status=VALD
   ObjectName:  Name=SELECT NAME FROM
     FullHashValue=28a0bd52de76008db45a3f29b9a7f11c Namespace=SQL AREA(00) Type=CURSOR(00)
     Children: 
       Child:  childNum='0'
         LibraryHandle:  Address=70000521f025fc0 LockMode=N PinMode=0 LoadLockMode=0 Status=VALD
           Name:  Namespace=SQL AREA(00) Type=CURSOR(00)
       Child:  childNum='1'
         LibraryHandle:  Address=70000521d0eeeb0 LockMode=N PinMode=X LoadLockMode=0 Status=VALD
           Name:  Namespace=SQL AREA(00) Type=CURSOR(00)
       Child:  childNum='2'
         LibraryHandle:  Address=70000521dec3790 LockMode=0 PinMode=0 LoadLockMode=0 Status=VALD
           Name:  Namespace=SQL AREA(00) Type=CURSOR(00)
           ObjectFreed=last freed from HPD addn data CBK
       Child:  childNum='3'
         LibraryHandle:  Address=70000521adcce68 LockMode=N PinMode=0 LoadLockMode=0 Status=VALD
           Name:  Namespace=SQL AREA(00) Type=CURSOR(00)

          
A query on dba_hist_active_sess_history reveals that only this session is with SQL_CHILD_NUMBER = 2, all other sessions are with SQL_CHILD_NUMBER = 1. Before and after this session crashes(exit), other sessions are still running.

Look carefully at childNum='1', we can see this child cursor marked with:

    PinMode=X
          
Now a possible interpretation for 'cursor: pin S wait on X' would be:

   When Oracle wants to "pin S" a cursor, it sequentially traverses all child cursors under the same parent.
   If it hits a cursor marked with: PinMode=X before it reaches the matched cursor, it posts:

        cursor: pin S wait on X


1. Stack Trace


Pick UNIX pid of blocked Oracle sessions waiting on Event: "cursor: pin S wait on X", make a stack trace.
Here the outputs on both AIX and Solaris, where the line:
    kkscsSearchChildList
probably indicates the sequential examination along all child cursors.

oracle@aix > procstack 64815340
 64815340: oracledb (LOCAL=NO)
 __fd_select(??, ??, ??, ??, ??) + 0xbc
 select(??, ??, ??, ??, ??) + 0x14
 skgpnap(??, ??, ??, ??) + 0x16c
 skgpwwait(??, ??, ??, ??, ??) + 0x204
 kgxWait(??, ??, ??, ??, ??, ??) + 0x1b8
 kgxModifyRefCount(??, ??, ??, ??) + 0x288
 kgxSharedExamine(??, ??, ??) + 0x3c
 kxsGetRuntimeLock(??, ??, ??, ??, ??) + 0x144
 kkscsCheckCursor(??, ??, ??, ??, ??, ??, ??, ??) + 0x1ec
 kkscsSearchChildList(??, ??, ??, ??, ??, ??, ??, ??) + 0x7b8
 kksfbc(??, ??, ??, ??, ??, ??, ??, ??) + 0x51f4
 kkspsc0(??, ??, ??, ??, ??, ??, ??) + 0x8b0
 kksParseCursor(??) + 0x78
 opiosq0(??, ??, ??, ??, ??) + 0x7f4
 kpooprx(0x7000100fb4086a0, 0x0, 0x0, 0x100000001, 0x0, 0xa4000000a4, 0x0) + 0x16c
 kpoal8(??, ??, ??) + 0x1bc
 opiodr(??, ??, ??, ??) + 0x3b4
 ttcpip(??, ??, ??, ??, ??, ??, ??, ??) + 0x34c
 opitsk(??, ??) + 0x2224
 opiino(??, ??, ??) + 0xb98
 opiodr(??, ??, ??, ??) + 0x3b4
 opidrv(??, ??, ??) + 0x414
 sou2o(??, ??, ??, ??) + 0xf0
 opimai_real(??, ??) + 0x1c0
 ssthrdmain(0x0, 0x200000002, 0xfffffffffffed18) + 0x1c4
 main(??, ??) + 0xd0
 __start() + 0x70


oracle@solaris :/export/home/oracle > pstack 1098
 pollsys  (fffffd7fffdf5860, 0, fffffd7fffdf58f0, 0)
 pselect () + 154
 select () + 72
 skgpwwait () + 168
 kgxWait () + 216
 kgxModifyRefCount () + 15e
 kgxSharedExamine () + 3b
 kxsGetRuntimeLock () + 137
 kkscsCheckCursor () + 22a
 kkscsSearchChildList () + 58f
 kksfbc () + 915
 kkspsc0 () + 9d7
 kksParseCursor () + 74
 opiosq0 () + 70a
 kpooprx () + 102
 kpoal8 () + 308
 opiodr () + 433
 ttcpip () + 593
 opitsk () + 6cc
 opiino () + 3c5
 opiodr () + 433
 opidrv () + 33b
 sou2o () + 7a
 opimai_real () + 265
 ssthrdmain () + 22e
 main () + a4
 ???????? ()

2. Mutex Sleep Reason


We have a SQL statement, whose parsing takes about 11 minutes. If we start two sessions to parse the same statement. One session is parsing, another is waiting for Event: cursor: pin S wait on X.

Collect AWR report for the duration of 11 minutes, Section: Mutex Sleep Summary shows:

Mutex Type Location Sleeps Wait Time (ms)
Cursor Pin kkslce [KKSCHLPIN2] 61,421 616,083
Library Cache kglhdgn2 106 1 0
Library Cache kglpnal1 90 1 0

We can see the 11 minutes of 616,083 Wait Time (ms), Sleeps of 61,421.
That is probably due to Scheduler clock tick frequency of 10 milliseconds, approximately the equation:
    61,421 x 10 = 616,083

The above observation seems conforming to MOS (Doc ID 1268724.1):
   "Cursor: Pin S Wait On X" Contention Mutex Sleep Reason Primarily ' kkslce [KKSCHLPIN2]'

MOS: How to Determine the Blocking Session for Event: 'cursor: pin S wait on X' (Doc ID 786507.1) has a detailed description:
   A session waits on this event when requesting a mutex for shareable operations related to pins (such as executing a cursor),
   but the mutex cannot be granted because it is being held exclusively by another session (which is most likely parsing the cursor).
   The column P2RAW in v$session or v$session_wait gives the blocking session for wait event cursor: pin S wait on X.


and gave the query to check it:

select p2raw,to_number(substr(to_char(rawtohex(p2raw)),1,8),'XXXXXXXX') sid
  from v$session
 where event = 'cursor: pin S wait on X'; 

in 64 bit platforms, 8 bytes are used.
  Top 4 bytes hold the session id (if the mutex is held X)
  Bottom 4 bytes hold the ref count (if the mutex is held S). 


3. cursor: pin S wait on X    Simulation


Setup test:

drop table testt;

create table testt as select 1 id, 'Test' name from dual;

Open a Sqlplus Session,

SQL (72) > select sid, pid, spid from v$session s, v$process p where s.paddr=p.addr and s.sid = sys.dbms_support.mysid;

 SID  PID  SPID
---- ---- -----
  72   34  1122

SQL (72) > alter system flush shared_pool; 

Pick one kks subroutine, for instance, kksFullTypeCheck. On Solaris, execute:

$ sudo dtrace -w -n 'pid$target::kksFullTypeCheck:entry {@[pid, ustack(10, 0)] = count(); stop(); exit(0);}' -p 1122  

On above Sqlplus Session, run:

SQL (72) > select id, name from testt where id = 1;

The Session is stopped.

Open a second Sqlplus Session, and run the same query:

SQL (83) > select sid, pid, spid from v$session s, v$process p where s.paddr=p.addr and s.sid = sys.dbms_support.mysid;

 SID  PID  SPID
---- ---- -----
 83    45  6677

SQL (83) > select id, name from testt where id = 1;

SID 83 is blocked.

Observe the "cursor: pin S wait on X" event by:

select sid, osid, chain_signature, blocker_is_valid, wait_event_text, in_wait_secs, num_waiters
from v$wait_chains where sid in (72, 83);

To unblock, execute:
  $ prun 1122


4. Slow Parsing in multiple Sessions


Further tests show that if a slow parsing takes x seconds for one statement in one single session, concurrently parsing it in n sessions will take a total elapsed time of (n*(n-1)*x + x) seconds for all sessions, even worse if CPU is saturated. So in average, that is about (n-1)*x seconds per session (assume n is relatively big). The main wait event is "cursor: pin S wait on X" among the concurrent sessions.

One workaround to get off the racing condition is to make the statement passed to each session semantic equivalent, but syntax (sql text) different, for example, adding different dummy hint, or appending different constant to "order by" clause in each session's statement. The downside is more space in shared pool.

Shared Pool - Free Memory, Fragmentation ?

Facing:
    ORA-04031: unable to allocate 32 bytes of shared memory ("shared pool","SELECT MAX(XX) FROM...","SQLA","tmp")

under shared pool memory distribution of:

Top 5 Areas Name Subpool_1 Subpool_2 Subpool_3 Subpool_4 Subpool_5 Subpool_6 Subpool_7 Sum
KKSSP 617'693 563'340 590'296 590'798 577'532 643'504 577'237 4'160'404
db_block_hash_buckets 529'039 535'429 529'039 539'525 535'429 529'044 535'429 3'732'935
KGLH0 554'532 485'312 464'006 353'634 450'528 346'045 332'455 2'986'514
SQLA 1'110 588'943 565'317 185'664 574'008 155'498 272'452 2'342'994
free memory 306'562 358'029 353'146 306'659 342'194 325'386 304'535 2'296'513

(see Blog: Shared Pool - Memory Allocation - unbalanced)

an intuitively skeptical question is:
               Why do I get ORA-04031 even though there is plenty of free memory (> 10%) ?
One unsubstantial reply is mostly: memory fragmentation (or memory leak).

This Blog is trying to disperse such fashionable pretext.

A simple way to dispute it is to make a heapdump and you will see FREE LISTS starting with size=32 in Bucket 0:
   FREE LISTS:
   Bucket 0 size=32

so the minimum memory chunk size in shared pool is 32 Byte, any free memory chunk is at least 32 Byte.

But above error says:
   unable to allocate 32 bytes
evidently there is truly no more free memory.

So where is the secrecy behind the controversial information ?

To understand it, firstly we will look at what free memory is in different aspect, then expose the memory allocation of certain popular areas (subheaps), and finally debate further on this theme.

1. Free Memory


Take a DB of shared_pool_size = 1408M with two Subpools, one direct way to get free memory statistics is:
   select round(bytes/1024/1024) mb from v$sgastat where pool='shared pool' and name = 'free memory';
returns:
 298
 
or on its internal x$ table:
   select KSMDSIDX, round(ksmsslen/1024/1024) SGASTAT_MB from x$ksmss where ksmssnam ='free memory';

returns:

  KSMDSIDX   SGASTAT_MB
  ---------  ----------
  0          208
  1          42
  2          48
which lists free memory per subpool, where ksmdsidx 0 denotes the "RESERVED EXTENTS" in "sga heap" top. Anyway, the total free memory matches 208 + 42 + 48 = 298.

A heapdump shows:

 HEAP DUMP heap name="sga heap"  desc=700000000000198
    reserved granule count 13 (granule size 16777216)
  RESERVED EXTENTS
 HEAP DUMP heap name="sga heap(1,0)"  desc=700000000052a48
  FREE LISTS
   Total free space   =  9970088
  RESERVED FREE LISTS
   Total reserved free space   = 29473232
  
 HEAP DUMP heap name="sga heap(2,0)"  desc=70000000005c310
  FREE LISTS
   Total free space   = 12790056
  RESERVED FREE LISTS
   Total reserved free space   = 31900768

ksmdsidx 0 is correlated well with heapdump, but not free memory in both subpools.

  KSMDSIDX  SGASTAT_MB  HEAP_DUMP                                   Delta
  --------  ----------  ------------------------------------------  ----- 
  0         208         round(16777216*13/1024/1024)         = 208      0
  1         42          round((9970088+29473232)/1024/1024)  =  38      4
  2         48          round((12790056+31900768)/1024/1024) =  43      5
(In heapdump, summing all chunks commented with "R-free" and "free" gives the same result)

So now the question is why v$sgastat (and respective x$ksmss) reports 9 MB (4+5) free memory than heapdump ?

Let's try to dig it out.

2. Subheaps: KGLH0, KGLS, PLDIA, SQLA, SQLK, SQLP


These subheaps are chosen since they are mostly allocated in a chunk size of 4096, and all together play a prevalent role in memory consumption (On the top of Page 157 of Book: Expert Oracle Database Architecture, there is one line:
  The shared pool is characterized by lots of small (generally 4KB or less) chunks of memory).

At first select them from v$sgastat:

 select name, round(bytes/1024/1024) mb
   from v$sgastat
  where pool='shared pool'
    and name in ('KGLH0', 'KGLS', 'PLDIA', 'SQLA', 'SQLK', 'SQLP')
 order by mb desc;

 NAME   MB
 -----------
 SQLA   219
 KGLH0  125
 KGLS   43
 PLDIA  9
 SQLP   5
 SQLK   0

another query on x$ksmsp displays more details about memory usage:

 select substr(ksmchcom, 1, 5)          name
       ,round(sum(ksmchsiz)/1024/1024) mb
       ,count(ksmchsiz)                cnt
       ,round(avg(ksmchsiz))           avg
       ,min(ksmchsiz)                  min
       ,max(ksmchsiz)                  max
   from x$ksmsp v
 where substr(ksmchcom, 1, 5) in ('KGLH0', 'KGLS^', 'PLDIA', 'SQLA^', 'SQLK^', 'SQLP^')
 group by substr(ksmchcom, 1, 5)
 order by mb desc;

 NAME   MB   CNT   AVG  MIN  MAX 
 ---------------------------------
 SQLA^  220 56269 4099 4096 28664
 KGLH0  126 32261 4096 4096 4640
 KGLS^  43  11005 4096 4096 4128
 PLDIA  9   2195  4096 4096 4112
 SQLP^  5   1209  4168 4096 5888
 SQLK^  0   19    4096 4096 4096

Look again on the same heapdump, extract all lines containing one special comment, say,

KGLH0^d020e92f
  Chunk  7000000a1cd3578 sz=     4096    recreate  "KGLH0^d020e92f "  latch=0
  Chunk  7000000a1d9c4d8 sz=     4096    recreate  "KGLH0^d020e92f "  latch=0
  Chunk  7000000a1efce68 sz=     4096    freeable  "KGLH0^d020e92f "  ds=7000000a1d9c450
  Chunk  7000000a7b8f880 sz=     4096    freeable  "KGLH0^d020e92f "  ds=7000000a1d9c450
  Chunk  7000000a7f07588 sz=     4096    freeable  "KGLH0^d020e92f "  ds=7000000a1d9c450
 
(see MOS: Troubleshooting and Diagnosing ORA-4031 Error [Video] (Doc ID 396940.1) about Chunk types
Chunk types:

Normal (freeable) chunks - These chunks are allocated in such a way that the user can explicitly free the chunk once they have finished with the memory.

Free chunks - These chunks are free and available for reuse should a request come into the pool for this chunk size or smaller.

Recreatable chunks - This is a special form of "freeable" memory. These chunks are placed on an LRU list when they are unpinned. If memory is needed, we go to the LRU list and free "recreatable" memory that hasn't been used for a while.

Permanent chunks - These chunks can be allocated in different ways. Some chunks are allocated and will remain in use for the "life" of the instance. Some "permanent" chunks are allocated but can be used over and over again internally as they are available.)

and then make an addr dump of KGLH0^d020e92f:  

 Processing Oradebug command 'dump heapdump_addr 1 0X7000000A1D9C450'
 HEAP DUMP heap name="KGLH0^d020e92f"  desc=7000000a1d9c450
 EXTENT 0 addr=7000000a1efce80
   Chunk  7000000a1efce90 sz=     1384    perm      "perm           "  alo=600
   Chunk  7000000a1efd3f8 sz=      152    freeable  "kgltbtab       "
   Chunk  7000000a1efd490 sz=      696    freeable  "policy chain   "
   Chunk  7000000a1efd748 sz=      144    freeable  "context chain  "
   ...
 EXTENT 1 addr=7000000a7f075a0
   Chunk  7000000a7f075b0 sz=      376    free      "               "
   ...
 EXTENT 2 addr=7000000a7b8f898
   Chunk  7000000a7b8f8a8 sz=     1760    perm      "perm           "  alo=1760
   Chunk  7000000a7b8ff88 sz=      416    free      "               "
   ...
 EXTENT 3 addr=7000000a1cd35a8
   Chunk  7000000a1cd35b8 sz=       80    perm      "perm           "  alo=80
   Chunk  7000000a1cd3608 sz=     3296    perm      "perm           "  alo=3296
   Chunk  7000000a1cd42e8 sz=       48    free      "               "
   ...
 Total heap size    =    16200
 FREE LISTS:
  Bucket 0 size=0
   Chunk  7000000a7b8ff88 sz=      416    free      "               "
   Chunk  7000000a7f075b0 sz=      376    free      "               "
   Chunk  7000000a1cd42e8 sz=       48    free      "               "
   Chunk  7000000a1cd35d8 sz=        0    kghdsx
 Total free space   =      840
 UNPINNED RECREATABLE CHUNKS (lru first):
 PERMANENT CHUNKS:
   Chunk  7000000a1efce90 sz=     1384    perm      "perm           "  alo=600
   ...
 Permanent space    =     6520

so total used memory is 16200 (including 840 free space, and 6520 Permanent space), however the allocated space is 5*4096 = 20480, so 20480 - 16200 = 4280 over allocation.

addr dump of "KGLH0^d020e92f" shows 3 free Chunks with size 416, 376, and 48.

 FREE LISTS:
  Bucket 0 size=0
   Chunk  7000000a7b8ff88 sz=      416    free      "               "
   Chunk  7000000a7f075b0 sz=      376    free      "               "
   Chunk  7000000a1cd42e8 sz=       48    free      "               "
   Chunk  7000000a1cd35d8 sz=        0    kghdsx
 Total free space   =      840
Make a cross-check with the same heapdump (as follows), we see no free Chunks in Bucket 43 with size=376, and Bucket 48 with size=416:

HEAP DUMP heap name="sga heap(1,0)"  desc=700000000052a48
 FREE LISTS:
  Bucket 42 size=368
  Bucket 43 size=376
  Bucket 44 size=384
  Bucket 45 size=392
  Bucket 46 size=400
  Bucket 47 size=408
  Bucket 48 size=416
  Bucket 49 size=424
HEAP DUMP heap name="sga heap(2,0)"  desc=70000000005c310
 FREE LISTS:
  Bucket 42 size=368
  Bucket 43 size=376
  Bucket 44 size=384
  Bucket 45 size=392
  Bucket 46 size=400
  Bucket 47 size=408
   Chunk  7000000a3e8c3d8 sz=      408    free      "               "
  Bucket 48 size=416
  Bucket 49 size=424

 
so the FREE LISTS in addr dump of "KGLH0^d020e92f" are counted in v$sgastat, but not counted in free memory of heapdump, that probably explains why v$sgastat displays more free memory than heapdump. Since they are not listed in any FREE LISTS, they can not be allocated to any later memory demand till their bound parental chunks returned to LRU LIST (UNPINNED RECREATABLE CHUNKS). I guess that Oracle takes such an approach to reduce memory fragmentation (and coalescing) in hoping that each allocated chunk is fully used in these subheaps. In summary, free memory in v$sgastat probably displays more than allocable free memory since it includes un-allocable free memory inside the allocated chunks(chunk-intra free memory).

3. Discussion


3.1. session_cached_cursors: KGLH0 and SQLA


Each Oracle object, whatever SQL cursor(both parent and child), Table, PL/SQL, has one KGLH0 memory allocation of multiple 4K. When session_cached_cursors is set, repeated parse calls (more than 3 times) of the same SQL (including recursive SQL) or PL/SQL statement by any session connected to DB are candidate for addition to session cursor cache (Understanding Shared Pool Memory Structures ).

Cursor in this cache is "partially pinned", that means, KGLH0(heap 0) is pinned, but not SQLA (heap 6). So when session_cached_cursors is set high, there will be potentially huge KGLH0 pinned, but not SQLA.

As a certain rule of thumb, SQLA should be proportional to KGLH0, otherwise they are out of originally designed range.

In fact, the DB which throws ORA-04031 has set session_cached_cursors = 600 (Oracle Default=50).
(see Blog: Shared Pool - Memory Allocation - unbalanced) And the memory statistics shows that KGLH0 is the third top memory consumer in all subpools, and SQLA in subpool_1 is extremely problematic. With 6000 concurrently connected sessions and session_cached_cursors = 600, there will be 3'600'000 pinned KGLH0 in the extreme case (this pure math number will not appear since majority of cursors are the same stored in shared_pool).

Continuing with our experiment, a library_cache dump("level 16") confirms that there is always one KGLH0 for each cursor (parent and child), and occasionally one SQLA, so more KGLH0 subheaps than SQLA subheaps. Obviously this is already an optimization since normally SQLA requires more memory than its corresponding KGLH0.

Library_cache dump also shows certain information about memory usage, for example, a particular SQLA:

    Block:  #='0' name=KGLH0^580dee70 pins=0 Change=NONE   
      Heap=70000521f4f8300 Pointer=70000521ad6f918 Extent=70000521ad6f7f8 Flags=I/-/P/A/-/- 
      FreedLocation=0 Alloc=20.015625 Size=23.859375 LoadTime=28198292040 
    Block:  #='6' name=SQLA^580dee70 pins=0 Change=NONE   
     Heap=7000000a0117ec8 Pointer=7000000a49c0040 Extent=7000000a49bf3e8 Flags=I/-/-/A/-/E
     FreedLocation=0 Alloc=23.171875 Size=23.742188 LoadTime=0
To find out what "Alloc" and "Size" denote, make an addr heapdump for Heap=7000000a0117ec8, then you will see following lines:

  dump heapdump_addr 1 0X7000000a0117ec8
    Total heap size    =    24312
    Total free space   =      504
    Permanent space    =       80

and then try to relate them together:

   Total heap size = Size  = 23.742188*1024 = 24312
   Total free space + Permanent space = 23.742188*1024 - 23.171875*1024 = 584 = 504 + 80
  
In the dump file when memory of shard_pool being under pressure (ORA-04031), probably there are certain offending cursors with noticeable KGLH0 or SQLA memory Size, for example: KGLH0^ac7e9a16 consumes about 131'343'512 Bytes.

DataBlocks:  
  Block:  #='0' name=KGLH0^ac7e9a16 pins=0 Change=NONE   
    Heap=700014eb0a10b30 Pointer=7000150fedd92e0 Extent=7000150fedd9170 Flags=I/-/P/A/-/-/- 
    FreedLocation=0 Alloc=128010.093750 Size=128265.148438 LoadTime=16455656254 

3.2. v$sgastat(x$ksmss) vs. x$ksmsp


In v$sgastat 'shared pool', Bytes for "free memory" statistics is really allocable free memory (top RESERVED EXTENTS, and FREE LISTS, RESERVED FREE LISTS in each subpool) plus un-allocable free memory (overhead) in allocated chunks. And Bytes for each v$sgastat component is the effectively occupied memory (not including overhead). So total memory matches the configured shared_pool_size.

Whereas x$ksmsp reports allocable memory in free chuncks. If one chunk is allocated, it is not counted even it still has free memory. Additionally it reports more details, for example, KGLH0 for each cursor. It also outputs one special row for "permanent memor". But it enumerates less rows than v$sgastat.

In conclusion, this chunk-intra free memory probably irritates such a confusion:
              I get ORA-04031 even though there is plenty of free memory (> 10%).

With following query, you can get a rough comparison of both aspects. By only running the subquery_factoring_clause, you can see that above mentioned subheaps:
    KGLH0, KGLS, PLDIA, SQLA, SQLK, SQLP
are mostly allocated in 4K, and there are also more KGLH0 than SQLA due to session_cached_cursors.


with sq as 
  (select substr(ksmchcom, 1, decode((instr(ksmchcom, '^') - 1), -1, 
                           length(ksmchcom), (instr(ksmchcom, '^') - 1))) name
         ,v.*
    from sys.x_ksmsp v)
  ,ksmsp as 
  (select name                          ksmsp_name
        ,round(sum(ksmchsiz)/1024/1024) ksmsp_mb
        ,count(ksmchsiz)                cnt
        ,round(avg(ksmchsiz))           avg
        ,min(ksmchsiz)                  min
        ,max(ksmchsiz)                  max
    from sq group by name)
  ,ksmss as 
  (select ksmssnam                      ksmss_name
      ,round(sum(ksmsslen)/1024/1024)  ksmss_mb
    from sys.x_ksmss 
    where (ksmssnam, ksmdsidx) not in (('free memory', 0))
    group by ksmssnam)
select ksmss_name
      ,ksmss_mb
      ,nvl(ksmss_mb, 0) - nvl(ksmsp.ksmsp_mb, 0) delta_mb
      ,ksmsp.*
from ksmss full outer join ksmsp
  on lower(ksmss.ksmss_name) = lower(ksmsp.ksmsp_name)
where ksmss.ksmss_name in ('KKSSP', 'db_block_hash_buckets', 'KGLH0', 'SQLA', 'free memory')
order by abs(delta_mb) desc nulls last;


KSMSS_NAME             KSMSS_MB  DELTA_MB  KSMSP_NAME   KSMSP_MB  CNT    AVG    MIN   MAX
---------------------- --------- --------- ------------ --------- ------ ------ ----- -------
db_block_hash_buckets  22        22
free memory            90        15        free memory  75        3938   20034  48    2096960
SQLA                   118       -1        SQLA         119       30336  4104   4096  33960
KGLH0                  116       -1        KGLH0        117       29871  4111   4096  52560
KKSSP                  3         0         KKSSP        3         860    4244   568   12352