Monday, March 27, 2017

Oracle 12c PL/SQL Function in the WITH Clause: wrong result

In order to make PL/SQL Function run faster in SQL, Oracle 12c introduced a new feature to integrate PL/SQL Function in the SQL WITH Clause to eliminate SQL-PLSQL context switching.

This Blog is trying to demonstrate that the outcome of this new feature is varied with "ORDER BY" clause.

Note: Tested in Oracle 12.1.0.2.0 on AIX, Solaris, Linux.


1. Build Test



drop table base_tab cascade constraints;

create table base_tab
(
  id    number(12) not null,
  seq   number(9)                    
);

create index base_tab#ix_1 on base_tab (seq, id);

create index base_tab#ix_2 on base_tab (id);

drop table date_tab cascade constraints;

create table date_tab
(
  id          number(12),
  base_id     number(12),
  come_date   date      ,
  constraint date_tab#pk primary key (base_id, come_date) enable validate
) organization index;

insert into base_tab (id, seq) values (1, 11111);
insert into base_tab (id, seq) values (2, 22222);
insert into base_tab (id, seq) values (3, 33333);
insert into base_tab (id, seq) values (4, 4444);

insert into date_tab (id, base_id, come_date) values (11, 1, to_date('2010-01-11', 'yyyy-mm-dd'));
insert into date_tab (id, base_id, come_date) values (33, 3, to_date('2030-03-13', 'yyyy-mm-dd'));
insert into date_tab (id, base_id, come_date) values (44, 4, to_date('2040-04-14', 'yyyy-mm-dd'));

commit;


2. Run Test



--*** test 1: returns 2 rows without order by *** --

with 
  function get_max_date_sqlwith (p_id in number) return date is
    l_date date;
  begin
    select come_date into l_date from (
      select come_date from date_tab where base_id = p_id
       order by come_date desc
       ) where rownum = 1;
    return l_date;
  end;
select b.id
     ,(select get_max_date_sqlwith(b.id) from dual) cdate
  from base_tab b
 where rownum <= 2
--  order by b.id
/

 ID CDATE
--- -----------
  4 14-APR-2040
  1 11-JAN-2010


--*** test 2: returns only 1 row with order by *** --

with 
  function get_max_date_sqlwith (p_id in number) return date is
    l_date date;
  begin
    select come_date into l_date from (
      select come_date from date_tab where base_id = p_id
       order by come_date desc
       ) where rownum = 1;
    return l_date;
  end;
select b.id
     ,(select get_max_date_sqlwith(b.id) from dual) cdate
  from base_tab b
 where rownum <= 2
 order by b.id
/

 ID CDATE
--- -----------
  1 11-JAN-2010

--*** test 3 with_plsql hint: returns 2 rows without order by *** --

select /*+ with_plsql */ * from 
(with 
  function get_max_date_sqlwith (p_id in number) return date is
    l_date date;
  begin
     select come_date into l_date from (
      select come_date from date_tab t where t.base_id = p_id
       order by come_date desc
       ) where rownum = 1;
    return l_date;
  end;
select b.id, get_max_date_sqlwith(b.id) cdate 
  from base_tab b) x
 where rownum <= 2
--  order by x.id
/

 ID CDATE
--- -----------
  4 14-APR-2040
  1 11-JAN-2010

--*** test 4 with_plsql hint: returns only 1 row with order by *** --

select /*+ with_plsql */ * from 
(with 
  function get_max_date_sqlwith (p_id in number) return date is
    l_date date;
  begin
     select come_date into l_date from (
      select come_date from date_tab t where t.base_id = p_id
       order by come_date desc
       ) where rownum = 1;
    return l_date;
  end;
select b.id, get_max_date_sqlwith(b.id) cdate 
  from base_tab b) x
 where rownum <= 2
 order by x.id
/

 ID CDATE
--- -----------
  1 11-JAN-2010


3. Standalone PL/SQL function



--*** test 5: returns 2 rows without order by *** --

create or replace function get_max_date (p_id in number) return date is
  l_date date;
begin
  select come_date into l_date from (
    select come_date from date_tab where base_id = p_id
     order by come_date desc
     ) where rownum = 1;
  return l_date;
end;
/

select b.id
     ,(select get_max_date(b.id) from dual) cdate
  from base_tab b
 where rownum <= 2
--  order by b.id
/

 ID CDATE
--- -----------
  4 14-APR-2040
  1 11-JAN-2010

--*** test 6: returns 2 rows with order by *** --

select b.id
     ,(select get_max_date(b.id) from dual) cdate
  from base_tab b
 where rownum <= 2
 order by b.id
/

 ID CDATE
--- -----------
  1 11-JAN-2010
  2


4. 12c UDF Pragma PL/SQL function



--*** test 7: returns 2 rows without order by *** --

create or replace function get_max_date_UDF (p_id in number) return date is
  l_date date;
  PRAGMA UDF;
begin
  select come_date into l_date from (
    select come_date from date_tab where base_id = p_id
     order by come_date desc
     ) where rownum = 1;
  return l_date;
end;
/

select b.id
     ,(select get_max_date_UDF(b.id) from dual) cdate
  from base_tab b
 where rownum <= 2
--  order by b.id
/

 ID CDATE
--- -----------
  4 14-APR-2040
  1 11-JAN-2010
  
--*** test 8: returns 2 rows with order by *** --

select b.id
     ,(select get_max_date_UDF(b.id) from dual) cdate
  from base_tab b
 where rownum <= 2
 order by b.id
/

 ID CDATE
--- -----------
  1 11-JAN-2010
  2

Monday, March 20, 2017

Oracle abstract_lob Memory Leak

Oracle MOS:
    Bug 14521799 : XMLTYPE.GETCLOBVAL IN AN ANONYMOUS BLOCK VIA EXECUTE IMMEDIATE AND USING LEAKS
reveals a CLOB memory leak.

This Blog will try to demonstrate that it is an abstract_lob Memory Leak.

In Oracle 10g, "What's New in Large Objects?" wrote:
    A new column named 'ABSTRACT_LOBS' has been added to the V$TEMPORARY_LOBS table.
    This column displays the number of abstract LOBs accumulated in the current session.
    Abstract LOBs are temporary lobs returned from queries involving XMLType columns.

Note: all tests are done in Oracle 12.1.0.2.0. See appended Test Code. Case C1 is from MOS Bug 14521799.


1. Run following 3 Tests, each time in a new SQL Session.



SQL (111) > exec test_run_all(1024, 2);

PGA_MEM(MB):Used=7, Alloc=8, Max=11--TEMPORARY_LOBS:CACHE_LOBS=0,NOCACHE_LOBS=0,ABSTRACT_LOBS=0
------ TestCase ------ C1
PGA_MEM(MB):Used=15,Alloc=16,Max=16--TEMPORARY_LOBS:CACHE_LOBS=0,NOCACHE_LOBS=0,ABSTRACT_LOBS=1024
------ TestCase ------ C2
PGA_MEM(MB):Used=24,Alloc=25,Max=25--TEMPORARY_LOBS:CACHE_LOBS=0,NOCACHE_LOBS=0,ABSTRACT_LOBS=2048
------ TestCase ------ C3
PGA_MEM(MB):Used=24,Alloc=25,Max=25--TEMPORARY_LOBS:CACHE_LOBS=0,NOCACHE_LOBS=0,ABSTRACT_LOBS=2049
------ TestCase ------ C4
PGA_MEM(MB):Used=24,Alloc=26,Max=26--TEMPORARY_LOBS:CACHE_LOBS=0,NOCACHE_LOBS=0,ABSTRACT_LOBS=2049
------ TestCase ------ C5
PGA_MEM(MB) Used=24,Alloc=26,Max=26--TEMPORARY_LOBS:CACHE_LOBS=0,NOCACHE_LOBS=0,ABSTRACT_LOBS=2049


SQL (222) > exec test_run_all(1024, 1024);

PGA_MEM(MB): Used=7, Alloc=8, Max=11--TEMPORARY_LOBS:CACHE_LOBS=0,NOCACHE_LOBS=0,ABSTRACT_LOBS=0
------ TestCase ------ C1
PGA_MEM(MB): Used=15,Alloc=16,Max=16--TEMPORARY_LOBS:CACHE_LOBS=0,NOCACHE_LOBS=0,ABSTRACT_LOBS=1024
------ TestCase ------ C2
PGA_MEM(MB): Used=24,Alloc=25,Max=25--TEMPORARY_LOBS:CACHE_LOBS=0,NOCACHE_LOBS=0,ABSTRACT_LOBS=2048
------ TestCase ------ C3
PGA_MEM(MB): Used=24,Alloc=26,Max=26--TEMPORARY_LOBS:CACHE_LOBS=0,NOCACHE_LOBS=0,ABSTRACT_LOBS=2049
------ TestCase ------ C4
PGA_MEM(MB): Used=24,Alloc=26,Max=26--TEMPORARY_LOBS:CACHE_LOBS=0,NOCACHE_LOBS=0,ABSTRACT_LOBS=2049
------ TestCase ------ C5
PGA_MEM(MB): Used=24,Alloc=26,Max=26--TEMPORARY_LOBS:CACHE_LOBS=0,NOCACHE_LOBS=0,ABSTRACT_LOBS=2049


SQL (333) > exec test_run_all(1024, 1024*16);

PGA_MEM(MB): Used=7,Alloc=8,  Max=11--TEMPORARY_LOBS:CACHE_LOBS=0,NOCACHE_LOBS=0,ABSTRACT_LOBS=0
------ TestCase ------ C1
PGA_MEM(MB): Used=49,Alloc=50,Max=50--TEMPORARY_LOBS:CACHE_LOBS=0,NOCACHE_LOBS=0,ABSTRACT_LOBS=1024
------ TestCase ------ C2
PGA_MEM(MB): Used=92,Alloc=93,Max=93--TEMPORARY_LOBS:CACHE_LOBS=0,NOCACHE_LOBS=0,ABSTRACT_LOBS=2048
------ TestCase ------ C3
PGA_MEM(MB): Used=92,Alloc=93,Max=93--TEMPORARY_LOBS:CACHE_LOBS=0,NOCACHE_LOBS=0,ABSTRACT_LOBS=2049
------ TestCase ------ C4
PGA_MEM(MB): Used=92,Alloc=93,Max=93--TEMPORARY_LOBS:CACHE_LOBS=0,NOCACHE_LOBS=0,ABSTRACT_LOBS=2049
------ TestCase ------ C5
PGA_MEM(MB): Used=92,Alloc=93,Max=93--TEMPORARY_LOBS:CACHE_LOBS=0,NOCACHE_LOBS=0,ABSTRACT_LOBS=2049

In Case C1 and C2, PGA_MEM is inflated, hence PGA memory leak; Augmented ABSTRACT_LOBS indicates that the leak is located in abstract_lobs, whereas in Case C3, C4 and C5, PGA_MEM and ABSTRACT_LOBS are constant.

Furthermore, LOB length 2 and 1024 consumes the same amount of memory, so there is certain minimum size for each ABSTRACT_LOB.

Oracle9i Docu: Temporary LOB Performance Guidelines in Oracle9i Application Developer's Guide - Large Objects (LOBs) has a Note:

Temporary LOBs created using a session locator are not cleaned up automatically at the end of function or procedure calls. The temporary LOB should be explicitly freed by calling DBMS_LOB.FREETEMPORARY().

which talks about "session locator", and there is nowhere mentioned "abstract_lob". It is not clear how both are related.

But since Oracle 10g, we can't find this Note any more.

Here is the new link of Oracle 12.2: Temporary LOB Performance Guidelines SecureFiles and Large Objects Developer's Guide.

It contains details about Temporary LOB usage and shows how to get LOB Access Statistics in dynamic performance views.


2. Open a new SQL Session, Run Case C1:



prompt -------- 1st Block --------

begin
 test_run(1, 2, 'C1');
 test_run(100, 2, 'C1');
 test_run(10000, 2, 'C1');
end;
/

prompt -------- 2nd Block --------

begin
 test_run(1, 2, 'C1');
 test_run(100, 2, 'C1');
 test_run(10000, 2, 'C1');
end;
/

-------- 1st Block --------

