Wednesday, April 17, 2019

Blog List

LOB ORA-22924: snapshot too old and Fix

To continue the discussion in Blog: UNDO Practice, this one will demonstrate LOB special UNDO error with code examples in Plsql and provide a fix.
    ORA-01555: snapshot too old: rollback segment number  with name "" too small
    ORA-22924: snapshot too old
We will test "too old" in two dimensions, one is according to space usage (LOB pctversion), other is according to life time (LOB retention).

At beginning, it was thought to find some concrete code examples to reproduce ORA-22924. Googled with "Oracle LOB ORA-22924: snapshot too old example", and paged over a dozen of returned results, it was still empty.

Note: All tests are done in 12.1.0.2.0 (12cR1)


1. Test Setup


First we create a table containing one LOB column and fill some data. The LOB column is stored as basicfile and using pctversion to control the old versions of LOB data. The pctversion is set to special value 0 so that ORA-22924 can be reproduced in each short run. We also tested pctversion default value 10, the same ORA-22924 is still reproducible (later we will also test retention Parameter).

---==================== PCTVERSION Test Setup ====================---

drop tablespace test_ts including contents and datafiles;

create tablespace test_ts datafile '/oradb/oradata/testdb/test_dbf.dbf' size 100m online;

drop table tab_lob cascade constraints;

create table tab_lob(id number, mylob clob) 
  lob (mylob) store as basicfile 
  (tablespace  test_ts
   enable      storage in row
   chunk       8192
   pctversion 0
   --pctversion 10        -- default of 10 (%)
   --retention   none
   nocache
   logging)
tablespace test_ts; 

declare
  l_cnt     number := 1e1;
  l_clob    clob   := to_clob(rpad('abc', 10000, 'x'));
begin
  for i in 1..l_cnt loop
    insert into tab_lob values(i, l_clob);
  end loop;
  commit;
end;
/   
Show LOB meta info:

---==================== PCTVERSION Test Meta Info ====================---
 
column table_name format a14;
column column_name format a14;
column segment_name format a28;
column column_name format a14;
column retention_type format a20;
  
select table_name, column_name, segment_name, pctversion, retention, retention_type 
  from dba_lobs where table_name in ('TAB_LOB');  
  
TABLE_NAME COLUMN_NAME SEGMENT_NAME              PCTVERSION  RETENTION RETENTION_TYPE
---------- ----------- ------------------------- ---------- ---------- --------------
TAB_LOB    MYLOB       SYS_LOB0003449207C00002$$          0            NO
  
 
select segment_name, segment_type from dba_segments where tablespace_name in ('TEST_TS');

SEGMENT_NAME                 SEGMENT_TYPE
---------------------------- ------------
TAB_LOB                      TABLE
SYS_IL0003449207C00002$$     LOBINDEX
SYS_LOB0003449207C00002$$    LOBSEGMENT
Create 3 procedures for our test.

---==================== PCTVERSION Test Meta Info ====================---

create or replace procedure lob_22924_select(p_id number, p_cnt number, p_sleep number) as
  l_clob           clob;
  l_null_check     boolean;
begin
  select mylob into l_clob from tab_lob where id = p_id;
  
  for i in 1..p_cnt loop
   dbms_output.put_line('------- Seq: '||i);
   
   -- getlength, no error
    dbms_output.put_line('LOB length check OK, length = '||dbms_lob.getlength(l_clob));
    
    -- null check, no error
    l_null_check := l_clob is null;
    l_null_check := l_clob is not null;
    dbms_output.put_line('LOB null check OK');
    
    -- content access, throw ORA-22924 under ORA-01555
    dbms_output.put_line('LOB content check, substr ='||dbms_lob.substr(l_clob, 10, 2000));
    
    dbms_lock.sleep(p_sleep);
  end loop;
end;
/

create or replace procedure lob_22924_update(p_id number, p_cnt number, p_sleep number) as
  l_clob      clob;
  l_pad       varchar2(1000) := rpad('abc', 100, 'x');
begin
  select mylob into l_clob from tab_lob where id = p_id;
  
  for i in 1..p_cnt loop
   update tab_lob set mylob = mylob||l_pad where id = p_id;
    commit;
    dbms_lock.sleep(p_sleep);
  end loop;
end;
/

create or replace procedure lob_22924_select_update(p_id number, p_cnt number, p_sleep number) as
  l_clob        clob;
  l_pad         varchar2(1000) := rpad('abc', 100, 'x');
  l_clob_upd    clob := to_clob(rpad('abc', 10000, 'x'));  
  l_null_check  boolean;
begin
  select mylob into l_clob from tab_lob where id = p_id;
  
  for i in 1..p_cnt loop
    dbms_output.put_line('------- Seq: '||i);  
    update tab_lob set mylob = mylob||l_pad where id = p_id;
    commit;
    
    -- getlength, no error
    dbms_output.put_line('LOB length check OK, length = '||dbms_lob.getlength(l_clob));
    
    -- null check, no error
    l_null_check := l_clob is null;
    l_null_check := l_clob is not null;
    dbms_output.put_line('LOB null check OK');
    
    -- content access, throw ORA-22924 under ORA-01555
    dbms_output.put_line('LOB content check, substr ='||dbms_lob.substr(l_clob, 10, 2000));
    
    dbms_lock.sleep(p_sleep);
  end loop;
end;
/


2. Test Run


We will make two different tests to generate ORA-22924. Once with two Sqlplus sessions, once with a single session.


2.1. Two Sessions.


We open two Sqlplus Sessions. In Session_1, call lob_22924_select to start a query:

-------------- Session_1@T1 select --------------
 
10:22:15 Sql > exec lob_22924_select(3, 1e2, 1);
  ------- Seq: 1
  LOB length check OK, length = 10000
  LOB null check OK
  LOB content check, substr =xxxxxxxxxx
  ------- Seq: 2
  LOB length check OK, length = 10000
  LOB null check OK
  LOB content check, substr =xxxxxxxxxx
  
  ...
  ------- Seq: 7
  LOB length check OK, length = 10000
  LOB null check OK
  BEGIN lob_22924_select(3, 1e2, 1); END;
  
  *
  ERROR at line 1:
  ORA-01555: snapshot too old: rollback segment number  with name "" too small
  ORA-22924: snapshot too old
  ORA-06512: at "SYS.DBMS_LOB", line 1109
  ORA-06512: at "S.LOB_22924_SELECT", line 19
  ORA-06512: at line 1
In Session_2, call lob_22924_update to start a loop update.

-------------- Session_2@T2 update --------------

10:22:24 Sql > exec lob_22924_update(3, 1e4, 0.01);
After a couple of seconds, Session_1 throws error ORA-01555 and ORA-22924. If we look procedure lob_22924_select, error occurs when we access content by dbms_lob.substr. For dbms_lob.getlength and LOB null check, there is no such error. Probably both dbms_lob.getlength and LOB null check are using LOB index, and LOB index is based on normal Oracle UNDO mechanism.

