Wednesday, November 7, 2018

Row Cache Objects, Row Cache Latch on Object Type: Plsql vs Java Call (Part-1) (II)


(I)-Tracing Methods      (II)-Object Type(Part-1)       (III)-Object Type(Part-2)       (IV)-Sql Executions (IV)      (V)-Contentions and Scalability


Oracle extends relational model by introducing object-oriented user-defined flavor: object types (ADTs).

Studied tracing methods in previous Blog, this Blog will discuss Row Cache Object Gets, Row Cache Latch Gets when using object types in Plsql and Java.

The previous Blogs recorded my slow and long journey in understanding Row Cache Objects and their Latches:
  1. java stored procedure calls and latch: row cache objects
  2. dbms_aq.dequeue - latch: row cache objects on AIX
  3. nls_database_parameters, dc_props, latch: row cache objects  
  4. row cache mutex in Oracle 12.2.0.1.0  
  5. Oracle ROWCACHE Views and Contents
  6. Oracle row cache objects Event: 10222, Dtrace Scripts (I)
Note: All tests are done in Oracle 12.1.0.2.


1. Plsql Function with object types


Assume a Plsql Function foo is defined as:

function foo (
   p_in    in     t_obj_in
  ,p_out      out t_obj_out
  ,p_inout in out t_obj_inout) 
return 
   t_obj_ret
where the function return and 3 parameters are all object types. 3 parameters are (IN, OUT, IN OUT) respectively.
(see appended Test Code).


2. Plsql Dynamic Call


Call foo 100 times:

BEGIN :1 := foo(:2, :3, :4); END;
by foo_proc with execute immediate, and monitor Row Cache Objects Gets with Dtrace Script: rco_dtrace_cache
(see Blog: Oracle row cache objects Event: 10222, Dtrace Script (I)):

begin
  trc_start(4294967295);
  foo_proc(100);
  trc_stop;
end;
/
Dtrace output shows:

-- 10222 trace level 4294967295, CID 11, 17 in same Addr --
*************** CID Stats with Address ****************
CID = 17   ADDR = 178D70438        CNT = 515
CID = 11   ADDR = 16F1C6A48        CNT = 515
CID = 7    ADDR = 17199E2D0        CNT = 501

*************** CID Stats ****************
CID = 17   CNT = 515    (dc_global_oids)
CID = 11   CNT = 515    (dc_object_ids/dc_objects)
CID = 7    CNT = 528    (dc_user_grants/dc_users)

*************** CID Stats Summary ****************
CNT = 1558
In the above output, CID is V$ROWCACHE.CACHE#.
    
  CID = 17  dc_global_oids
  CID = 11  dc_object_ids
            (renamed as dc_objects in 10g, still visible in v$rowcache_parent.
            see MOS: How to Match a Row Cache Object Child Latch to its Row Cache (Doc ID 468334.1))
  CID = 7   dc_user_grants 
            (SUBORDINATE, its PARENT: dc_users)
For each foo Call, dc_object_ids (CID = 11) is requested as follows:
  1 for T_OBJ_RET
  1 for T_OBJ_IN
  1 for T_OBJ_OUT
  2 for T_OBJ_INOUT  
so 5 dc_object_ids GETs are needed for each foo Call (T_OBJ_INOUT requires 2), 100 Calls resulted in 500 GETs. (see later discussion in Section 4. Plsql Dynamic Call with trace level 15).

Each dc_object_ids GET is started by one dc_global_oids (CID = 17) GET, and terminated by one dc_users (CID = 7) GET. They are processed sequentially as:
  dc_global_oids  CID = 17 GET
  dc_object_ids   CID = 11 GET
  dc_users        CID = 7  GET