PGA_MEM(MB): Used=7, Alloc=8, Max=11--TEMPORARY_LOBS:CACHE_LOBS=0,NOCACHE_LOBS=0,ABSTRACT_LOBS=1
PGA_MEM(MB): Used=7, Alloc=8, Max=11--TEMPORARY_LOBS:CACHE_LOBS=0,NOCACHE_LOBS=0,ABSTRACT_LOBS=101
PGA_MEM(MB): Used=95,Alloc=96,Max=96--TEMPORARY_LOBS:CACHE_LOBS=0,NOCACHE_LOBS=0,ABSTRACT_LOBS=10101

-------- 2nd Block --------

PGA_MEM(MB): Used=95,Alloc=96,Max=96--TEMPORARY_LOBS:CACHE_LOBS=0,NOCACHE_LOBS=0,ABSTRACT_LOBS=1
PGA_MEM(MB): Used=95,Alloc=96,Max=96--TEMPORARY_LOBS:CACHE_LOBS=0,NOCACHE_LOBS=0,ABSTRACT_LOBS=101
PGA_MEM(MB): Used=95,Alloc=96,Max=96--TEMPORARY_LOBS:CACHE_LOBS=0,NOCACHE_LOBS=0,ABSTRACT_LOBS=10101

The output shows that the PGA_MEM is not released (leak) between two Blocks, however ABSTRACT_LOBS count is reset.That means once the call if terminated, abstract_lobs in v$temporary_lobs is reset to 0, none abstract_lobs is exposed any more in this view, however their PGA memory is not released.


3. Test till ORA-04030


This test is trying to allocate more than 32GB PGA, and it will take about half hour till hitting ORA-04030 ERROR.

During the test, open another new SQL session, sample PGA memory by:

SQL(555) > exec pga_sampling(777, 3600);

See Blog: dbms_session.get_package_memory_utilization and limitations

Open one more new SQL session, and watch sampling result by (only partial result are shown):

SQL(666) > select * from process_memory_detail_v order by timestamp desc, bytes desc; 

CATEGORY  NAME                  HEAP_NAME         BYTES            ALLOCATION_COUNT 
-------   ---------------       ---------------   --------------   ---------------- 
                                                  
Other     permanent memory      kokltcr: creat    31,680,073,912       8,579,890
Other     free memory           kokltcr: creat       648,951,096       6,239,915
Other     free memory           session heap         616,868,032         445,136
Other     kokltcr: create clob  koh dur heap d       299,515,712       1,559,980

Open a new SQL Session, Run Case C1 and it will raise ORA-04030:
        
SQL(777) > exec test_run(1024*1024*2, 1024*16, 'C1');
------ TestCase ------ C1
BEGIN test_run(1024*1024*2, 1024*16, 'C1'); END;

*
ERROR at line 1:
ORA-04030: out of process memory when trying to allocate 4040 bytes (kokltcr: creat,kghsseg: kolaslCreateCtx)
ORA-06512: at "S.CRE_CLOB", line 10

The incident file looks like:

ORA-04030: out of process memory when trying to allocate 169040 bytes (pga heap,kgh stack)
ORA-04030: out of process memory when trying to allocate 4040 bytes (kokltcr: creat,kghsseg: kolaslCreateCtx)

========= Dump for incident 22642 (ORA 4030) ========
----- Beginning of Customized Incident Dump(s) -----
=======================================
TOP 10 MEMORY USES FOR THIS PROCESS
---------------------------------------

*** 2017-03-17 22:06:16.101
95%   30 GB, 8600973 chunks: "permanent memory          "  
         kokltcr: creat  ds=fffffd77ec09d628  dsprt=fffffd7ffbebb900
 2%  620 MB, 6255235 chunks: "free memory               "  
         kokltcr: creat  ds=fffffd77ec09d628  dsprt=fffffd7ffbebb900
 2%  590 MB, 446319 chunks: "free memory               "  
         session heap    ds=fffffd7ffc02d728  dsprt=fffffd7ffc358350
 1%  286 MB, 1563814 chunks: "kokltcr: create clob      "  
         koh dur heap d  ds=fffffd7ffbebb900  dsprt=fffffd7ffc02d728
 0%   62 MB, 781909 chunks: "kolraloc-1                "  
         kolr heap ds i  ds=fffffd7ffc048488  dsprt=fffffd7ffc02d728
 0%   61 MB, 3850 chunks: "kolrde_alloc              "  
         koh-kghu sessi  ds=fffffd7ffc05edd8  dsprt=fffffd7ffc02d728
 0%   48 MB, 781907 chunks: "kolrarfc:lobloc_kolrhte   "  
         kolr heap ds i  ds=fffffd7ffc048488  dsprt=fffffd7ffc02d728
 0%   27 MB, 195483 chunks: "free memory               "  
         koh dur heap d  ds=fffffd7ffbebb900  dsprt=fffffd7ffc02d728
 0%  828 KB, 17329 chunks: "free memory               "  
         kolr heap ds i  ds=fffffd7ffc048488  dsprt=fffffd7ffc02d728
 0%  505 KB,  34 chunks: "permanent memory          "  
         pga heap        ds=fffffd7ffc345640  dsprt=0

We can see that "30 GB, 8600973 chunks" are allocated as "permanent memory", that probably explains why it is not reclaimable and hence a memory leak.


4. Temporary LOBs: CACHE_LOBS, NOCACHE_LOBS, ABSTRACT_LOBS


Here a small test of Temporary LOBs: CACHE_LOBS, NOCACHE_LOBS, ABSTRACT_LOBS, and their space usage (tested in Oracle 12cR1 and 12cR2).

------------------------------ SetUp -------------------------------
create or replace package lob_cache_test_pkg as
 g_CACHE_LOBS    clob;
 g_NOCACHE_LOBS  clob;
 g_ABSTRACT_LOBS clob;
end;
/

create or replace procedure lob_cache_test_CACHE_LOBS (p_cnt number) as 
 l_txt varchar2(10) := '0123456789';
begin
  for i in 1..p_cnt loop
    dbms_lob.createtemporary(
      lob_loc => lob_cache_test_pkg.g_CACHE_LOBS, cache => true, dur => dbms_lob.call);
    -- without assignment, or with "dbms_lob.writeappend" create CACHE_LOBS. 
    dbms_lob.writeappend(lob_loc => lob_cache_test_pkg.g_CACHE_LOBS, amount => 10, buffer => l_txt);
  end loop;
end;
/

create or replace procedure lob_cache_test_NOCACHE_LOBS (p_cnt number) as 
 l_txt varchar2(10) := '0123456789';
begin
  for i in 1..p_cnt loop
    dbms_lob.createtemporary(
      lob_loc => lob_cache_test_pkg.g_NOCACHE_LOBS, cache => false, dur => dbms_lob.call);
    -- without assignment, or with "dbms_lob.writeappend" create NOCACHE_LOBS. 
    dbms_lob.writeappend(lob_loc => lob_cache_test_pkg.g_NOCACHE_LOBS, amount => 10, buffer => l_txt);
  end loop;
end;
/

-- 12cR1 not reported space (BLOCKs) usage of ABSTRACT_LOBS in v$tempseg_usage. 
-- But 12cR2 Reported, and put them into CACHE_LOBS.
create or replace procedure lob_cache_test_ABSTRACT_LOBS (p_cnt number) as 
 l_txt varchar2(10) := '0123456789';
begin
  for i in 1..p_cnt loop
    dbms_lob.createtemporary(
      lob_loc => lob_cache_test_pkg.g_ABSTRACT_LOBS, cache => true, dur => dbms_lob.call);
    -- with direct text assignment create ABSTRACT_LOBS. 
    lob_cache_test_pkg.g_ABSTRACT_LOBS := l_txt;
  end loop;
end;
/
Run test and show the output:

--------------------------- Test on 12cR2 ---------------------------
-- It takes hours with "dbms_session.reset_package" to free created temporary LOBs 
-- if their number is high (more than 1,000,000). 
-- LOB Subroutine Callstack: kdlt_freetemp -> kdl_destroy -> kdlclose -> memcmp
--
-- ALTER SYSTEM KILL SESSION 'sid,serial#' releases memory immediately.

exec dbms_session.reset_package; 

select l.*, t.blocks  --t.* 
from v$session s, v$temporary_lobs l, v$tempseg_usage t
where s.sid = l.sid and s.saddr = t.session_addr;

exec lob_cache_test_CACHE_LOBS(1122);

select l.*, t.blocks  --t.* 
from v$session s, v$temporary_lobs l, v$tempseg_usage t
where s.sid = l.sid and s.saddr = t.session_addr;

exec lob_cache_test_NOCACHE_LOBS(1133);

select l.*, t.blocks  --t.* 
from v$session s, v$temporary_lobs l, v$tempseg_usage t
where s.sid = l.sid and s.saddr = t.session_addr;

exec lob_cache_test_ABSTRACT_LOBS(1144);

select l.*, t.blocks  --t.* 
from v$session s, v$temporary_lobs l, v$tempseg_usage t
where s.sid = l.sid and s.saddr = t.session_addr;

--------------------------- Test Result on 12cR2 ---------------------------
   SID CACHE_LOBS NOCACHE_LOBS ABSTRACT_LOBS     CON_ID     BLOCKS
  ---- ---------- ------------ ------------- ---------- ----------
   738          0            0             0          0          0

SQL > exec lob_cache_test_CACHE_LOBS(1122);

   SID CACHE_LOBS NOCACHE_LOBS ABSTRACT_LOBS     CON_ID     BLOCKS
  ---- ---------- ------------ ------------- ---------- ----------
   738       1122            0             0          0       1280
      
SQL > exec lob_cache_test_NOCACHE_LOBS(1133);

   SID CACHE_LOBS NOCACHE_LOBS ABSTRACT_LOBS     CON_ID     BLOCKS
  ---- ---------- ------------ ------------- ---------- ----------
   738       1122         1133             0          0       2304

SQL > exec lob_cache_test_ABSTRACT_LOBS(1144);

   SID CACHE_LOBS NOCACHE_LOBS ABSTRACT_LOBS     CON_ID     BLOCKS
  ---- ---------- ------------ ------------- ---------- ----------
   738       2266         1133          1144          0       3584


5. Test Code



create or replace function cre_clob(p_clob_len number) return clob as
  --l_text varchar2(1024) := lpad('a', 1024, 'b');
  l_clob clob;
  --l_blob blob;                    -- BLOB has similar behaviour
  --l_raw  raw(100) := '4b53554e';
  l_text  varchar2(32767);
begin
  --x := 'aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa';
  --dbms_lob.createtemporary(l_clob, true, dbms_lob.session);
  --for i in 1..1024 loop
  -- dbms_lob.writeappend(l_clob, length(l_text) , l_text);
  --end loop;
  --l_blob := l_raw;
  --return l_blob;
  
  l_text := lpad('a', p_clob_len, 'b');
  
  l_clob := l_text;
  return l_clob;
end;
/

create or replace type t_clob as object(c clob);
/

create or replace type t_clob_tab as table of clob;
/

create or replace procedure print_lob_and_mem as
 l_ret varchar2(400); 
 l_sid number := sys.dbms_support.mysid;
 l_mb  number := 1024*1024;
begin
  select 'PGA_MEM(MB): '||'Used='||round(p.pga_used_mem/l_mb)||', Alloc='||round(p.pga_alloc_mem/l_mb)||', Max='||round(p.pga_max_mem/l_mb)||
        ' --- TEMPORARY_LOBS: '||'CACHE_LOBS='||cache_lobs||', NOCACHE_LOBS='||nocache_lobs||', ABSTRACT_LOBS='||abstract_lobs
   into l_ret
   from v$process p, v$session s, v$temporary_lobs l
 where p.addr=s.paddr and s.sid = l.sid and s.sid = l_sid;
 dbms_output.put_line(l_ret);
end;
/

--exec print_lob_and_mem;

create or replace procedure test_run(p_cnt number, p_clob_len number, p_case varchar2) as
  l_stmt_var_c1 varchar2(100); 
  l_stmt_var_c2 varchar2(100); 
  l_stmt_var_c3 varchar2(100);
  l_stmt_var_c4 varchar2(100);
  l_clob        clob; 
  l_clob_t      t_clob     := t_clob(null);
  l_clob_tab    t_clob_tab := t_clob_tab();