Session_1 output shows that LOB length is always 10000, which implies that the checked LOB data is pointing to the fetched data and never changed. It acts like a consistent view in READ ONLY transaction (or SERIALIZABLE transaction).


2.2. One Session


We open one single Sqlplus Session Session_2, call lob_22924_select_update to start a query, then make updates:

-------------- Session_3@T3 update --------------

10:28:33 Sql > exec lob_22924_select_update(7, 1e2, 1);
  ------- Seq: 1
  LOB length check OK, length = 10000
  LOB null check OK
  LOB content check, substr =xxxxxxxxxx
  ------- Seq: 2
  LOB length check OK, length = 10000
  LOB null check OK
  LOB content check, substr =xxxxxxxxxx
  
  ...
  ------- Seq: 54
  LOB length check OK, length = 10000
  LOB null check OK
  BEGIN lob_22924_select_update(7, 1e2, 1); END;
  
  *
  ERROR at line 1:
  ORA-01555: snapshot too old: rollback segment number  with name "" too small
  ORA-22924: snapshot too old
  ORA-06512: at "SYS.DBMS_LOB", line 1109
  ORA-06512: at "S.LOB_22924_SELECT_UPDATE", line 23
  ORA-06512: at line 1
After about 50 seconds, it throws error ORA-01555 and ORA-22924.

lob_22924_select_update is a merge of previous select (lob_22924_select) and update (lob_22924_update). When we run both in one single session, we get the same error. That means even though we update the current LOB version, the old consistent version is still kept in the same session. And any access to the content can hit ORA-22924 error.


3. Retention Test


LOB column can also be configured to store old versions of LOB data for a period of time by normal retention, rather than using a percentage of the table space by above pctversion.

First we change the DDL to use retention, fill data and show meta info:

---==================== RETENTION Test ====================

alter system set undo_retention = 900;    --(Default 900)

drop table tab_lob cascade constraints;

create table tab_lob(id number, mylob clob) 
  lob (mylob) store as basicfile 
  (tablespace  test_ts
   enable      storage in row
   chunk       8192
   --pctversion 0
   retention   none
   nocache
   logging)
tablespace test_ts; 

declare
  l_cnt     number := 1e1;
 l_clob    clob   := to_clob(rpad('abc', 10000, 'x'));
begin
  for i in 1..l_cnt loop
    insert into tab_lob values(i, l_clob);
  end loop;
  commit;
end;
/   

select table_name, column_name, segment_name, pctversion, retention, retention_type 
  from dba_lobs where table_name in ('TAB_LOB');  
  
TABLE_NAME COLUMN_NAME SEGMENT_NAME              PCTVERSION  RETENTION RETENTION_TYPE
---------- ----------- ------------------------- ---------- ---------- --------------
TAB_LOB    MYLOB       SYS_LOB0003449216C00002$$                   900 YES
We can see that default retention is picked from undo_retention default 900 seconds. To speed up out test, we can low it to a short time, for example, 3 seconds:

alter system set undo_retention = 3;  

alter table tab_lob modify lob (mylob) (retention);  
  
select table_name, column_name, segment_name, pctversion, retention, retention_type 
  from dba_lobs where table_name in ('TAB_LOB');  
  
TABLE_NAME COLUMN_NAME SEGMENT_NAME              PCTVERSION  RETENTION RETENTION_TYPE
---------- ----------- ------------------------- ---------- ---------- --------------
TAB_LOB    MYLOB       SYS_LOB0003449216C00002$$                     3 YES
Then restore original undo_retention, and recompile invalidated procedures:

alter system set undo_retention = 900; 

alter procedure lob_22924_select compile;
alter procedure lob_22924_select_update compile;
alter procedure lob_22924_update compile;    
Now we can repeat the same tests (two or one sessions) as pctversion, and get the same errors.

With retention, it can require longer time to erase the kept CR copy because of Oracle AUM (Automatic Undo Management). Therefore it needs to a higher update loops (p_cnt) when calling lob_22924_select_update to hit ORA-22924.

We also noticed that when running several concurrent update sessions (each updates a different row), the error appears quicker and more frequent because all LOB data (from different rows) are stored in the same datafile.


4. Fix


The problem of ORA-22924 is that we are retaining a LOB Locator to an old version of LOB data, and if this old version gets too old (overwritten by newer versions), we hit the error when accessing that Locator.

Oracle permanent LOB CR views are implemented by versions (different copies) to conform to the ANSI standard (ACID regime). LOB data does not generate rollback information (redo/undo). Only LOB Index generates undo/redo because it is implemented in normal Oracle undo/redo mechanism.

However for Oralee temporary LOBs, CR, undo and versions are not supported. They are stored in Temporary Tablespace and are session private.

In the fix below, LOB content is at first copied to a local temporary LOB so that we always preserve a CR data for later access (analogue to normal CR view at the point of query start).

Note that dbms_lob.copy is used to create a new CR copy (new instance) of LOB content. Direct LOB assignment by Sql or Plsql do not fix ORA-22924: snapshot too old.

create or replace procedure lob_22924_select_fix(p_id number, p_cnt number, p_sleep number) as
  l_clob           clob;
  l_null_check     boolean;
  l_clob_temp      clob;
begin
  -- create temporary lob
  dbms_lob.createtemporary(lob_loc => l_clob_temp, cache => true, dur => dbms_lob.call);
  
  select mylob into l_clob from tab_lob where id = p_id;
  
  -- copy content of Permanent LOB Locator to Temporary LOB Locator (pass by value)
  dbms_lob.copy(dest_lob => l_clob_temp, src_lob => l_clob, amount => dbms_lob.getlength(l_clob));
  
  -- Note: two following approaches not fix ORA-22924: snapshot too old 
  -- because Temporary LOB Locator is overwritten by Permanent LOB Locator
  -- and Temporary LOB Locator points to the Permanent LOB Locator (pass by pointer). 
  --   select mylob into l_clob_temp from tab_lob where id = p_id;   -- not fix ORA-22924 by Sql
  --   l_clob_temp := l_clob;                                        -- not fix ORA-22924 by Plsql
  
  for i in 1..p_cnt loop
    dbms_output.put_line('------- Seq: '||i);
   
    -- getlength, no error
    dbms_output.put_line('LOB length check OK, length = '||dbms_lob.getlength(l_clob_temp));
    
    -- null check, no error
    l_null_check := l_clob_temp is null;
    l_null_check := l_clob_temp is not null;
    dbms_output.put_line('LOB null check OK');
    
    -- content access by local temp copy, not throw ORA-22924 under ORA-01555
    dbms_output.put_line('LOB content check, substr ='||dbms_lob.substr(l_clob_temp, 10, 2000));
    
    dbms_lock.sleep(p_sleep);
  end loop;
  
  -- free temporary lob
  dbms_lob.freetemporary(lob_loc => l_clob_temp);
end;
/ 

Wednesday, November 7, 2018