In total, it amounts to 5*3*100=1500 Row Cache Objects GETs for 100 foo Calls, which are:
  500 dc_global_oids (CACHE#=17)
  500 dc_objects     (CACHE#=8)
  500 dc_users       (CACHE#=10)
As we learned, for each Row Cache Objects GET, it requires 3 "latch: row cache objects" GETs.
That is 3*1500 = 4500 Latch GETs for 100 foo Calls.

The 3 consecutive "latch: row cache objects" GETs for one Row Cache Object Get are at 3 "Where" Locations:
  kqrpre: find obj   
  kqreqd             
  kqreqd: reget      
Query below can also be used to watch Row Cache Objects GETs and the respective "latch: row cache objects" GETs. (restricted to latch#: 8, 9, 10 in Oracle 12.1.0.2)
                                                          
with rc as (
  select min(parameter) rc_parameter, sum(gets) rc_gets, sum(getmisses) rc_getmisses, 
         decode(substr(parameter, 1, 9), 'dc_users', 8, 'dc_object', 9, 'dc_global', 10) la_child#,
         listagg(cache#, ', ') within group (order by cache#) cache#_list,
         listagg(parameter, ', ') within group (order by length(parameter)) parameter_list
  from   v$rowcache where cache# in (7,10, 8,11, 17) and gets > 0 
  group by substr(parameter, 1, 9))
select latch#, child#, name, gets, misses, sleeps, spin_gets, rc.*, 3*gets RC_theory_gets
from v$latch_children la, rc
where la.latch# = 411 and la.child# in (8, 9, 10) 
  and la.child# = rc.la_child# 
order by la.child#;   
The statistics of dc_objects in V$ROWCACHE_PARENT is (to be used for later comparison):

select cache#, cache_name, count(distinct address) 
from V$ROWCACHE_PARENT 
where cache_name like 'dc_objects%' 
group by cache#, cache_name order by cache#;

CACHE# CACHE_NAME COUNT(DISTINCTADDRESS)
------ ---------- ----------------------
     8 dc_objects                   7010
    11 dc_objects                    810
We can also simply use the PL/SQL script provided in Blog: Oracle row cache objects Event: 10222, Dtrace Script (I) to parse above 10222 trace file, and then run one query to get Row Cache Objects GETs:

exec import_10222_trc_proc(1, 'testdb_ora_25675_rco_trc_09_12_29.trc');

select cid, cid_type, cid_subordinate#, cid_parameter, count(*) cnt, sum(elapsed_us) elapsed_us from (
  select ts_us - lag(ts_us) over(partition by run order by line_nbr) elapsed_us, t.*
  from import_10222_trc t
  where run=1 
    and sql like 'begin :1 := foo(:2, :3, :4); end;%'
  order by run, line_nbr)
group by cid, cid_type, cid_subordinate#, cid_parameter order by cnt desc;

CID  CID_TYPE     CID_SUBORDINATE#  CID_PARAMETER   CNT  ELAPSED_US
--- ------------ ----------------- --------------- ---- -----------
17   PARENT                         dc_global_oids  500  133632
11                                                  500  94677
7    SUBORDINATE  0                 dc_users        500  235832


3. Java Call


Call foo 100 times in Java CallableStatement:
                                                          
BEGIN :1 := K.FOO(:2, :3, :4); END;
with command:
                                                          
java RCOObjTypeJDBC1 "jdbc:oracle:thin:k/s@testDB:1521:testDB" 100 1
and monitor Row Cache Objects Gets with Dtrace Script: rco_dtrace_cache.

Dtrace output (CID: V$ROWCACHE.CACHE#) shows:
    
*************** CID Stats with Address ****************
CID = 17   ADDR = 172298F88        CNT = 10
CID = 7    ADDR = 171958160        CNT = 11
CID = 8    ADDR = 16F367C50        CNT = 20
CID = 10   ADDR = 17199E2D0        CNT = 35
CID = 17   ADDR = 17279C738        CNT = 703
CID = 11   ADDR = 16F367C50        CNT = 712 
CID = 7    ADDR = 17199E2D0        CNT = 705

*************** CID Stats ****************
CID = 8    CNT = 24
CID = 10   CNT = 43
CID = 17   CNT = 724
CID = 11   CNT = 712
CID = 7    CNT = 716

*************** CID Stats Summary ****************
CNT = 2219
In Java, for each foo Call, dc_object_ids (CID = 11) is requested as follows:
  2 for T_OBJ_RET
  1 for T_OBJ_IN
  2 for T_OBJ_OUT
  2 for T_OBJ_INOUT  
Comparing to Plsql Call, only T_OBJ_IN requires 1 GET, all other 3 requires 2 GETs.
So 7 dc_object_ids GETs for each foo Call in Java, 2 more GETs than Plsql.

In total, it amounts to 7*3*100=1500=2100 Row Cache Objects GETs for 100 foo Calls.

And it requires 3*2100 = 6300 Latch GETs for 100 foo Calls.


4. Plsql Dynamic Call with trace level 15


If setting 10222 trace level to 15 (instead of max: 4294967295), and call foo 100 times:
                                                          
begin
  trc_start(15);
  foo_proc(100);
  trc_stop;
end;
/
Dtrace output looks like:
    
-- 10222 trace level 15, CID 11, 17 in different Addr --
*************** CID Stats with Address ****************
CID = 11   ADDR = 16F1C6A48        CNT = 15
CID = 17   ADDR = 178D70438        CNT = 15

CID = 17   ADDR = 17AE5F738        CNT = 100  --T_OBJ_RET
CID = 17   ADDR = 17194DE90        CNT = 100  --T_OBJ_IN
CID = 17   ADDR = 171AB8238        CNT = 100  --T_OBJ_OUT
CID = 17   ADDR = 16EFB4A18        CNT = 200  --T_OBJ_INOUT

CID = 11   ADDR = 16F367C50        CNT = 100  --1 T_OBJ_RET
CID = 11   ADDR = 16F190060        CNT = 100  --1 T_OBJ_IN
CID = 11   ADDR = 16F184B20        CNT = 100  --1 T_OBJ_OUT
CID = 11   ADDR = 16F183A60        CNT = 200  --2 T_OBJ_INOUT

CID = 7    ADDR = 171921A90        CNT = 502

*************** CID Stats ****************
CID = 17   CNT = 515
CID = 11   CNT = 515
CID = 7    CNT = 528

*************** CID Stats Summary ****************
CNT = 1558
We can see that CID 11, 17 are allocated in different ADDR for each different type, whereas level 4294967295 stored:
  all CID 11 in the same addrss for all 4 Object Types;
  all CID 17 in the same addrss for all 4 Object Types;
So this trace level can dictate memory allocation algorithm, probably some powerful logic behind the trace level.

Check statistics of dc_objects in V$ROWCACHE_PARENT again, now it increased to 814 for CACHE#=11 dc_objects. whereas in Section 2, it is 810, exactly 4 more for 4 Object Types.
    
select cache#, cache_name, count(distinct address) 
from V$ROWCACHE_PARENT 
where cache_name like 'dc_objects%' 
group by cache#, cache_name order by cache#;

CACHE# CACHE_NAME COUNT(DISTINCTADDRESS)
------ ---------- ----------------------
     8 dc_objects                   7010
    11 dc_objects                    814


5. Plsql Static Call


If call foo 100 times in the usual static way (see appended code):
    
begin
  trc_start(4294967295);
  foo_proc_static(100);
  trc_stop;
end;
/
Dtrace output looks like:
    
*************** CID Stats with Address ****************
CID = 17   ADDR = 178D70438        CNT = 3
CID = 11   ADDR = 16F1C6A48        CNT = 3
CID = 7    ADDR = 1716FDFB0        CNT = 2

*************** CID Stats ****************
CID = 17   CNT = 3
CID = 11   CNT = 3
CID = 7    CNT = 2

*************** CID Stats Summary ****************
CNT = 8
There is no noticable Row Cache Objects GETs, and the latches.


6. dc_global_oids


Pick one foo execution from trace file, all 4 Binds are underlined with a 32 length hex value.

=====================
PARSING IN CURSOR #18446604434611618256 len=35 dep=0 uid=49 oct=47 lid=49 
     tim=13815978483655 hv=1325814719 ad='16eff1050' sqlid='8nkt65d7hcnxz'
BEGIN :1 := K.FOO(:2, :3, :4); END;
...
BINDS #18446604434611618256:
 Bind#0
  oacflg=03 fl2=1000000 frm=00 csi=02 siz=2560 off=0
7807E9A68357082FE054005056984D97
 Bind#1
  oacflg=03 fl2=1000000 frm=00 csi=02 siz=0 off=640
7807E9A682B5082FE054005056984D97
 Bind#2
  oacflg=03 fl2=1000000 frm=00 csi=02 siz=0 off=1280
7807E9A682BA082FE054005056984D97
 Bind#3
  oacflg=03 fl2=1000000 frm=00 csi=02 siz=0 off=1920
77DDFDFCEB484AF6E054005056984D97

kqrpad: new po 17ae5f738 from kqrpre1.1
 KQR Parent Cache Object:
kqrReadFromDB : kqrpre1.1 po=17ae5f738 flg=8000 cid=17 eq=16d24be18 idx=0 dsflg=0
...
kqrfrpo: Free po 17ae5f738
Take above 4 Bind values and run query below, we obtained the full info of 4 objects from OBJ$ via OID$.

select g.*, o.obj#, o.name, o.oid$ 
from   sys.oid$ g, 
       sys.obj$ o
where g.oid$ in ('7807E9A68357082FE054005056984D97', 
                 '7807E9A682B5082FE054005056984D97', 
                 '7807E9A682BA082FE054005056984D97', 
                 '77DDFDFCEB484AF6E054005056984D97')
  and g.obj# = o.obj#;
                 
 USER# OID$                                 OBJ#  INDEX#     OBJ# NAME         OID$
------ -------------------------------- -------- ------- -------- ------------ --------------------------------
     1 7807E9A68357082FE054005056984D97  2360168       0  2360168 T_OBJ_RET    7807E9A68357082FE054005056984D97
     1 7807E9A682B5082FE054005056984D97  2360169       0  2360169 T_OBJ_IN     7807E9A682B5082FE054005056984D97
     1 7807E9A682BA082FE054005056984D97  2360170       0  2360170 T_OBJ_OUT    7807E9A682BA082FE054005056984D97
     1 77DDFDFCEB484AF6E054005056984D97  2360171       0  2360171 T_OBJ_INOUT  77DDFDFCEB484AF6E054005056984D97
OID$ is a small table with 4 Columns, whereas OBJ$ is a rich table with 25 Columns. So OID$ looks like a fast translation lookaside table (analoque CPU TLB).

Therefore dc_global_oids is probably used to map OID$.oid$ to OBJ$.

Since each Bind is 640 length ("off" difference is 640, total "siz=2560"), they are not stored in DC. For each foo execution, they are read into DC from Buffer Cache by "kqrReadFromDB" as "kqrpad: new po", and evicted as "kqrfrpo: Free po" (see later discussion). Hence each dc_object_ids (CID = 11) is preceded by a dc_global_oids (CID = 17).

If run dc_global_oids query in Blog: Oracle ROWCACHE Views and Contents, one can also see those 4 Objects.


7. Row Cache Internals: kqrReadFromDB and kqrfrpo


10222 trace shows that Row Cache is not able to cache those Object Types and the call statement. Each time it needs to invoke "kqrReadFromDB" to create a new DC row, use it, and then evicted by "kqrfrpo : freed to heap". In the following example, it took 427 us for one such Read.

Since 10046 trace (see next Section) does not show any Disk(Physical) Read, probably "kqrReadFromDB" is a subroutine to read DC row from Buffer Cache. In that case, reading one DC row looks like a single row distilling process from a Buffer Cache Block (e.g 8K), which may contains multiple DC rows.
    
kqrpre1 : done po=16f1c6a48 cid=11 flg=2 hash=abe278ab 36ab78b6 eq=17179fc10 
  obobn=2360168 obname=T_OBJ_RET obtyp=13 obsta=1 obflg=0 SQL=begin :1 := test_fun_1(:2, :3, :4); end; 
  time=1582475964

  --=====  START kqrpad: new po =====--
  --===== Not kept, each time new loaded  =====--

kqrpad: new po 17199e2d0 from kqrpre1.1
      KQR Parent Cache Object:
      pob = 17199e2d0 flg = 00000000 cid =  7 xcb = 0 hbk = 17199e8a8
      hbk=[17199e8b8,17199e8b8]     hbk=[17199e8d8,17199e8d8]       hbk=[17199e8f8,17199e8f8] 
      own=17199e3a0[17199e3a0,17199e3a0] wat=17199e3b0[17199e3b0,17199e3b0] mod=0
kqrReadFromDB : kqrpre1.2 po=17199e2d0 flg=8000 cid=7 eq=17179f7d0 idx=1 dsflg=0
kqrReadFromDB : kqrpre1.3 po=17199e2d0 flg=8000 cid=7 eq=17179f7d0 idx=0 dsflg=0
kqrpre1 : done po=17199e2d0 cid=7 flg=2 hash=de7751cd 395edb55 eq=17179f7d0 SQL=begin :1 := foo(:2, :3, :4); end; time=1582476252
kqrmupin : kqrpspr2 Unpin po 17199e2d0 cid=7 flg=2 hash=395edb55 time=1582476298
kqrmupin : free po=17199e2d0 flg=2
kqrfrpo: Free po 17199e2d0
      KQR Parent Cache Object:
      pob = 17199e2d0 flg = 00000002 cid =  7 xcb = 0 hbk = 17199e8a8
      hbk=[1800df578,1800df578]     hbk=[180055cf8,180055cf8]       hbk=[17199e8f8,17199e8f8] 
      own=17199e3a0[17199e3a0,17199e3a0] wat=17199e3b0[17199e3b0,17199e3b0] mod=0
kqrfrpo : freed to heap po=17199e2d0 time=1582476391

  --===== END: kqrfrpo : freed to heap =====--
  --=====  Elapsed 1582476391-1582475964=427 us =====--

kqrmupin : kqrpspr2 Unpin po 16f1c6a48 cid=11 flg=2 hash=36ab78b6 time=1582476413


8. 10046 Trace file


Here the TKProf output of 10046 Trace file created from above 100 times Java Call in Section 3 for dc_global_oids, dc_objects, and dc_users respectively.

Each recursive query made about 700 logical Reads for 100 foo Executions, no disk access.
    
============================= 100 foo Executions =============================
SQL ID: 8nkt65d7hcnxz Plan Hash: 0

BEGIN :1 := K.FOO(:2, :3, :4); END;

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute    100      0.88       0.89          0        132          0         100
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total      101      0.88       0.89          0        132          0         100

============================= dc_global_oids =============================
SQL ID: 0gx3b09qrx9f5 Plan Hash: 1964104430

select obj#,index# 
from
 oid$ where user#=:1 and oid$=:2

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute    714      0.12       0.12          0          0          0           0
Fetch      714      0.00       0.00          0       2853          0         711
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total     1429      0.13       0.13          0       2853          0         711

TABLE ACCESS BY INDEX ROWID OID$ (cr=3 pr=0 pw=0 time=12 us cost=2 size=29 card=1)
 INDEX UNIQUE SCAN I_OID1 (cr=3 pr=0 pw=0 time=11 us cost=1 size=0 card=1)(object id 501)

============================= dc_objects =============================
SQL ID: 1p5grz1gs7fjq Plan Hash: 813480514

select obj#,type#,ctime,mtime,stime, status, dataobj#, flags, oid$, spare1, 
  spare2, spare3, signature, spare7, spare8, spare9 
from
 obj$ where owner#=:1 and name=:2 and namespace=:3 and remoteowner is null 
  and linkname is null and subname is null

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute    731      0.17       0.17          0          0          0           0
Fetch      731      0.00       0.00          0       2921          0         728
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total     1463      0.18       0.18          0       2921          0         728

TABLE ACCESS BY INDEX ROWID BATCHED OBJ$ (cr=3 pr=0 pw=0 time=15 us cost=2 size=106 card=1)
 INDEX RANGE SCAN I_OBJ2 (cr=3 pr=0 pw=0 time=14 us cost=2 size=0 card=1)(object id 1591124)

********************************************************************************
SQL ID: 87gaftwrm2h68 Plan Hash: 1072382624

select o.owner#,o.name,o.namespace,o.remoteowner,o.linkname,o.subname 
from
 obj$ o where o.obj#=:1

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute    712      0.07       0.07          0          0          0           0
Fetch      712      0.00       0.00          0       2848          0         712
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total     1425      0.08       0.08          0       2848          0         712

TABLE ACCESS BY INDEX ROWID BATCHED OBJ$ (cr=4 pr=0 pw=0 time=13 us cost=2 size=51 card=1)
 INDEX RANGE SCAN I_OBJ1 (cr=3 pr=0 pw=0 time=9 us cost=2 size=0 card=1)(object id 1591123)

============================= dc_users =============================
SQL ID: 2tkw12w5k68vd Plan Hash: 1457651150

select user#,password,datats#,tempts#,type#,defrole,resource$, ptime,
  decode(defschclass,NULL,'DEFAULT_CONSUMER_GROUP',defschclass),spare1,spare4,
  ext_username,spare2 
from
 user$ where name=:1

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse      755      0.00       0.00          0          0          0           0
Execute    755      0.07       0.07          0          0          0           0
Fetch      755      0.00       0.00          0       2265          0         755
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total     2265      0.08       0.08          0       2265          0         755

TABLE ACCESS BY INDEX ROWID USER$ (cr=3 pr=0 pw=0 time=34 us cost=1 size=314 card=1)
 INDEX UNIQUE SCAN I_USER1 (cr=2 pr=0 pw=0 time=18 us cost=1 size=0 card=1)(object id 1591161)

********************************************************************************
SQL ID: 4kt3cun8s5fp5 Plan Hash: 2709293936

select name,password,datats#,tempts#,type#,defrole,resource$, ptime, 
  decode(defschclass,NULL,'DEFAULT_CONSUMER_GROUP',defschclass),spare1,spare4,
  ext_username,spare2 
from
 user$ where user#=:1

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse      714      0.00       0.00          0          0          0           0
Execute    714      0.07       0.07          0          0          0           0
Fetch      714      0.00       0.00          0       2142          0         714
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total     2142      0.08       0.08          0       2142          0         714

TABLE ACCESS CLUSTER USER$ (cr=3 pr=0 pw=0 time=11 us cost=1 size=314 card=1)
 INDEX UNIQUE SCAN I_USER# (cr=2 pr=0 pw=0 time=5 us cost=1 size=0 card=1)(object id 1591131)

********************************************************************************
SQL ID: 8t373z5u9ztup Plan Hash: 0

begin :1 := dbms_pickler.get_type_shape(:2,:3,:4,:5,:6,:7,:8,:9,:10); end;

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        4      0.00       0.00          0          0          0           0
Execute      4      0.02       0.03          3         20          0           4
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        8      0.03       0.04          3         20          0           4
********************************************************************************
By the way, the last dbms_pickler call is discussed in Blog: JDBC, Oracle object/collection, dbms_pickler, NOPARALLEL sys.type$ query


9. Summary


For each foo Call in Dynamic Plsql, there are 5 dc_object_ids (CID = 11) GETs as follows:
  1 for T_OBJ_RET
  1 for T_OBJ_IN
  1 for T_OBJ_OUT
  2 for T_OBJ_INOUT  
Each dc_object_ids GET is started by one dc_global_oids (CID = 17) GET, and terminated by one dc_users (CID = 7) GET.

So total 5*3 = 15 Row Cache Objects GETs, which demand 15*3=45 Row Cache Latch GETs.

In case of Java, however, for each foo Call, there are 7 dc_object_ids (CID = 11) GETs as follows:
  2 for T_OBJ_RET
  1 for T_OBJ_IN
  2 for T_OBJ_OUT
  2 for T_OBJ_INOUT 
So total 7*3 = 21 Row Cache Objects GETs, which demand 21*3=63 Row Cache Latch GETs.


10. Plsql Test Code


    
--=========== object types parameters (IN, OUT, IN OUT) ===========--

create or replace type t_obj_ret   force as object (id number, name varchar2(30));
/

create or replace type t_obj_in    force as object (id number, name varchar2(30));
/

create or replace type t_obj_out   force as object (id number, name varchar2(30));
/

create or replace type t_obj_inout force as object (id number, name varchar2(30));
/

--=========== function foo ===========--

create or replace function foo (
  p_in    in     t_obj_in := null
 ,p_out      out t_obj_out
 ,p_inout in out t_obj_inout) return t_obj_ret 
as
  l_ret          t_obj_ret;
begin
  -- l_ret.id return 1122+112=1234
  if p_in is null then
    l_ret      := t_obj_ret(9876, 'p_in is NULL');
  else
    l_ret      := t_obj_ret(p_in.id + 112, p_in.name);
  end if;
  p_out      := t_obj_out(p_inout.id, p_inout.name);
  p_inout.id := l_ret.id;  
  return l_ret;
end;
/

--=========== Plsql Dynamic Call ===========--

create or replace procedure foo_proc (p_cnt number) as
  l_stmt    varchar2(100);
  l_ret     t_obj_ret;
  l_in      t_obj_in;
  l_out     t_obj_out;
  l_inout   t_obj_inout;
begin
  l_in      := t_obj_in(1122, 'T_OBJ_IN');
  --l_in      := null;      -- call by NULL, same cid GETs
  l_inout   := t_obj_inout(1144, 'T_OBJ_INOUT');
  
  l_stmt := q'[begin :1 := foo(:2, :3, :4); end;]';
  
  for i in 1..p_cnt loop
    execute immediate l_stmt 
      using OUT l_ret, IN l_in, OUT l_out, IN OUT l_inout;
  end loop;
  dbms_output.put_line('l_ret.id='  ||l_ret.id);
end;
/

-- exec foo_proc(100);

--=========== Plsql Static Call ===========--

-- less than 10 CID Calls
create or replace procedure foo_proc_static (p_cnt number) as
  l_ret     t_obj_ret;
  l_in      t_obj_in;
  l_out     t_obj_out;
  l_inout   t_obj_inout;
begin
  l_in      := t_obj_in(1122, 'T_OBJ_IN');
  l_inout   := t_obj_inout(1144, 'T_OBJ_INOUT');
  
 for i in 1..p_cnt loop
    l_ret := foo(l_in, l_out, l_inout); 
  end loop;
  dbms_output.put_line('l_ret.id='  ||l_ret.id);
end;
/

-- exec foo_proc_static(100);

--=========== Trace start and stop ===========--

create or replace procedure trc_start(p_level number := 4294967295, p_incl number := 3) as
  l_ident_trc varchar2(100);
  l_ident_hpf varchar2(100);
begin
  l_ident_trc := 'rco_trc_'||to_char(sysdate, 'HH24_MI_SS');
  l_ident_hpf := 'rco_hpf_'||to_char(sysdate, 'HH24_MI_SS')||'.hpf';
  dbms_application_info.set_module('ksun_mod1', 'ksun_act1');
  execute immediate q'[alter session set max_dump_file_size = UNLIMITED]';
  execute immediate 'alter session set tracefile_identifier=''' || l_ident_trc || '''';
  
  if p_incl >= 2 then
    dbms_monitor.session_trace_enable(waits=>true, binds=>true);
  end if;
  
  if p_incl >= 3 then
    sys.dbms_hprof.start_profiling('HPROF_DIR', l_ident_hpf);
  end if;
  
  if p_incl >= 1 then
    execute immediate
     'alter session set events ''10222 trace name context forever, level ' || p_level || '''';
  end if;
end;
/

create or replace procedure trc_stop as
  l_ret    binary_integer;
  l_intval integer;
  l_strval varchar2(100);
begin
  sys.dbms_hprof.stop_profiling;
  l_ret := dbms_utility.get_parameter_value('session_cached_cursors', intval => l_intval, strval => l_strval);
  dbms_output.put_line('l_intval='||l_intval||', l_strval='||l_strval);
  execute immediate 'alter session set session_cached_cursors = 0';
  dbms_monitor.session_trace_disable;
  execute immediate q'[alter session set events '10222 trace name context off']';
  execute immediate 'alter session set session_cached_cursors = '||l_intval;
end;
/


11. Java Test Code


    
import java.sql.DriverManager;
import java.sql.Connection;
import java.sql.CallableStatement;
import java.sql.SQLException;
import java.sql.Types;
import java.sql.ResultSet;
import java.math.BigDecimal;
import java.util.Vector;
import oracle.sql.ARRAY;
import oracle.sql.ArrayDescriptor;
import oracle.sql.STRUCT;
import oracle.sql.StructDescriptor;
import oracle.jdbc.OracleConnection;
import oracle.jdbc.OracleTypes;

// RCOObjTypeJDBC1    
//     0: (no trace, wait); 1: (trace, wait); 2: (no trace, no wait)
// RCOObjTypeJDBC1 "jdbc:oracle:thin:k/s@testDB:1521:testDB" 100 0

public class RCOObjTypeJDBC1 {
  static String TRCSTART = "begin trc_start; end;";
  static String TRCSTOP  = "begin trc_stop; end;";
  // parameters(IN, OUT, IN OUT) different Types
  static String TESTSTMT = "BEGIN :1 := K.FOO(:2, :3, :4); END;";  
   
  public static void main(String[] args) {
    String jdbcURL = args[0];
    int loopCNT    = Integer.parseInt(args[1]);
    int trc        = Integer.parseInt(args[2]);
    
    Connection conn = null;
    CallableStatement cStmt;
    
    for(int i=0; i < 1; i++){
     try {
       Class.forName("oracle.jdbc.driver.OracleDriver");
     } catch (ClassNotFoundException e) {
       System.out.println("Where is your Oracle JDBC Driver ?");
       e.printStackTrace();
       return;
     }
     
     try {
       conn = DriverManager.getConnection(jdbcURL);
       if (trc < 2) {
         Thread.sleep(30*1000);   // wait to prepare dtrace
       }
       
       if (trc == 1) {
       cStmt = conn.prepareCall(TRCSTART);
         cStmt.execute();
         cStmt.close();  
        }
        
        dbcall(conn, loopCNT);
            
       if (trc == 1) {
        cStmt = conn.prepareCall(TRCSTOP);
         cStmt.execute();
         cStmt.close();
        }
 
       conn.close(); 
     } catch (Exception e) {
       System.out.println("Connection Failed! Check output console");
       e.printStackTrace();
       return;
     }
   }
  }
 
  static void dbcall(Connection conn, int loopNo) {
    CallableStatement cStmt;
    
    if (conn != null) {
      try {      
        cStmt = conn.prepareCall(TESTSTMT);
        StructDescriptor dpIn    = StructDescriptor.createDescriptor("K.T_OBJ_IN", conn);
        StructDescriptor dpInOut = StructDescriptor.createDescriptor("K.T_OBJ_INOUT", conn);
        
        Object [] objField = new Object[2];
        
        objField[0] = new Integer(1122); 
        objField[1] = new String("T_OBJ_IN.name");
        
        STRUCT objIn    = new STRUCT(dpIn, conn, objField);
        STRUCT objInOut = new STRUCT(dpInOut, conn, objField);
        
        STRUCT objRet = null;
        STRUCT objOut = null;
        BigDecimal idVal;
        
        for(int i=0; i < loopNo; i++){
         cStmt.registerOutParameter(1, OracleTypes.STRUCT, "K.T_OBJ_RET");
         //cStmt.registerOutParameter(1, OracleTypes.STRUCT, "K.T_OBJ_RET_SUPER");
         cStmt.setObject(2, objIn);
         //call by NULL, same cid GETs
         //cStmt.setNull(2, OracleTypes.STRUCT, "K.T_OBJ_IN");
         cStmt.setObject(4, objInOut);
         cStmt.registerOutParameter(3, OracleTypes.STRUCT, "K.T_OBJ_OUT");
         cStmt.registerOutParameter(4, OracleTypes.STRUCT, "K.T_OBJ_INOUT");
         cStmt.execute();
         objRet   = (STRUCT)cStmt.getObject(1);
         objOut   = (STRUCT)cStmt.getObject(3);
         objInOut = (STRUCT)cStmt.getObject(4);
        }
        idVal = (BigDecimal)objOut.getAttributes()[0];
        System.out.println("objOut.id =" + idVal.intValue());
        cStmt.close();   
      } catch (SQLException e) {
        e.printStackTrace();
      }
    } else {
      System.out.println("Failed to make connection!");
    }
  }
}

Oracle row cache objects Event: 10222, Dtrace Scripts (I)

You don’t understand anything until you learn it more than one way.
Marvin Minsky


(I)-Tracing Methods       (II)-Object Type(Part-1)      (III)-Object Type(Part-2)       (IV)-Sql Executions (IV)      (V)-Contentions and Scalability


This small Oracle Row Cache Cookbook is made of a series of 5 Blogs:
Oracle row cache objects Event: 10222, Dtrace Script (I)
Row Cache Objects, Row Cache Latch on Object Type: Plsql vs Java Call (Part-1) (II)
Row Cache Objects, Row Cache Latch on Object Type: Plsql vs Java Call (Part-2) (III)
Row Cache and Sql Executions (IV)
Latch: row cache objects Contentions and Scalability (V)


This Blog will present two tracing methods of row cache objects Gets, which provide more deep insights than ordinary Oracle dynamic performance views (v$rowcache, v$latch, etc.).

At first we explore Event: 10222 to trace row cache objects Gets, and then create a PL/SQL script to import and analyse the generated trace files.

As a second approach, three Dtrace scripts are composed and tested:
   -. rco_dtrace_cache: trace each Row Cache Object Get with its arguments.
   -. rco_dtrace_latch: printout each Row Cache Latch Get call stack.
   -. rco_dtrace_std:   draw a State Transition Diagram for Object and Latch Gets.
The difference of three methods are their precision of perceiving granularity.
   (1). dynamic performance views: statement
   (2). 10222 trace:               row cache
   (3). dtrace:                    latch (atomic locking mechanism)
Note: all tests are done in Oracle 12cR1 (12.1.0.2.0), and 12cR2 (12.2.0.1.0).


1. Trace Event: 10222


Perform the tracing on the same query as Blog: nls_database_parameters, dc_props, latch: row cache objects, and compare with the output of dynamic performance views in that Blog.

More details are revealed by increasing the tracing Level.


1.1. Level 4


alter session set max_dump_file_size = UNLIMITED;

alter session set tracefile_identifier = 'row_cache_10222_4';
alter session set events '10222 trace name context forever, level 4';  
select value from nls_database_parameters where parameter = 'NLS_CHARACTERSET';
alter session set events '10222 trace name context off';

---------------------- Output ----------------------

kqrpre1 : found po=18f058b68 flg=2 hash=5b42c02e .
kqrpre1 : done po=18f058b68 cid=15 flg=2 hash=5b42c02e 0 eq=13feab2b0 .

kqrpre1 : found po=142020320 flg=2 hash=2155f5c0 .
kqrpre1 : done po=142020320 cid=15 flg=2 hash=2155f5c0 0 eq=13feab2b0 .

1.2. Level 255


alter session set tracefile_identifier = 'row_cache_10222_255';
alter session set events '10222 trace name context forever, level 255';  
select value from nls_database_parameters where parameter = 'NLS_CHARACTERSET';
alter session set events '10222 trace name context off';

---------------------- Output ----------------------

kqrpre1 : found po=18f058b68 flg=2 hash=5b42c02e time=2235042744
kqrmpin : kqrLockAndPinPo Pin po 18f058b68 cid=15 flg=2 hash=5b42c02e time=2235042857
kqrpre1 : done po=18f058b68 cid=15 flg=2 hash=5b42c02e 0 eq=13fea3cd0 time=2235042872
kqrmupin : kqrpspr2 Unpin po 18f058b68 cid=15 flg=2 hash=5b42c02e time=2235042890

kqrpre1 : found po=142020320 flg=2 hash=2155f5c0 time=2235042919
kqrmpin : kqrLockAndPinPo Pin po 142020320 cid=15 flg=2 hash=2155f5c0 time=2235042945
kqrpre1 : done po=142020320 cid=15 flg=2 hash=2155f5c0 0 eq=13fea3cd0 time=2235043046
kqrmupin : kqrpspr2 Unpin po 142020320 cid=15 flg=2 hash=2155f5c0 time=2235043061

1.3. Level 4294967295


alter session set tracefile_identifier = 'row_cache_10222_4294967295';
alter session set events '10222 trace name context forever, level 4294967295';  
select value from nls_database_parameters where parameter = 'NLS_CHARACTERSET';
alter session set events '10222 trace name context off';

---------------------- Output ----------------------

kqrpre1 : found po=18f058b68 flg=2 hash=5b42c02e time=2271264535
kqrmpin : kqrLockAndPinPo Pin po 18f058b68 cid=15 flg=2 hash=5b42c02e
time=2271264669
kqrpre1 : done po=18f058b68 cid=15 flg=2 hash=5b42c02e 0 eq=13fea57f8 SQL=select value from nls_database_parameters where parameter = 'NLS_CHARACTERSET' time=2271264687
kqrmupin : kqrpspr2 Unpin po 18f058b68 cid=15 flg=2 hash=5b42c02e time=2271264704
kqrmupin : free po=18f058b68 flg=2
kqrfrpo: Free po 18f058b68
 KQR Parent Cache Object:
 pob = 18f058b68 flg = 00000002 cid = 15 xcb = 0 hbk = 18f05ac38
 hbk=[f84f96e8,151186580] 
 own=18f058c38[18f058c38,18f058c38] wat=18f058c48[18f058c48,18f058c48] mod=0
kqrfrpo : freed to heap po=18f058b68 time=2271264814

kqrpre1 : found po=142020320 flg=2 hash=2155f5c0 time=2271264844
kqrmpin : kqrLockAndPinPo Pin po 142020320 cid=15 flg=2 hash=2155f5c0
time=2271264871
kqrpre1 : done po=142020320 cid=15 flg=2 hash=2155f5c0 0 eq=13fea57f8 SQL=select value from nls_database_parameters where parameter = 'NLS_CHARACTERSET' time=2271264885
kqrmupin : kqrpspr2 Unpin po 142020320 cid=15 flg=2 hash=2155f5c0 time=2271264904
kqrmupin : free po=142020320 flg=2
kqrfrpo: Free po 142020320
 KQR Parent Cache Object:
 pob = 142020320 flg = 00000002 cid = 15 xcb = 0 hbk = 1420223f0
 hbk=[1511862a0,18f077dd0] 
 own=1420203f0[1420203f0,1420203f0] wat=142020400[142020400,142020400] mod=0
kqrfrpo : freed to heap po=142020320 time=2271264992

1.4. Trace Level Discussion


Tests showed:
  Level 4 (5, 7, 15 are same) prints only kqrpre1 subroutine call. 
  Level 255 prints kqrpre1, kqrmpin, kqrmupin.
  Level 4294967295 prints kqrpre1, kqrmpin, kqrpre1, kqrmupin, kqrmupin, kqrfrpo, kqrfrpo.
where 4294967295 (2^32-1) seems the maximum tracing level with most details, including SQL statements.

"cid" denotes Cache ID; "kqrpre1" is for row cache object Read; "po" is for Parent Object.

There is also Event: 10205 which says:

  10205, 00000, "row cache debugging"
   // *Cause:
   // *Action:
   /  At level 1, KQR will dump out latch clean-up debugging traces.
   /  At level 2, KQR will dump out bootstrap debugging traces.
   /  At level 3, KQR will invalidate, remove from the cache and put 0xff's
   /              in row cache objects that are not currently locked.
But it is not able to generate trace file with 10205.


1.5. Are trace levels always bitmap additive ?


A common belief of trace levels is bitmap additive (all binary numbers are positive, different, power of 2).

If we run following Plsql, Level 516 output includes SQL statements. Since 516 is bitmap additive of 4 and 512:
    516 = 4 + 512 = 2^2 + 2^9 
Level 4 or Level 512 should contain SQL statements. But the test shows that Level 4 contains only "kqrpre1" in 12cR1 (and "kqreqd" in 12cR2); Level 512 does not generate any trace file. So Level 516 is not bitmap additive in this case, probably some hard-coded logic
(Level 513, 514 and 515 also not generate any trace file).

create or replace procedure test10222_trace_level as
  type         t_level_tab is table of pls_integer;
  l_level_tab  t_level_tab := new t_level_tab(4, 512, 513, 514, 515, 516);
  l_trc_prefix varchar2(256) := 'row_cache_10222_Level_';
  l_val        varchar2(256);
begin
  for i in 1..l_level_tab.count loop
    execute immediate q'[alter session set tracefile_identifier = ']' ||l_trc_prefix||l_level_tab(i)||q'[']';
    execute immediate q'[alter session set events '10222 trace name context forever, level ]'||l_level_tab(i)||q'[']';
    select value into l_val from nls_database_parameters where parameter = 'NLS_CHARACTERSET';
    execute immediate q'[alter session set events '10222 trace name context off']';
  end loop;
end;
/

exec test10222_trace_level;


2. 10222 Trace Import and Analyse


2.1. Import


Import the trace files into DB via external files (see appended PL/SQL Script)

set serveroutput on

exec import_10222_trc_proc(1, 'testdb_ora_7920_row_cache_10222_4.trc');

exec import_10222_trc_proc(2, 'testdb_ora_7920_row_cache_10222_255.trc');

exec import_10222_trc_proc(3, 'testdb_ora_7920_row_cache_10222_4294967295.trc');

2.2. Analyze


Here a list of queries to analyze Trace Level 4294967295 (RUN=3).

select rownum line_nbr, text1 from raw_10222_trc_ext;

select * from import_10222_trc 
where run=3 
order by run, line_nbr;

select cid, cid_type, cid_subordinate#, cid_parameter, count(*) cnt 
from import_10222_trc 
where run=3 
group by cid, cid_type, cid_subordinate#, cid_parameter 
order by cnt desc;

CID  CID_TYPE     CID_SUBORDINATE#  CID_PARAMETER   CNT
---  -----------  ----------------  -------------   ---
15   PARENT                         dc_props        63
7    SUBORDINATE  0                 dc_users        14
17   PARENT                         dc_global_oids  4
11                                                  4
8    PARENT                         dc_objects      1
                                                    1

select ts_us - lag(ts_us) over(partition by run order by line_nbr) elapsed_us, t.*
from import_10222_trc t 
where run=3 
order by run, line_nbr;

select cid, cid_type, cid_subordinate#, cid_parameter, count(*) cnt, sum(elapsed_us) elapsed_us from (
  select ts_us - lag(ts_us) over(partition by run order by line_nbr) elapsed_us, t.*
  from import_10222_trc t
  where run=3 order by run, line_nbr)
group by cid, cid_type, cid_subordinate#, cid_parameter order by cnt desc;

-- only tested on Solaris (x86-64)
select * from import_10222_trc t, v$rowcache_parent r
where t.run=3 and '0000000'||t.po_address = r.address(+)
order by run, line_nbr;

3. Dtrace Script


3.1 Row Cache Object Gets


Run the same query in one Sqlplus Session (SID: 123, SPID: 7890), and at the same time, trace it by following trace Script (see appended Dtrace Script: rco_dtrace_cache).

SQL (123, 456) > select value from nls_database_parameters where parameter = 'NLS_CHARACTERSET';

sudo dtrace -n \
'pid$target::kqrLockAndPinPo:entry /execname == "oracle"/ {
  @CID_ADDR_CNT[arg0, arg1] = count(); 
  @CID_CNT[arg0] = count();
  printf("\nCID = %-4d ADDR = %-16X\n", arg0, arg1);}
END {
  printf("\n----- CID_ADDR CNT -----\n"); printa("CID = %-4d ADDR = %-16X CNT = %-10@d\n", @CID_ADDR_CNT);
  printf("\n----- CID CNT -----\n"); printa("CID = %-4d CNT = %-10@d\n", @CID_CNT);
  printf("\n*** all except 1st counting doubled ***\n");}
' -p 7890

 CPU     ID                    FUNCTION:NAME
...
   5  80618            kqrLockAndPinPo:entry
CID = 15   ADDR = 18F058B68
...
   5  80618            kqrLockAndPinPo:entry
CID = 15   ADDR = 142020320
...

----- CID_ADDR CNT -----
CID = 15   ADDR = 18F058B68        CNT = 1
CID = 15   ADDR = 142020320        CNT = 1
...

----- CID CNT -----
CID = 11   CNT = 3
CID = 17   CNT = 3
CID = 15   CNT = 60
We can see that ADDR matches 10222 Trace Event output, for example, po=18f058b68.


3.2 State Transition Diagram


Run Dtrace Script: rco_dtrace_std to draw a State Transition Diagram of latch Get (kslgetl) and Latch Free (kslfre) for each Row Cache Object GET. (Note: kslgetl is exClusive latch get, whereas ksl_get_shared_latch is Shared latch get(in S or X Mode))

Here the output for one Row Cache Object GET. It shows 3 kslgetl Calls at 3 different Locations ("where"), all are prefixed with "Transition", followed by one kslfre
(note the indented function entry and return).

Those are probably the 3 unclear "latch: row cache objects" GETs, discussed in Oracle Core: Essential Internals for DBAs and Developers Page 167. (see Blog: nls_database_parameters, dc_props, latch: row cache objects )

-> kqrpre1
---------Step 1 at 2018 Oct 18 08:50:25 (Elapsed-ns=1491587737)---------
  -> kslgetl
---------Step 2 at 2018 Oct 18 08:50:25 (Elapsed-ns=104489)---------
            Entry State(nproc_pid=>0x0, flag=>0x0, gets=>0x4A04F, latch=>0x19B, level=>0x4, where=>0x1171)
            Transition > kslgetl:entry(Addr=>0x182D98958, Immed_Get=>1, Why=>0, Where=>4441(0x1159))
  <- kslgetl
---------Step 3 at 2018 Oct 18 08:50:25 (Elapsed-ns=32606)---------
            Return State(nproc_pid=>0x1B, flag=>0x0, gets=>0x4A050, latch=>0x19B, level=>0x4, where=>0x1159)
  -> kqrLockAndPinPo
---------Step 4 at 2018 Oct 18 08:50:25 (Elapsed-ns=36536)---------
            CID = 15   ADDR = 171999DD8
  <- kqrLockAndPinPo
---------Step 5 at 2018 Oct 18 08:50:25 (Elapsed-ns=24430)---------
  -> kslfre
---------Step 6 at 2018 Oct 18 08:50:25 (Elapsed-ns=8813)---------
            Transition > kslfre:entry(Addr=>0x182D98958) ===Latch freed===
  <- kslfre
---------Step 7 at 2018 Oct 18 08:50:25 (Elapsed-ns=14267)---------
<- kqrpre1
---------Step 8 at 2018 Oct 18 08:50:25 (Elapsed-ns=11490)---------
-> kslgetl
---------Step 9 at 2018 Oct 18 08:50:25 (Elapsed-ns=6415)---------
            Entry State(nproc_pid=>0x0, flag=>0x0, gets=>0x4A050, latch=>0x19B, level=>0x4, where=>0x1159)
            Transition > kslgetl:entry(Addr=>0x182D98958, Immed_Get=>1, Why=>0, Where=>4464(0x1170))
<- kslgetl
---------Step 10 at 2018 Oct 18 08:50:25 (Elapsed-ns=6092)---------
            Return State(nproc_pid=>0x1B, flag=>0x0, gets=>0x4A051, latch=>0x19B, level=>0x4, where=>0x1170)
-> kslfre
---------Step 11 at 2018 Oct 18 08:50:25 (Elapsed-ns=10545)---------
            Transition > kslfre:entry(Addr=>0x60164110) ===Latch freed===
<- kslfre
---------Step 12 at 2018 Oct 18 08:50:25 (Elapsed-ns=4733)---------
-> kslgetl
---------Step 13 at 2018 Oct 18 08:50:25 (Elapsed-ns=4412)---------
            Entry State(nproc_pid=>0x0, flag=>0x0, gets=>0x4A051, latch=>0x19B, level=>0x4, where=>0x1170)
            Transition > kslgetl:entry(Addr=>0x182D98958, Immed_Get=>1, Why=>0, Where=>4465(0x1171))
<- kslgetl
---------Step 14 at 2018 Oct 18 08:50:25 (Elapsed-ns=5110)---------
            Return State(nproc_pid=>0x1B, flag=>0x0, gets=>0x4A052, latch=>0x19B, level=>0x4, where=>0x1171)
-> kslfre
---------Step 15 at 2018 Oct 18 08:50:25 (Elapsed-ns=4445)---------
            Transition > kslfre:entry(Addr=>0x182D98958) ===Latch freed===
<- kslfre
The 3 consecutive latch Gets for one Row Cache Object GET are at 3 different Locations ("Where"):
  Where=>4441(0x1159): kqrpre: find obj   -- latch Get at 1st Location
  Where=>4464(0x1170): kqreqd             -- latch Get at 2nd Location
  Where=>4465(0x1171): kqreqd: reget      -- latch Get at 3rd Location
which can be found by sql below:

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;
 
select * from sys.X_GV$LATCH_MISSES 
where parent_name in ('row cache objects') 
  and indx in (4441, 4464, 4465); 
  
INDX  PARENT_NAME        WHERE             NWFAIL_COUNT  SLEEP_COUNT  WTR_SLP_COUNT  LONGHOLD_COUNT  LOCATION        
----- ----------------------  -----------------------------  ------------  -----------  -------------  --------------
4441  row cache objects  kqrpre: find obj  0             2            8              0               kqrpre: find obj
4464  row cache objects  kqreqd            0             0            0              0               kqreqd          
4465  row cache objects  kqreqd: reget     0             6            0              0               kqreqd: reget 


3.3 Call Stack and Call Sequence (Update 2020-Aug-03)


There are 3 latch gets, the first call is from kqrpre1 with Call Stack:

  kslgetl ()
  kqrpre1 ()
  kkdlpftld ()
  qerfxFetch ()
  opifch2 ()
the second and third calls are from kqreqd with Call Stack:

  kslgetl ()
  kqreqd ()
  kqrprl ()
  kkdlpftld ()
  qerfxFetch ()
kqrpre1 calls latch get/free (kslgetl/kslfre) with Call Sequence (latch location 0x1159):

  <kgghash>
  <kslgetl>      -- Where=>4441(0x1159)
  <kqrCacheHit>
  <kqrLockAndPinPo>
  <kslfre>
kqreqd calls latch get/free (kslgetl/kslfre) twice, with Call Sequence (latch location 0x1170 and 0x1171):

  <kslgetl>     -- Where=>4464(0x1170)
  <KGHISPIR>    -- "pin recreatable" 
  <kghupr>      -- "unpin recreatable"
  <kslfre>
  
  <kslgetl>     -- Where=>4465(0x1171)
  <kglFreeSO>   -- "free state object"
  <kslfre>
To find RowCache object, kqrpre1 first calls <kgghash> to compute a hash value and map to po (Rowcache Parent Object) value as shown in above 10222 trace:

  kqrpre1 : found po=0x9675c390 flg=2 hash=819e131 pso=0x9511def8 dur=CALL


4. 12cR2 10222 Trace Event


Make the same trace in Oracle 12cR2 for 3 different Levels, here the output:


4.1. Level 4


kqrpre1 : found po=0x9675c390 flg=2 hash=819e131 pso=0x9511def8 dur=CALL .
kqrpre1 : done po=0x9675c390 cid=15 flg=2 hash=819e131 0 eq=0x63dfbd98 pso=0x9511def8 dur=CALL .
kqreqd: eq: 0x63dfbd98
kqreqd freeing enqeue: eq: 0x63dfbd98

4.2. Level 255


kqrmpin : kqrpre: found po Pin po 0x9675c390 cid=15 flg=2 hash=819e131
time=1980227738
kqrpre1 : found po=0x9675c390 flg=2 hash=819e131 pso=0x9511def8 dur=CALL time=1980227746
kqrpre1 : done po=0x9675c390 cid=15 flg=2 hash=819e131 0 eq=0x63dfc580 pso=0x9511def8 dur=CALL time=1980227754
kqrprl: eq=0x63dfc580 fpInUse=FALSE
ksedsts()+346<-kqrprl()+1221<-kkdlpExecSqlCbk()+570<-kkdlpExecSql()+114<-kkdlpGet()+317<-kkdlpftld()+229<-qerfxFetch()+6519<-opifch2()+3267<-kpoal8()+3436<-opiodr()+1229<-ttcpip()+1257<-opitsk()+1940<-opiino()+941<-opiodr()+1229<-opidrv()+1021<-sou2o()+145
<-opimai_real()+455<-ssthrdmain()+417<-main()+262<-__libc_start_main()+256.
kqreqd: eq: 0x63dfc580
kqrmupin : kqrReleaseLock Unpin po 0x9675c390 cid=15 flg=2 hash=819e131 time=1980227875
kqreqd freeing enqeue: eq: 0x63dfc580

4.3. Level 4294967295


kqrmpin : kqrpre: found po Pin po 0x9675c390 cid=15 flg=2 hash=819e131
time=1845554855
kqrpre1 : found po=0x9675c390 flg=2 hash=819e131 pso=0x9511def8 dur=CALL time=1845554916
found stack: ksedsts()+346<-kqrpre1()+4784<-kkdlpExecSqlCbk()+418<-kkdlpExecSql()+114<-kkdlpGet()+317<-kkdlpftld()+229<-qerfxFetch()+6519<-opifch2()+3267<-kpoal8()+3436<-opiodr()+1229<-ttcpip()+1257<-opitsk()+1940<-opiino()+941<-opiodr()+1229<-opidrv()+1021
<-sou2o()+145<-opimai_real()+455<-ssthrdmain()+417<-main()+262<-__libc_start_main()+256.
kqrpre1 : done po=0x9675c390 cid=15 flg=2 hash=819e131 0 eq=0x63dfc0e0 pso=0x9511def8 dur=CALL SQL=select value from nls_database_parameters where parameter = 'NLS_CHARACTERSET' time=1845564279
done stack: ksedsts()+346<-kqrpre1()+2566<-kkdlpExecSqlCbk()+418<-kkdlpExecSql()+114<-kkdlpGet()+317<-kkdlpftld()+229<-qerfxFetch()+6519<-opifch2()+3267<-kpoal8()+3436<-opiodr()+1229<-ttcpip()+1257<-opitsk()+1940<-opiino()+941<-opiodr()+1229<-opidrv()+1021
<-sou2o()+145<-opimai_real()+455<-ssthrdmain()+417<-main()+262<-__libc_start_main()+256.
kqrprl: eq=0x63dfc0e0 fpInUse=FALSE
ksedsts()+346<-kqrprl()+1221<-kkdlpExecSqlCbk()+570<-kkdlpExecSql()+114<-kkdlpGet()+317<-kkdlpftld()+229<-qerfxFetch()+6519<-opifch2()+3267<-kpoal8()+3436<-opiodr()+1229<-ttcpip()+1257<-opitsk()+1940<-opiino()+941<-opiodr()+1229<-opidrv()+1021<-sou2o()+145
<-opimai_real()+455<-ssthrdmain()+417<-main()+262<-__libc_start_main()+256.
kqreqd: eq: 0x63dfc0e0
kqrmupin : kqrReleaseLock Unpin po 0x9675c390 cid=15 flg=2 hash=819e131 time=1845566287
kqreqd freeing enqeue: eq: 0x63dfc0e0

4.4. 12cR2 vs. 12cR1


Note that in Oracle 12.2.0.1.0 (12cR2), "row cache mutex" replaced 12.1.0.2.0 (12cR1) "latch: row cache objects". (See Blog: row cache mutex in Oracle 12.2.0.1.0 )

It seems that 10222 Trace event still generates similar output with more information, for example, call stacks.

Comparing the function calling sequence of Level 255 between 12cR1 and 12cR2:

  12cR1: kqrpre1(found) -> kqrmpin        -> kqrpre1(done) -> kqrmupin
  12cR2: kqrmpin        -> kqrpre1(found) -> kqrpre1(done) -> kqrmupin
12cR1: kqrpre1 and kqrmpin (kqrmupin) are interleaved, whereas 12cR2 shows that kqrpre1 is enclosed by kqrmpin (kqrmupin). So 12cR2 improved trace output.


5. Row Cache Internals: kqrpre1 and kqrfrpo


Pick one Row Cache Object GET from the output of above 10222 Level 4294967295, it shows that Row Cache is not able to cache it. Each time it needs to invoke "kqrpre1" (Row Cache Parent Read) to create a new DC row, use it, and then release it by "kqrfrpo : freed to heap". It took 279 us (2271264814-2271264535) for one such Read.

kqrpre1 : found po=18f058b68 flg=2 hash=5b42c02e time=2271264535
kqrmpin : kqrLockAndPinPo Pin po 18f058b68 cid=15 flg=2 hash=5b42c02e
time=2271264669
kqrpre1 : done po=18f058b68 cid=15 flg=2 hash=5b42c02e 0 eq=13fea57f8 SQL=select value from nls_database_parameters where parameter = 'NLS_CHARACTERSET' time=2271264687
kqrmupin : kqrpspr2 Unpin po 18f058b68 cid=15 flg=2 hash=5b42c02e time=2271264704
kqrmupin : free po=18f058b68 flg=2
kqrfrpo: Free po 18f058b68
 KQR Parent Cache Object:
 pob = 18f058b68 flg = 00000002 cid = 15 xcb = 0 hbk = 18f05ac38
 hbk=[f84f96e8,151186580] 
 own=18f058c38[18f058c38,18f058c38] wat=18f058c48[18f058c48,18f058c48] mod=0
kqrfrpo : freed to heap po=18f058b68 time=2271264814
We will look further in next Blog: Row Cache Objects, Row Cache Latch on Object Type: Plsql vs Java Call (Part-1) (II)


6. Discussions


Row Cache is a mechanisms analogue to CPU Cache:
  "CPU Cache" transfer "cache lines" between "Main Memory"  and "L1 Cache".

  "Row Cache" transfer "DC rows"     between "Buffer Cache" and "DC Cache".
Row Cache is more like a "software" cache because "Row Cache" and its hidden "Buffer Cache" are in SGA memory,
whereas "CPU Cache (L1)" and its underlying "Main Memory" are located in separate hardware.

Any cache miss results in a "Main Memory/Buffer" with much longer latency. The cache hit rate plays an important role in determining the performance.

Section 3.2 State Transition Diagram showed that each Row Cache Object GET is a cache miss.


7. 10222 Trace Import and Analyse Script


drop table raw_10222_trc_ext;

create table raw_10222_trc_ext
( text1 varchar2(1000)
)
organization external
(type oracle_loader
 default directory PLSHPROF_DIR
 access parameters
 (
   records delimited by newline CHARACTERSET AL32UTF8
   badfile aaa_db_io:'trc_ext.bad'
   logfile aaa_db_io:'trc_ext.log'
   discardfile aaa_db_io:'trc_ext.dsc'
   fields terminated by ','  OPTIONALLY ENCLOSED BY '"'
   missing field values are null
   ( text1 position(1:1000)
   )
 )
 location ('testdb_ksun_trc_row_cache_10222_15.trc')
) reject limit unlimited;

select rownum line_nbr, text1 from raw_10222_trc_ext;

drop table import_10222_trc;

create table import_10222_trc (run number, line_nbr number, cid number, ts_us number, po_address varchar2(32), 
  cid_type varchar2(12), cid_subordinate# number, cid_parameter varchar2(40), 
  obobn number, obname varchar2(100), sql varchar2(100), raw_lines varchar2(4000));

create or replace procedure import_10222_trc_proc (p_run number, p_trc_file varchar2, p_delete_old boolean := true) as 
  l_line_sep    varchar2(3) := '###';
  l_pos_1       number;
  l_pos_2       number;
  l_raw_lines   varchar2(32000);
  l_line_nbr    number           := 1;
  l_cid         number;
  l_ts_us       number;
  l_po_address  varchar2(32000);
  l_obobn       number;
  l_obname      varchar2(32000);
  l_sql         varchar2(32000);
begin
  -- setup trace file location
  execute immediate 'alter table raw_10222_trc_ext location (''' || p_trc_file || ''')';
  
  -- delete old RUN
  if p_delete_old then
    delete from import_10222_trc where run = p_run;
    commit;
  end if;
  
  -- concatenate same PO lines into one line
  for c in (select rownum line_nbr, text1 from raw_10222_trc_ext) loop
    dbms_output.put_line('Raw line_nbr: '||c.line_nbr ||'--text1: '||c.text1);
    if l_raw_lines is null then
      l_raw_lines := c.text1;
    else
      l_raw_lines := l_raw_lines ||l_line_sep||c.text1;
    end if;
    
    if c.text1 like 'kqrpre1 : found po=%' or c.text1 like 'kqrpad: new po%' then
      l_raw_lines := substr(l_raw_lines, 1, 4000);
      insert into import_10222_trc(run, line_nbr, raw_lines) values(p_run, l_line_nbr, l_raw_lines);
      commit;
      l_line_nbr  := c.line_nbr;
      l_raw_lines := c.text1;
    end if;
  end loop;
  
  -- insert last line
  if length(l_raw_lines) > 0 then
   l_raw_lines := substr(l_raw_lines, 1, 4000);
    insert into import_10222_trc(run, line_nbr, raw_lines) values(p_run, l_line_nbr, l_raw_lines);
    commit;
  end if;

 -- parse raw_lines
  for c in (select line_nbr, raw_lines from import_10222_trc
             where raw_lines like 'kqrpre1 : found po=%' or raw_lines like 'kqrpad: new po%') loop
    dbms_output.put_line('Parsing line_nbr: '||c.line_nbr||'--text1: '||c.raw_lines);
    l_cid        := regexp_substr(c.raw_lines, 'cid=(\d*)', 1, 1, 'i', 1);
    l_pos_1      := instr(c.raw_lines, 'time=', -1);
    if l_pos_1 > 0 then
      l_ts_us    := regexp_substr(c.raw_lines, 'time=(\d*)', l_pos_1, 1, 'i', 1);
    end if;
    l_po_address := substr(upper(regexp_substr(c.raw_lines, 'po=(\S*)', 1, 1, 'i', 1)), 1, 32);
    l_obobn      := regexp_substr(c.raw_lines, 'obobn=(\d*)', 1, 1, 'i', 1);
    l_obname     := substr(regexp_substr(c.raw_lines, 'obname=(\S*)', 1, 1, 'i', 1), 1, 100);
    l_pos_2      := instr(c.raw_lines, 'SQL=', 1) + 4;
    
    if (l_pos_2 > 4) then
     l_pos_1      := instr(c.raw_lines, 'time=', l_pos_2);
     if l_pos_1 = 0 then l_pos_1 := l_pos_2 + 100; end if;
      l_sql        := substr(substr(c.raw_lines, l_pos_2, l_pos_1 - l_pos_2), 1, 100);
    else
     l_sql := null;
    end if;
    
    update import_10222_trc 
       set cid        = l_cid
          ,ts_us      = l_ts_us
          ,po_address = l_po_address
          ,obobn      = l_obobn
          ,obname     = l_obname
          ,sql        = l_sql
     where run = p_run and line_nbr = c.line_nbr; 
    commit;
  end loop;

  -- add v$rowcache info
  update import_10222_trc t 
     set (cid_type, cid_subordinate#, cid_parameter) = 
         (select type, subordinate#, parameter from v$rowcache r where r.cache# = t.cid and rownum=1)
   where run = p_run;
  commit;
end;
/


8. Dtrace Scripts


8.1. rco_dtrace_cache


sudo dtrace -n \
'pid$target::kqrLockAndPinPo:entry /execname == "oracle"/ {
  @cid_addr_cnt[arg0, arg1] = count();
  @cid_cnt[arg0] = count();
  @cid_cnt_total = count();
  ustack(5, 0);
  printf("\nCID = %-4d ADDR = %-16X\n", arg0, arg1);}
END { 
   /** Only first call in new opened Sqlplus has not double counting **/
   printf("\n\n*************** CID Stats with Address (double counting) ****************");
   printa("\nCID = %-4d ADDR = %-16X CNT = %-10@d", @cid_addr_cnt);
   printf("\n*************** CID Stats ****************");
   printa("\nCID = %-4d CNT = %-10@d", @cid_cnt);
   printf("\n*************** CID Stats Summary ****************");
   printa("\nCNT = %-10@d", @cid_cnt_total); }
' -p $1

Update (30-May-2021)

Nenad (All-round Database Topics) found that double counting user calls can be avoided by specifying the module name, like

   pid$target:oracle:kqrLockAndPinPo:entry
instead of

   pid$target::kqrLockAndPinPo:entry
Here some tests in Oracle 19c
(Note: Oracle 12.2.0.1.0 (12cR2), "row cache mutex" replaced 12.1.0.2.0 (12cR1) "latch: row cache objects". See Blog: row cache mutex in Oracle 12.2.0.1.0 )

At first we list all kqr* functions:

SQL > select value from nls_database_parameters where parameter = 'NLS_CHARACTERSET';

$ sudo dtrace -n 'pid$target::kqr*:entry { @[probefunc] = count(); }' -p 25986

	dtrace: description 'pid$target::kqr*:entry ' matched 310 probes
		  kqrAllocateEnqueue        194
		  kqrCacheHit               194
		  kqrFreeEnqueue            194
		  kqrGetPOMutexInt          194
		  kqrLockPo                 194
		  kqrReleaseLock            194
		  kqreqd                    194
		  kqrget                    194
		  kqrhsh                    194
		  kqrmpin                   194
		  kqrmupin                  194
		  kqrpre1                   194
		  kqrpre2                   194
		  kqrprl                    194
		  kqrpspr                   194
		  
	*Note: kqrLockAndPinPo not listed, probably it is an Oracle 12.1 function
Then we list probes for above probe functions. There are two probe modules for each function (that is why we have the double counting), for example,

$ sudo dtrace -l -f kqrLockPo 
         ID   PROVIDER          MODULE           FUNCTION NAME
      90031   pid25986           a.out          kqrLockPo entry
      90032   pid25986          oracle          kqrLockPo entry
         
$ sudo dtrace -l -f kqrpre1    
         ID   PROVIDER          MODULE           FUNCTION NAME
      90029   pid25986           a.out            kqrpre1 entry
      90030   pid25986          oracle            kqrpre1 entry
Now we can use one of following probes to specify module and hence avoid double counting:

$ sudo dtrace -n 'pid$target:oracle:kqrpre1:entry {@[probefunc] = count();}' -p 25986
$ sudo dtrace -n 'pid$target:a.out:kqrpre1:entry  {@[probefunc] = count();}' -p 25986
$ sudo dtrace -i '90029 {@[probefunc] = count();}'
$ sudo dtrace -i '90030 {@ = count(); }'
We can also directly list each function with its probe module as follows:

SQL >select value from nls_database_parameters where parameter = 'NLS_CHARACTERSET';

$ sudo dtrace -n 'pid$target::kqr*:entry {@[probefunc, probemod] = count();}' -p 25986
	dtrace: description 'pid$target::kqr*:entry ' matched 310 probes
	    kqrAllocateEnqueue          a.out          97
	    kqrAllocateEnqueue          oracle         97
	    ......                      
	    kqrpre1                     a.out          97
	    kqrpre1                     oracle         97
	    ......                      
	    kqrpspr                     a.out          97
	    kqrpspr                     oracle         97

8.2. rco_dtrace_latch


sudo dtrace -F -n \
'
BEGIN {roread = 0; step = 1; self->func = "ne"; self->name = "na"; prev_ts = timestamp;}
pid$target::kqrpre1:entry /execname == "oracle" && self->func != probefunc / {roread = 1;
   printf("\n---------Step %d at %Y (Elapsed-ns=%d)---------", step, walltimestamp, (timestamp-prev_ts));
   self->func = probefunc; self->name = probename; step = step + 1; prev_ts = timestamp;
   @cnt[probefunc] = count();}
pid$target::kqrpre1:return /roread ==1/ {roread = 0;
   printf("\n---------Step %d at %Y (Elapsed-ns=%d)---------", step, walltimestamp, (timestamp-prev_ts));
   self->func = probefunc; self->name = probename; step = step + 1; prev_ts = timestamp;}
pid$target::kslgetl:entry /step > 1 && self->func != probefunc / {
   printf("\n---------Step %d at %Y (Elapsed-ns=%d)---------", step, walltimestamp, (timestamp-prev_ts));
   self->func = probefunc; self->name = probename; step = step + 1; prev_ts = timestamp;
   @cnt[probefunc] = count();}
pid$target::kslgetl:return /self->func == probefunc && self->name != probename/{
   printf("\n---------Step %d at %Y (Elapsed-ns=%d)---------", step, walltimestamp, (timestamp-prev_ts));
   self->func = probefunc; self->name = probename; step = step + 1;  prev_ts = timestamp;}
pid$target::kslfre:entry /step > 1 && self->func != probefunc / {
   printf("\n---------Step %d at %Y (Elapsed-ns=%d)---------", step, walltimestamp, (timestamp-prev_ts));
   self->func = probefunc; self->name = probename; step = step + 1; prev_ts = timestamp;
   @cnt[probefunc] = count();}
pid$target::kslfre:return /self->func == probefunc && self->name != probename/{
   printf("\n---------Step %d at %Y (Elapsed-ns=%d)---------", step, walltimestamp, (timestamp-prev_ts));
   self->func = probefunc; self->name = probename; step = step + 1;  prev_ts = timestamp;}
pid$target::kqrLockAndPinPo:entry /step > 1 && self->func != probefunc / {
   printf("\n---------Step %d at %Y (Elapsed-ns=%d)---------", step, walltimestamp, (timestamp-prev_ts));
   self->func = probefunc; self->name = probename; step = step + 1; prev_ts = timestamp;
   @cnt[probefunc] = count();}
pid$target::kqrLockAndPinPo:return /self->func == probefunc && self->name != probename/{
   printf("\n---------Step %d at %Y (Elapsed-ns=%d)---------", step, walltimestamp, (timestamp-prev_ts));
   self->func = probefunc; self->name = probename; step = step + 1; prev_ts = timestamp;}
' -p $1

8.3. rco_dtrace_std (@TODO improve it)


sudo dtrace -F -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 {step = 1; self->func = "na"; self->name = "na"; prev_ts = timestamp;}
pid$target::kqrpre1:entry /execname == "oracle" && self->func != probefunc / {self->roread = 1;
   printf("\n---------Step %d at %Y (Elapsed-ns=%d)---------", step, walltimestamp, (timestamp-prev_ts));
   self->func = probefunc; self->name = probename; step = step + 1; prev_ts = timestamp;
   @cnt_func[probefunc] = count();}
pid$target::kqrpre1:return /self->roread ==1/ {self->roread = 0;
   printf("\n---------Step %d at %Y (Elapsed-ns=%d)---------", step, walltimestamp, (timestamp-prev_ts));
   self->func = "na"; self->name = probename; step = step + 1; prev_ts = timestamp;}
pid$target::kslgetl:entry /step > 1 && self->func != probefunc / {
   printf("\n---------Step %d at %Y (Elapsed-ns=%d)---------", step, walltimestamp, (timestamp-prev_ts));
   self->func = probefunc; self->name = probename; step = step + 1; prev_ts = timestamp;
   @cnt_func[probefunc] = count();
   ls = ((latchstate *) copyin(arg0, sizeof(latchstate)));
   printf("\n            Entry State(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(Addr=>0x%X, Immed_Get=>%d, Why=>%d, Where=>%d(0x%X))",
          probefunc, probename, arg0, arg1, arg2, arg3, arg3);
   self->addr = arg0; self->loc = arg3;}
pid$target::kslgetl:return /self->func == probefunc && self->name != probename/{
   @sum[self->addr, self->loc] = sum(timestamp - prev_ts);
   @avg[self->addr, self->loc] = avg(timestamp - prev_ts);
   @max[self->addr, self->loc] = max(timestamp - prev_ts);
   @cnt[self->addr, self->loc] = count();
   @sum_total = sum(timestamp - prev_ts);
   @cnt_total = count();
   printf("\n---------Step %d at %Y (Elapsed-ns=%d)---------", step, walltimestamp, (timestamp-prev_ts));
   self->func = probefunc; self->name = probename; step = step + 1;  prev_ts = timestamp;
   ls = ((latchstate *) copyin(self->addr, sizeof(latchstate)));
   printf("\n            Return State(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);}
pid$target::kslfre:entry /step > 1 && self->func != probefunc / {
   printf("\n---------Step %d at %Y (Elapsed-ns=%d)---------", step, walltimestamp, (timestamp-prev_ts));
   self->func = probefunc; self->name = probename; step = step + 1; prev_ts = timestamp;
   @cnt_func[probefunc] = count();
   printf("\n            Transition > %s:%s(Addr=>0x%-X) ===Latch freed===", probefunc, probename, arg0);}
pid$target::kslfre:return /self->func == probefunc && self->name != probename/{
   printf("\n---------Step %d at %Y (Elapsed-ns=%d)---------", step, walltimestamp, (timestamp-prev_ts));
   self->func = probefunc; self->name = probename; step = step + 1;  prev_ts = timestamp;}
pid$target::kqrLockAndPinPo:entry /step > 1 && self->func != probefunc / {
   printf("\n---------Step %d at %Y (Elapsed-ns=%d)---------", step, walltimestamp, (timestamp-prev_ts));
   self->func = probefunc; self->name = probename; step = step + 1; prev_ts = timestamp;
   @cnt_func[probefunc] = count();
   @cid_addr_cnt[arg0, arg1] = count();
   @cid_cnt[arg0] = count();
   @cid_cnt_total = count();
   printf("\n            CID = %-4d ADDR = %-16X", arg0, arg1);}
pid$target::kqrLockAndPinPo:return /self->func == probefunc && self->name != probename/{
   printf("\n---------Step %d at %Y (Elapsed-ns=%d)---------", step, walltimestamp, (timestamp-prev_ts));
   self->func = probefunc; self->name = probename; step = step + 1; prev_ts = timestamp;}
END {
   trunc(@sum, 10); trunc(@avg, 10); trunc(@max, 10); trunc(@cnt, 10);
   printf("\n\n*************** Latch Stats (time in ns) ****************");
   printf("\nAddr           Where");
   printa("\n0x%-10X %6d sum = %10@d", @sum); printf("\n----------------------");
   printa("\n0x%-10X %6d avg = %10@d", @avg); printf("\n----------------------");
   printa("\n0x%-10X %6d max = %10@d", @max); printf("\n----------------------");
   printa("\n0x%-10X %6d cnt = %10@d", @cnt); printf("\n----------------------");
   printa("\nsum_total = %10@d", @sum_total);
   printa("\ncnt_total = %10@d", @cnt_total);

   /** @TODO not exact **/
   printf("\n\n*************** CID Stats with Address ****************");
   printa("\nCID = %-4d ADDR = %-16X CNT = %-10@d", @cid_addr_cnt);
   printf("\n*************** CID Stats ****************");
   printa("\nCID = %-4d CNT = %-10@d", @cid_cnt);
   printf("\n*************** CID Stats Summary ****************");
   printa("\nCNT = %-10@d", @cid_cnt_total);

   printf("\n\n*************** probefunc Stats ****************");
   printa("\n%-20s cnt = %10@d", @cnt_func);}
' -p $1

Thursday, October 18, 2018

Oracle ROWCACHE Views and Contents


1. ROWCACHE Views


Oralce pvovided 3 Views on Row Cache Objects.
V$ROWCACHE (X$KQRST): 
    a summary view of DC statistics. The suffix "ST" in underlying X$ Table probably means STatistics.
    One special Column: FASTGETS is marked as Reserved for internal use,
    which could indicate that some on-going work of new development.
    
    V$ROWCACHE is a stats view having 70 fixed rows.
    An appropriate name would be V$ROWCACHE_Stats.

V$ROWCACHE_PARENT (X$KQRFS): 
    an instantaneous view of DC activity. Its 4 real-time Columns:
      LOCK_MODE, LOCK_REQUEST, TXN, SADDR                        
    indicate that this view is reflecting each lock owner and each row waiter instantaneously.
    
    It is a run-time view having dynamic number of rows (eg. 61057).
    An appropriate name would be V$ROWCACHE_objects.

V$ROWCACHE_SUBORDINATE (X$KQRFP): 
    list 4 existed Subcache(Subordinate): 
    
    select cache#, subcache_name, count(*) cnt from V$ROWCACHE_SUBORDINATE 
     group by cache#, subcache_name order by subcache_name desc;
    
        CACHE#  SUBCACHE_NAME             CNT
        ------ ------------------------- ----
        7       dc_user_grants            32
        8       dc_object_grants          492
        16      dc_histogram_data_values  142
        16      dc_histogram_data         26
        
    It has a dynamic number of rows (eg. 2225). It looks like a residue of Row Cache development,
    and it is not clear about its practical usage.


2. ROWCACHE Contents


Learned from Case study on Oracle rowcache internals, cached non-existent objects and a describe bug, we can compose queries to list all Dictionary Caches and their contents. Each query looks like how Oracle makes the recursive queries to acces Row Caches.
(Note that Solaris x86 is little-endian)

We can compose queries to list all Dictionary Caches and their contents. Each query looks like how Oracle makes the recursive queries to acces Row Caches.
(Note that Test DB on Solaris x86 is little-endian)

At first, create a conversion function.

----helper function----
create or replace function dump_hex2str (dump_hex varchar2) return varchar2 is
  l_str varchar2(100);
begin
  with sq_pos as (select level pos from dual connect by level <= 1000)
      ,sq_chr as (select pos, chr(to_number(substr(dump_hex, (pos-1)*2+1, 2), 'XX')) ch
                  from sq_pos where pos <= length(dump_hex)/2)
  select listagg(ch, '') within group (order by pos) word
    into l_str
  from sq_chr;
  return l_str;
end;
/
Here the queries to read Row Caches and some example outputs.


2.1. dc_props


select dump_hex2str(rtrim(key, '0')) dc_prop_name, v.* 
from v$rowcache_parent v 
where cache_name in ('dc_props') 
order by key; 

  DC_PROP_NAME                  INDX  HASH  ADDRESS           CACHE#  CACHE_NAME  EXISTENT
  ----------------------------- ----- ----- ----------------- ------- ----------- --------
  BACK_END_DB                   37420  48    000000017AC05ED8  15      dc_props    N
  DBTIMEZONE                    37377  7     000000017C1D2538  15      dc_props    Y
  DEFAULT_EDITION               37416  46    000000017C3D9668  15      dc_props    Y
  DEFAULT_PERMANENT_TABLESPACE  37378  7     00000001783FDF00  15      dc_props    Y
  DEFAULT_TBS_TYPE              37384  12    000000017C1DAB98  15      dc_props    Y
  DEFAULT_TEMP_TABLESPACE       37371  0     000000017C1B0A78  15      dc_props    Y
  ...
  NLS_CALENDAR                  37374  3     000000017C18CF18  15      dc_props    Y
  NLS_CHARACTERSET              37402  29    000000017C18F038  15      dc_props    Y
  ... 
  60 rows selected.


2.2. dc_global_oids


with ro as (select /*+ materialize */ substr(key, 9, 32) key_oid$, ro.* 
              from v$rowcache_parent ro where cache_name in ('dc_global_oids') 
               and rownum <= 100    -- select 100 for test
              )
    ,so as (select /*+ materialize */ obj#, ro.* from sys.oid$, ro where oid$ = ro.key_oid$)
select owner||'.'||object_name object, so.*
  from dba_objects do, so
 where object_id = so.obj#;

  OBJECT         OBJ#     KEY_OID$                          INDX  HASH  ADDRESS           CACHE#  CACHE_NAME      EXISTENT
  -------------- -------- --------------------------------- ----- ----- ----------------- ------- --------------- --------
  SYS.PRVT_ILM   1581930  2CE6B7D8955B3AEBE054D48564CDEC20  1799  508   00000001714A1DD0  17      dc_global_oids  Y
  SYS.PRVT_ILM   1581930  2CE6B7D895B03AEBE054D48564CDEC20  1788  158   00000001714A3BF0  17      dc_global_oids  Y
  K.T_OBJ_RET    2360168  795ECCD5A45D48DDE054005056984D97  1793  410   00000001714DE8C0  17      dc_global_oids  Y
  K.T_OBJ_IN     2360169  7807E9A682B5082FE054005056984D97  1786  126   00000001714F2078  17      dc_global_oids  Y
  K.T_OBJ_OUT    2360170  7807E9A682BA082FE054005056984D97  1794  464   00000001714FB2B0  17      dc_global_oids  Y
  K.T_OBJ_INOUT  2360171  77DDFDFCEB484AF6E054005056984D97  1785  105   00000001714FB4E0  17      dc_global_oids  Y 


2.3. dc_objects


select to_number(ltrim((substr(key, 7, 2)||substr(key, 5, 2)||substr(key, 3, 2)||substr(key, 1, 2)), '0'), 'XXXX') Schema_User_ID,
       (select username from dba_users where user_id = 
          to_number(ltrim((substr(key, 7, 2)||substr(key, 5, 2)||substr(key, 3, 2)||substr(key, 1, 2)), '0'), 'XXXX')) username,
       dump_hex2str(rtrim(substr(key, 13), '0')) dc_object_name, 
       to_number(trim(both '0' from substr(key, 11, 2)||substr(key, 9, 2)), 'XXXX') key_str_len,
       v.* 
from v$rowcache_parent v 
where cache_name in ('dc_objects') 
  and rownum<= 100                  -- select 100 for test
order by key; 

  SCHEMA_USER_ID  USERNAME           DC_OBJECT_NAME               KEY_STR_LEN  INDX  HASH   ADDRESS           CACHE#  CACHE_NAME  EXISTENT
  --------------- ------------------ ---------------------------- ------------ ----- ------ ----------------- ------- ----------- --------
                                     FILE$                        5            546   11880  000000017BF87310  8       dc_objects  Y
                                     UNDO$                        5            505   4027   000000017BFAA5E0  8       dc_objects  Y
                                     VIEW$                        5            534   10244  0000000164B8D4B8  8       dc_objects  Y
                                     PROPS$                       6            585   17055  000000017B72E3C8  8       dc_objects  Y
  1                                  DUAL                         4            607   19722  0000000177B824B8  8       dc_objects  Y
  1                                  V$ROWCACHE_PARENT            17           610   20351  00000001662CEAB0  8       dc_objects  Y
  1                                  SYS_TEMP_0FD9D664D_E88F5145  27           512   5516   0000000164D16BF0  8       dc_objects  N
  49              K                  FOO                          3            532   10104  0000000177BD3AB8  8       dc_objects  Y
  49              K                  T_OBJ_RET                    9            676   30902  00000001662AD9B8  8       dc_objects  Y
  49              K                  DBA_OBJECTS                  11           519   6726   000000016630D270  8       dc_objects  N
  49              K                  DBMS_OUTPUT                  11           594   18151  00000001662796D0  8       dc_objects  N
  49              K                  DUMP_HEX2STR                 12           517   6336   0000000179577980  8       dc_objects  Y
  49              K                  V$ROWCACHE_PARENT            17           639   24261  00000001662D0EA0  8       dc_objects  N
  1779            GSMADMIN_INTERNAL  CLOUD                        5            646   26011  0000000164E42DF0  8       dc_objects  Y


2.4. dc_tablespaces


select to_number(substr(key, 5, 2)||substr(key, 3, 2)||substr(key, 1, 2), 'XXXXXX') ts#, 
      (select name from v$tablespace 
        where ts# = to_number(substr(key, 5, 2)||substr(key, 3, 2)||substr(key, 1, 2), 'XXXXXX')) ts_name,
       v.* 
from v$rowcache_parent v 
where cache_name in ('dc_tablespaces') 
  and rownum <= 100       -- select 100 for test
order by 1;
 
  TS#   TS_NAME   INDX  HASH  ADDRESS           CACHE#  CACHE_NAME      EXISTENT
  ----- --------- ----- ----- ----------------- ------- --------------- --------
  0     SYSTEM    56    4     0000000164DB14D0  0       dc_tablespaces  Y
  3     TEMP      23    2     0000000170F58628  0       dc_tablespaces  Y
  1999  USER1     37    2     0000000182F74750  0       dc_tablespaces  Y
  2000  USER2     68    5     0000000166167F68  0       dc_tablespaces  Y


2.5. dc_users


The output shows that SYS is in CACHE#=7, whereas SYSTEM in CACHE#=10.

select to_number(substr(key, 3, 2)||substr(key, 1, 2), 'XXXX') key_len,
       dump_hex2str(rtrim(substr(key, 5, 2*to_number(substr(key, 3, 2)||substr(key, 1, 2), 'XXXX')), '0')) user_or_role_name, 
       v.* 
from v$rowcache_parent v 
where cache_name in ('dc_users') 
  and rownum <= 100       -- select 100 for test
order by key;

  KEY_LEN  USER_OR_ROLE_NAME  INDX  HASH   ADDRESS           CACHE#  CACHE_NAME  EXISTENT
  -------- ------------------ ----- ------ ----------------- ------- ----------- --------
  3        SYS                1406  10788  0000000165B77CA0  7       dc_users    Y
  3        SYS                2342  51836  0000000165B77CA0  7       dc_users    Y
  5        OUTLN              1419  41803  0000000165E54C78  10      dc_users    Y
  5        OUTLN              2331  21366  0000000165E54C78  10      dc_users    Y
  6        DBSNM              1408  14676  00000001672EDCD0  10      dc_users    Y
  6        DBSNM              2338  45053  00000001672EDCD0  10      dc_users    Y
  6        SYSTEM             1422  50615  000000017C2F6468  10      dc_users    Y
  6        SYSTEM             2330  17882  000000017C2F6468  10      dc_users    Y


2.6. dc_sequences


create sequence test_seq start with 1 cache 1000;
 
with sq as (                                                                                      
  select to_number(substr(key, 5, 2)||substr(key, 3, 2)||substr(key, 1, 2), 'XXXXXX') seq_object_id
        ,v.*                                                                                       
   from v$rowcache_parent v                                                                       
  where cache_name in ('dc_sequences'))                                                           
select o.object_name, seq_object_id, cache#, cache_name 
    --,sq.*                                   
  from dba_objects o, sq                                                                          
 where o.object_id   = sq.seq_object_id                                                            
   and o.object_name = 'TEST_SEQ';                                                                
                                                                                                   
  OBJECT_NAM  SEQ_OBJECT_ID  CACHE#  CACHE_NAME
  ----------  -------------  ------  ------------
  TEST_SEQ          4153811      13  dc_sequences 


2.7 dc_rollback_segments


with sq as (
  select to_number(ltrim((substr(key, 7, 2)||substr(key, 5, 2)||substr(key, 3, 2)||substr(key, 1, 2)), '0'), 'XXXX') 
            rollback_segment_id
         ,indx, hash, address, cache#, cache_name    -- v.*
    from v$rowcache_parent v
   where cache_name in ('dc_rollback_segments'))
select s.sid, s.serial#, t.xidusn, t.xidslot, t.xidsqn, t.ubafil, t.ubablk
      ,(select segment_name from dba_rollback_segs where segment_id = sq.rollback_segment_id) segment_name
      ,sq.*
from  sq, v$session s, v$transaction t 
where sq.rollback_segment_id = t.xidusn and s.taddr=t.addr;

  SID SERIAL# XIDUSN XIDSLOT XIDSQN UBAFIL UBABLK SEGMENT_NAME           ROLLBACK_SEGMENT_ID INDX HASH ADDRESS          CACHE# CACHE_NAME
  --- ------- ------ ------- ------ ------ ------ ---------------------- ------------------- ---- ---- ---------------- ------ --------------------
  558   53837    264      23    152      3  15926 _SYSSMU264_2251784465$                 264 2731 3975 00000000A22DBD00      3 dc_rollback_segments
  722   27322    280      16    142      3  12193 _SYSSMU280_2691079894$                 280 2819 7188 00000000A22D8A00      3 dc_rollback_segments
       
-- Only those rollback_segments have 'ACTIVE' undo_extents
select * from dba_undo_extents where status = 'ACTIVE';

  OWN SEGMENT_NAME           TABLESPACE_NAME EXTENT_ID FILE_ID BLOCK_ID   BYTES BLOCKS RELATIVE_FNO COMMIT_JTIME COMMIT_WTIME STATUS
  --- ---------------------- --------------- --------- ------- -------- ------- ------ ------------ ------------ ------------ ------
  SYS _SYSSMU264_2251784465$ UNDO                    2       3    15872 1048576    128            3                           ACTIVE
  SYS _SYSSMU280_2691079894$ UNDO                    2       3    12160 1048576    128            3                           ACTIVE


-- Lock held to perform DDL on the undo segment
select * from v$enqueue_statistics where eq_type = 'US';  

-- 'US' Lock
select * from v$lock where type = 'US';


3. ROWCACHE Hash Bucket (Update 2020-Aug-03)


With following query, we can see that 60 rowcache objects in dc_props are distributed into 37 hash buckets:

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

  HASH_BUCKET HASH_BUCKET_SIZE
  ----------- ----------------
            1                3
            4                1
            6                2
            8                2
            9                1
           11                2
          ...             ...
           62                3
           63                1
           64                1
  
  37 rows selected.
The bucket size is varied from 1 to 3. Any size bigger than 1 will incur hash collision.

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

  HASH_BUCKET_SIZE NUMBER_OF_BUCKETS NUMBER_OF_ROWCACHE_OBJECTS
  ---------------- ----------------- --------------------------
                 1                20                         20
                 2                11                         22
                 3                 6                         18

Wednesday, October 10, 2018

Result Cache: RC Enqueue and Contention (V)

This Blog will discuss 'enq: RC - Result Cache: Contention' when two (or multi) sessions adding the same Result Cache item at about the same time.

In the previous 4 Blogs, we showed 4 different cases of Result Cache Invalidation and the subsequent Result Cache: RC Latch Contention.
1. PL/SQL Function Result Cache Invalidation (I) (DML and Select for Update)
2. Result Cache: RC Latch Contention and RESULT_CACHE_MAX_SIZE (II))
3. Result Cache: RC Latch Contention and PL/SQL Exception Handler (III)
4. Result Cache:0 rows updated Invalidations (IV) 
Note: All tests are done in Oracle 12.1.0.2.


1. RC Latch vs. RC Enqueue


Adding a new RC item requires 4 RC Latch Gets (1 S Mode and successive 3 X Mode) and 4 subsequent Releases (kslfre), so that the single RC Latch is held solely in the necessary critical code path for a short time during whole RC item building time. (see Blog: PL/SQL Function Result Cache Invalidation (I))

Prepare Test:

--============ Test Setup ============--
create or replace function test_build_time (p_id number) return number result_cache as
begin
 dbms_lock.sleep(p_id);
  return p_id;
end;
/

SQL > exec dbms_result_cache.flush;
Open two Sessions to add two different new RC items at about same time.

--============ Session_1 @T1 (started at 05:06:24) ============--
05:06:08 SQL > var ret number;
05:06:15 SQL > exec :ret := test_build_time(9.1);
Elapsed: 00:00:09.12
05:06:33 SQL >

--============ Session_2 @T2 (started at 05:06:25) ============--
05:06:09 SQL > var ret number;
05:06:16 SQL > exec :ret := test_build_time(9.2);
Elapsed: 00:00:09.22
05:06:34 SQL >
Above test demonstrates that each adding takes the specified build_time (09.12, 09.22), hence no RC Latch contentions. Both seemed running independently alone even though they are running concurrently.

Now it arises the question, what happens when two different sessions adding identical RC item at about same time ?

RC Latch (ksl_get_shared_latch) does not have the knowledge of RC item content, and two sessions do not hold it during whole RC item building time. Therefore RC Latch is not able to protect the uniqueness of this new RC item.

The Oracle answer is RC Enqueue to coordinate such access, analogue to TX Enqueue.


2. Building Phases


Run test:

--============ Test Run ============--
SQL > exec :ret := test_build_time(15.8);

--============ Test Output ============--
06:53:10 SQL > var ret number;
06:53:20 SQL > exec :ret := test_build_time(15.8);
Elapsed: 00:00:15.80
06:53:36 SQL >
If during the Test Run, we frequently run query (for example, with SQLcl repeat command):

select id, status, name, creation_timestamp, (sysdate-creation_timestamp)*86400 elapsed_seconds, 
       scan_count, lru_number, build_time --, cache_id, cache_key
from v$result_cache_objects 
where type = 'Result' and name like '%TEST_BUILD_TIME%'
order by id desc;
We can observe that adding a new RC item experiences 3 phases, with status changed at different timestamp:
  New (0 - 10 second)
      -> Bypass (10 - 15.8 second)  
            -> Published (after 15.8 second)
10 seconds is a timeout and will be looked later.

At the end, we have the output:

 ID STATUS    NAME                      CREATION_TIMESTAMP  ELAPSED_SECONDS SCAN_COUNT LRU_NUMBER BUILD_TIME
--- --------- ------------------------- ------------------- --------------- ---------- ---------- ----------
  1 Published "K"."TEST_BUILD_TIME"::8. 2018-10-09 06:53:20              17          0        886       1580
The two columns in v$result_cache_objects denote:
  CREATION_TIMESTAMP: Starting TimeStamp of Build
  BUILD_TIME:         Elapsed Time of Build (in centisecond)
The intermediate status "Bypass" (10 - 15.8 second) seems related to "Bypass Object (BO)" mentioned in:
Bug 23738186 : HIGH RESULT CACHE LATCHES AFTER MIGRATION TO 12.1.0.2
(superseded by Bug 26436717 : RESULT CACHE: "BYPASS OBJECTS" INCORRECTLY USED BY WAITING PROCESSES.
This bug fixes a flaw in the original fix for bug# 23738186)

See Blog: Result Cache: RC Latch Contention and PL/SQL Exception Handler (III)


3. Result Cache: RC Enqueue


Run following test, we can see that adding a new Row requires 2 enq REQs (311-309=2).

select eq_name, total_req#, succ_req#, cum_wait_time from v$enqueue_statistics where eq_type in ('RC');
exec :ret := test_build_time(16.8);
select eq_name, total_req#, succ_req#, cum_wait_time from v$enqueue_statistics where eq_type in ('RC');

--============ Test Output ============--
11:53:24 SQL > select eq_name, total_req#, succ_req#, cum_wait_time from v$enqueue_statistics where eq_type in ('RC');
  EQ_NAME                        TOTAL_REQ#  SUCC_REQ# CUM_WAIT_TIME
  ------------------------------ ---------- ---------- -------------
  Result Cache: Enqueue                 309        309             0

11:54:02 SQL > exec :ret := test_build_time(16.8);
Elapsed: 00:00:16.82

11:54:19 SQL > select eq_name, total_req#, succ_req#, cum_wait_time from v$enqueue_statistics where eq_type in ('RC');
  EQ_NAME                        TOTAL_REQ#  SUCC_REQ# CUM_WAIT_TIME
  ------------------------------ ---------- ---------- -------------
  Result Cache: Enqueue                 311        311             0

4. Two Sessions adding the same Result Cache item at about the same time


Add the same Result Cache item at about the same time in two sessions, and trace both session with Event 10704 & 10046.

During test, run query below to watch 'enq: RC - Result Cache: Contention':

  select * from v$wait_chains;

4.1. Session_1 adding item started at 18:55:06


--============ Session_1 @T1 (18:55:06) ============--
exec dbms_result_cache.flush;

set time on timing on
column eq_name format a25
var ret number;

select eq_name, total_req#, total_wait#, succ_req#, failed_req#, cum_wait_time from v$enqueue_statistics where eq_type in ('RC');
alter session set events='10046 trace name context forever, level 12 : 10704 trace name context forever, level 3' tracefile_identifier='RC_Enq_1';
exec :ret := test_build_time(18.8);
alter session set events='10046 trace name context off : 10704 trace name context off ';
select eq_name, total_req#, total_wait#, succ_req#, failed_req#, cum_wait_time from v$enqueue_statistics where eq_type in ('RC');

--============ Session_1 Output (started at 18:55:06)============--
18:55:04 SQL> select eq_name, total_req#, total_wait#, succ_req#, failed_req#, cum_wait_time from v$enqueue_statistics where eq_type in ('RC');
  EQ_NAME                   TOTAL_REQ# TOTAL_WAIT#  SUCC_REQ# FAILED_REQ# CUM_WAIT_TIME
  ------------------------- ---------- ----------- ---------- ----------- -------------
  Result Cache: Enqueue            670           8        666           4        215480

18:55:06 SQL> exec :ret := test_build_time(18.8);
Elapsed: 00:00:18.83

18:55:25 SQL> select eq_name, total_req#, total_wait#, succ_req#, failed_req#, cum_wait_time from v$enqueue_statistics where eq_type in ('RC');
  EQ_NAME                   TOTAL_REQ# TOTAL_WAIT#  SUCC_REQ# FAILED_REQ# CUM_WAIT_TIME
  ------------------------- ---------- ----------- ---------- ----------- -------------
  Result Cache: Enqueue            674           9        669           5        225480

--============ Session_1 Trace (irelevant lines removed) ============--
*** SESSION ID:(189.37589) 2018-10-09 18:55:06.768
PARSING IN CURSOR #139879855170464 len=43 dep=0 uid=49 oct=47 lid=49 tim=12989538062736 hv=3533163271 ad='1513d9108' sqlid='4ffwn7z99gks7'
BEGIN :ret := test_build_time(18.8); END;
ksqgtl *** RC-00000002-FFFFFFFF-00000000-00000000 mode=4 flags=0x10400 timeout=21474836 ***
ksqgtl: RETURNS 0
ksqgtl *** RC-00000002-0024034D-00000000-00000000 mode=3 flags=0x10000 timeout=0 ***
ksqgtl: RETURNS 0
ksqgtl *** RC-00000001-00000001-00000000-00000000 mode=6 flags=0x10000 timeout=0 ***
ksqgtl: RETURNS 0

*** 2018-10-09 18:55:25.592
WAIT #139879855170464: nam='PL/SQL lock timer' ela= 18805802 duration=0 p2=0 p3=0 obj#=-1 tim=12989556871029
EXEC #139879855170464:c=859,e=18808207,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,plh=0,tim=12989556871192

4.2. Session_2 adding item started at 18:55:10 (4 seconds after Session_1)


--============ Session_2 @T2 (18:55:10) ============--
set time on timing on
column eq_name format a25
var ret number;

select eq_name, total_req#, total_wait#, succ_req#, failed_req#, cum_wait_time from v$enqueue_statistics where eq_type in ('RC');
alter session set events='10046 trace name context forever, level 12 : 10704 trace name context forever, level 3' tracefile_identifier='RC_Enq_2';
exec :ret := test_build_time(18.8);
alter session set events='10046 trace name context off : 10704 trace name context off ';
select eq_name, total_req#, total_wait#, succ_req#, failed_req#, cum_wait_time from v$enqueue_statistics where eq_type in ('RC');

--============ Session_2 Output (started at 18:55:10, 4 seconds after Session_1) ============--
17:54:08 SQL> select eq_name, total_req#, total_wait#, succ_req#, failed_req#, cum_wait_time from v$enqueue_statistics where eq_type in ('RC');
  EQ_NAME                   TOTAL_REQ# TOTAL_WAIT#  SUCC_REQ# FAILED_REQ# CUM_WAIT_TIME
  ------------------------- ---------- ----------- ---------- ----------- -------------
  Result Cache: Enqueue            673           8        669           4        215480

18:55:10 SQL> exec :ret := test_build_time(18.8);
Elapsed: 00:00:28.84

18:55:39 SQL> select eq_name, total_req#, total_wait#, succ_req#, failed_req#, cum_wait_time from v$enqueue_statistics where eq_type in ('RC');
  EQ_NAME                   TOTAL_REQ# TOTAL_WAIT#  SUCC_REQ# FAILED_REQ# CUM_WAIT_TIME
  ------------------------- ---------- ----------- ---------- ----------- -------------
  Result Cache: Enqueue            674           9        669           5        225480

--============ Session_2 Trace (irelevant lines removed) ============--
*** SESSION ID:(363.50996) 2018-10-09 18:55:11.039
PARSING IN CURSOR #139824425361968 len=43 dep=0 uid=49 oct=47 lid=49 tim=12989542327336 hv=3533163271 ad='1513d9108' sqlid='4ffwn7z99gks7'
BEGIN :ret := test_build_time(18.8); END;
ksqgtl *** RC-00000001-00000001-00000000-00000000 mode=4 flags=0x10000 timeout=10 ***
ksqgtl: no transaction
ksqgtl: use existing ksusetxn DID
ksqgtl:
 ksqlkdid: 0001-001A-00000B01
*** ksudidTrace: ksqgtl
 ksusesdi:   0000-0000-00000000
 ksusetxn:   0001-001A-00000B01
ksqcmi: RC-00000001-00000001-00000000-00000000 mode=4 timeout=10

*** 2018-10-09 18:55:21.052
WAIT #139824425361968: nam='enq: RC - Result Cache: Contention' ela= 10003442 name|mode=1380122628 chunkNo=1 blockNo=1 obj#=1591122 tim=12989552331028
ksqcmi: returns 51
ksqgtl: RETURNS 51

*** 2018-10-09 18:55:39.858
WAIT #139824425361968: nam='PL/SQL lock timer' ela= 18805872 duration=0 p2=0 p3=0 obj#=-1 tim=12989571137038

4.3. Discussions


Sqlplus output shows:
  Session_1 started at 18:55:06, and took 18.83 seconds.
  
  Session_2 started at 18:55:10 (4 seconds later), and took 28.84 seconds.
            28.84 is (10 + 18.8). We will look it later.
Above trace shows:
  Session_1 made 3 "ksqgtl *** RC" in mode=4, 3, 6, all succeded "ksqgtl: RETURNS 0",
                    with ela= 18805802 us on 'PL/SQL lock timer'.
           
  Session_2 made 1 "ksqgtl *** RC" in mode=4, failed "ksqgtl: RETURNS 51", 
                    with ela= 10003442 us on 'enq: RC - Result Cache: Contention'
                     and ela= 18805872 us on 'PL/SQL lock timer'.
                    total ela is about 28.8 seconds.
           "ksqgtl *** RC" is marked with "timeout=10".

               name|mode=1380122628 chunkNo=1 blockNo=1 obj#=1591122
            means:
               "1380122628" = 0x52430004 = RC 04 
               "1591122" is object_id of SYS.OBJ$
               "chunkNo=1 blockNo=1" is RC row pointer, similar to Heap Table ROWID: "block_id row_number".  
v$enqueue_statistics query output is consistent with above trace output:
  4 REQ# (674-670), 1 WAIT# (9-8), 3 SUCC_REQ# (669-666), 1 FAILED_REQ# (5-4)
  CUM_WAIT_TIME increase 10000 ms (225480 - 215480).

5. Hidden Parameters: _result_cache_timeout


Above the trace output reveals "timeout=10" for 'enq: RC - Result Cache: Contention' (ela= 10003442). Lookup all 17 Result Cache Hidden Parameters listed in Blog: PL/SQL Function Result Cache Invalidation (I)

The only matched one with default value 10 is:
  _result_cache_timeout: maximum time (sec) a session waits for a result, default = 10
Let's make a few tests to gamble its behaviours:
    Each test is done by two sessions to add the same item with different time delay.
    Different tests are carried out by varying build_time.
    Then modify "_result_cache_timeout" from 10 to 33 to make more tests.


Case_1. build_time=8.5 < 10, Session_2 starts 2 seconds aftet Session_1.


-- Session_2 started within NEW phase (10 seconds timeout) of Session_1.
-- Item ready in Session_1 at 11:36:05. 
-- Session_2's timeout at 11:35:59 + 10 =  11:36:09.
-- (11:36:05 < 11:36:09): Session_2 can get result before timeout. 

--============ Session_1 (started at 11:35:57) ============--
11:35:06 SQL> exec :ret := test_build_time(8.5);
Elapsed: 00:00:08.51
11:36:05 SQL>

--============ Session_2 (started at 11:35:59) ============--
11:35:06 SQL> exec :ret := test_build_time(8.5);
Elapsed: 00:00:06.17
11:36:05 SQL>

Case_2. build_time=20.1 > 10, Session_2 starts 2 seconds aftet Session_1.


-- Session_2 started within NEW phase of Session_1.
-- Item ready in Session_1 at 11:52:35. 
-- Session_2's timeout at 11:52:17 + 10 =  11:52:27.
-- (11:52:35 > 11:52:27): Session_2 can NOT get result before timeout. 

--============ Session_1 (started at 11:52:15) ============--
11:47:34 SQL> exec :ret := test_build_time(20.1);
Elapsed: 00:00:20.10
11:52:35 SQL>

--============ Session_2 (started at 11:52:17) ============--
11:47:47 SQL> exec :ret := test_build_time(20.1);
Elapsed: 00:00:30.12     -- timeout(10) + build_time(20.1) = 30.12
11:52:47 SQL>

Case_3. build_time=20.2 > 10, Session_2 starts 13 seconds aftet Session_1.


-- Session_2 started within BYPASS phase of Session_1.
-- Item ready in Session_1 at 11:53:53. 
-- Session_2's timeout at 11:53:47 + 10 =  11:53:57.
-- (11:53:53 < 11:53:57): Session_2 can get result before timeout.  

--============ Session_1 (started at 11:53:33) ============--
11:52:35 SQL> exec :ret := test_build_time(20.2);
Elapsed: 00:00:20.21
11:53:53 SQL>

--============ Session_2 (started at 11:53:47) ============--
11:52:47 SQL> exec :ret := test_build_time(20.2);
Elapsed: 00:00:20.21
11:54:07 SQL>

Increase "_result_cache_timeout" from 10 to 33, and make further tests:

alter system set "_result_cache_timeout"=33;

Case_4. build_time=20.4 < 33, Session_2 starts 13 seconds aftet Session_1.


-- Session_2 started within NEW phase (33 seconds timeout) of Session_1.
-- Item ready in Session_1 at 12:19:15. 
-- Session_2's timeout at 12:19:08 + 33 =  12:19:42.
-- (12:19:15 < 12:19:42): Session_2 can get result before timeout.  

--============ Session_1 (started at 12:18:55) ============--
12:18:51 SQL> exec :ret := test_build_time(20.4);
Elapsed: 00:00:20.42
12:19:15 SQL>

--============ Session_2 (started at 12:19:08) ============--
12:19:06 SQL> exec :ret := test_build_time(20.4);
Elapsed: 00:00:07.00
12:19:15 SQL>

Case_5. build_time=40.2 > 33, Session_2 starts 8 seconds aftet Session_1.


-- Session_2 started within NEW phase of Session_1.
-- Item ready in Session_1 at 13:14:56. 
-- Session_2's timeout at 13:14:20 + 33 =  13:14:53.
-- (13:14:56 > 13:14:53): Session_2 can NOT get result before timeout.  

--============ Session_1 (started at 13:14:12) ============--
13:14:02 SQL> exec :ret := test_build_time(40.2);
Elapsed: 00:00:40.20
13:14:56 SQL>

--============ Session_2 (started at 13:14:20) ============--
13:12:57 SQL> exec :ret := test_build_time(40.2);
Elapsed: 00:01:13.21   -- timeout(33) + build_time(40.2) = 73.2 = 01:13.21
13:15:33 SQL>

Case_6. build_time=40.1 > 33, Session_2 starts 12 seconds aftet Session_1.


-- Session_2 started within NEW phase of Session_1.
-- Item ready in Session_1 at 12:24:39. 
-- Session_2's timeout at 12:24:11 + 33 =  12:24:43.
-- (12:24:39 < 12:24:43): Session_2 can get result before timeout.  

--============ Session_1 (started at 12:23:59) ============--
12:19:15 SQL> exec :ret := test_build_time(40.1);
Elapsed: 00:00:40.12
12:24:39 SQL>

--============ Session_2 (started at 12:24:11) ============--
12:19:15 SQL> exec :ret := test_build_time(40.1);
Elapsed: 00:00:28.71
12:24:39 SQL>

Case_7. build_time=40.3 > 33, Session_2 starts 35 seconds aftet Session_1.


-- Session_2 started within BYPASS phase of Session_1.
-- Item ready in Session_1 at 13:39:42. 
-- Session_2's timeout at 13:39:37 + 33 =  13:40:10.
-- 13:39:42 < 13:40:10): Session_2 can get result before timeout.  

--============ Session_1 (started at 13:39:02) ============--
13:38:39 SQL > exec :ret := test_build_time(40.3);
Elapsed: 00:00:40.30
13:39:42 SQL >

--============ Session_2 (started at 13:39:37) ============--
13:38:32 SQL > exec :ret := test_build_time(40.3);
Elapsed: 00:00:40.30
13:40:17 SQL >
In summary, it looks like:
   When Session_2 started within NEW phase of Session_1, it experienced a long wait if it can not get the result built by Session_1
   within its timeout, for example, Case_2 (_result_cache_timeout=10) and Case_5 (_result_cache_timeout=33).

   When Session_2 started within BYPASS phase of Session_1, it built the RC item itself, hence "BYPASS" the Session_1's Build.
   It took exact the specified time, for example, Case_3 (_result_cache_timeout=10) and Case_7 (_result_cache_timeout=33).

If we repeat the test of Section 4, trace file will show "timeout=33":

ksqgtl *** RC-00000001-00000001-00000000-00000000 mode=4 flags=0x10000 timeout=33 ***
By the way, above tests showed that Result Cache can not be used in "Delay" (or "TIMEOUT") functions since only Session_1 has a specified duration in the first time, all other function calls take (almost) 0 time, or nondeterministic time.