begin 
  l_stmt_var_c1 := 'begin select cre_clob('||p_clob_len||') into :c1 from dual; end;';
  l_stmt_var_c2 := 'begin select cre_clob('||p_clob_len||') into :c1 from dual; end;'; 
  l_stmt_var_c3 := 'begin select t_clob(cre_clob('||p_clob_len||')) into :c1 from dual; end;';  
  l_stmt_var_c4 := 'begin select cre_clob('||p_clob_len||') bulk collect into :c1 from dual connect by level <= 1; end;'; 
  
  dbms_output.put_line('------ TestCase ------ '||p_case);
  
  for i in 1..p_cnt loop 
   case p_case
    when 'C1' then
      execute immediate l_stmt_var_c1 using out l_clob;          -- abstrace_lob increasing
        --dbms_lob.freetemporary(l_clob);           -- no help
        --dbms_session.free_unused_user_memory();   -- no help
      when 'C2' then
        execute immediate l_stmt_var_c2 using out l_clob_t.c;    -- abstrace_lob increasing
        l_clob := l_clob_t.c;
      when 'C3' then
        execute immediate l_stmt_var_c3 using out l_clob_t;      -- abstrace_lob constant
        l_clob := l_clob_t.c;
      when 'C4' then
        execute immediate l_stmt_var_c4 using out l_clob_tab;    -- abstrace_lob constant
        l_clob := l_clob_tab(1);
      when 'C5' then
         l_clob := cre_clob(p_clob_len);                         -- abstrace_lob constant
    end case;
  end loop; 
  
  print_lob_and_mem;
end; 
/

--exec test_run(100, 1024, 'C1');

create or replace procedure test_run_all(p_cnt number, p_clob_len number) as
begin
 print_lob_and_mem;
 test_run(p_cnt, p_clob_len, 'C1');
 test_run(p_cnt, p_clob_len, 'C2');
 test_run(p_cnt, p_clob_len, 'C3');
 test_run(p_cnt, p_clob_len, 'C4');
 test_run(p_cnt, p_clob_len, 'C5');
end;
/

PL/SQL Function Result Cache Invalidation (I)

Oracle PL/SQL Function Result Cache is a global cross-session cached associative array, mapping from base data sources to function result, and stored in shared pool:

SQL(64) > select * from v$sgastat where name like '%Result Cache%';

POOL         NAME                            BYTES
------------ -------------------------- ----------
shared pool  Result Cache: Cache Mgr           256
shared pool  Result Cache: Memory Mgr          208
shared pool  Result Cache: State Objs        69920
shared pool  Result Cache                   159880

If changes to any of data sources are committed, the cached result becomes invalid by the DML session, and get rebuilt by the user session which is accessing the function. All build, invalidate and access are synchronized by a single latch:

SQL(854) > select * from v$latch where name = 'Result Cache: RC Latch';

Note: all tests are done in Oracle 12.1.0.2.0. See appended Test Code.

1. Build


Run:

SQL(64) > exec dbms_result_cache.flush;
SQL(64) > exec run_test;

List Result Cache:

select scn_to_timestamp(scn) scn_time, ro.* 
from v$result_cache_objects ro 
where 1=1
--  and type = 'Dependency'
--  and status = 'Invalid'
order by scn_time, scn;

Display dependencies:

select count(*) from v$result_cache_dependency;

 COUNT(*)
---------
       51

select distinct
  from_obj.name from_name, from_obj.type, from_obj.status, from_obj.namespace,
  from_obj.scn, scn_to_timestamp(from_obj.scn) scn_time,
  to_obj.name to_name, to_obj.type to_type, to_obj.status to_status, to_obj.namespace to_namespace, 
  to_obj.scn to_scn, scn_to_timestamp(to_obj.scn) to_scn_time
from v$result_cache_objects    from_obj, 
     v$result_cache_dependency dep,
     v$result_cache_objects    to_obj
where from_obj.id = dep.result_id 
  and to_obj.id   = dep.depend_id
--  and to_obj.name in ('K.RC_TAB_DEP', 'K.RC_TAB')
--  and from_obj.name like '%"K"."%GET_VAL"%'
order by from_obj.scn;


2. Invalidate



SQL(64) > update rc_tab_dep set dval=33 where did = 3;

SQL(64) > select s.sid, t.used_urec from v$transaction t, v$session s 
           where t.ses_addr=s.saddr and s.sid=sys.dbms_support.mysid;      
 
 SID  USED_UREC
---- ----------
  64          1 

SQL(64) > select * from v$result_cache_statistics
            where lower(name) like '%invalid%'; 

 ID NAME                   VALUE
--- ---------------------- -----
  8 Invalidation Count     0
  9 Delete Count Invalid   0

SQL(64) > select count(*) from v$result_cache_dependency;

 COUNT(*)
---------
       51

SQL(64) > commit;

SQL(64) > select * from v$result_cache_statistics
            where lower(name) like '%invalid%'; 

 ID NAME                   VALUE
--- ---------------------- -----
  8 Invalidation Count     17
  9 Delete Count Invalid   0
  
SQL(64) > select count(*) from v$result_cache_dependency;

 COUNT(*)
---------
       0  

The granularity of invalidation seems in table unit, even only one single row is updated, all result cache entries depending on that table are invalidate. Above test shows that "Invalidation Count" is increased from 0 to 17 (17 "GET_VAL" result cache entries).

3. Invalidate: select for update


Rebuild Cache, and then run a "select for update" for one row:

SQL(64) > exec dbms_result_cache.flush;
SQL(64) > exec run_test;

SQL(64) > select * from rc_tab_dep where did = 3 for update;

SQL(64) > select s.sid, t.used_urec from v$transaction t, v$session s 
           where t.ses_addr=s.saddr and s.sid=sys.dbms_support.mysid;      
 
 SID  USED_UREC
---- ----------
  64          1 

Get spid 13699 of test session (SID 64), open a Solaris window, run command:

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

Back to SQL Window, run:

SQL(64) > commit;

Session is hanging.

Solaris window prints out Stack Trace:

    oracle`qesrcRO_Invalidate
    oracle`qesrcDO_Invalidate+0x9c8
    oracle`qesrcCM_PreCmt_+0xd81
    oracle`ktcCommitTxn_new+0x2a7
    oracle`ktcCommitTxn+0x59
    oracle`ktdcmt+0x8b
    oracle`k2lcom+0x94
    oracle`k2send+0x4f3
    oracle`xctctl+0x62
    oracle`xctCommitTxn+0x2b8

Open a second SQL Window, build Result Cache for function get_val_2, which is irrelevant to function get_val:

SQL(512) > exec run_test_2;

Make some check on Unix side:

-- spid 10502 of test session (SID 512), check callstack:

$  pstack 10502

 fffffd7ffc9d3e3b semsys   (2, c00000f, fffffd7fffdf4968, 1, d0)
 0000000001ab90f5 sskgpwwait () + 1e5
 0000000001ab8c95 skgpwwait () + c5
 0000000001ab7ab0 kslgess () + 980
 0000000001ab6cef ksl_get_shared_latch () + 39f
 0000000005ab76ab qesrcPin_Get () + 8cb
 0000000005aa8ff4 qesrcCM_Acquire () + 354
 000000000bd2287d psdfrcLookup () + 12d
 000000000e001883 pevm_ENTERX () + 143
 000000000dfc2907 pfrinstr_ENTERX () + 47
 0000000001a435ca pfrrun_no_tool () + 12a
 
$  ipcs -as
 T         ID      KEY        MODE        OWNER    GROUP  CREATOR   CGROUP NSEMS   OTIME    CTIME
 Semaphores:
 s  201326607   0x375d691c --ra-r-----   oracle      dba   oracle      dba   704 13:14:45 15:52:33

We can see:
 semid = 201326607 = 0xc00000f
 
and "0xc00000f" is 
 semsys   (2, c00000f, fffffd7fffdf4968, 1, d0)
 
in pstack output, and 2 is semop defined in syscall.h:
 semop (...) :: semsys(2, ...)
 
 int semop(int semid, struct sembuf *sops, size_t nsops);
 

If we truss the blocking session, we can also see the same semid with semnum begin 34 and 16.
One thing we noticed is that truss de-blocks (unlock) the blocking session (like prun).

$  truss -dp 13699 
/1:     833.5393        semctl(201326607, 34, SETVAL, 1)                = 0
/1:     833.5395        semctl(201326607, 16, SETVAL, 1)                = 0
/1:     833.5395        lwp_info(0xFFFFFD7FFFDF7440)                    = 0

It hangs on Result Cache: RC Latch.

On a third SQL Window, watch the blocking:

SQL(1024) > select sid, blocker_sid, blocker_is_valid, wait_event_text, p2 from v$wait_chains;

  SID BLOCKER_SID BLOCK WAIT_EVENT_TEXT    P2
----- ----------- ----- --------------- -----
  512          64 TRUE  latch free        559
   64             FALSE

SQL(1024) > select * from v$latchholder;

 PID  SID LADDR            NAME                       GETS
---- ---- ---------------- ---------------------- --------
  25   64 00000000600572B0 Result Cache: RC Latch  15564353

On a fourth SQL Window, make select for update on another row:

SQL(768) > select * from rc_tab_dep where did = 5 for update;

       DID       DVAL
---------- ----------
         5         50
1 row selected.

SQL(768) > commit;

The commit is also hanging on "latch free" of 'Result Cache: RC Latch'.

And all other sessions which are accessing or updating Result Cache are waiting for the same latch free (ksl_get_shared_latch).

In this test, we started one transaction by "select for update", but did not update any row, however, "commit" triggered a call to "qesrcRO_Invalidate", hence held "RC Latch". Any other later session which requires this latch is waiting for "latch free".

Furthermore, query on any one of
  v$result_cache_objects
  v$result_cache_dependency
  v$result_cache_statistics

is also pending on "RC Latch" "latch free".

The above Stack Trace shows that when a transaction user session calls commit command, commit takes a detour to visit Result Cache along its code path in order to perform the invalidation before publishing the confirmed and consistent news to the world. Therefore, Function Result Cache is not free of charge. It demands the resources to maintain the database wide consistence, and thus PL/SQL Function Result Cache (in Oracle Database PL/SQL Language Reference) said:

Oracle Database automatically detects all data sources (tables and views) that are queried while a result-cached function is running. If changes to any of these data sources are committed, the cached result becomes invalid and must be recomputed. The best candidates for result-caching are functions that are invoked frequently but depend on information that changes infrequently or never.

This behavior of "SELECT FOR UPDATE" is described in Oracle MOS
    Bug 17855824 : PLSQL RESULT CACHE WRONGLY INVALIDATED BY A SELECT FOR UPDATE STATEMENT


4. RC Latch "ksl_get_shared_latch" tracing


For each RC Latch Get, the call stack looks like:

 0000000001ab696b ksl_get_shared_latch () + 1b
 0000000005ab76ab qesrcPin_Get () + 8cb
 0000000005aa8ff4 qesrcCM_Acquire () + 354
 000000000bd2287d psdfrcLookup () + 12d
 000000000e001883 pevm_ENTERX () + 143
In case of Latch Miss, the process yields the CPU and goes to sleep:

 fffffd7ffc9d396a yield () + a
 0000000005ab78d6 qesrcPin_Get () + af6
 0000000005aa8ff4 qesrcCM_Acquire () + 354
 000000000bd2287d psdfrcLookup () + 12d
 000000000e001883 pevm_ENTERX () + 143
Run the same test, and measure Latch Get time in qesrcCM_Acquire (CM: Cache Manager) by dtrace:

SQL > exec run_test;