Latch: row cache objects Contentions and Scalability (V)


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


This Blog will test the scalability of row cache objects discussed in previous 4 Blogs:
  1. Oracle row cache objects Event: 10222, Dtrace Script (I)
  2. Row Cache Objects, Row Cache Latch on Object Type: Plsql vs Java Call (Part-1) (II)
  3. Row Cache Objects, Row Cache Latch on Object Type: Plsql vs Java Call (Part-2) (III)
  4. Row Cache and Sql Executions (IV)
and then attempt to build a mathematical model to assess such system.

Empirical data and model predication demonstrate that such system is hardly to be scalable with the number of CPUs because of Latch contentions.

In a pure row cache object system, theoretically, 3 Processors (CPU); experimentally, 9 Processors are necessitated to (almost) achieve the maximum throughput. Extra Processors can only put up high contentions.

The possible alternatives could be using Oracle basic (Built-in) data types or object string serialization.

Finally, we are trying to show that "row cache objects Latch" falls into the same destiny as the single "Result Cache: RC Latch" discussed in Blog: PL/SQL Function Result Cache Invalidation (I)

As a secondary earning of this exercise, "library cache: mutex X" contentions are observed related to Oracle Object Types.

Note: All tests are done in Oracle 12.1.0.2.0 on Solaris, Linux, AIX (SMT 4, LCPU=24) with 6 physical processors.


1. Test


We will make the test based on the code of Blog: Row Cache Objects, Row Cache Latch on Object Type: Plsql vs Java Call (Part-1) (II)


1.1. Plsql Test


Run (see appended Test Code: Plsql):
exec foo_proc_sessions_ctrl(1e9, 10);
which performs dynamic Plsql Call (foo_proc) for 9 different parallel degrees, each of which is running for 10 minutes.

Then collect the test data by query:
select * from exec_stats_v;
Table below shows number of parallel (concurrent) sessions, total number of executions, cpu_time in seconds, concurrency_wait_time in seconds, and microseconds per execution.
exec_stats_v (Plsql SQL_ID: 241pfd82cu4wj)

SESSIONS   EXECUTIONS CPU_TIME_S CONCURRENCY_WAIT_TIME_S US_PER_EXEC
--------   ---------- ---------- ----------------------- -----------
AIX            
       1    6,535,357        251                       0          65
       3   17,355,458        714                      75          74
       6   21,327,093      1,069                     664         117
      12   24,797,761      1,353                   1,814         198
      18   25,037,784      1,740                   2,992         297
      24   20,691,357      2,597                   2,537         542
      36   19,048,665      2,945                   7,872         963
      42   19,199,984      2,872                  11,683       1,132
      48   19,214,011      2,815                  15,315       1,306
               
Linux          
       1   13,992,932        413                       0          30
       3   32,715,487      1,216                      44          39
       6   52,665,062      2,222                     316          48
      12   49,743,420      2,146                   2,321          98
      18   50,448,264      2,249                   4,525         149
      24   50,836,921      2,340                   6,895         201
      36   51,864,133      2,458                  12,002         307
      42   48,914,411      2,495                  14,942         390
      48   48,549,375      2,535                  17,989         460
               
Solairs        
       1    8,096,318        413                       0          51
       3   21,850,342      1,212                      45          57
       6   32,609,592      1,923                     520          75
      12   42,217,169      2,555                   1,693         125
      18   42,890,535      2,615                   3,548         193
      24   42,955,245      2,631                   5,667         265
      36   43,117,305      2,633                   9,372         406
      42   42,523,671      2,616                  11,551         480
      48   40,546,142      2,506                  13,915         561 
The above result shows:
  Throughput (EXECUTIONS) from 1 to 3 SESSIONS climbs approximately linearly; of 6 SESSIONS tends to be flat or descending.
  Max throughput is achieved with around 9 parallel Sessions.
  The performance is saturated by more than 12 parallel Sessions. 
  The response time per execution (US_PER_EXEC) gets increased, probably due to the Latch contentions
    (sessions spend more time on Latch Gets instead of real work).
During the test, we also collect the data for Row Cache Object Gets, and Row Cache Latch Gets.

Here the output for parallel sessions 12 and 42.
select * from rco_stats_v where sessions in (12, 42) order by child#;

rco_stats_v

SESSIONS  CHILD#  RC_PARAMETER      GETS       MISSES    SLEEPS  SPIN_GETS  WAIT_TIME_S  RC_GETS    RC_GETMISSES  RC_THEORY_GETS  CACHE#_LIST  PARAMETER_LIST
--------  ------  ----------------  ---------  --------  ------  ---------  -----------  ---------  ------------  --------------  -----------  ----------------------------
   12       8     dc_users          633984132  19649121  52958   19596500   262          211328141  0             1901952396      7, 10        dc_users, dc_users
   12       9     dc_object_grants  633984845  54784381  58712   54726007   292          211328352  0             1901954535      8, 8         dc_objects, dc_object_grants
   12       10    dc_global_oids    633982830  52451846  68813   52383487   346          211327687  0             1901948490      17           dc_global_oids
            
   42       8     dc_users          638662605  22653084  56234   22597401   2274         212887753  47            1915987815      7, 10        dc_users, dc_users
   42       9     dc_object_grants  638674026  56604969  65236   56540334   3006         212891172  552           1916022078      8, 8         dc_objects, dc_object_grants
   42       10    dc_global_oids    638657482  64387264  76460   64311564   3905         212885997  30            1915972446      17           dc_global_oids
Look the case of 42 SESSIONS, although all 3 Latch Gets are similar, dc_global_oids suffers most, then dc_object_grants, and dc_users least. They are exposed by the different MISSES, SLEEPS, SPIN_GETS, WAIT_TIME. We will use this info in the later causality modeling.

Note Latch GETS is 3 times of RC_GETS.


1.2. Java Test


Run appended shell script:
ksh ./foo_proc_sessions_java 600
which invokes Java (RCOObjTypeJDBC1) to call foo_proc for 9 different parallel degrees, each of which is running for 10 minutes, same as above Plsql Test.

Then collect the similar data for Java Call as Table below.

exec_stats_v (Java SQL_ID: 8nkt65d7hcnxz)

SESSIONS EXECUTIONS CPU_TIME_S  CONCURRENCY_WAIT_TIME_S US_PER_EXEC
-------- ---------- ----------  ----------------------- -----------
AIX                                                                
      1   3,288,798         166                       0          86
      3   8,965,468         498                      39          99
      6  11,661,246         701                     221         148
     12  14,770,591       1,186                     972         274
     18  14,791,463       1,715                   1,534         459
     24  13,030,697       2,220                   1,727         749
     36  12,096,987       2,211                   5,475       1,173
     42  11,845,242       2,090                   8,166       1,388
     48  11,732,373       2,080                  11,252       1,661
                                                                   
