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.