$ dtrace -n \
'BEGIN {self->start_wts = walltimestamp; self->start_ts = timestamp;}
pid$target::qesrcCM_Acquire:entry /execname == "oracle"/ { self->rc = 1; }
pid$target::ksl_get_shared_latch:entry /execname == "oracle" && self->rc == 1/ { self->ts = timestamp; }
pid$target::ksl_get_shared_latch:return /self->ts > 0/ {  
 @lquant["ns"] = lquantize(timestamp - self->ts, 0, 10000, 1000); 
 @avgs["AVG_ns"] = avg(timestamp - self->ts);
 @mins["MIN_ns"] = min(timestamp - self->ts);
 @maxs["MAX_ns"] = max(timestamp - self->ts);
 @sums["SUM_ms"] = sum((timestamp - self->ts)/1000000);
 @counts[ustack(10, 0)] = count(); 
 self->rc = 0; self->ts = 0;}
END { printf("Start: %Y, End: %Y, Elapsed_ms: %d\n", self->start_wts, walltimestamp, (timestamp - self->start_ts)/1000000);}
' -p 13699

  Start: 2017 Sep  4 14:54:02, End: 2017 Sep  4 14:54:06, Elapsed_ms: 3939

  ns
           value  ------------- Distribution ------------- count
               0 |                                         0
            1000 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@      15
            2000 |@@                                       1
            3000 |                                         0
            4000 |                                         0
            5000 |                                         0
            6000 |@@                                       1
            7000 |                                         0

  AVG_ns    1605
  MIN_ns    1140
  MAX_ns    6891
  SUM_ms       0

  oracle`ksl_get_shared_latch+0x17a
  oracle`qesrcCM_Acquire+0x34b
  oracle`psdfrcLookup+0x119
  oracle`pevm_ENTERX+0x142
  oracle`pfrinstr_ENTERX+0x3e
  oracle`pfrrun_no_tool+0xc2
  oracle`pfrrun+0x4a2
  oracle`plsql_run+0x278
  oracle`peicnt+0x14d
  oracle`kkxexe+0x205
    17


5. Causal Analysis of Result Cache


V$RESULT_CACHE_OBJECTS provides 4 time related columns:
(a). CREATION_TIMESTAMP: 
      Time when the object was first time created in Result Cache, and never changed for both TYPE: Result and Dependency.
   
(b). SCN:    
      For TYPE = Result, it is the SCN of first time created in Result Cache, same as CREATION_TIMESTAMP;
      Its STATUS is 'Published' if valid; 'Invalid' if invalidated (for example, due to Dependency).
      Its OBJECT_NO is always 0.

      For TYPE = Dependency, when first time inserted, it is the SCN of time created in Result Cache, same as CREATION_TIMESTAMP.
      Its STATUS is always 'Published', never 'Invalid'. Therefore for Dependency, there is no 'Invalid'.
      Once changed, it is the last Commit SCN (Getting Oracle Transaction Commit SCN).
      SCN timestamp minus CREATION_TIMESTAMP gives us the time span from time Created to time Changed.
      Any existence of this time difference indicates the Change of Dependency, 
      hence it can be used to track Result Invalidation caused by its Dependencies.
      Its OBJECT_NO is Dictionary object number (DBA_OBJECTS.object_id).
     
(c). LRU_NUMBER and SCAN_COUNT: 
      LRU list position, the bigger the value, the more recent the usage.
      (Oracle Docu wrote "the smaller the value, the more recent the usage". It seems not the case.)
      LRU_NUMBER is monotonic and increases one for each access of Result Cache.
      To maintain this ordering, LRU_NUMBERs are shifted by increasing 1 to reflect RC access. 
      It is not clear if there exist multiple LRU Chains because each LRU_NUMBER can have multiple rows.
      (select lru_number, count(*) from v$result_cache_objects where lru_number > 0 group by lru_number order by 2 desc;)

      Following test shows that SCAN_COUNT is the number of calls for one Result Cache item;
      LRU_NUMBER is the total number of calls over entire Result Cache.

 
create or replace function test_scan_lru (p_id number) return number result_cache as
begin
  return p_id;
end;
/

exec dbms_result_cache.flush;

select name, scan_count, lru_number 
from v$result_cache_objects 
where type = 'Result' and name like '%TEST_SCAN_LRU%';

 -- no rows selected

declare
  l_ret number;
begin
  for i in 1..1e6 loop
    l_ret := test_scan_lru(123);
  end loop;
end;
/

select name, scan_count, lru_number 
from v$result_cache_objects 
where type = 'Result' and name like '%TEST_SCAN_LRU%';

 -- NAME                                                   SCAN_COUNT   LRU_NUMBER
 -- ----  ---------------------------------------------- ------------ ------------
 -- "S".  "GET_VAL_3"::8."GET_VAL_3"#3048d2af80817a01 #1      999,999   48,007,056

declare
  l_ret number;
begin
  for i in 1..1e6 loop
    l_ret := test_scan_lru(123);
  end loop;
end;
/

select name, scan_count, lru_number 
from v$result_cache_objects 
where type = 'Result' and name like '%TEST_SCAN_LRU%';

 -- NAME                                                 SCAN_COUNT   LRU_NUMBER
 -- -------------------------------------------------- ------------ ------------
 -- "S"."GET_VAL_3"::8."GET_VAL_3"#3048d2af80817a01 #1    1,999,999   49,007,056
Synthesizing above information, we can compose 3 queries to track Result Cache invalidations, and 2 queries to monitor its usage (see appended "Result Cache Monitoring Views").

-- Last invalidated Dependencies
select * from rc_scn_view;

-- last invalidated Dependencies and Result
select * from rc_scn_dep_view;

-- RC usage
select * from rc_lru_number_view;

-- RC memory
select * from rc_memory_view;
 
-- RC stats
select * from rc_stats_view;


6. Result Cache: RC Latch S mode and X mode Blocking Chains


We will make S mode and X mode blocking test based on the calling API revealed in Blog Oracle 12 and latches:
 The kslgetl and ksl_get_shared_latch functions take the following arguments:
    1-latch address
    2-immediate get (0 means yes, 1 means no)
    3-where (X$KSLLW.INDX)
    4-why (X$KSLWSC.INDX)
    5-mode (8=shared,16=exclusive; only for ksl_get_shared_latch function)
The above text needs two corrections. We will have a look later.
   (1). arguments why (arg2) comes before where(arg3)
   (2). X$KSLLW.INDX and X$KSLWSC.INDX are the same (equal join columns), both point to the where (location).
        X$KSLLW is parent table, X$KSLWSC is child table. 
If Mode=16, arg5 is 20000000 00000000 | <PID>.

It seems that Oracle calls different subroutines for different Latches. ksl_get_shared_latch is C subroutine to get shared Latch (in S Mode or X Mode), for example, result_cache Latch; whereas kslgetl is used to get exclusive Latch, for example, row cache objects Latch.

Following documents have a deep investigation of Latches and Mutexes:
     New features of Latches and Mutexes in Oracle 12c
     [Oracle] Researching internal latch implementation (ksl_get_shared_latch, kslfre, kslgetsl_w) and crashing PMON
     The missing argument of ksl_get_shared_latch : the power of disassembly in action


6.1. S mode Blocking


--------------------- Setup ---------------------
create or replace function rc_s_x_mode_blocking_func (p_x number) return number result_cache as
begin
  return p_x;
end;
/

create or replace procedure rc_s_x_mode_blocking_proc (p_x number) as
 l_x number;
begin
  l_x := rc_s_x_mode_blocking_func(p_x);
end;
/

--------------------- Prepare Test ---------------------
-- Open 3 Test Sessions (SID): S1(4335), S2(6122), S3(7497) with Process (SPID): P1(6114), P2(26548), P3(26550); 
-- and one monitoring Sessions (SID): S4.
-- S1 and S2 request S Mode to get already built Items, where S3 requests X Mode to add a new Item.

-- Build 2 Items in Result Cache.

SQL (S4) > exec dbms_result_cache.flush;

SQL (S4) > exec rc_s_x_mode_blocking_proc(1);
SQL (S4) > exec rc_s_x_mode_blocking_proc(2);

--------------------- Test Steps ---------------------

--==== @T1: S1 requets S Mode, stop at Return (stop at Entry has no blocking). Launch Dtrace at first, then run plsql.

SQL (S1)> exec rc_s_x_mode_blocking_proc(1);

P1$ sudo dtrace -w -n \
'pid$target::qesrcCM*:entry /execname == "oracle"/ { self->rc = 1; }
pid$target::ksl_get_shared_latch:entry /execname == "oracle" && self->rc == 1  && arg4 == 8 / { 
  printf("\n--------Calling %s:%s(Addr=>0x%X, Immed_Get=>%d, Why=>%d, Where=>%d(0x%X), Mode=>%d, PID=>0x%X)", 
         probefunc, probename, arg0, arg1, arg2, arg3, arg3, arg4, arg5);
  self->rc = 2;}
pid$target::ksl_get_shared_latch:return /self->rc == 2/ {
   printf("\n--------Stopped at %s:%s", probefunc, probename);
   printf("\n--------ustack(5, 0)--------"); ustack(5, 0);
   stop(); exit(0);}
' -p 6114

 CPU     ID                    FUNCTION:NAME
   1  80660       ksl_get_shared_latch:entry
--------Calling ksl_get_shared_latch:entry
    (Addr=>0x600572B0, Immed_Get=>1, Why=>1, Where=>5358(0x14EE), Mode=>8, PID=>0x1)
   1  80661      ksl_get_shared_latch:return
--------Stopped at ksl_get_shared_latch:return
--------ustack(5, 0)--------
              oracle`ksl_get_shared_latch+0x1b8
              oracle`qesrcCM_Acquire+0x354
              oracle`psdfrcLookup+0x12d
              oracle`pevm_ENTERX+0x143
              oracle`pfrinstr_ENTERX+0x47

-- oradebug peek RC Latch address
SQL> oradebug setmypid
Statement processed.
SQL> oradebug peek 0x600572B0 24
[0600572B0, 0600572C8) = 00000001 00000000 0C56FEFC 0000022F 00000002 000014EE
                            Nproc  ˆX flag     gets   latch#   level#    where


SQL (S4)> select addr, gets, misses, sleeps, immediate_gets, spin_gets, wait_time from v$latch where latch# in (559) or name in ('Result Cache: RC Latch');
  ADDR              GETS       MISSES   SLEEPS  IMMEDIATE_GETS  SPIN_GETS  WAIT_TIME
  ----------------  ---------  -------  ------  --------------  ---------  ----------
  00000000600572B0  207027964  1011584  508174  0               797961     4975709595

SQL (S4)> select * from v$latchholder;
  PID  SID   LADDR             NAME                    GETS     
  ---- ----  ----------------  ----------------------  ---------  
  33   4335  00000000600572B0  Result Cache: RC Latch  207027964 


--==== @T2: S2 requets S Mode, not blocked

SQL (S2)> exec rc_s_x_mode_blocking_proc(2);

SQL (S4)> select addr, gets, misses, sleeps, immediate_gets, spin_gets, wait_time from v$latch where latch# in (559) or name in ('Result Cache: RC Latch');
  ADDR              GETS       MISSES   SLEEPS  IMMEDIATE_GETS  SPIN_GETS  WAIT_TIME
  ----------------  ---------  -------  ------  --------------  ---------  ----------
  00000000600572B0  207027965  1011584  508174  0               797961     4975709595

SQL (S4)> select * from v$latchholder;
  PID  SID   LADDR             NAME                    GETS     
  ---- ----  ----------------  ----------------------  ---------  
  33   4335  00000000600572B0  Result Cache: RC Latch  207027965 

--==== @T3: S3 requets X Mode Request, blocked by S1, Wait: latch free. Launch Dtrace at first, then run plsql.

SQL (S3)> exec rc_s_x_mode_blocking_proc(3);

P3$ sudo dtrace -n \
'pid$target::qesrcCM*:entry /execname == "oracle"/ { self->rc = 1; }
pid$target::ksl_get_shared_latch:entry /execname == "oracle" && self->rc == 1  && arg4 == 16 / { 
  printf("\n--------Calling %s:%s(Addr=>0x%X, Immed_Get=>%d, Why=>%d, Where=>%d(0x%X), Mode=>%d, PID=>0x%X))", 
          probefunc, probename, arg0, arg1, arg2, arg3, arg3, arg4, arg5);
  printf("\n--------ustack(5, 0)--------"); ustack(5, 0); self->rc = 0;}
' -p 26550

 CPU     ID                    FUNCTION:NAME
   1  80816       ksl_get_shared_latch:entry
--------Calling ksl_get_shared_latch:entry
    (Addr=>0x600572B0, Immed_Get=>1, Why=>1, Where=>5347(0x14E3), Mode=>16, PID=>0x2000000000000023))
--------ustack(5, 0)--------
              oracle`ksl_get_shared_latch
              oracle`qesrcCM_AddDO_+0x43b5
              oracle`qesrcCM_AddDO+0xf3
              oracle`qesrcCM_Acquire+0x702
              oracle`psdfrcLookup+0x12d