Linux                                                              
      1   4,788,119         197                       0          50
      3  12,325,022         647                      22          66
      6  20,053,654       1,233                     261          91
     12  20,646,925       1,050                   1,518         156
     18  20,118,792       1,016                   3,261         257
     24  19,740,172       1,148                   5,525         393
     36  19,285,554       1,229                  10,114         662
     42  19,069,527       1,226                  12,541         806
     48  18,363,626       1,194                  15,031         978
                                                                   
Solairs                                                            
      1   3,790,741         294                       0          77
      3   9,154,792         774                     112          99
      6  13,334,385       1,213                     631         149
     12  16,216,973       1,565                   1,711         264
     18  16,971,173       1,720                   2,622         400
     24  17,062,335       1,745                   3,962         551
     36  16,616,651       1,735                   6,995         925
     42  16,492,514       1,733                  10,003       1,117
     48  16,264,599       1,721                  13,106       1,323
The result shows that throughput (EXECUTIONS) is about 2 times lower than Plsql, and response time (US_PER_EXEC) is about 2 times higher than Plsql.

In Blog: Row Cache Objects, Row Cache Latch on Object Type: Plsql vs Java Call (Part-1) (II), we see that each dynamic Plsql foo execution requires 45 Row Cache Latch Gets, whereas that of Java is 63. About 40% more Latch Gets in Java, but its throughput is about 2 times lower than Plsql.


2. Modeling


Let's try to model 3 Row Cache Object (CID: 17, 11, 7) Gets, and respective Latch Gets, each of which contains 3 latch Locations ("Where").

In the following discussion, we model:
  Oracle Session        as Job
  Row Cache Object Get  as Task
  Row Cache  Latch Get  as Machine
Suppose we have one Workshop W, and n Job Generators:
  G = (G1, G2, ... ,Gn)
each holds one single Job in each instant (one terminated, a new produced).

Each Job is made of 3 Tasks (sub-Jobs):
  J_i = (Si_1, Si_2, Si_3)
Each Task consists of 3 Work Units:
  Si_1 = (Si_1_u1, Si_1_u2, Si_1_u3)
  Si_2 = (Si_2_u1, Si_2_u2, Si_2_u3)
  Si_3 = (Si_3_u1, Si_3_u2, Si_3_u3)
They are subject to constraints:
  All 3 Tasks in each Job have to be processed sequentially.
  All 3 Work Units in each Task have to be processed sequentially.
  The Tasks and Work Units among different Jobs can be in parallel.
The Workshop is equipped with an assembly line, which consists of 3 Machines (Processors):
  W = (M1, M2, M3)
Each Machine possesses 3 Processing Units:
  M1 = (p1_1, p1_2, p1_3)
  M2 = (p2_1, p2_2, p2_3)
  M3 = (p3_1, p3_2, p3_3)
3 Machines are dedicated respectively for 3 Tasks:
  Si_1 is processed exclusively by M1
  Si_2 is processed exclusively by M2
  Si_3 is processed exclusively by M3
3 processing Units in each Machine are running sequentially.

M1, M2, M3 are running in parallel (inter-parallel); but Machine'3 processing Units are hardly running in parallel (no intra-parallel).

The service time of 3 Machines are:
  t1 
  t2 
  t3 
So minimum processing time of each JOB is (t1 + t2 + t3).

Assume t1 < t2 <t3 (later empirical data support such presumption), after n-th Job being processed, there will be:
  n*(t2-t1)/t1 
Jobs waiting before M2 after M1;
  n*(t3-t2)/t2 
Jobs waiting before M3 after M2;

In total, there will be:
  n*(t3-t1)/t2 
Jobs waiting inside Workshop (approximated).

i-th Job (J_i) waiting time before M3 is:
  i*(t3-t2)      1 <= i <= n*(t3-t2)/t2 
The accumulation waiting time before M3 is:
   (t3-t2) * (n*(t3-t2)/t2)*(1 + n*(t3-t2)/t2) / 2
  = n^2 * (t3-t2)^3 / (2 * t2^2)       -- approximated
The accumulation waiting time inside Workshop (approximated): (before M2 and M3, no Waiting Before M1 for empirical data)
  n^2 * (t3-t1)^3 / (2 * t1^2)
average waiting time is:
  n * (t3-t1)^3 / (2 * t1^2)
Put all together, average response time can be expressed as:
    response_time (rt) = waiting_time (wt) + service_time (st)
                       = n * (t3-t1)^3 / (2 * t1^2) + t3
    
    throughput         = (1 / rt)  
                      <= (1 / t3)
Therefore,
  total response time is quadratically to n.
  average response time is linearly to n.
  maximum throughput is 1 / max(t1, t2, t3).    
Since there are n Job Generators, and each Generator can produce next Job once previous Job is terminated (boundary condition). So there are total n Jobs in the system.

Take an example:
  n  =  12
  
  t1 = 255
  t2 = 324
  t3 = 410
    
  t1 + t2 + t3 = 989 (255+324+410)
The accumulation waiting time inside entire Workshop:
           
  12*12*(410-255)*(410-255)*(410-255)/(2*255*255) = 4123
average waiting time:
  12*(410-255)*(410-255)*(410-255)/(2*255*255)    = 343 = 4123/12 
average response time:
  343 + 410 = 753
In the above discussion, Job is modelled by 2 Layers:
  Task
  Work Unit
Workshop is also modelled by 2 Layers correspondingly:
  Machine 
  Processing Units
Till now, we only assess the first Layer. The second Layer have not yet been taken into account:
  Work Units 
  Processing Units 
Back to Row Cache, the scope of model is still too far to reflect the real system because we only consider inter-parallel, but no intra-parallel. It is not precise because intra-parallel is related to 2nd and 3rd Latch Get Locations; whereas inter-parallel is related to 1st Latch Get Locations.

Besides that, the real system is influenced by Latch timeout, spinning, process Preemption, Multithreading, and hardware specialities (e.g. Solaris LWP, AIX SMT).

As evidenced by the model, there exists no deadlock in such a system since all operations are performed sequentially.


3. Model Justification


To verify the model, 3 parameters t1, t2, t3 have to be acquired.

Run foo_proc (see Blog: Row Cache Objects, Row Cache Latch on Object Type: Plsql vs Java Call (Part-1) (II)) with 10222 trace in an idle system.

Then excerpt all 3 Cache Gets (CID: 17, 11, 7) for one Object instance Get, for example, T_OBJ_OUT (This is only illustrative. In practice, more representative data should be captured).

Here is an example from Solaris (irrelevant lines removed):
(12cR1 10222 trace is hard to read, 12cR2 improved. see Blog: Oracle row cache objects Event: 10222, Dtrace Script (I))

--================ Start T_OBJ_OUT Get ================--

kqrfrpo : freed to fixed free list po=175d2f708 time=1459184662

  ##********* cid = 17, Start time=1459184662 *********--
kqrpad: new po 17727bac0 from kqrpre1.1