-- oradebug peek RC Latch address              
SQL>  oradebug peek 0x600572B0 24
[0600572B0, 0600572C8) = 00000001 40000000 0C56FEFE 0000022F 00000002 000014EE
                            Nproc  ˆX flag     gets   latch#   level#    where  

--******** S3 stopped here, resumed when S1 is set run ********--

   1  80816       ksl_get_shared_latch:entry
--------Calling ksl_get_shared_latch:entry
    (Addr=>0x600572B0, Immed_Get=>1, Why=>1, Where=>5358(0x14EE), Mode=>16, PID=>0x2000000000000023))
--------ustack(5, 0)--------
              oracle`ksl_get_shared_latch
              oracle`qesrcPin_Get+0x959
              oracle`qesrcCM_Acquire+0x354
              oracle`psdfrcLookup+0x12d
              oracle`pevm_ENTERX+0x143

   1  80816       ksl_get_shared_latch:entry
--------Calling ksl_get_shared_latch:entry
    (Addr=>0x600572B0, Immed_Get=>1, Why=>1, Where=>5374(0x14FE), Mode=>16, PID=>0x2000000000000023))
--------ustack(5, 0)--------
              oracle`ksl_get_shared_latch
              oracle`qesrcCM_Release+0x293
              oracle`psdfrcWriteResult+0x213
              oracle`pevm_RET+0x3d9
              oracle`pfrinstr_RET+0x26

P4$ pstack 26550

  ------------  lwp# 1 / thread# 1  ---------------
   ffff80ffbdba36eb semsys   (2, 33, ffff80ffbfff2f68, 1, 29d)
   000000000578adc5 sskgpwwait () + 1e5
   000000000578a965 skgpwwait () + c5
   000000000578972d kslgess () + 92d
   00000000057889bf ksl_get_shared_latch () + 39f
   00000000097a4145 qesrcCM_AddDO_ () + 43b5
   00000000097a4d03 qesrcCM_AddDO () + f3
   00000000097aa772 qesrcCM_Acquire () + 702
   000000000fa4e10d psdfrcLookup () + 12d
   0000000011d2e163 pevm_ENTERX () + 143

SQL (S4)> select addr, gets, misses, sleeps, immediate_gets, spin_gets, wait_time from v$latch where latch# in (559) or name in ('Result Cache: RC Latch');
  ADDR              GETS       MISSES   SLEEPS  IMMEDIATE_GETS  SPIN_GETS  WAIT_TIME
  ----------------  ---------  -------  ------  --------------  ---------  ----------
  00000000600572B0  207027966  1011584  508174  0               797961     4975709595

SQL (S4)> select * from v$latchholder;
  PID  SID   LADDR             NAME                    GETS     
  ---- ----  ----------------  ----------------------  ---------  
  33   4335  00000000600572B0  Result Cache: RC Latch  207027966 
  
SQL (S4)> select sid, blocker_sid, blocker_is_valid, chain_signature, in_wait wait_event_text, p1, p2, p3, in_wait_secs, num_waiters from v$wait_chains;  
  SID   OSID   BLOCKER_SID  BLOCKER_OSID  BLOCKER_IS_VALID  CHAIN_SIGNATURE                IN_WAIT  WAIT_EVENT_TEXT  P1          P2   P3  IN_WAIT_SECS  NUM_WAITERS
  ----  -----  -----------  ------------  ----------------  -----------------------------  -------  ---------------  ----------  ---  --  ------------  -----------  
  4335  6114                              FALSE             <='latch free'  FALSE                                                        1
  7497  26550  4335         6114          TRUE              <='latch free'  TRUE     latch free       1610969776  559  0   406           0
 

--==== @T4: S2 requets S Mode again, blocked by S1. Wait Event: latch free. But the real Blocking is caused by S3.

SQL (S2)> exec rc_s_x_mode_blocking_proc(2);

P2$ pstack 26548

   ffff80ffbdba36eb semsys   (2, 33, ffff80ffbfff3948, 1, 11d)
   000000000578adc5 sskgpwwait () + 1e5
   000000000578a965 skgpwwait () + c5
   000000000578972d kslgess () + 92d
   00000000057889bf ksl_get_shared_latch () + 39f
   00000000097b8a7b qesrcPin_Get () + 8cb
   00000000097aa3c4 qesrcCM_Acquire () + 354
   000000000fa4e10d psdfrcLookup () + 12d
   0000000011d2e163 pevm_ENTERX () + 143

SQL (S4)> select addr, gets, misses, sleeps, immediate_gets, spin_gets, wait_time from v$latch where latch# in (559) or name in ('Result Cache: RC Latch');
  ADDR              GETS       MISSES   SLEEPS  IMMEDIATE_GETS  SPIN_GETS  WAIT_TIME
  ----------------  ---------  -------  ------  --------------  ---------  ----------
  00000000600572B0  207027966  1011584  508174  0               797961     4975709595

SQL (S4)> select * from v$latchholder;
  PID  SID   LADDR             NAME                    GETS     
  ---- ----  ----------------  ----------------------  ---------  
  33   4335  00000000600572B0  Result Cache: RC Latch  207027966
  
SQL (S4)> select sid, osid, blocker_sid, blocker_osid, blocker_is_valid, chain_signature, in_wait, wait_event_text, p1, p2, p3, in_wait_secs, num_waiters from v$wait_chains;
  SID   OSID   BLOCKER_SID  BLOCKER_OSID  BLOCKER_IS_VALID  CHAIN_SIGNATURE                IN_WAIT  WAIT_EVENT_TEXT  P1          P2   P3  IN_WAIT_SECS  NUM_WAITERS
  ----  -----  -----------  ------------  ----------------  -----------------------------  -------  ---------------  ----------  ---  --  ------------  -----------
  4335  6114                              FALSE             <='latch free'  FALSE                                                        2
  7497  26550  4335         6114          TRUE              <='latch free'  TRUE     latch free       1610969776  559  0   1403          0
  6122  26548  4335         6114          TRUE              <='latch free'  TRUE     latch free       1610969776  559  0   803           0

 
--==== @T5: resumne S1 running

P1$ prun 6114

SQL (S4)> select addr, gets, misses, sleeps, immediate_gets, spin_gets, wait_time from v$latch where latch# in (559) or name in ('Result Cache: RC Latch');
  ADDR              GETS       MISSES   SLEEPS  IMMEDIATE_GETS  SPIN_GETS  WAIT_TIME
  ----------------  ---------  -------  ------  --------------  ---------  ----------
  00000000600572B0  207027970  1011586  508177  0               797961     6975739595
Above test shows that compatible S Mode not blocking each other; but it blocks X Mode request at ksl_get_shared_latch:entry. Once there exists an X Mode request at ksl_get_shared_latch:entry, all coming S Mode requests are blocked.

Probably this is the behaviour pointed out in Presentation: New features of Latches and Mutexes in Oracle 12c (Andrey Nikolaev) Page 28:
    If the latch is being held in S mode, the X mode waiter will block all further requests.

At T2, V$LATCHHOLDER shows S1 is a RC Latch Holder, but there are not yet any blocked sessions. So the existence of Latch Holder does not necessarily mean blockings.

From T3 (or T4) to T5, V$LATCH shows there are 4 (207027970-207027966) Gets, 2 (1011586-1011584) Misses, 3 (508177-508174) Sleeps. Among them,
     S3 made 3 X Mode (16) Gets, 1 Miss and 2 Sleeps.
     S2 made 1 S Mode (8) Get, 1 Miss and 1 Sleep.

S3 made 3 X Mode Gets for:
     qesrcCM_AddDO
     qesrcCM_Acquire
     psdfrcWriteResult

It also demonstrated that 1 Miss can provoke more Sleeps.

If we expand GV$LATCH_MISSES definition by adding column: INDX:

CREATE OR REPLACE FORCE VIEW X_GV$LATCH_MISSES as
SELECT t1.indx              INDX,
       t1.inst_id           INST_ID,       
       t1.ksllasnam         PARENT_NAME,   
       t2.ksllwnam          "WHERE",       
       t1.kslnowtf          NWFAIL_COUNT,  
       t1.kslsleep          SLEEP_COUNT,   
       t1.kslwscwsl         WTR_SLP_COUNT, 
       t1.kslwsclthg        LONGHOLD_COUNT,
       t2.ksllwnam          LOCATION,      
       t1.con_id            CON_ID         
  FROM x$ksllw t2, x$kslwsc t1
 WHERE t2.indx = t1.indx;
and run query below to map INDX to "WHERE" or "LOCATION".

select * from sys.X_GV$LATCH_MISSES 
where parent_name in ('Result Cache: RC Latch') 
  and indx in (5347, 5358, 5374, 5359);
  
INDX  INST_ID  PARENT_NAME             WHERE                          NWFAIL_COUNT  SLEEP_COUNT  WTR_SLP_COUNT  LONGHOLD_COUNT  LOCATION
----- -------  ----------------------  -----------------------------  ------------  -----------  -------------  --------------  -----------------------------
5347  1        Result Cache: RC Latch  Result Cache: Serialization01  0             9633         119281         712             Result Cache: Serialization01
5358  1        Result Cache: RC Latch  Result Cache: Serialization12  0             1303643      1036967        79711           Result Cache: Serialization12
5359  1        Result Cache: RC Latch  Result Cache: Serialization13  0             1776         116077         176             Result Cache: Serialization13
5374  1        Result Cache: RC Latch  Result Cache: Serialization28  0             2300         53438          474             Result Cache: Serialization28  
In GV$LATCH_MISSES definition, parent x$ksllw stores "WHERE" names, child x$kslwsc stores real values. Both WHERE and LOCATION are same.

In AWR Section: Latch Miss Sources, only gv$latch_misses (nwfail_count, sleep_count, wtr_slp_count) are visible. Unfortunately longhold_count is not reported, but longhold_count often signifies the X Mode Requests, which caused RC Latch longhold.

oradebug peek shows S Mode Blocking state transition. Flag 40000000 denotes S Mode Blocking.

--==== @T1: S1 requets S Mode. Get RC item at 1st Session, then Stop
[0600572B0, 0600572C8) = 00000001 00000000 0C56FEFC 0000022F 00000002 000014EE   
                            Nproc ˆX flag      gets   latch#   level#    where
                            
--==== @T3: S3 requets X Mode Request. Add RC item at 3rd Session, blocked
[0600572B0, 0600572C8) = 00000001 40000000 0C56FEFE 0000022F 00000002 000014EE   
                            Nproc ˆX flag      gets   latch#   level#    where
Note: In AIX oradebug peek output, "ˆX flag" comes before "Nproc":

SQL> oradebug peek 0x0700000000055978 24;
SQL> [700000000055978, 700000000055990) = 00000000 00000001 0D298B4B 022F0000 00000002 000014EE
SQL> [700000000055978, 700000000055990) = 40000000 00000001 0D298B4F 022F0000 00000002 000014EE
SQL> [700000000055978, 700000000055990) = 40000000 00000000 0D298B50 022F0000 00000002 000014EE
                                           ˆX flag    Nproc     gets   latch#   level#    where

SQL> [700000000055978, 700000000055990) = 20000000 00000058 0D2984B2 022F0000 00000002 000014FE
                                           ˆX flag     pidˆ     gets   latch#   level#    where


6.2. X mode Blocking


The approach we picked out to study Oracle RC Latch activity is trying to depict its State-Transition Diagrams.
  dtrace to show Transition Event (Call Stack), paused to view State.
  oradebug Peek to display State.
  prun to resume Transition.

--------------------- Test X Mode Blocking ---------------------
-- Open 2 Solaris Windows, and one Sqlplus session. 
-- In first Solaris Windows, run dtrace; in second Solaris Windows, run oradebug and host prun.
-- Launch Dtrace at first, then run plsql.

SQL > exec rc_s_x_mode_blocking_proc(6);   

sudo dtrace -w -n \
'BEGIN {self->seq = 1; }
pid$target::qesrcCM*:entry /execname == "oracle"/ { self->rc = 1; }
pid$target::ksl_get_shared_latch:entry / self->rc > 0 && arg0 == 0x600572B0 && (arg4 == 8 || arg4 == 16) / { 
   printf("\nStep %d at %Y--------Calling %s:%s(Addr=>0x%X, Immed_Get=>%d, Why=>%d, Where=>%d(0x%X), Mode=>%d, PID=>0x%X)", 
          self->seq, walltimestamp, probefunc, probename, arg0, arg1, arg2, arg3, arg3, arg4, arg5);
   self->rc = 2; self->seq = self->seq + 1; }
pid$target::ksl_get_shared_latch:return /self->rc > 1/ {
   printf("\nStep %d at %Y--------Stopped at %s:%s", self->seq, walltimestamp, probefunc, probename);
   printf("\n--------ustack(5, 0)--------"); ustack(5, 0); self->seq = self->seq + 1; 
   stop();}
pid$target::kslfre:entry /self->rc > 1 && arg0 == 0x600572B0/ {
   printf("\nStep %d at %Y--------Stopped at %s:%s(Addr=>0x%-X)", self->seq, walltimestamp, probefunc, probename, arg0);
   printf("\n--------ustack(5, 0)--------"); ustack(5, 0); self->seq = self->seq + 1; self->rc = 3; 
   stop();} 
pid$target::kslfre:return /self->rc == 3/ {
   printf("\nStep %d at %Y--------Stopped at %s:%s(Addr=>0x%-X)", self->seq, walltimestamp, probefunc, probename, arg0);
   printf("\n--------ustack(5, 0)--------"); ustack(5, 0); self->seq = self->seq + 1; self->rc = 2;
   stop();}       
' -p 24559

SQL> oradebug peek 0x600572B0 24
     [0600572B0, 0600572C8) = 00000000 00000000 84BD178B 0000022F 00000002 000014FE
SQL> host prun 24559

dtrace: allowing destructive actions
 CPU     ID                    FUNCTION:NAME
   1  81838       ksl_get_shared_latch:entry
Step 1 at 2017 Sep 21 12:04:56--------Calling ksl_get_shared_latch:entry
       (Addr=>0x600572B0, Immed_Get=>1, Why=>1, Where=>5358(0x14EE), Mode=>8, PID=>0x1)

   1  81839      ksl_get_shared_latch:return
Step 3 at 2017 Sep 21 12:04:56--------Stopped at ksl_get_shared_latch:return
--------ustack(5, 0)--------
              oracle`ksl_get_shared_latch+0x1b8
              oracle`qesrcCM_Acquire+0x354
              oracle`psdfrcLookup+0x12d
              oracle`pevm_ENTERX+0x143
              oracle`pfrinstr_ENTERX+0x47

SQL> oradebug peek 0x600572B0 24             
     [0600572B0, 0600572C8) = 00000001 00000000 84BD178C 0000022F 00000002 000014EE
SQL> host prun 24559                   

   1  81838       ksl_get_shared_latch:entry
Step 5 at 2017 Sep 21 12:06:05--------Calling ksl_get_shared_latch:entry
     (Addr=>0x600572B0, Immed_Get=>1, Why=>1, Where=>5347(0x14E3), Mode=>16, PID=>0x2000000000000023)

   1  81839      ksl_get_shared_latch:return
Step 7 at 2017 Sep 21 12:06:05--------Stopped at ksl_get_shared_latch:return
--------ustack(5, 0)--------
              oracle`ksl_get_shared_latch+0x1b8
              oracle`qesrcCM_AddDO+0xf3
              oracle`qesrcCM_Acquire+0x702
              oracle`psdfrcLookup+0x12d
              oracle`pevm_ENTERX+0x143
              
SQL> oradebug peek 0x600572B0 24
     [0600572B0, 0600572C8) = 00000023 20000000 84BD178D 0000022F 00000002 000014E3         
SQL> host prun 24559     

   1  81838       ksl_get_shared_latch:entry
Step 9 at 2017 Sep 21 12:08:07--------Calling ksl_get_shared_latch:entry
     (Addr=>0x600572B0, Immed_Get=>1, Why=>1, Where=>5358(0x14EE), Mode=>16, PID=>0x2000000000000023)

   1  81839      ksl_get_shared_latch:return
Step 11 at 2017 Sep 21 12:08:07--------Stopped at ksl_get_shared_latch:return
--------ustack(5, 0)--------
              oracle`ksl_get_shared_latch+0x1b8
              oracle`qesrcCM_Acquire+0x354
              oracle`psdfrcLookup+0x12d
              oracle`pevm_ENTERX+0x143
              oracle`pfrinstr_ENTERX+0x47
              
SQL> oradebug peek 0x600572B0 24  
     [0600572B0, 0600572C8) = 00000023 20000000 84BD178E 0000022F 00000002 000014EE
SQL> host prun 24559               

   1  81838       ksl_get_shared_latch:entry
Step 13 at 2017 Sep 21 12:08:51--------Calling ksl_get_shared_latch:entry
     (Addr=>0x600572B0, Immed_Get=>1, Why=>1, Where=>5374(0x14FE), Mode=>16, PID=>0x2000000000000023)

   1  81839      ksl_get_shared_latch:return
Step 15 at 2017 Sep 21 12:08:51--------Stopped at ksl_get_shared_latch:return
--------ustack(5, 0)--------
              oracle`ksl_get_shared_latch+0x1b8
              oracle`psdfrcWriteResult+0x213
              oracle`pevm_RET+0x3d9
              oracle`pfrinstr_RET+0x26
              oracle`pfrrun_no_tool+0x12a
              
SQL> oradebug peek 0x600572B0 24  
     [0600572B0, 0600572C8) = 00000023 20000000 84BD178F 0000022F 00000002 000014FE
SQL> host prun 24559               

   1  81840                     kslfre:entry
Step 16 at 2017 Sep 21 12:09:27--------Stopped at kslfre:entry(Addr=>0x600572B0)
--------ustack(5, 0)--------
              oracle`kslfre
              oracle`qesrcCM_Release+0x22d
              oracle`psdfrcWriteResult+0x213
              oracle`pevm_RET+0x3d9
              oracle`pfrinstr_RET+0x26

   1  81841                     kslfre:entry
Step 17 at 2017 Sep 21 12:09:27--------Stopped at kslfre:entry(Addr=>0x600572B0)
--------ustack(5, 0)--------
              oracle`kslfre
              oracle`qesrcCM_Release+0x22d
              oracle`psdfrcWriteResult+0x213
              oracle`pevm_RET+0x3d9
              oracle`pfrinstr_RET+0x26
              
SQL> oradebug peek 0x600572B0 24  
     [0600572B0, 0600572C8) = 00000023 20000000 84BD178F 0000022F 00000002 000014FE
SQL> host prun 24559               

   0  81842                    kslfre:return