kqrReadFromDB : kqrpre1.1 po=17727bac0 flg=8000 cid=17 eq=1753067e0 idx=0 dsflg=0
kqrpre1 : done po=17727bac0 cid=17 flg=2 hash=3c4bb9d0 0 eq=1753067e0 SQL=begin :1 := foo(:2, :3, :4); end; time=1459184804

  ##------- cid = 17, End time=1459184917, Elapsed = 255 (1459184917-1459184662) ------- 
kqrfrpo : freed to fixed free list po=17727bac0 time=1459184917

  ##--********* cid = 11, Start time=1459184917, including cid = 7 *********--

kqrpad: new po 175d2f708 from kqrpre1.1

kqrReadFromDB : kqrpre1.3 po=175d2f708 flg=8000 cid=11 eq=1753067e0 idx=0 dsflg=0
kqrpre1 : done po=175d2f708 cid=11 flg=2 hash=94b841cf a9461655 eq=1753067e0 
          obobn=2360170 obname=T_OBJ_OUT obtyp=13 obsta=1 obflg=0 SQL=begin :1 := foo(:2, :3, :4); end; time=1459185132

  ##--********* cid = 7, Start time=1459185132 *********--

kqrpad: new po 170d94488 from kqrpre1.1

kqrReadFromDB : kqrpre1.3 po=170d94488 flg=8000 cid=7 eq=176e410b8 idx=0 dsflg=0
kqrpre1 : done po=170d94488 cid=7 flg=2 hash=de7751cd 395edb55 eq=176e410b8 
          SQL=begin :1 := foo(:2, :3, :4); end; time=1459185415

  ##------- cid = 7, End time=1459185542, Elapsed = 410 (1459185542-1459185132) -------
kqrfrpo : freed to heap po=170d94488 time=1459185542

kqrmupin : kqrpspr2 Unpin po 175d2f708 cid=11 flg=2 hash=a9461655 time=1459185556

  ##------- cid = 11, End time=1459185651, Elapsed = 734 (1459185651-1459184917), Pure = 324 (734-410) -------
kqrfrpo : freed to fixed free list po=175d2f708 time=1459185651

--================ End T_OBJ_OUT Get ================--
Following values are captured (trace file "time" is in microsecond):
----------------------- Solaris ----------------------
  t1 = 255 us   for cid = 17
  t2 = 324 us   for cid = 11 
  t3 = 410 us   for cid =  7 (covered by cid = 11)
  
  total Elapsed = 989 us (255+324+410)
Here data for Linux and AIX:
----------------------- Linux ----------------------
  t1 = 136 us   for cid = 17
  t2 = 164 us   for cid = 11 
  t3 = 229 us   for cid =  7 (covered by cid = 11)
  
  total Elapsed = 529 us (136+164+229) 

----------------------- AIX ----------------------
  t1 = 143 us   for cid = 17
  t2 = 186 us   for cid = 11 
  t3 = 252 us   for cid =  7 (covered by cid = 11)
  
  total Elapsed = 581 us (143+186+252)  
Using the above average response time formula:
    n * (t3-t1)^3 / (2 * t1^2) + t3
for example, in case of Solaris, substitute variables and run query:

select * from (
  select level sessions,
         round(level*(410-255)*(410-255)*(410-255)/(2*255*255)) + 410 model_us_per_exec
  from dual connect by level < 100
) where sessions in (1, 3, 6, 12, 18, 24, 36, 42, 48); 
we obtained the average response time in microsecond (us) per execution: MODEL_US_PER_EXEC.

Both test data and model data are shown in table below.

The test are performed with different parallel (concurrent) sessions, varying from 1 to 48, for a duration of about 10 minutes. Table shows number of sessions, total number of executions, microseconds per execution by test and model.

All tests are done in Oracle 12.1.0.2.0 on Solaris, Linux, AIX (SMT 4, LCPU=24) with 6 physical processors. AIX and Linux are added for comparison.

Parallel | Test       | Test        | Model      
SESSIONS | EXECUTIONS | US_PER_EXEC | US_PER_EXEC
---------| ---------- | ----------- | -----------
Solairs  |            |             |            
       1 |  8,096,318 |          51 |         439
       3 | 21,850,342 |          57 |         496
       6 | 32,609,592 |          75 |         582
      12 | 42,217,169 |         125 |         754
      18 | 42,890,535 |         193 |         925
      24 | 42,955,245 |         265 |       1,097
      36 | 43,117,305 |         406 |       1,441
      42 | 42,523,671 |         480 |       1,613
      48 | 40,546,142 |         561 |       1,784
---------| ---------- | ----------- | -----------
AIX      |            |             |            
       1 |  6,535,357 |          65 |         284
       3 | 17,355,458 |          74 |         347
       6 | 21,327,093 |         117 |         442
      12 | 24,797,761 |         198 |         632
      18 | 25,037,784 |         297 |         822
      24 | 20,691,357 |         542 |       1,012
      36 | 19,048,665 |         963 |       1,392
      42 | 19,199,984 |       1,132 |       1,582
      48 | 19,214,011 |       1,306 |       1,772
---------| ---------- | ----------- | -----------
Linux    |            |             |            
       1 | 13,992,932 |          30 |         251
       3 | 32,715,487 |          39 |         294
       6 | 52,665,062 |          48 |         359
      12 | 49,743,420 |          98 |         490
      18 | 50,448,264 |         149 |         620
      24 | 50,836,921 |         201 |         751
      36 | 51,864,133 |         307 |       1,012
      42 | 48,914,411 |         390 |       1,142
      48 | 48,549,375 |         460 |       1,273
Now it is open to judge the model by comparing the empirical observations with model predicated values, and inspect its capability of extrapolation.


4. Row Cache Objects Latch: dedicated


Following query shows that there exists a 1-to-1 mapping between Row Cache and Row Cache Latch. Each Cache is protected by one single dedicated Latch. Hence accessing Row Cache is serialized by its designated Latch.

create view sys.x_kqrst as select * from x$kqrst;