Step 18 at 2017 Sep 21 12:10:25--------Stopped at kslfre:return(Addr=>0x172)
--------ustack(5, 0)--------
              oracle`kslfre+0x172
              oracle`psdfrcWriteResult+0x213
              oracle`pevm_RET+0x3d9
              oracle`pfrinstr_RET+0x26
              oracle`pfrrun_no_tool+0x12a
              
SQL> oradebug peek 0x600572B0 24  
     [0600572B0, 0600572C8) = 00000000 00000000 84BD178F 0000022F 00000002 000014FE 
Only looking the oradebug peek output, we can see the state transition of RC Latch values:

SQL> oradebug peek 0x600572B0 24  --S0: initial  
    [0600572B0, 0600572C8) = 00000000 00000000 84BD178B 0000022F 00000002 000014FE
                                 pidˆ  ˆX flag     gets   latch#   level#    where    

SQL> oradebug peek 0x600572B0 24  --S1: Mode=>8  qesrcCM_Acquire+0x354
    [0600572B0, 0600572C8) = 00000001 00000000 84BD178C 0000022F 00000002 000014EE
SQL> host prun 24559  
    
SQL> oradebug peek 0x600572B0 24  --S2: Mode=>16 qesrcCM_AddDO+0xf3
    [0600572B0, 0600572C8) = 00000023 20000000 84BD178D 0000022F 00000002 000014E3
SQL> host prun 24559  

SQL> oradebug peek 0x600572B0 24  --S3: Mode=>16 qesrcCM_Acquire+0x354
    [0600572B0, 0600572C8) = 00000023 20000000 84BD178E 0000022F 00000002 000014EE
SQL> host prun 24559  

SQL> oradebug peek 0x600572B0 24  --S4: Mode=>16 psdfrcWriteResult+0x213
    [0600572B0, 0600572C8) = 00000023 20000000 84BD178F 0000022F 00000002 000014FE
SQL> host prun 24559  

SQL> oradebug peek 0x600572B0 24  --S5: psdfrcWriteResult -> qesrcCM_Release -> kslfre:entry
    [0600572B0, 0600572C8) = 00000023 20000000 84BD178F 0000022F 00000002 000014FE
SQL> host prun 24559  

SQL> oradebug peek 0x600572B0 24  --S6: psdfrcWriteResult -> qesrcCM_Release -> kslfre:return
    [0600572B0, 0600572C8) = 00000000 00000000 84BD178F 0000022F 00000002 000014FE
From S1 to S4, each Step gets once Latch, in total, it requires 4 RC Latch Gets (from 84BD178C to 84BD178F), which are one S Mode(8), and 3 X Mode(16). Therefore, inserting new RC items is much expensive than simply fetching them. In consequence, more latch free wait event on RC Latch pervades over system.

If after the first dtrace stop (Step S1), we also open 3 Sqlplus Sesssions to fetch already existed Result Cache Item (S Mode Get):

SQL > exec rc_s_x_mode_blocking_proc(1);
We observed the following behaviours:
  From S0 -> S1: S Mode get.
  From S2 -> S3 and S3 -> S4: one single blocked S Mode Session(the 1st wating Session) can get RC Latch (deblocked);
                              other Sessions are still blocked (kslfre called ???).
  From S4 -> S5: no S Mode Sessions can get RC Latch, all S Mode Sessions are still blocked.
  From S5 -> S6: all S Mode Sessions get RC Latch.
It looks like that during each X Mode state transition in that X Mode session, maximum one S Mode Session can occasionally get RC Latch, all other S Mode Sessions have to wait till "kslfre" called by that X Mode Session (of course, other X Mode Sessions are also blocked. And first RC Latch Get by each X Mode Session is a S Mode Get).

Above oradebug peek also shows that S Mode and X Mode Blockings are marked by different flags:
  S Mode Blocking:  Blocking is achieved by flag 0x40000000 bit in the latch value.
  X Mode Blocking:  Blocking is achieved by flag 0x20000000 bit in the latch value.                            
In S Mode Blocking, first position (4 bytes) stores Nproc; whereas in X Mode Blocking, first position stores blocking session PID.

[0600572B0, 0600572C8) = 00000001 40000000 0C56FEFE 0000022F 00000002 000014EE
                            Nproc  ˆX flag     gets   latch#   level#    where
                            
[0600572B0, 0600572C8) = 00000023 20000000 84BD178D 0000022F 00000002 000014E3
                             pidˆ  ˆX flag     gets   latch#   level#    where  
Refering to X_GV$LATCH_MISSES (GV$LATCH_MISSES with INDX), we can map INDX to "WHERE":
  5347 (0x14E3) -> Result Cache: Serialization01
  5358 (0x14EE) -> Result Cache: Serialization12
  5360 (0x14F0) -> Result Cache: Serialization14
  5374 (0x14FE) -> Result Cache: Serialization28
Cross-checking with V$RESULT_CACHE_OBJECTS:
  V$RESULT_CACHE_OBJECTS.creation_timestamp = timestamp of psdfrcWriteResult+0x213 Call
  V$RESULT_CACHE_OBJECTS.build_time = 
    from  timestamp of psdfrcWriteResult+0x213 Call 
    to    timestamp of (psdfrcWriteResult -> qesrcCM_Release ->) kslfre:entry Call
Look further two Addresses, they contain Misses: 0x70C257=7389783, and Sleeps: 0xAC913=706835

SQL> oradebug peek 0x0600572C8 24
[0600572C8, 0600572E0) = 00000001 00000000 00000000 0070C257 00000000 00000000

SQL> oradebug peek 0x0600572E0 24
[0600572E0, 0600572F8) = 5CA280DF 00000005 000AC913 00000000 00000000 00000000


6.3. X mode Blocking: Dtrace


With following Dtrace script, we will draw a State Transition Diagram to demonstrate 4 RC Latch Gets (1 S Mode and successive 3 X Mode) when adding a new RC item (only one S Mode when fetching an existed item). For each Transition, we show State Entry and State Return. We can see that there is a kslfre call between two Transitions. That is probably why occasionally other S Mode Sessions (fetching an existed item) can still get RC Latch during this X Mode Session (adding a new item) as discussed in the last section.

-- Launch Dtrace at first, then run plsql to add a new RC item.

SQL > exec rc_s_x_mode_blocking_proc(7); 

sudo dtrace -n \
'
typedef unsigned int ub4;

typedef struct latchstate /* latch state */ {
    ub4 nproc_pid;  /* Nproc or pid   */
    ub4 flag;       /* blocking flag  */ 
    ub4 gets;       /* number of gets */
    ub4 latch;      /* latch number   */
    ub4 level;      /* latch level    */
    ub4 where; } latchstate;
    
BEGIN {laddr = 0x600572B0; step = 1; begin_gets = 0, end_gets = 0; prev_ts = timestamp;
   self->evt = "begin"; self->loc = 0x0;}
pid$target::qesrcCM*:entry /execname == "oracle"/ { self->rc = 1; }
pid$target::ksl_get_shared_latch:entry /self->rc > 0 && arg0 == laddr && (self->evt != probefunc || self->loc != arg3)/ { 
   printf("\n---------Step %d at %Y (Elapsed-ns=%d)---------", step, walltimestamp, (timestamp-prev_ts));
   ls = ((latchstate *) copyin(arg0, sizeof(latchstate)));
   begin_gets = (begin_gets == 0 ? ls->gets: begin_gets); end_gets = ls->gets;
   printf("\n***State Entry>>>(nproc_pid=>0x%X, flag=>0x%X, gets=>0x%X, latch=>0x%X, level=>0x%X, where=>0x%X)"
           ,ls->nproc_pid, ls->flag, ls->gets, ls->latch, ls->level, ls->where);
   printf("\n>>>Transition>>>%s:%s\n      (Addr=>0x%X, Immed_Get=>%d, Why=>%d, Where=>%d(0x%X), Mode=>%d, PID=>0x%X)", 
          probefunc, probename, arg0, arg1, arg2, arg3, arg3, arg4, arg5);
   self->evt = probefunc; self->loc = arg3;    
   ustack(5, 0);   
   step = step + 1; self->entry = 1; prev_ts = timestamp;} 
pid$target::ksl_get_shared_latch:return /self->rc > 0 && self->entry == 1/ {
   ls = ((latchstate *) copyin(laddr, sizeof(latchstate))); 
   printf("\n>>>State Return***(nproc_pid=>0x%X, flag=>0x%X, gets=>0x%X, latch=>0x%X, level=>0x%X, where=>0x%X)"
           ,ls->nproc_pid, ls->flag, ls->gets, ls->latch, ls->level, ls->where);
    self->entry = 0;}   
pid$target::kslfre:entry /self->rc > 0 && arg0 == laddr && self->evt != probefunc/ {
   printf("\n---------Step %d at %Y (Elapsed-ns=%d)---------", step, walltimestamp, (timestamp-prev_ts));
   ls = ((latchstate *) copyin(arg0, sizeof(latchstate)));
   end_gets = ls->gets;
   printf("\n>>>Transition>>>%s:%s(Addr=>0x%-X)", probefunc, probename, arg0);
   self->evt = probefunc; self->loc = 0x0;
   printf("\n===Latch freed===");
   ustack(5, 0); step = step + 1; prev_ts = timestamp;}      
END {
   printf("\n---------Step %d at %Y (Elapsed-ns=%d)---------", step, walltimestamp, (timestamp-prev_ts));
   printf("\nLatch Gets = %d (%d - %d)", (end_gets - begin_gets), (unsigned long)begin_gets, (unsigned long)end_gets); }
' -p 18118

 CPU     ID                    FUNCTION:NAME
   4  81846       ksl_get_shared_latch:entry
---------Step 1 at 2017 Sep 25 08:14:15 (Elapsed-ns=2668662103)---------
***State Entry>>>(nproc_pid=>0x0, flag=>0x0, gets=>0x84BD1DBE, latch=>0x22F, level=>0x2, where=>0x14EE)
>>>Transition>>>ksl_get_shared_latch:entry
      (Addr=>0x600572B0, Immed_Get=>1, Why=>1, Where=>5358(0x14EE), Mode=>8, PID=>0x1)
              oracle`ksl_get_shared_latch
              oracle`qesrcPin_Get+0x8cb
              oracle`qesrcCM_Acquire+0x354
              oracle`psdfrcLookup+0x12d
              oracle`pevm_ENTERX+0x143

   4 128142      ksl_get_shared_latch:return
>>>State Return***(nproc_pid=>0x1, flag=>0x0, gets=>0x84BD1DBF, latch=>0x22F, level=>0x2, where=>0x14EE)
   4  89490                     kslfre:entry
---------Step 2 at 2017 Sep 25 08:14:15 (Elapsed-ns=48752)---------
>>>Transition>>>kslfre:entry(Addr=>0x600572B0)
===Latch freed===
              oracle`kslfre
              oracle`qesrcPin_Get+0xaf6
              oracle`qesrcCM_Acquire+0x354
              oracle`psdfrcLookup+0x12d
              oracle`pevm_ENTERX+0x143

   4  81846       ksl_get_shared_latch:entry
---------Step 3 at 2017 Sep 25 08:14:15 (Elapsed-ns=19989)---------
***State Entry>>>(nproc_pid=>0x0, flag=>0x0, gets=>0x84BD1DBF, latch=>0x22F, level=>0x2, where=>0x14EE)
>>>Transition>>>ksl_get_shared_latch:entry
      (Addr=>0x600572B0, Immed_Get=>1, Why=>1, Where=>5347(0x14E3), Mode=>16, PID=>0x2000000000000024)
              oracle`ksl_get_shared_latch
              oracle`qesrcCM_AddDO_+0x43b5
              oracle`qesrcCM_AddDO+0xf3
              oracle`qesrcCM_Acquire+0x702
              oracle`psdfrcLookup+0x12d

   4 128142      ksl_get_shared_latch:return
>>>State Return***(nproc_pid=>0x24, flag=>0x20000000, gets=>0x84BD1DC0, latch=>0x22F, level=>0x2, where=>0x14E3)
   4  89490                     kslfre:entry
---------Step 4 at 2017 Sep 25 08:14:15 (Elapsed-ns=11792)---------
>>>Transition>>>kslfre:entry(Addr=>0x600572B0)
===Latch freed===
              oracle`kslfre
              oracle`qesrcCM_AddDO_+0x2e0
              oracle`qesrcCM_AddDO+0xf3
              oracle`qesrcCM_Acquire+0x702
              oracle`psdfrcLookup+0x12d

   4  81846       ksl_get_shared_latch:entry
---------Step 5 at 2017 Sep 25 08:14:15 (Elapsed-ns=9352)---------
***State Entry>>>(nproc_pid=>0x0, flag=>0x0, gets=>0x84BD1DC0, latch=>0x22F, level=>0x2, where=>0x14E3)
>>>Transition>>>ksl_get_shared_latch:entry
      (Addr=>0x600572B0, Immed_Get=>1, Why=>1, Where=>5358(0x14EE), Mode=>16, PID=>0x2000000000000024)
              oracle`ksl_get_shared_latch
              oracle`qesrcPin_Get+0x959
              oracle`qesrcCM_Acquire+0x354
              oracle`psdfrcLookup+0x12d
              oracle`pevm_ENTERX+0x143

   4 128142      ksl_get_shared_latch:return
>>>State Return***(nproc_pid=>0x24, flag=>0x20000000, gets=>0x84BD1DC1, latch=>0x22F, level=>0x2, where=>0x14EE)
   4  89490                     kslfre:entry
---------Step 6 at 2017 Sep 25 08:14:15 (Elapsed-ns=25046)---------
>>>Transition>>>kslfre:entry(Addr=>0x600572B0)
===Latch freed===
              oracle`kslfre
              oracle`qesrcPin_Get+0xaf6
              oracle`qesrcCM_Acquire+0x354
              oracle`psdfrcLookup+0x12d
              oracle`pevm_ENTERX+0x143

   4  81846       ksl_get_shared_latch:entry
---------Step 7 at 2017 Sep 25 08:14:15 (Elapsed-ns=25170)---------
***State Entry>>>(nproc_pid=>0x0, flag=>0x0, gets=>0x84BD1DC1, latch=>0x22F, level=>0x2, where=>0x14EE)
>>>Transition>>>ksl_get_shared_latch:entry
      (Addr=>0x600572B0, Immed_Get=>1, Why=>1, Where=>5374(0x14FE), Mode=>16, PID=>0x2000000000000024)
              oracle`ksl_get_shared_latch
              oracle`qesrcCM_Release+0x293
              oracle`psdfrcWriteResult+0x213
              oracle`pevm_RET+0x3d9
              oracle`pfrinstr_RET+0x26

   4 128142      ksl_get_shared_latch:return
>>>State Return***(nproc_pid=>0x24, flag=>0x20000000, gets=>0x84BD1DC2, latch=>0x22F, level=>0x2, where=>0x14FE)
   4  89490                     kslfre:entry