select count(distinct latch_child), count(distinct cache#)
  from (
  select la.child# latch_child, kqrstcid cache#, kqrsttxt parameter, dc.*, la.* 
  from sys.x_kqrst dc, v$latch_children la 
  where dc.kqrstcln = la.child# and la.name='row cache objects'
  )
where kqrsttyp =1
order by latch_child;

COUNT(DISTINCTLATCH_CHILD)  COUNT(DISTINCTCACHE#)
--------------------------  ---------------------
56                          56


select *
  from (
  select la.child# latch_child, kqrstcid cache#, kqrsttxt parameter, kqrsttyp  --, dc.*, la.* 
  from sys.x_kqrst dc, v$latch_children la 
  where dc.kqrstcln = la.child# and la.name='row cache objects'
  )
where kqrsttyp =1   -- parent
order by latch_child;

LATCH_CHILD  CACHE#  PARAMETER              KQRSTTYP
----------- ------- ---------------------  ---------
8            10      dc_users               1
9            8       dc_objects             1
10           17      dc_global_oids         1
18           15      dc_props               1
For example, to access Object Type: T_OBJ_OUT, we should sequentially go though 3 Caches:
  dc_global_oids
  dc_objects
  dc_users
and each of which is guarded by its responsible Child Latch:
  10
  9
  8  
It looks like that "row cache objects Latch" works similar to the single "Result Cache: RC Latch" discussed in Blog: PL/SQL Function Result Cache Invalidation (I). But the difference is that later is optional, and can be turned off; but the former is an unavoidable obstacle.

To this point, we can have a further look of other Oracle Latches. Probably only cache buffers chains Latch is conceived to be scale (nonetheless "latch: cache buffers chains" Wait Event) since each of which has a limited responsibility and it amounts to majority of Latch (> 75%). Any excessive usage of other Latches is rated as irrational, hence contentions.

select l.name, count(*) cnt, round(100*ratio_to_report(count(*)) over (), 2) ratio 
from v$latch l, v$latch_children k
where l.latch# = k.latch#(+) 
--  and l.name in ('cache buffers chains', 'row cache objects', 'shared pool', 'Result Cache: RC Latch', 'kokc descriptor allocation latch')
--  and lower(l.name) like '%kokc%'
group by l.name order by cnt desc, l.name;

NAME                               CNT     RATIO
--------------------------------- ------  ------
cache buffers chains               32768   75.38
simulator hash latch               2048    4.71
...                                        
row cache objects                  56      0.13
...                                        
shared pool                        7       0.02
...                                        
Result Cache: RC Latch             1       0
... 
kokc descriptor allocation latch   1       0

770 rows selected.
(-------------- cache buffers chains --------------
Hidden Parameters and default values: 
  _db_block_hash_latches=32768    Number of database block hash latches,
  _db_block_hash_buckets=1048576  Number of database block hash buckets 
           1048576/32768=32       buckets per latch
 
Blog: Hot Block Identification and latch: cache buffers chains
-------------- simulator hash latch --------------
Blog: Row Cache and Sql Executions (IV)
-------------- row cache objects --------------
"Current Location" 
and
Blog: nls_database_parameters, dc_props, latch: row cache objects
-------------- shared pool --------------
Blog: sql_id and idn to shared pool subpool
-------------- Result Cache: RC Latch --------------
Blog: Result Cache:0 rows updated Invalidations (IV)
-------------- kokc descriptor allocation latch --------------
Bug 14382262  latch free wait event in"kokc descriptor allocation latch"

Blog: dbms_aq.dequeue - latch: row cache objects on AIX
Blog: Shared Pool - KKSSP
)


5. AWR/ASH - Row Cache Objects


We collect AWR/ASH reports for one 10 minutes Run of Plsql Test in 42 parallel sessions, and extract all Row Cache Objects related Sections.


5.1. Load Profile


DB CPU(s) Per Second: 5.9 shows that all 6 CPU are busy (CPU intensive), and about 100*(1-5.9/66.2) = 91% of DB Time are in waiting.

Load Profile
  Per Second Per Transaction Per Exec Per Call
DB Time(s): 66.2 373.6 0 195.01
DB CPU(s): 5.9 33.2 0 17.34


5.2. Top 10 Foreground Events by Total Wait Time


23 %DB time is in Waiting Event for latch: row cache objects, with Wait Avg(ms) 46.85 (probably bigger than 10 ms CPU Scheduling time slice).

9 %DB time is in Waiting Event for library cache: mutex X, with Wait Avg(ms) 10.49.

Top 10 Foreground Events by Total Wait Time
Event Waits Total Wait Time (sec) Wait Avg(ms) % DB time
latch: row cache objects 196,081 9185.8 46.85 23
library cache: mutex X 367,581 3856 10.49 9.6
DB CPU   3554.8   8.9


5.3. SQL ordered by Elapsed Time


SQL_ID: 241pfd82cu4wj has 42,533,404 Executions with Elapsed Time 20,423.63 seconds, all in CPU.

SQL ordered by Elapsed Time
Elapsed Time (s) Executions Elapsed Time per Exec (s) %Total %CPU %IO SQL Id SQL Text
24,895.60 42 592.75 62.27 14.26 0 22thkvvjndnmj DECLARE job BINARY_INTEGER := ...
20,423.63 42,533,404 0 51.09 12.81 0 241pfd82cu4wj begin :1 := foo(:2, :3, :4); e...


5.4. Latch Activity and Latch Sleep Breakdown


Total Latch Gets is 1,916,333,412, with 197,952 Sleeps, about 7.5% of Latch Miss (Gets/Misses=143,650,808/1,916,333,412). 197,952 Sleeps matches Latch Waits in Section "Top 10 Foreground Events by Total Wait Time".

Look rco_stats_v table for 42 SESSIONS, the 3 GETs for 3 Caches (dc_global_oids, dc_object_grants, dc_users) summing together is 1,915,994,113, close to above Total Latch Gets.

Same matches for MISSES, SLEEPS, SPIN_GETS, WAIT_TIME_S.

Latch Activity
Latch Name Get Requests Pct Get Miss Avg Slps /Miss Wait Time (s)
row cache objects 1,916,333,412 7.5 0 9186

Latch Sleep Breakdown
Latch Name Get Requests Misses Sleeps Spin Gets
row cache objects 1,916,333,412 143,650,808 197,952 143,454,769


5.5. Latch Miss Sources


Blog: Oracle row cache objects Event: 10222, Dtrace Script (I) shows that each Latch Get goes through 3 consecutive 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
Here we can see "kqrpre: find obj" is main blocker (Waiter Sleeps: 179,972), whereas "kqreqd: reget" is the top victim (Sleeps: 157,629), which accounts for about 80% (157,629/197,952) of Latch Sleeps.

In the above discussion, we noted that inter-parallel is related to 1st Latch Get Locations.

Latch Miss Sources
Latch Name Where NoWait Misses Sleeps Waiter Sleeps
row cache objects kqreqd: reget 0 157,629 3,121
row cache objects kqrpre: find obj 0 33,484 179,972
row cache objects kqreqd 0 6,812 14,827


5.6. Mutex Sleep Summary


This is related to library cache: mutex X (to be discussed in next Section).

Mutex Sleep Summary
Mutex Type Location Sleeps Wait Time (ms)
Library Cache kglpndl1 95 163,409 1,187,289
Library Cache kglhdgn2 106 161,608 1,191,330
Library Cache kglpin1 4 58,848 393,368
Library Cache kgllkdl1 85 31,551 186,930
Library Cache kglpnal1 90 30,451 176,736
Library Cache kglget1 1 30,157 233,526
Library Cache kglhdgn1 62 26,839 229,241


5.7. Child Latch Statistics


See rco_stats_v.

Child Latch Statistics
Latch Name Child Num Get Requests Misses Sleeps Spin & Sleeps 1->3+
row cache objects 9 638,804,551 56,606,984 65,237 56542348/0/0/0
row cache objects 8 638,793,715 22,654,054 56,248 22598358/0/0/0
row cache objects 10 638,788,857 64,389,752 76,467 64314045/0/0/0


5.8. Dictionary Cache Stats


See rco_stats_v.

I almost overlooked this Section because each popular Oracle term gets two names.

Dictionary Cache Stats
Cache Get Requests Pct Miss Scan Reqs Pct Miss Mod Reqs Final Usage
dc_global_oids 212,933,433 0 0   0 69
dc_objects 212,938,294 0 0   117 3,585
dc_users 212,935,101 0 0   0 89


5.9. Top SQL with Top Events, Top Events


This ASH Section listed our foo statement triggering the Top Events.

Top SQL with Top Events
SQL ID Plan Hash Executions % Activity Event % Event SQL Text
241pfd82cu4wj   2048 84.37 latch: row cache objects 41.39 begin :1 := foo(:2, :3, :4); e...
241pfd82cu4wj   2048 84.37 CPU + Wait for CPU 34.99 begin :1 := foo(:2, :3, :4); e...
241pfd82cu4wj   2048 84.37 library cache: mutex X 7.92 begin :1 := foo(:2, :3, :4); e...

Top Events
Event Event Class Session Type % Activity Avg Active Sessions
CPU + Wait for CPU CPU FOREGROUND 45.57 18.39
latch: row cache objects Concurrency FOREGROUND 41.39 16.71
library cache: mutex X Concurrency FOREGROUND 12.92 5.22


5.10. Top Event P1/P2/P3 Values



Top Event P1/P2/P3 Values
Event % Event P1, P2, P3 Values % Activity Parameter 1 Parameter 2 Parameter 3
latch: row cache objects 41.39 "6490258456","411","0" 18.91 address number tries
latch: row cache objects   "6490257608","411","0" 11.94 address number tries
latch: row cache objects   "6490258032","411","0" 10.54 address number tries
library cache: mutex X 12.92 "595386336", "3143916060672", "10136848668098666" 0.66 idn value where

Pick all 3 P1 Parameters in Event latch, run query below. The output shows that they point to the 3 Child_Latches (10, 9, 8) repectively.

select to_number(addr, 'XXXXXXXXXXXXXXXX') addr_num, addr,
       child#, gets, misses, sleeps, spin_gets, wait_time
 from v$latch_children lat
where latch#=411 
  and (addr like '%'||trim(to_char(6490258456, 'XXXXXXXXX'))
    or addr like '%'||trim(to_char(6490257608, 'XXXXXXXXX'))
    or addr like '%'||trim(to_char(6490258032, 'XXXXXXXXX')))
order by sleeps desc;

ADDR_NUM    ADDR              CHILD#  GETS       MISSES    SLEEPS  SPIN_GETS  WAIT_TIME
----------  ----------------  ------  ---------  --------  ------  ---------  ----------
6490258456  0000000182D97C18  10      638829560  64389752  76467   64314045   3905162356
6490258032  0000000182D97A70  9       638989001  56607014  65237   56542378   3006243205
6490257608  0000000182D978C8  8       639105230  22654062  56248   22598366   2274407991


6. library cache: mutex X


Look ASH Section - Top Event P1/P2/P3 Values, pick P1 Parameters in Event mutex, run query below.

The output shows that P1 Parameter: "595386336" represents T_OBJ_IN.

with start_snap as (
  select mutex_identifier, location, max(gets) gets, max(sleeps) sleeps, min(sleep_timestamp) min_ts
   from v$mutex_sleep_history
  where sleep_timestamp < sysdate -30/1440 
   group by mutex_identifier, location)
 ,end_snap as (
  select mutex_identifier, location, min(gets) gets, min(sleeps) sleeps, max(sleep_timestamp) max_ts
   from v$mutex_sleep_history
  where sleep_timestamp < sysdate -1/1440 
   group by mutex_identifier, location)
 ,delta as (
  select e.mutex_identifier, e.location, 
       e.gets   - nvl(s.gets, 0)   gets,
       e.sleeps - nvl(s.sleeps, 0) sleeps, min_ts, max_ts
  from start_snap s, end_snap e
  where e.mutex_identifier = s.mutex_identifier (+) 
    and e.location = s.location (+))
 ,snap as (
  select mutex_identifier, sum(gets) gets, sum(sleeps) sleeps, min(min_ts) min_ts, max(max_ts) max_ts
    from delta group by mutex_identifier
   order by sleeps desc
  )  
select o.hash_value, name, s.gets, s.sleeps, s.min_ts, s.max_ts
 from v$db_object_cache o, snap s
where o.hash_value = s.mutex_identifier
--  and mutex_identifier = 595386336
  and rownum <= 5
order by s.sleeps desc;

HASH_VALUE  NAME         GETS        SLEEPS
----------  -----------  ----------  ------
2812823600  T_OBJ_RET    1063400668  19362
668251247   T_OBJ_INOUT  1276396207  13660
595386336   T_OBJ_IN     1063241644   9290
415170529   T_OBJ_OUT    1063009333   8719
4198378475  FOO           254328227   1902
By the above output, if T_OBJ_IN occupies to 0.66 %Activity, T_OBJ_RET could be estimated as 1.38% (0.66*19362/9290) %Activity. Probably not always the TOP consumer is displayed in ASH.

Following query would give an output similar to AWR Section: Mutex Sleep Summary.
(The data in v$mutex_sleep_history is contained within a circular buffer, with the most recent sleeps shown)

with start_snap as (
  select mutex_identifier, location, max(gets) gets, max(sleeps) sleeps
   from v$mutex_sleep_history
  where sleep_timestamp < timestamp'2018-12-17 08:04:30' 
   group by mutex_identifier, location)
 ,end_snap as (
  select mutex_identifier, location, min(gets) gets, min(sleeps) sleeps
   from v$mutex_sleep_history
  where sleep_timestamp < timestamp'2018-12-17 08:14:50'
   group by mutex_identifier, location)
 ,delta as (
  select e.mutex_identifier, e.location, 
       e.gets   - nvl(s.gets, 0)   gets,
       e.sleeps - nvl(s.sleeps, 0) sleeps
  from start_snap s, end_snap e
  where e.mutex_identifier = s.mutex_identifier (+) 
    and e.location = s.location (+))
select location, sum(gets) gets, sum(sleeps) sleeps
  from delta group by location
 order by sleeps desc;
 
LOCATION                    GETS        SLEEPS
--------------------------  ----------  ------
kglhdgn2 106                977757576   13812
kglpndl1  95                1062042442  12725
kglpin1   4                 1020903933  11455
kglpnal1  90                 680931048   9432
kgllkdl1  85                 425439695   5679
kksLockDelete [KKSCHLPIN6]   425095566   3199
kglget1   1                  255195587   2600
kglhdgn1  62                 336370181   2466
kksxsccmp [KKSCHLPIN5]       169434152    242
kksfbc [KKSCHLFSP2]          169595310    232
A quick alternative is to create multiple copies of hot objects, for example, for T_OBJ_IN, and T_OBJ_RET (See Blog: "library cache: mutex X" and Application Context)

alter system set "_kgl_hot_object_copies"= 255 scope=spfile;

alter system set "_kgl_debug"=
      "name='T_OBJ_IN'   schema='K'    namespace=1  debug=33554432", 
      "name='T_OBJ_RET'  schema='K'    namespace=1  debug=33554432"
      scope=spfile;


7. Test Code: Plsql



drop sequence foo_seq;

create sequence foo_seq;

create or replace force view rco_stats_record_v as
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 localtimestamp ts, addr, child#, name, gets, misses, sleeps, spin_gets, wait_time, 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#; 

drop table rco_stats;

create table rco_stats as select 0 run, 0 sessions, v.* from rco_stats_record_v v where 1=2;

create or replace force view rco_stats_v  as
select run, sessions, ts, child#, rc_parameter
      ,gets - lag(gets) over (partition by rc_parameter order by run, sessions) gets
      ,misses - lag(misses) over (partition by rc_parameter order by run, sessions) misses
      ,sleeps - lag(sleeps) over (partition by rc_parameter order by run, sessions) sleeps
      ,spin_gets - lag(spin_gets) over (partition by rc_parameter order by run, sessions) spin_gets
      ,round((wait_time - lag(wait_time) over (partition by rc_parameter order by run, sessions))/1e6) wait_time_s
      ,rc_gets - lag(rc_gets) over (partition by rc_parameter order by run, sessions) rc_gets
      ,rc_getmisses - lag(rc_getmisses) over (partition by rc_parameter order by run, sessions) rc_getmisses
      ,rc_theory_gets - lag(rc_theory_gets) over (partition by rc_parameter order by run, sessions) rc_theory_gets
      ,cache#_list, parameter_list
from rco_stats v;


-- Plsql  241pfd82cu4wj    begin :1 := foo(:2, :3, :4); end; 
-- Java   8nkt65d7hcnxz    BEGIN :1 := K.FOO(:2, :3, :4); END;

create or replace force view exec_stats_record_v as
select localtimestamp ts, sql_id, executions, elapsed_time, cpu_time, concurrency_wait_time
from v$sqlarea v 
where (lower(sql_text) like 'begin :1 := %foo(:2, :3, :4); end;%' or sql_id in ('241pfd82cu4wj', '8nkt65d7hcnxz'))
  and last_active_time = (select max(last_active_time) from v$sqlarea where sql_id in ('241pfd82cu4wj', '8nkt65d7hcnxz'))
  and rownum = 1
order by v.last_active_time desc;     

drop table exec_stats;

create table exec_stats as select 0 run, 0 sessions, v.* from exec_stats_record_v v where 1=2;

create or replace force view exec_stats_v as
select run, sessions, ts
      ,executions - lag(executions) over (order by run, sessions) executions
      ,round((elapsed_time - lag(elapsed_time) over (order by run, sessions))/1e6) elapsed_time_s
      ,round((cpu_time - lag(cpu_time) over (order by run, sessions))/1e6) cpu_time_s
      ,round((concurrency_wait_time - lag(concurrency_wait_time) over (order by run, sessions))/1e6) concurrency_wait_time_s
      ,round((elapsed_time - lag(elapsed_time) over (order by run, sessions))/(nullif (executions - lag(executions) over (order by run, sessions), 0))) us_per_exec
      ,sql_id
from exec_stats;

create or replace procedure record_stats (p_sessions number) as 
  l_run   number;
begin
  l_run := foo_seq.nextval;
  insert into rco_stats  select l_run, p_sessions, v.* from rco_stats_record_v v;
  insert into exec_stats select l_run, p_sessions, v.* from exec_stats_record_v v;
  commit;
  sys.dbms_workload_repository.create_snapshot('ALL');  
end;
/

create or replace procedure k.foo_proc_sessions(p_session_cnt number, p_cnt number) as
  l_job_id pls_integer;
begin
  for i in 1.. p_session_cnt loop
    --dbms_job.submit(l_job_id, 'begin foo_proc('||p_cnt||'); end;');
    dbms_job.submit(l_job_id, 'begin while true loop foo_proc('||p_cnt||'); end loop; end;');
  end loop;
  commit;
end;
/

--exec foo_proc_sessions(6, 1e9);

--exec clean_jobs;

create or replace procedure k.foo_proc_sessions_ctrl(p_cnt number, p_dur_min number := 10) as
  type    t_num_tab is table of number;
  l_nums  t_num_tab := new t_num_tab(1, 3, 6, 12, 18, 24, 36, 42, 48);
  l_run   number;
begin
  foo_proc(10);   -- warmup
  clean_jobs; 
  record_stats(0);
  
  for n in 1..l_nums.count loop
    foo_proc_sessions(l_nums(n), p_cnt);    -- n Sessions
    dbms_lock.sleep(p_dur_min*60);          -- m minutes
    clean_jobs; 
    record_stats(l_nums(n)); 
  end loop;
end;
/

-- exec foo_proc_sessions_ctrl(1e9, 10);


8. Test Code: UNIX Script for Java Test



-------------- create Script: foo_proc_sessions_java ------
#!/bin/ksh

# setup CLASSPATH
export CLASSPATH=$CLASSPATH:java-path:jdbc-path:RCOObjTypeJDBC1-path

function db_record_stats {
  `sqlplus -s /nolog << EOF
  connect k/k
  exec k.record_stats($1);
  exit;
  EOF`  
}

# warm up
/usr/java/bin/java -Xmx30m -Xms8m RCOObjTypeJDBC1 "jdbc:oracle:thin:k/s@testdb:1521:testdb"  10 2
sleep 2

# MOS (Doc ID 2336567.1). new Oracle Database 12c installation.
# ./foo_proc_sessions_java[20]: db_record_stats[9]: PL/SQL: not found [No such file or directory]

db_record_stats 0

for i in 1 3 6 12 18 24 36 42 48
do
  echo "Sessions Count: $i"
  j=1
  while [[ $j -le $i ]]
  do
    echo "Run: $j"
    /usr/java/bin/java -Xmx30m -Xms8m RCOObjTypeJDBC1 "jdbc:oracle:thin:k/s@testdb:1521:testdb"  1000000000 2 &
    (( j = j + 1 ))
  done
  
  sleep $1   # run interval
  
  for pid in $(ps -ef | awk '/RCOObjTypeJDBC1/ {print $2}')
  do 
      if [ -n "$pid" -a -e /proc/$pid ]; then
          echo "Kill Pid: $pid"   # kill if exist
          kill -9 $pid 
      fi    
  done
  sleep 2     # grace period for killing 
  
  db_record_stats $i
done


-------------- called by ----
chmod a+x ./foo_proc_sessions_java
ksh ./foo_proc_sessions_java 600