---------Step 8 at 2017 Sep 25 08:14:15 (Elapsed-ns=9845)---------
>>>Transition>>>kslfre:entry(Addr=>0x600572B0)
===Latch freed===
              oracle`kslfre
              oracle`qesrcCM_Release+0x22d
              oracle`psdfrcWriteResult+0x213
              oracle`pevm_RET+0x3d9
              oracle`pfrinstr_RET+0x26

^C
   1      2                             :END
---------Step 9 at 2017 Sep 25 08:14:17 (Elapsed-ns=2254749376)---------
Latch Gets = 4 (2226986430 - 2226986434)


7. RESULT_CACHE Object Status Transition


SQL RESULT_CACHE hint has an option of SNAPSHOT. which specifies the Expired time interval. In the following test, we set "snapshot=5" (5 seconds) to track status transition of RESULT_CACHE Object:
    New -> Published -> Expired -> Invalid

As the test shows, SNAPSHOT option turns off usual RESULT_CACHE invalidation of DML statement, and allows stale Read (dirty Read, non Consistency Read) of RESULT_CACHE.

We observed this usage in Oracle dynamic sampling (SNAPSHOT=3600). In real application, this undocumented feature can be used to make RESULT_CACHE as a database-wide provider of periodically sampling data.

----------------- Test Code -----------------
exec dbms_result_cache.flush;

select /*+ RESULT_CACHE(snapshot=5) */ id, val from rc_tab where id = 3;
select status, name from v$result_cache_objects; 

exec dbms_lock.sleep(2);
update rc_tab set val = -val where id = 3;
commit;
select id, val from rc_tab where id = 3;     

--stale Read
select /*+ RESULT_CACHE(snapshot=5) */ id, val from rc_tab where id = 3;
select status, name from v$result_cache_objects; 

exec dbms_lock.sleep(3);
select status, name from v$result_cache_objects; 

exec dbms_lock.sleep(1);
select /*+ RESULT_CACHE(snapshot=5) */ id, val from rc_tab where id = 3;
select status, name from v$result_cache_objects;

----------------- Test Output -----------------

07:11:00 > exec dbms_result_cache.flush;
07:11:00 > select /*+ RESULT_CACHE(snapshot=5) */ id, val from rc_tab where id = 3;
  
          ID        VAL
  ---------- ----------
           3         30
07:11:00 > select status, name from v$result_cache_objects;

  STATUS    NAME
  --------- -----------------------------------------------------------------------
  Published select /*+ RESULT_CACHE(snapshot=5) */ id, val from rc_tab where id = 3

07:11:00 > exec dbms_lock.sleep(2);
07:11:02 > update rc_tab set val = -val where id = 3;
  1 row updated.
07:11:02 > commit;
07:11:02 > select id, val from rc_tab where id = 3;
  
          ID        VAL
  ---------- ----------
           3        -30
           
07:11:02 > --stale Read           
07:11:02 > select /*+ RESULT_CACHE(snapshot=5) */ id, val from rc_tab where id = 3;
  
          ID        VAL
  ---------- ----------
           3         30
07:11:02 > select status, name from v$result_cache_objects;

  STATUS    NAME
  --------- -----------------------------------------------------------------------
  Published select /*+ RESULT_CACHE(snapshot=5) */ id, val from rc_tab where id = 3

07:11:02 > exec dbms_lock.sleep(3);
07:11:05 > select status, name from v$result_cache_objects;

  STATUS    NAME
  --------- -----------------------------------------------------------------------
  Expired   select /*+ RESULT_CACHE(snapshot=5) */ id, val from rc_tab where id = 3

07:11:05 > exec dbms_lock.sleep(1);
07:11:06 > select /*+ RESULT_CACHE(snapshot=5) */ id, val from rc_tab where id = 3;
  
          ID        VAL
  ---------- ----------
           3        -30
07:11:06 > select status, name from v$result_cache_objects;

  STATUS    NAME
  --------- -----------------------------------------------------------------------
  Published select /*+ RESULT_CACHE(snapshot=5) */ id, val from rc_tab where id = 3
  Invalid   select /*+ RESULT_CACHE(snapshot=5) */ id, val from rc_tab where id = 3
  2 rows selected.


8. Result Cache History Recording


There exist no DBA_HIST_* views to display the RC history of active sessions. We can create a small utility to record RC history usages (see appended code).

For example, we record 10 snaps in an interval of 1 second for top 5 rows, and then check the created history.

exec rc_scn_record_hist(p_snaps => 10, p_interval=> 1, p_rows => 5);

select * from hist_rc_scn 
order by ts, sign(extract(minute from(scn_diff))*60 + extract(second from(scn_diff))) desc
        ,scn desc, scn_diff desc, status, name, id;

select * from hist_rc_scn_dep 
order by ts, sign(extract(minute from(f_scn_diff))*60 + extract(second from(f_scn_diff))) desc
        ,f_scn desc, f_scn_diff desc, f_status, f_name;
        
select * from hist_rc_lru_number t
order by ts, name;   

select * from hist_rc_memory t
order by ts, free; 

select * from hist_rc_stats t
order by name, ts;   


9. Result Cache Hidden Parameters


Here a list of RC hidden parameters in Oracle 12.1.0.2.0:
Name                                       Description                                             Default 
------------------------------------------ ------------------------------------------------------- -------
_result_cache_auto_size_threshold          result cache auto max size allowed                      100       
_result_cache_auto_time_threshold          result cache auto time threshold                        1000 
_result_cache_auto_execution_threshold     result cache auto execution threshold                   1    
_result_cache_deterministic_plsql          result cache deterministic PLSQL functions              FALSE
_result_cache_block_size                   result cache block size                                 1024 
_result_cache_copy_block_count             blocks to copy instead of pinning the result            1    
_result_cache_global                       Are results available globally across RAC?              TRUE 
_result_cache_timeout                      maximum time (sec) a session waits for a result         10   
_result_cache_auto_time_distance           result cache auto time distance                         300  
_result_cache_auto_dml_monitoring_slots    result cache auto dml monitoring slot                   4    
_result_cache_auto_dml_monitoring_duration result cache auto dml monitoring duration               15   
_result_cache_auto_dml_threshold           result cache auto dml threshold                         16   
_result_cache_auto_dml_trend_threshold     result cache auto dml trend threshold                   20   
_optimizer_ads_result_cache_life           result cache shelf life for ADS queries                 3600 
_client_result_cache_bypass                bypass the client result cache                          FALSE
_re_result_cache_keysiz                    defines max number key for result cache hash table      20   
_re_result_cache_size                      defines max number of cached elements for result cache  20   
In verbatim text, they sound like something to regulate the refresh of Result Cache or its Dynamic Performance Views. But it is not clear how to make the test cases to detect their usage.

10. Test Code



drop table rc_tab;

drop table rc_tab_dep;

drop table rc_tab_2;

create table rc_tab (id number, val number);

create table rc_tab_dep (did number, dval number);

create table rc_tab_2 (id number, val number);

insert into rc_tab select level, level*10 from dual connect by level <= 17;

insert into rc_tab_dep select level, level*10 from dual connect by level <= 17;

insert into rc_tab_2 select level, level*10 from dual connect by level <= 13;

commit;

create or replace function get_val_dep (p_did number) return number as
  l_dval_dep number;
begin
  select dval into l_dval_dep from rc_tab_dep where did = p_did;
  return l_dval_dep;
end;
/

create or replace function get_val (p_id number) return number result_cache as
  l_val     number;
  l_val_dep number;
begin
  select val into l_val from rc_tab where id = p_id;
  l_val_dep := get_val_dep(p_id);
  return l_val + l_val_dep;
end;
/

create or replace procedure run_test as
  l_val number;
begin
  -- SQL RESULT_CACHE
  --for c in (select /*+ RESULT_CACHE */ * from rc_tab) loop
  --  null;
  --end loop;
  
  for i in 1 .. 17 loop
    l_val := get_val(i);
  end loop;
end;
/

create or replace function get_val_2 (p_id number) return number result_cache as
  l_val     number;
  l_val_dep number;
begin
  select val into l_val from rc_tab_2 where id = p_id;
  return l_val;
end;
/

create or replace procedure run_test_2 as
  l_val number;
begin
  for i in 1 .. 13 loop
    l_val := get_val_2(i);
  end loop;
end;
/


11. Result Cache Monitoring Views



drop view rc_scn_view;

create view rc_scn_view as
select systimestamp ts, scn_to_timestamp(t.scn) scn_time, (scn_to_timestamp(scn) - creation_timestamp) scn_diff, t.*  
from   v$result_cache_objects t
order by sign(extract(minute from(scn_diff))*60 + extract(second from(scn_diff))) desc
        ,scn desc, scn_diff desc, status, name, id;    

drop view rc_scn_dep_view;

create view rc_scn_dep_view as
with rs_scn as 
  (select scn_to_timestamp(t.scn) scn_time, (scn_to_timestamp(scn) - creation_timestamp) scn_diff, 
          id, type, status, name, namespace, creation_timestamp, scn, object_no, invalidations, row_count
   from   v$result_cache_objects t)
select systimestamp ts,
       f.scn_time f_scn_time, f.scn_diff f_scn_diff, f.id f_id, f.type f_type, f.status f_status, f.name f_name, f.namespace f_namespace, 
       f.creation_timestamp f_creation_timestamp, f.scn f_scn, f.object_no f_object_no, f.invalidations f_invalidations, f.row_count f_row_count,
       t.scn_time t_scn_time, t.scn_diff t_scn_diff, t.id t_id, t.type t_type, t.status t_status, t.name t_name, t.namespace t_namespace, 
       t.creation_timestamp t_creation_timestamp, t.scn t_scn, t.object_no t_object_no, t.invalidations  t_invalidations, t.row_count t_row_count
from rs_scn                    f, 
     v$result_cache_dependency d,
     rs_scn                    t
where f.id    = d.result_id(+) 
  and t.id(+) = d.depend_id
--  and t.name in ('K.RC_TAB_DEP', 'K.RC_TAB')
--  and f.name like '%"K"."%GET_VAL"%'
order by sign(extract(minute from(f.scn_diff))*60 + extract(second from(f.scn_diff))) desc
        ,f.scn desc, f.scn_diff desc, f.status, f.name;
        
drop view rc_lru_number_view;

create view rc_lru_number_view as
select systimestamp ts, name, cache_id, type, status, namespace
      ,min(lru_number) min_lru, max(lru_number) max_lru, max(lru_number) - min(lru_number) lru_diff
      ,count(*) rc_count, sum(block_count) blocks, sum(ceil(row_count*row_size_avg/1024)) est_blocks
      ,sum(row_count) row_cnt, min(row_size_min) row_size_min, max(row_size_max) row_size_max, round(avg(row_size_avg)) row_size_avg
      ,sum(pin_count) pin_count, round(avg(scan_count)) avg_scan_cnt
      ,sum(build_time*10) build_time_ms, round(avg(build_time*10), 3) avg_build_time, min(build_time*10) min_build_time, max(build_time*10) max_build_time
      ,sum(invalidations) invalidations
from   v$result_cache_objects t
where  lru_number > 0
group by name, cache_id, type, status, namespace
order by rc_count desc, avg_scan_cnt desc;  

drop view rc_memory_view;

create view rc_memory_view as 
select systimestamp ts, v.* from
(select free, count(*) cnt, min(offset) min_offset, max(offset) max_offset from v$result_cache_memory group by free) v;

drop view rc_stats_view;

create view rc_stats_view as 
select systimestamp ts, v.* from v$result_cache_statistics v;


12. Result Cache History Recording



drop table hist_rc_scn;

create table hist_rc_scn as select 123456 snap_id, v.* from rc_scn_view v where 1=2;

drop table hist_rc_scn_dep;

create table hist_rc_scn_dep as select 123456 snap_id, v.* from rc_scn_dep_view v where 1=2;

drop table hist_rc_lru_number;

create table hist_rc_lru_number as select 123456 snap_id, v.* from rc_lru_number_view v where 1=2;

drop table hist_rc_memory;

create table hist_rc_memory as select 123456 snap_id, v.* from rc_memory_view v where 1=2;

drop table hist_rc_stats;

create table hist_rc_stats as select 123456 snap_id, v.* from rc_stats_view v where 1=2;


create or replace procedure rc_scn_record_hist(p_snaps number := 10, p_interval number := 1, p_rows number := 10) as
begin
  for i in 1..p_snaps loop
    insert into hist_rc_scn   
    select i snap_id, c.* from  
    (select v.* from rc_scn_view v 
     order by sign(extract(minute from(scn_diff))*60 + extract(second from(scn_diff))) desc
             ,scn desc, scn_diff desc, status, name, id) c
    where rownum <= p_rows;
    
    insert into hist_rc_scn_dep 
    select i snap_id, c.* from 
    (select v.* from rc_scn_dep_view v
     order by sign(extract(minute from(f_scn_diff))*60 + extract(second from(f_scn_diff))) desc
             ,f_scn desc, f_scn_diff desc, f_status, f_name) c
    where rownum <= p_rows;
    
    insert into hist_rc_lru_number 
    select i snap_id, c.* from rc_lru_number_view c;    
    
    insert into hist_rc_memory 
    select i snap_id, c.* from rc_memory_view c;
        
    insert into hist_rc_stats 
    select i snap_id, c.* from rc_stats_view c;     
     
    commit;
    dbms_lock.sleep(p_interval);
  end loop;
end;
/

truncate table hist_rc_scn;
truncate table hist_rc_scn_dep;
truncate table hist_rc_lru_number;
truncate table hist_rc_memory;
truncate table hist_rc_stats;

exec rc_scn_record_hist(p_snaps => 10, p_interval=> 1, p_rows => 5);

select * from hist_rc_scn 
order by ts, sign(extract(minute from(scn_diff))*60 + extract(second from(scn_diff))) desc
        ,scn desc, scn_diff desc, status, name, id;

select * from hist_rc_scn_dep 
order by ts, sign(extract(minute from(f_scn_diff))*60 + extract(second from(f_scn_diff))) desc
        ,f_scn desc, f_scn_diff desc, f_status, f_name;
        
select * from hist_rc_lru_number t
order by ts, name;  

select * from hist_rc_memory t
order by ts, free; 

select * from hist_rc_stats t
order by name, ts;