Monday, September 18, 2017

Blog List

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

If we have fixed all the causes of Result Cache: RC Latch Contention discussed in previous two Blogs, the system still suffers from such Contention. There could exist the cases, which we have not yet covered.

In this Blog, we will discuss the third case: "Result Cache: RC Latch Contention and PL/SQL Exception Handler". So in total we have found 3 Cases:
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)
Note: All tests are done in Oracle 11.2.0.4, 12.1.0.2, 12.2.0.1 on AIX, Solaris, Linux with 6 physical processors.

Update (2017-Sep-19): One day after this Blog appeared, it turns out that there exists an on-going bug fix, which probably addresses Case (II) and (III).
Bug 23738186 : HIGH RESULT CACHE LATCHES AFTER MIGRATION TO 12.1.0.2
This fix addresses the Result Cache (RC) latch contention when the RC is in the LRU regime.The following changes are part of this fix:
1. Bypass Object (BO)
Currently, when a RC function throws an exception or a RC SQL exceeds memory limit, the under-construction Result Object (RO) is marked invalid and released. The customer's application has some RC functions that have a high rate of exceptions, which leads to high rate of invalid RO creation, which in turn leads to noticeable x-latch contention. To reduce these wasteful RO creations, we will instead store a BO when the function+parameters throws an exception. A BO is a regular RO that is created, on client directive, by the RC, but unlike regular RO's a BO can never be read. A BO uses exactly one block that contains the RO header but no data. A client trying to read a BO always gets a (non-storable) miss which forces the client to handle the miss by executing the function. Note, unlike regular misses, a non-storable miss does not allow the client to create a new RO. We have introduced two new statistics in v$result_cache_statistics to track the creation and use of BO's (for an example see tkqgcbug.sql/log).
2. Group release of invalid objects
Release all invalid objects together (instead of one at a time).
3. Improved LRU list processing
Instead of scanning all object on the list looking for the min lru#, stop the scan when the first un-scanned object (i.e. scan_count is 0) is reached.


1. Test Code


Out test table (TEST_TAB) contains 4 rows (1-4). Any select not in (1, 2, 3, 4) will get NO_DATA_FOUND exception.

We create 4 result_cache functions for 4 different scenarios:
  1. rc_c1: exception handler and return 
  2. rc_c2: exception handler and no return
  3. rc_c3: exception handler, raise again
  4. rc_c4: no exception handler

--------------------------------- Test Setup ---------------------------------
drop table test_tab;
drop table rc_latch_hist;
drop table rc_stats_hist;

create table test_tab as select level x from dual connect by level <= 4;

create table rc_latch_hist as 
select 'aaaaaaaaaaaaaaaaaaaa' snap_name, systimestamp ts, v.* from v$latch v where name = 'Result Cache: RC Latch'; 

create table rc_stats_hist as 
select 'aaaaaaaaaaaaaaaaaaaa' snap_name, systimestamp ts, v.* from v$result_cache_statistics v;

-- exception handler: return
create or replace function rc_c1(p_x number) return number result_cache as
  l_ret number;
begin
  select x into l_ret from test_tab where x = p_x;
  return l_ret;
  exception when others then return null;   --NO_DATA_FOUND
end;
/

-- exception handler: no return
create or replace function rc_c2(p_x number) return number result_cache as
  l_ret number;
begin
  select x into l_ret from test_tab where x = p_x;
  return l_ret;
  exception when others then null;
end;
/

-- exception handler: raise again
create or replace function rc_c3(p_x number) return number result_cache as
  l_ret number;
  my_excep exception;
  pragma exception_init(my_excep, -20001);
begin
  select x into l_ret from test_tab where x = p_x;
  return l_ret;
  exception when others then raise_application_error(-20001, 'My Private Exception'); 
end;
/

-- no exception handler
create or replace function rc_c4(p_x number) return number result_cache as
  l_ret number;
begin
  select x into l_ret from test_tab where x = p_x;
  return l_ret;
end;
/

create or replace procedure rc_proc_case(p_case number, p_rc_limit number) as
  l_sql_bool_val boolean := true;
  l_ret varchar2(10);
begin
 dbms_application_info.set_module('RC Test', 'RC_CASE_'||p_case);
  for x in 1..p_rc_limit loop
   begin
    case p_case 
      when 1 then l_ret := rc_c1(x);
      when 2 then l_ret := rc_c2(x);
      when 3 then l_ret := rc_c3(x);
      when 4 then l_ret := rc_c4(x);
    end case;
    exception when others then null;
    end;
  end loop;
end;
/

create or replace procedure rc_case_job(p_case number, p_job_cnt number, p_rc_limit number) as
  l_job_id pls_integer;
begin
  for i in 1.. p_job_cnt loop
    dbms_job.submit(l_job_id, 'begin while true loop rc_proc_case('||p_case||', '||p_rc_limit||'); end loop; end;');
  end loop;
  commit;
end;    
/

create or replace procedure clean_jobs as
begin
  for c in (select job from dba_jobs) loop
    begin
       dbms_job.remove (c.job);
    exception when others then null;
    end;
    commit;
  end loop;

  for c in (select d.job, d.sid, (select serial# from v$session where sid = d.sid) ser 
              from dba_jobs_running d) loop
    begin
      execute immediate
             'alter system kill session '''|| c.sid|| ',' || c.ser|| ''' immediate';
      dbms_job.remove (c.job);
    exception when others then null;
    end;
    commit;
  end loop;
  
  -- select * from dba_jobs;
  -- select * from dba_jobs_running;
end;
/

create or replace procedure rc_record_rc_latch(p_snap_name varchar2) as
begin
  insert into rc_latch_hist
  select p_snap_name snap_name, systimestamp ts, v.* from v$latch v where name = 'Result Cache: RC Latch';
  insert into rc_stats_hist
  select p_snap_name snap_name, systimestamp ts, v.* from v$result_cache_statistics v;
  commit; 
end;    
/

create or replace procedure rc_case_test(p_sleep number) as
begin
  clean_jobs;
  rc_record_rc_latch('Start');             
  rc_case_job(p_case=> 1, p_job_cnt=> 2, p_rc_limit=> 4); dbms_lock.sleep(p_sleep);
  rc_record_rc_latch('No_Error');          
  rc_case_job(p_case=> 1, p_job_cnt=> 1, p_rc_limit=> 5); dbms_lock.sleep(p_sleep);
  rc_record_rc_latch('Except_Return') ;     
  rc_case_job(p_case=> 2, p_job_cnt=> 1, p_rc_limit=> 5); dbms_lock.sleep(p_sleep);
  rc_record_rc_latch('Except_No_Return');  
  rc_case_job(p_case=> 3, p_job_cnt=> 1, p_rc_limit=> 5); dbms_lock.sleep(p_sleep);
  rc_record_rc_latch('Except_Raise');      
  rc_case_job(p_case=> 4, p_job_cnt=> 1, p_rc_limit=> 5); dbms_lock.sleep(p_sleep);
  rc_record_rc_latch('No_Hanler');
  clean_jobs;
end;    
/


2. Single Session Observation Test


Run following small test code:

column name format    a20
column rc_name format a48
column value format   a10
set numformat         999,999,999,999,999
column id format      999,999
alter session set nls_date_format ='dd-mon-yyyy hh24:mi:ss';
exec dbms_result_cache.flush;

select id, type, status, name rc_name, creation_timestamp, scn, lru_number from v$result_cache_objects v order by 3 desc, name, status;

var l_x number;
exec :l_x := rc_c4(1);
exec dbms_lock.sleep(1);
select id, type, status, name rc_name, creation_timestamp, scn, lru_number from v$result_cache_objects v order by 3 desc, name, status;

exec :l_x := rc_c4(5);
exec dbms_lock.sleep(1);
select id, type, status, name rc_name, creation_timestamp, scn, lru_number from v$result_cache_objects v order by 3 desc, name, status;
Output shows that there is "Invalid" Result when hitting NO_DATA_FOUND.

SQL > select id, type, status, name rc_name, creation_timestamp, scn, lru_number from v$result_cache_objects v order by 3 desc, name, status;
  no rows selected

SQL > exec :l_x := rc_c4(1);
SQL > select id, type, status, name rc_name, creation_timestamp, scn, lru_number from v$result_cache_objects v order by 3 desc, name, status;
   ID TYPE       STATUS    RC_NAME                                     CREATION_TIMESTAMP            SCN           LRU_NUMBER
  --- ---------- --------- ------------------------------------------- -------------------- -------------------- ---------------
    1 Result     Published "K"."RC_C4"::8."RC_C4"#3048d2af80817a01 #1  2017*sep*18 06:58:33    9,237,974,126,701   1,985,444,743
    0 Dependency Published K.RC_C4                                     2017*sep*18 06:58:33    9,237,974,126,701               0
    2 Dependency Published K.TEST_TAB                                  2017*sep*18 06:58:33    9,237,974,126,701               0

SQL > exec :l_x := rc_c4(5);
  ORA-01403: no data found
SQL > select id, type, status, name rc_name, creation_timestamp, scn, lru_number from v$result_cache_objects v order by 3 desc, name, status;
   ID TYPE       STATUS    RC_NAME                                     CREATION_TIMESTAMP            SCN           LRU_NUMBER
  --- ---------- --------- ------------------------------------------- -------------------- -------------------- ---------------
    1 Result     Published "K"."RC_C4"::8."RC_C4"#3048d2af80817a01 #1  2017*sep*18 06:58:33    9,237,974,126,701   1,985,444,743
    0 Dependency Published K.RC_C4                                     2017*sep*18 06:58:33    9,237,974,126,701               0
    2 Dependency Published K.TEST_TAB                                  2017*sep*18 06:58:33    9,237,974,126,701               0
    3 Result     Invalid   "K"."RC_C4"::8."RC_C4"#3048d2af80817a01 #1  2017*sep*18 06:58:34    9,237,974,126,701               0


3. Multiple Session Concurrency Test


On a UNIX machine with 6 physical processors, we start 6 Oracle Jobs one after another with an interval of about 60 seconds before each launch. At same time, we collect RC Latch and RC Stats between each launch.
1. First 2 Jobs (base load) select row 1-4, and there is no exception. 
   All other Jobs select row 1-5, and hence get exception when select row 5.
2. Job 3 has exception handler and returns null. 
3. Job 4 has exception handler, but does not have return. 
4. Job 5 has exception handler, but raises again.
5. Job 6 does not have exception handler.

truncate table rc_latch_hist;
truncate table rc_stats_hist;
exec dbms_result_cache.flush;
exec rc_case_test(60);
During the test, if we monitor RC Objects, we can see the status: "New" and "Invalid".

select type, status, name, count(*) from v$result_cache_objects 
group by type, status, name order by type desc, status, name;

TYPE       STATUS    NAME                                         COUNT(*)
---------- --------- ------------------------------------------ ----------
Result     Invalid   "K"."RC_C2"::8."RC_C2"#3048d2af80817a01 #1          7
Result     Invalid   "K"."RC_C3"::8."RC_C3"#3048d2af80817a01 #1          1
Result     New       "K"."RC_C3"::8."RC_C3"#3048d2af80817a01 #1          1
Result     New       "K"."RC_C4"::8."RC_C4"#3048d2af80817a01 #1          1
Result     Published "K"."RC_C1"::8."RC_C1"#3048d2af80817a01 #1          5
Result     Published "K"."RC_C2"::8."RC_C2"#3048d2af80817a01 #1          4
Result     Published "K"."RC_C3"::8."RC_C3"#3048d2af80817a01 #1          4
Result     Published "K"."RC_C4"::8."RC_C4"#3048d2af80817a01 #1          4
Dependency Published K.RC_C1                                             1
Dependency Published K.RC_C2                                             1
Dependency Published K.RC_C3                                             1
Dependency Published K.RC_C4                                             1
Dependency Published K.TEST_TAB                                          1
After the test, we look the collected stats, which shows the difference of RC Latch SLEEPS in 4 different scenarios.

The test result demonstrates that except the first scenario: "rc_c1: exception handler and return", all other 3 PL/SQL Result Cache implantations can cause RC Latch Contentions.

select v.*, round(wait_time/(nullif (sleeps, 0)), 2) wait_time_us_per_sleep
from (
    select snap_name, ts
          ,gets-lag(gets) over(order by ts) gets
          ,misses-lag(misses) over(order by ts) misses
          ,sleeps-lag(sleeps) over(order by ts) sleeps
          ,spin_gets-lag(spin_gets) over(order by ts) spin_gets
          ,wait_time-lag(wait_time) over(order by ts) wait_time
    from rc_latch_hist
) v order by ts;

SNAP_NAME         TS                                  GETS      MISSES     SLEEPS    SPIN_GETS    WAIT_TIME  WAIT_TIME_US_PER_SLEEP
----------------- --------------------------- ------------ ----------- ---------- ------------ ------------ -----------------------
Start             18-SEP-2017 07:59:55 +02:00                                                                
No_Error          18-SEP-2017 08:00:55 +02:00   61,623,726     790,876     0           790,876            0  
Except_Return     18-SEP-2017 08:01:55 +02:00  127,973,369   6,743,323     1         6,743,469            3                       3
Except_No_Return  18-SEP-2017 08:02:55 +02:00  135,558,711  14,221,514  1,277,086   12,948,140    7,762,707                       6
Except_Raise      18-SEP-2017 08:03:56 +02:00  123,932,503  16,996,212  2,304,628   14,752,639   14,765,338                       6
No_Hanler         18-SEP-2017 08:04:56 +02:00  112,230,114  18,895,634  3,322,022   15,724,684   22,069,024                       7

select name, snap_name, ts
      ,value-lag(value) over(partition by name order by ts) value
from rc_stats_hist
where name in ('Create Count Success', 'Delete Count Invalid')
order by name, ts;

NAME                    SNAP_NAME            TS                             VALUE
----------------------- -------------------- ------------------------------ ----------
Create Count Success    Start                18-SEP-2017 07:59:55 +02:00
Create Count Success    No_Error             18-SEP-2017 08:00:55 +02:00        4
Create Count Success    Except_Return        18-SEP-2017 08:01:55 +02:00        1
Create Count Success    Except_No_Return     18-SEP-2017 08:02:55 +02:00       747,926
Create Count Success    Except_Raise         18-SEP-2017 08:03:56 +02:00     1,410,675
Create Count Success    No_Hanler            18-SEP-2017 08:04:56 +02:00     2,025,890
Delete Count Invalid    Start                18-SEP-2017 07:59:55 +02:00
Delete Count Invalid    No_Error             18-SEP-2017 08:00:55 +02:00        0
Delete Count Invalid    Except_Return        18-SEP-2017 08:01:55 +02:00        0
Delete Count Invalid    Except_No_Return     18-SEP-2017 08:02:55 +02:00       747,902
Delete Count Invalid    Except_Raise         18-SEP-2017 08:03:56 +02:00     1,410,676
Delete Count Invalid    No_Hanler            18-SEP-2017 08:04:56 +02:00     2,025,891


4. SQL Result Cache Difference


In the above test, we use PL/SQL Result Cache. if we replace all of them by SQL Result Cache, for example:

create or replace function rc_c4(p_x number) return number as
  l_ret number;
begin
  select /*+ result_cache */ x into l_ret from test_tab where x = p_x;   
  return l_ret;
end;
/
make a similar test:

exec clean_jobs;
exec dbms_result_cache.flush;
exec rc_case_job(p_case=> 4, p_job_cnt=> 4, p_rc_limit=> 5);
and monitor RC Objects by:

select type, status, name, count(*) from v$result_cache_objects 
group by type, status, name order by type desc, status, name;

TYPE       STATUS    NAME                                                        COUNT(*)
---------- --------- ---------------------------------------------------------- ---------
Result     Published SELECT /*+ result_cache */ X FROM TEST_TAB WHERE X = :B1           5
Dependency Published K.TEST_TAB                                                         1
There does exist any RC status "New" or "Invalid". We can hardly observe RC Latch Contentions because there are no RC Latch SLEEPS. Therefore SQL Result Cache and PL/SQL Result Cache are probably NOT equivalent.

It is not clear how Oracle internally handles differently SQL Result Cache and PL/SQL Result Cache. But it could affect real applications when using them differently.

Monday, September 11, 2017

Result Cache: RC Latch Contention and RESULT_CACHE_MAX_SIZE (II)

Result Cache memory is limited by RESULT_CACHE_MAX_SIZE. Its default value is 1% of SHARED_POOL_SIZE. When allocated space reaches RESULT_CACHE_MAX_SIZE, any new request can cause contention of "Result Cache: RC Latch". RC Latch "ksl_get_shared_latch" Gets jumps from an order of magnitude Microseconds (us) to Millisecond (ms). The single RC Latch could eventually serialize the system ("Result Cache: Serialization12").

Each RC row takes at least one RC BLOCK (1K). In case of caching SQL Collection, it can occupy more than 1 BLOCK.

In the previous Blog, we discussed the RC Latch Contention caused by RC invalidation triggered by DML statements (Blog: PL/SQL Function Result Cache Invalidation)

Note: all tests are done in Oracle 11.2.0.4, 12.1.0.2, 12.2.0.1 on AIX, Solaris, Linux.

Update (2017-Sep-18): Oracle MOS: SQL Query Result Cache. Includes: [Video] (Doc ID 1108133.1)
RESULT_CACHE_MAX_SIZE defines the memory allocated to the result cache. When set to 0, the Result cache is disabled. The Default value is either 0.25% of MEMORY_TARGET or 0.5% of SGA_TARGET or 1% of SHARED_POOL_SIZE and is chosen by the database based on total memory available to the SGA and on the memory management method currently in use.


1. Test_1: Under Memory Limit


Test DB runs on a UNIX machine with 6 physical processors, and configured with:
 
  shared_pool_size         1408M
  
  result_cache_max_size    14432K
  result_cache_max_result  5
  result_cache_mode        MANUAL
When not specially set, result_cache_max_size is derived from shared_pool_size, which is about 1% of shared_pool_size in default.

Each RC row requires at least one RC BLOCK (1K), and with result_cache_max_size = 14432K, we can have maximum about 14432 RC Rows (ignoring some overhead).

Run test with 4 parallel sessions to create 13000 RC Rows (see appended Test Code):
 
exec clean_jobs;
exec dbms_result_cache.flush;
exec dbms_result_cache.memory_report(TRUE);
exec rc_fun_jobs(4, 13000);
Run query below, we can hardly observe RC Latch Sleeps increasing:
 
select latch#, name, gets, misses, spin_gets, sleeps, wait_time 
from v$latch where name = 'Result Cache: RC Latch'; 
-- latch# in (436, 559, 665) for Oracle 11.2.0.4/12.1.0.2, 12.2.0.1
Latch Misses is comprised of Spin_gets and Sleeps (see Blog: Is latch misses statistic gathered or deduced ? ), and the long wait is exposed by Sleeps.

In AWR report - "Top 10 Foreground Events by Total Wait Time" Section, it is presented as column "Wait Avg(ms)". In case of RC Latch, we can see it in the line "latch free". AWR "Latch Sleep Breakdown" Section contains more details.

Crosscheck RC memory usage by:
 
SQL > exec dbms_result_cache.memory_report(TRUE);
R e s u l t   C a c h e   M e m o r y   R e p o r t
[Parameters]
Block Size          = 1K bytes
Maximum Cache Size  = 14432K bytes (14432 blocks)
Maximum Result Size = 721K bytes (721 blocks)
[Memory]
Total Memory = 13540016 bytes [0.917% of the Shared Pool]

... Fixed Memory = 46272 bytes [0.003% of the Shared Pool]
....... Memory Mgr = 208 bytes
....... Cache Mgr  = 256 bytes
....... Bloom Fltr = 2K bytes

....... State Objs = 43760 bytes
... Dynamic Memory = 13493744 bytes [0.914% of the Shared Pool]
....... Overhead = 157168 bytes
........... Hash Table    = 64K bytes (4K buckets)
........... Chunk Ptrs    = 24K bytes (3K slots)
........... Chunk Maps    = 12K bytes
........... Miscellaneous = 157168 bytes
....... Cache Memory = 13024K bytes (13024 blocks)
........... Unused Memory = 23 blocks
........... Used Memory = 13001 blocks
............... Dependencies = 1 blocks (1 count)
............... Results = 13000 blocks
................... PLSQL   = 13000 blocks (13000 count)


SQL > select id, name, value from v$result_cache_statistics order by name;

   ID NAME                           VALUE
----- ------------------------------ ----------
    3 Block Count Current            13024
    2 Block Count Maximum            14432
    1 Block Size (Bytes)             1024
    6 Create Count Failure           0
    5 Create Count Success           13321
    9 Delete Count Invalid           321
   10 Delete Count Valid             0
   12 Find Copy Count                34959999
    7 Find Count                     34370958
   11 Hash Chain Length              1-5
    8 Invalidation Count             0
   13 Latch (Share)                  0
    4 Result Size Maximum (Blocks)   721


SQL > select name, bytes from v$sgastat where name in ('Result Cache');

NAME               BYTES
------------- ----------
Result Cache    13493744


SQL > column name     format a50
SQL > column cache_id format a30
SQL > select name, cache_id, type, status, namespace, sum(block_count) blocks, sum(ceil(row_count*row_size_avg/1024)) est_blocks
      from v$result_cache_objects
      group by name, cache_id, type, status, namespace;

NAME                                               CACHE_ID                       TYPE       STATUS    NAMESPACE      BLOCKS EST_BLOCKS
-------------------------------------------------- ------------------------------ ---------- --------- ---------- ---------- ----------
K.RC_FUN                                           K.RC_FUN                       Dependency Published                     1          0
"K"."RC_FUN"::8."RC_FUN"#8cd0e193d8974f19 #1       cyma7sjgpkr5zbtbp804tt27r7     Result     Published PLSQL           13000      13000
RC memory is under its maximum Limit.

"Block Count Current: 13024" < "Block Count Maximum: 14432", and "Delete Count Invalid: 0".

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


:BEGIN dtrace started: 2017 Sep 11 07:11:57
:END dtrace ended: 2017 Sep 11 07:11:59 ,Elapsed_ms: 1978
  ns
           value  ------------- Distribution ------------- count
             < 0 |                                         0
               0 |@@@@@@@@@@@@@@                           102706
            1000 |@@@@@@@@@@@@@@@@@@@@@@@@@@               186749
            2000 |                                         2193
            3000 |                                         54
            4000 |                                         49
            5000 |                                         42
            6000 |                                         28
            7000 |                                         16
            8000 |                                         9
            9000 |                                         10
        >= 10000 |                                         107

  AVG_ns     1167
  MIN_ns      827
  MAX_ns   169083
  SUM_ms        0

           oracle`ksl_get_shared_latch+0x1b8
           oracle`qesrcCM_Acquire+0x354
           oracle`psdfrcLookup+0x12d
           oracle`pevm_ENTERX+0x143
           oracle`pfrinstr_ENTERX+0x47
           oracle`pfrrun_no_tool+0x12a
           oracle`pfrrun+0x4c0
           oracle`plsql_run+0x288
           oracle`peicnt+0x946
           oracle`kkxexe+0x2f3
  291963
In average, each Get takes 1,167 Nanoseconds:


2. Test_2: Over Memory Limit


Stop above tests, re-run the test to create 15000 RC Rows, make the same checks:
 
exec clean_jobs;
exec dbms_result_cache.flush;
exec dbms_result_cache.memory_report(TRUE);
exec rc_fun_jobs(4, 15000);

SQL > exec dbms_result_cache.memory_report(TRUE);
R e s u l t   C a c h e   M e m o r y   R e p o r t
[Parameters]
Block Size          = 1K bytes
Maximum Cache Size  = 14432K bytes (14432 blocks)
Maximum Result Size = 721K bytes (721 blocks)
[Memory]
Total Memory = 14984624 bytes [1.015% of the Shared Pool]

... Fixed Memory = 46272 bytes [0.003% of the Shared Pool]
....... Memory Mgr = 208 bytes
....... Cache Mgr  = 256 bytes
....... Bloom Fltr = 2K bytes

....... State Objs = 43760 bytes
... Dynamic Memory = 14938352 bytes [1.012% of the Shared Pool]
....... Overhead = 159984 bytes
........... Hash Table    = 64K bytes (4K buckets)
........... Chunk Ptrs    = 24K bytes (3K slots)
........... Chunk Maps    = 12K bytes
........... Miscellaneous = 159984 bytes
....... Cache Memory = 14432K bytes (14432 blocks)
........... Unused Memory = 0 blocks
........... Used Memory = 14432 blocks
............... Dependencies = 1 blocks (1 count)
............... Results = 14431 blocks
................... PLSQL   = 14431 blocks (14431 count)


SQL > select id, name, value from v$result_cache_statistics order by name;

   ID NAME                           VALUE
----- ------------------------------ ----------
    3 Block Count Current            14432
    2 Block Count Maximum            14432
    1 Block Size (Bytes)             1024
    6 Create Count Failure           0
    5 Create Count Success           143128
    9 Delete Count Invalid           169
   10 Delete Count Valid             128528
   12 Find Copy Count                80928
    7 Find Count                     86758
   11 Hash Chain Length              1-5
    8 Invalidation Count             0
   13 Latch (Share)                  0
    4 Result Size Maximum (Blocks)   721


SQL > select name, bytes from v$sgastat where name in ('Result Cache');

NAME                   BYTES
----------------- ----------
Result Cache        14938352


SQL > select name, cache_id, type, status, namespace, sum(block_count) blocks, sum(ceil(row_count*row_size_avg/1024)) est_blocks
      from v$result_cache_objects
      group by name, cache_id, type, status, namespace;

NAME                                               CACHE_ID                       TYPE       STATUS    NAMESPACE      BLOCKS EST_BLOCKS
-------------------------------------------------- ------------------------------ ---------- --------- ---------- ---------- ----------
"K"."RC_FUN"::8."RC_FUN"#8cd0e193d8974f19 #1       cyma7sjgpkr5zbtbp804tt27r7     Result     New       PLSQL               1          0
K.RC_FUN                                           K.RC_FUN                       Dependency Published                     1          0
"K"."RC_FUN"::8."RC_FUN"#8cd0e193d8974f19 #1       cyma7sjgpkr5zbtbp804tt27r7     Result     Published PLSQL           14430      14430
dbms_result_cache.memory_report shows RC Memory reaches result_cache_max_size:
 
 Total Memory = 14984624 bytes [1.015% of the Shared Pool]
"Block Count Current: 14432" = "Block Count Maximum: 14432", and "Delete Count Invalid: 128528".

Output of query on v$result_cache_objects occasionally contains one line with Status "NEW" when repeatedly running.

Perform the latch Sleeps check:
 
select latch#, name, gets, misses, spin_gets, sleeps, wait_time 
from v$latch where name = 'Result Cache: RC Latch';

 LATCH# NAME                         GETS     MISSES  SPIN_GETS     SLEEPS  WAIT_TIME
------- ---------------------- ---------- ---------- ---------- ---------- ----------
    559 Result Cache: RC Latch  696395773 3217974991 2909396116 1023307692 7.9453E+11
It shows that Sleeps goes up steadily when each time run the query.

Again measuring latch Get time by dtrace:
 
Start: 2017 Sep 11 07:40:44, End: 2017 Sep 11 07:40:46, Elapsed_ms: 2333
  ns
           value  ------------- Distribution ------------- count
               0 |                                         0
            1000 |@                                        15
            2000 |                                         1
            3000 |                                         0
            4000 |                                         0
            5000 |                                         0
            6000 |                                         0
            7000 |                                         0
            8000 |                                         0
            9000 |                                         0
        >= 10000 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@  747

  AVG_ns     3029147
  MIN_ns        1031
  MAX_ns    87959260
  SUM_ms        1951

            oracle`ksl_get_shared_latch+0x1b8
            oracle`qesrcCM_Acquire+0x354
            oracle`psdfrcLookup+0x12d
            oracle`pevm_ENTERX+0x143
            oracle`pfrinstr_ENTERX+0x47
            oracle`pfrrun_no_tool+0x12a
            oracle`pfrrun+0x4c0
            oracle`plsql_run+0x288
            oracle`peicnt+0x946
            oracle`kkxexe+0x2f3
  763
In average, each get takes 3,029,147 Nanoseconds (3 Microseconds).

RC Latch "ksl_get_shared_latch" Gets jumps from an order of magnitude Microseconds (us) to Millisecond (ms).

In real applications, we can also build a histogram on RC creation_timestamp to track RC usages. (see Blog: Latch free waits, Dynamic Statistics, and the Result Cache and MOS Doc ID 2002089.1: High "Latch Free" Waits with Contention on 'Result Cache: RC Latch' when RESULT_CACHE_MODE = MANUAL on Oracle 12c)
 
select trunc(creation_timestamp, 'MI') rc_create_ts
      ,name, cache_id, type, status, namespace
      ,count(*) rc_count, round(avg(scan_count)) avg_scan_cnt, sum(block_count) blocks, sum(ceil(row_count*row_size_avg/1024)) est_blocks 
from   v$result_cache_objects t
where  lru_number > 0
group by name, cache_id, type, status, namespace, trunc(creation_timestamp, 'MI')
order by 1, rc_count desc, avg_scan_cnt desc; 
Blog: PL/SQL Function Result Cache Invalidation contains 5 views in Section: Causal Analysis of Result Cache, and provides some code for Result Cache History Recording.


3. RC Latch Contention and CPU Usage


There exists one common understanding that Latch Contention is manifested in UNIX as high CPU Usage. In both above tests, we have a machine with 6 physical processors, and started 4 parallel sessions, so there is no CPU saturation.

When creating 13000 RC Rows, we observe the CPU usage with top for our 4 processes:
 
load averages:  3.98,  2.85,  2.09;                    up 148+17:47:10 07:55:59
73 processes: 68 sleeping, 5 on cpu
CPU states: 32.9% idle, 66.8% user,  0.3% kernel,  0.0% iowait,  0.0% swap
Memory: 24G phys mem, 9991M free mem, 30G total swap, 30G free swap

   PID USERNAME LWP PRI NICE  SIZE   RES STATE    TIME    CPU COMMAND
 16030 oracle     1   3    0 4712M 4632M cpu/5    4:50 16.75% oracle
 16032 oracle     1   1    0 4712M 4632M cpu/4    4:50 16.69% oracle
 16026 oracle     1   1    0 4712M 4632M cpu/2    4:50 16.45% oracle
 16028 oracle     1   1    0 4712M 4632M cpu/1    4:50 16.39% oracle
When creating 15000 RC Rows:
 
load averages:  1.16,  1.69,  1.84;                    up 148+17:54:36 08:03:25
73 processes: 71 sleeping, 2 on cpu
CPU states: 81.7% idle, 17.5% user,  0.8% kernel,  0.0% iowait,  0.0% swap
Memory: 24G phys mem, 9991M free mem, 30G total swap, 30G free swap

   PID USERNAME LWP PRI NICE  SIZE   RES STATE    TIME    CPU COMMAND
 16134 oracle     1   1    0 4712M 4632M cpu/2    1:35  6.52% oracle
 16132 oracle     1   1    0 4712M 4637M sleep    1:31  4.76% oracle
 16138 oracle     1   1    0 4712M 4632M sleep    1:39  3.42% oracle
 16136 oracle     1   1    0 4712M 4632M sleep    1:36  3.23% oracle
The differences are:
 
Creating 13000 RC Rows has:
  load averages:  3.98
  5 on cpu
  66.8% user
  
Creating 15000 RC Rows has:
  load averages:  1.16
  2 on cpu
  17.5% user
Probably Latch Spins is burning CPU; whereas Latch Sleeps yields CPU. Therefore when talking about Latch contentions, it would be necessary to distinguish between Spin_gets and Sleeps. On a AIX machine with 6 cores and SMT=4 (see Blog: IBM AIX POWER7 CPU Usage and Throughput), run test:
 
  exec rc_fun_jobs(4, 15000);
and list call stacks of all 4 processes for 4 running Oracle sessions (common code removed):
 
$ > procstack 52166700 57278636 58982430 62521360

52166700: ora_j004_aix3
  thread_wait(0xbb800000bb8) + 0x22c
  sskgpwwait(??, ??, ??, ??, ??) + 0x54
  skgpwwait(??, ??, ??, ??, ??) + 0x12c
  ksliwat(??, ??, ??) + 0x1f08
  kslwaitctx(??, ??) + 0xe0
  ksqcmi(??, ??, ??, ??, ??, ??, ??, ??) + 0x6b4c
  ksqgtlctx(??, ??, ??, ??, ??, ??, ??, ??) + 0x10bc
  ksqgelctx(??, ??, ??, ??, ??, ??, ??, ??) + 0x21c
  qesrcCM_Wait(??, ??, ??) + 0x3c4
  qesrcCM_Acquire(??, ??, ??, ??, ??, ??) + 0x474
  psdfrcLookup(??, ??, ??, ??, ??, ??) + 0x124
  pevm_ENTERX(??, ??, ??, ??) + 0x150
  pfrinstr_ENTERX(0xfffffffffff44a0, 0x7000100e5e4e618, 0x122053f58) + 0x60
  pfrrun_no_tool(??, ??, ??) + 0x7c

57278636: ora_j003_aix3
  sskgpwpost(??, ??, ??, ??) + 0x44
  sskgpwwait(??, ??, ??, ??, ??) + 0x54
  skgpwwait(??, ??, ??, ??, ??) + 0x12c
  kslgess(0x0, 0x1600000010, 0x200000002, 0x1, 0x14fe000014fe) + 0x9c8
  ksl_get_shared_latch(??, ??, ??, ??, ??, ??) + 0x460
  qesrcCM_Release(??, ??, ??) + 0x18c
  psdfrcWriteResult(??, ??, ??, ??) + 0x360
  pevm_RET(??, ??) + 0x380
  pfrinstr_RET(0xfffffffffff4490, 0x7000100e5e4e658, 0x122053f58) + 0x4c
  pfrrun_no_tool(??, ??, ??) + 0x7c

58982430: ora_j001_aix3
  thread_wait(0x10e0000012c) + 0x22c
  sskgpwwait(??, ??, ??, ??, ??) + 0x54
  skgpwwait(??, ??, ??, ??, ??) + 0x12c
  kslgess(0x8, 0x8e00000008, 0x200000002, 0x1, 0x14ee000014ee) + 0x9c8
  ksl_get_shared_latch(??, ??, ??, ??, ??, ??) + 0x460
  qesrcPin_Get(??, ??, ??, ??, ??, ??, ??, ??) + 0x218
  qesrcCM_Acquire(??, ??, ??, ??, ??, ??) + 0x368
  psdfrcLookup(??, ??, ??, ??, ??, ??) + 0x124
  pevm_ENTERX(??, ??, ??, ??) + 0x150
  pfrinstr_ENTERX(0xfffffffffff4490, 0x7000100e5e4e618, 0x122053f58) + 0x60

62521360: ora_j000_aix3
  qesrcCM_MakeRoom(??, ??, ??) + 0xec
  qesrcMM_Alloc(??, ??, ??) + 0x16c
  qesrcRO_New(??, ??, ??, ??) + 0xa9c
  qesrcPin_Get(??, ??, ??, ??, ??, ??, ??, ??) + 0x6f4
  qesrcCM_Acquire(??, ??, ??, ??, ??, ??) + 0x368
  psdfrcLookup(??, ??, ??, ??, ??, ??) + 0x124
  pevm_ENTERX(??, ??, ??, ??) + 0x150
  pfrinstr_ENTERX(0xfffffffffff4590, 0x7000100e5e4e618, 0x122053f58) + 0x60
  pfrrun_no_tool(??, ??, ??) + 0x7c
  pfrrun(??) + 0x136c
  plsql_run(??, ??, ??) + 0x310
  peicnt(??, ??) + 0x284
  kkxexe(??) + 0x2b4
  opiexe(??, ??, ??) + 0x4594
  opiodr(??, ??, ??, ??) + 0x3d4
  rpidrus(??) + 0x21c
  skgmstack(??, ??, ??, ??, ??) + 0xc0
  rpidru(??) + 0xa8
  rpiswu2(??, ??, ??, ??, ??, ??, ??, ??) + 0x5ac
  rpidrv(??, ??, ??, ??) + 0xe14
  rpiexe(??) + 0x80
  kkjex1e(??) + 0x1824
  kkjex1e_cdb(??, ??, ??, ??, ??) + 0x1d8
  kkjsexe() + 0x4f4
  kkjrdp() + 0x384
  opirip(??, ??, ??) + 0x408
  opidrv(??, ??, ??) + 0x484
  sou2o(??, ??, ??, ??) + 0x110
  opimai_real(??, ??) + 0x144
  ssthrdmain(0x0, 0x300000003, 0xfffffffffffebf8) + 0x1e4
  main(??, ??) + 0xf0
  __start() + 0x70
We can see that 4 processes are executing respectively:
 
  thread_wait(0xbb800000bb8)
  sskgpwpost(??, ??, ??, ??)
  thread_wait(0x10e0000012c)
  qesrcCM_MakeRoom(??, ??, ??) 
Two processes are waiting with thread_wait. AIX Document said:
  int thread_wait(timeout):  Specifies the maximum length of time, in milliseconds, to wait for a posting.
and two timeout values are:
 
  0x12c =  300
  0xbb8 = 3000
One speculation is that the first timeout is 300, that is, thread_wait(300). In case of later Sleep (not got RC Latch after first 300ms sleeping), timeout is multiplied by 10 (3000).

The thread_post subroutine posts the thread the occurrence of an event, hence waking up the sleeping threads.

The last process (Oracle session) is creating a new RC Row after holding Latch (qesrcPin_Get):
 
  qesrcCM_MakeRoom(??, ??, ??) 
  qesrcMM_Alloc(??, ??, ??)
  qesrcRO_New(??, ??, ??, ??) 
  qesrcPin_Get(??, ??, ??, ??, ??, ??, ??, ??)
  qesrcCM_Acquire(??, ??, ??, ??, ??, ??)


4. Big Rows


In above tests, each RC row has a size less than 1024 Bytes. When caching SQL Collections, we can make the row size more than 1K. Here two similar tests (see appended Collection Test Code) with each row taking about 2K (ROW_SIZE_AVG = 1099 Bytes, i.e 2 RC Blocks). one is under result_cache_max_size, another is beyond that.
 
exec clean_jobs;
exec dbms_result_cache.flush;
exec dbms_result_cache.memory_report(TRUE);
exec rc_tab_jobs(4, 6500, 100);

exec clean_jobs;
exec dbms_result_cache.flush;
exec dbms_result_cache.memory_report(TRUE);
exec rc_tab_jobs(4, 7500, 100);


5. Possible Solutions


Adapt (increase) result_cache_max_size to satisfy cache requests or reduce cache usage. It can be dynamically increased by:
 
alter system set result_cache_max_size = 30M;
We can also disable Result Cache by either dynamically setting result_cache_max_size = 0, or bypass RC:
 
alter system set result_cache_max_size = 0;

exec dbms_result_cache.bypass(true);
exec dbms_result_cache.bypass(false);
The difference is that "result_cache_max_size = 0" releases RC memory, but bypass instructs code bypassing RC, but still keeps the RC memory.

Oracle 12.2 introduced RC Black List, and dbms_result_cache is enhanced with 4 APIs:
 
  exec dbms_result_cache.Black_List_Add('cyma7sjgpkr5zbtbp804tt27r7', TRUE);     -- Add cache_id to black-list
  exec dbms_result_cache.Black_List_Remove('cyma7sjgpkr5zbtbp804tt27r7', TRUE);  -- Remove cache_id from black-list
  exec dbms_result_cache.Black_List_clear(TRUE);                                 -- Remove all cache_id's from black-list
  select * from table(dbms_result_cache.Black_List);                             -- List all contents of the black-list
They allow us to regulate RC usage in granularity of each single cache_id, instead of toggling whole RC Cache.


6. Test Code


 
create or replace function rc_fun(p_var_1 varchar2, p_var_2 varchar2) return pls_integer result_cache as
  l_ret pls_integer;
begin
  l_ret := length(p_var_1) + 1e3*length(p_var_2);
  return l_ret;
end;
/

create or replace procedure rc_proc(p_rc_limit number) as
  l_ret pls_integer;
begin
  for i in 1..p_rc_limit loop
    l_ret := rc_fun('p1_'||i, 'p2_'||(i + p_rc_limit));
  end loop;
end;
/

create or replace procedure rc_fun_jobs(p_job_cnt number, p_rc_limit number) as
  l_job_id pls_integer;
begin
  for i in 1.. p_job_cnt loop
    dbms_job.submit(l_job_id, 'begin while true loop rc_proc('||p_rc_limit||'); end loop; end;');
  end loop;
  commit;
end;    
/

create or replace procedure clean_jobs as
begin
  for c in (select job from dba_jobs) loop
    begin
       dbms_job.remove (c.job);
    exception when others then null;
    end;
    commit;
  end loop;

  for c in (select d.job, d.sid, (select serial# from v$session where sid = d.sid) ser 
              from dba_jobs_running d) loop
    begin
      execute immediate
             'alter system kill session '''|| c.sid|| ',' || c.ser|| ''' immediate';
      dbms_job.remove (c.job);
    exception when others then null;
    end;
    commit;
  end loop;
  
  -- select * from dba_jobs;
  -- select * from dba_jobs_running;
end;
/


7. Collection Test Code


 
create or replace type num_tab force is table of number(10)
/

create or replace function rc_fun_tab(p_id number, p_tab_cnt number) return num_tab result_cache as
  l_ret  num_tab := new num_tab();
begin
  for i in 1..p_tab_cnt loop
    l_ret.extend;
    l_ret(i) := p_id + i;
  end loop;
  return l_ret;
end;
/

create or replace procedure rc_proc_tab(p_rc_limit number, p_tab_cnt number) as
  l_ret num_tab := new num_tab();
begin
  for i in 1..p_rc_limit loop
    l_ret := rc_fun_tab(i, p_tab_cnt);
  end loop;
end;
/

create or replace procedure rc_tab_jobs(p_job_cnt number, p_rc_limit number, p_tab_cnt number) as
  l_job_id pls_integer;
begin
  for i in 1.. p_job_cnt loop
    dbms_job.submit(l_job_id, 'begin while true loop rc_proc_tab('||p_rc_limit||', '||p_tab_cnt||'); end loop; end;');
  end loop;
  commit;
end;    
/

Friday, July 21, 2017

nls_database_parameters, dc_props, latch: row cache objects

This Blog will demonstrate latch: row cache objects on Dictionary Cache dc_props when querying nls_database_parameters.

Note: all tests are done in Oracle 12.1.0.2.0.

Reference: NLS understanding in this Blog is acquired and cited from:
    Oracle MOS: The Priority of NLS Parameters Explained (Where To Define NLS Parameters) (Doc ID 241047.1)


latch: row cache objects


At first, find v$rowcache.cache# mapping to v$latch_children.child#, then query nls_database_parameters, collecting statistics before and after test:

select r.kqrstcid cache#, r.kqrsttxt parameter, c.child#  --, r.*, c.* 
from x$kqrst r, v$latch_children c 
where r.kqrstcln = c.child# 
  and r.kqrsttxt = 'dc_props'
  and c.name     = 'row cache objects';

 CACHE# PARAMETER  CHILD#
------- --------- -------
     15 dc_props       18

select r.cache#, r.type, r.parameter, r.gets, r.count, c.name, c.child#, c.gets latch_gets
from v$rowcache r, v$latch_children c
where r.parameter = 'dc_props' and c.name = 'row cache objects' and c.child# = 18;  

 CACHE#   TYPE PARAMETER     GETS  COUNT              NAME  CHILD#  LATCH_GETS
------- ------ --------- -------- ------ ----------------- ------- -----------
     15 PARENT dc_props    140920     60 row cache objects      18      422820
                                                                    
select value from nls_database_parameters where parameter = 'NLS_CHARACTERSET';
  VALUE   
  --------
  AL32UTF8
  
select r.cache#, r.type, r.parameter, r.gets, r.count, c.name, c.child#, c.gets latch_gets
from v$rowcache r, v$latch_children c
where r.parameter = 'dc_props' and c.name = 'row cache objects' and c.child# = 18;  

 CACHE#   TYPE PARAMETER     GETS  COUNT              NAME  CHILD#  LATCH_GETS
------- ------ --------- -------- ------ ----------------- ------- -----------
     15 PARENT dc_props    140980     60 row cache objects      18      423000
We can see that dc_props GETs increased 60 (140980 - 140920), and LATCH_GETS increased 180 (423000 - 422820).

nls_database_parameters is defined by:

create or replace force view sys.nls_database_parameters (parameter, value) as
  select name, substr (value$, 1, 64) from x$props where name like 'NLS%';
A query on v$rowcache_parent for 'dc_props' shows:

select cache_name, existent, count(*) cnt from v$rowcache_parent 
 where cache_name = 'dc_props' group by cache_name, existent;

  CACHE_NAME  EXISTENT   CNT
  ----------- --------- ----
  dc_props    Y           37
  dc_props    N           23
It contains 60 rows, of which 37 are existing objects, 23 are not. Total number of 'dc_props' Cache entries: v$rowcache.COUNT = 60 is corresponding to 60 parent objects of v$rowcache_parent.

37 existing objects can be confirmed by:

select count(*) from x$props; 
   COUNT(*)
  ---------
         37
These 37 existing objects are probably originated from:

select * from sys.props$;
select * from database_properties;
Since the query on nls_database_parameters is a TABLE FULL scan on X$PROPS.

select value from nls_database_parameters where parameter = 'NLS_CHARACTERSET';

----------------------------------------------------------------------------
| Id  | Operation        | Name    | Rows  | Bytes | Cost (%CPU)| Time     |
----------------------------------------------------------------------------
|   0 | SELECT STATEMENT |         |     1 |    28 |     0   (0)| 00:00:01 |
|*  1 |  FIXED TABLE FULL| X$PROPS |     1 |    28 |     0   (0)| 00:00:01 |
----------------------------------------------------------------------------
and v$rowcache_parent contains 60 rows for 'dc_props', a TABLE FULL scan makes 60 GETs in v$rowcache, although the underlying X$PROPS contains only 37 EXISTENT objects. It seems that NON-EXISTENT objects also require the similar handling.

For each rowcache GET, it requires 3 "latch: row cache objects" GETs, that is why we have 180 LATCH_GETS.
(see Oracle Core: Essential Internals for DBAs and Developers Page 167:
    there was a common pattern indicating three latch gets for each dictionary cache get)

Oracle 12c V$ROWCACHE_PARENT wrote:

V$ROWCACHE_PARENT displays information for parent objects in the data dictionary. There is one row per lock owner, and one waiter for each object. This row shows the mode held or requested. For objects with no owners or waiters, a single row is displayed.

In case of acute wait of latch: row cache objects, we can try to find the lock owner or waiter by:

select s.sid, s.program, r.* 
  from v$rowcache_parent r, v$session s
 where cache_name = 'dc_props' 
   and (lock_mode != '0' or lock_request != '0')
   and r.saddr = s.saddr(+);
In essence, dc_props seems the Dictionary Cache (Row Cache) of Sys Table: sys.props.


NLS_CHARACTERSET semantics and Solutions


Oracle stores NLS settings in 3 levels: database/instance/session:
  nls_database_parameters
  nls_instance_parameters
  nls_session_parameters
  
and the precedence is ordered from low to high.
(Note: Any setting explicit used in SQL will always take precedence about all other settings)
In application semantics, session specific NLS settings should be selected because of precedence.

Additionally, it defines:
  v$nls_parameters 
A view that shows the current session parameters and the *DATABASE* characterset as seen in the NLS_DATABASE_PARAMETERS view.

MOS Doc ID 241047.1 Section C) The Database Parameters - NLS_DATABASE_PARAMETERS wrote:

These parameters are "overruled" by NLS_INSTANCE_PARAMETERS and NLS_SESSION_PARAMETERS.
The only exception are the NLS_CHARACTERSET and NLS_NCHAR_CHARACTERSET settings.
The NLS_CHARACTERSET and NLS_NCHAR_CHARACTERSET parameters cannot be overruled by instance or session parameters.
They are defined by the value specified in "create database ..." and are not intended to be changed afterwords dynamically.

Look the definition of nls_session_parameters:

CREATE OR REPLACE FORCE VIEW SYS.NLS_SESSION_PARAMETERS (PARAMETER, VALUE) AS
SELECT SUBSTR (parameter, 1, 30), SUBSTR (VALUE, 1, 64)
  FROM v$nls_parameters
 WHERE     parameter != 'NLS_CHARACTERSET'
       AND parameter != 'NLS_NCHAR_CHARACTERSET';
and definition of gv$nls_parameters (underlying view):

SELECT inst_id,
       parameter,
       VALUE,
       con_id
  FROM x$nls_parameters
 WHERE parameter != 'NLS_SPECIAL_CHARS'
and count each by:

select count(*) from nls_session_parameters;  
   COUNT(*)
  ---------
         17
  
select count(*) from v$nls_parameters;             
   COUNT(*)
  ---------
         19  
The discrepancy are exactly the two excluded NLS_(NCHAR)_CHARACTERSET parameters, nls_session_parameters is a subset of v$nls_parameters.

select parameter, value from v$nls_parameters 
minus
select parameter, value from nls_session_parameters;

  PARAMETER              VALUE
  ---------------------- ---------
  NLS_CHARACTERSET       AL32UTF8
  NLS_NCHAR_CHARACTERSET AL16UTF16
Therefore, in order to avoid latch: row cache objects on dc_props, we can run the equivalent:

  select value from v$nls_parameters where parameter = 'NLS_CHARACTERSET';
instead of query:

  select value from nls_database_parameters where parameter = 'NLS_CHARACTERSET';
The later generates 60 rowcache GETs, and 180 latch: row cache objects on dc_props for each run. Therefore, severe row cache objects latch contention occurs if we frequently query nls_database_parameters.

We can verify this solution by:

select r.cache#, r.type, r.parameter, r.gets, r.count, c.name, c.child#, c.gets latch_gets
from v$rowcache r, v$latch_children c
where r.parameter = 'dc_props' and c.name = 'row cache objects' and c.child# = 18;  

 CACHE#   TYPE PARAMETER    GETS  COUNT              NAME  CHILD#  LATCH_GETS
------- ------ --------- ------- ------ ----------------- ------- -----------
     15 PARENT dc_props   141046     60 row cache objects      18      423198
                                                                    
select value from v$nls_parameters where parameter = 'NLS_CHARACTERSET';
  VALUE   
  --------
  AL32UTF8
   
select r.cache#, r.type, r.parameter, r.gets, r.count, c.name, c.child#, c.gets latch_gets
from v$rowcache r, v$latch_children c
where r.parameter = 'dc_props' and c.name = 'row cache objects' and c.child# = 18;  

 CACHE#   TYPE PARAMETER    GETS  COUNT              NAME  CHILD#  LATCH_GETS
------- ------ --------- ------- ------ ----------------- ------- -----------
     15 PARENT dc_props   141046     60 row cache objects      18      423198
Obviously there are neither rowcache GETs, nor latch: row cache objects, because NLS session parameters (v$nls_parameters) are stored in session memory UGA and are not visible for other sessions, whereas nls_database_parameters is setup in a DB wide globally shared space (SGA) and have to be protected by latch: row cache objects.

In general, latch: row cache objects is documented as protecting data dictionary cache, but we saw that it is also used to safeguard X$PROPS.

Similar to v$nls_parameters, database NLS_CHARACTERSET can also be gotten by:

select sys_context('userenv','language') from dual;
select userenv ('language') from dual;    -- userenv 12c deprecated 
without rowcache GETs and latch: row cache objects.

sys_context('userenv','language') returns the language and territory currently used by the current session, along with the database character set in UNIX-like format:
   language_territory.characterset
Usually SYS_CONTEXT returns the value of parameter associated with the context namespace at the current instant for the current session. Since database NLS_CHARACTERSET is a database wide parameter, sys_context returns the correct value.

Further more, MOS Doc ID 241047.1 explained the difference between database character set and OS env NLS_LANG character set:

The database character set is not the same as the character set of the NLS_LANG that you started this connection with!
The OS environment NLS_LANG (from where you started this connection) is reflected in v$session_connect_info.CLIENT_CHARSET:

  select CLIENT_CHARSET, v.* from v$session_connect_info v;
MOS Doc ID 241047.1 wrote:

D1) sys.props$
    SQL>select name,value$ from sys.props$ where name like '%NLS%';
    This gives the same info as NLS_DATABASE_PARAMETERS. You should use NLS_DATABASE_PARAMETERS instead of props$

We saw that NLS_DATABASE_PARAMETERS is underlined by X$PROPS, whereas SYS.PROPS$ is a real table. The former select generates row cache GETs and requires latch: row cache objects, the later not. Therefore from performance point of view, they are not the same.

v$database select and control file sequential read

V$DATABASE is one single row view, displaying information about the database from the control file. Its content is a direct mapping of control files without intermediate cache area. Each query on v$database is translated as a few physical I/O reads.

Note: all tests are done in Oracle 12.1.0.2.0.


1. control file sequential read Watching


Run query and trace by Event 10046:

SQL (sid 35) > select name from v$database;

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        2      0.00       0.00          0          0          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      0.00       0.00          0          0          0           1

Rows     Row Source Operation
-------  ---------------------------------------------------
      1  MERGE JOIN CARTESIAN (cr=0 pr=0 pw=0 time=311 us cost=0 size=12 card=1)
      1   FIXED TABLE FULL X$KCCDI (cr=0 pr=0 pw=0 time=176 us cost=0 size=12 card=1)
      1   BUFFER SORT (cr=0 pr=0 pw=0 time=134 us cost=0 size=0 card=1)
      1    FIXED TABLE FULL X$KCCDI2 (cr=0 pr=0 pw=0 time=121 us cost=0 size=0 card=1)

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  control file sequential read                    7        0.00          0.00
********************************************************************************

We can see that each name query on v$database triggers 7 control file sequential read. The similar statistics can be observed by:

select * from v$session_event where event = 'control file sequential read' and sid = 35; 
select * from v$system_event  where event = 'control file sequential read';

Run the same query again and truss unix process:

SQL (sid 35) > select name from v$database;

oracle@testdb $ truss -t pread -p 4326
  pread(257, "15C2\0\001\0\0\0\0\0\0\0".., 16384, 16384) = 16384
  pread(257, "15C2\0\007\0\0\08A141D\0".., 16384, 114688) = 16384
  pread(257, "15C2\0\0\t\0\0\08A141D\0".., 16384, 147456) = 16384
  pread(257, "15C2\0\001\0\0\0\0\0\0\0".., 16384, 16384) = 16384
  pread(257, "15C2\0\007\0\0\08A141D\0".., 16384, 114688) = 16384
  pread(257, "15C2\0\0\t\0\0\08A141D\0".., 16384, 147456) = 16384
  pread(257, "15C2\0\08004\0\08A141D\0".., 16384, 0x01200000) = 16384

oracle@testdb $ pfiles 4326
  257: S_IFREG mode:0640 dev:181,65553 ino:4300 uid:100 gid:101 size:24264704
       O_RDWR|O_DSYNC|O_LARGEFILE FD_CLOEXEC
       advisory write lock set by process 16900
       /oratestdb/oradata/testdb/control01.ctl
  
-- where 4326 is pid of Oracle sid 35, 257 is fd of first control file.

Monitoring the same query by dtrace:

oracle@testdb $ sudo dtrace -n 'pid$target::_pread:entry {@[arg0, ustack(12, 0)] = count();}' -p 4326
  257
libc.so.1`_pread               libc.so.1`_pread                 libc.so.1`_pread                 
libc.so.1`pread+0x85           libc.so.1`pread+0x85             libc.so.1`pread+0x85          
oracle`skgfqio+0x284           oracle`skgfqio+0x284             oracle`skgfqio+0x284          
oracle`ksfd_skgfqio+0x195      oracle`ksfd_skgfqio+0x195        oracle`ksfd_skgfqio+0x195     
oracle`ksfd_io+0x2e79          oracle`ksfd_io+0x2e79            oracle`ksfd_io+0x2e79         
oracle`ksfdread+0x746          oracle`ksfdread+0x746            oracle`ksfdread+0x746         
a.out`kccrhd+0x208             a.out`kccrbp+0x279               a.out`kccrbp+0x279            
a.out`kccgft_refresh_hdr+0x68  a.out`kccsed_rbl+0x1dc           a.out`kccsed_rbl+0xfc         
a.out`kccgftcs+0x2a2           a.out`kccgft_refresh_hdr+0x141   a.out`kccgft_refresh_hdr+0x141
a.out`kccxdi+0x8d              a.out`kccgftcs+0x2a2             a.out`kccgftcs+0x2a2          
a.out`qerfxFetch+0x5df         a.out`kccxdi+0x8d                a.out`kccxdi+0x8d             
a.out`rwsfcd+0x6f              a.out`qerfxFetch+0x5df           a.out`qerfxFetch+0x5df        

libc.so.1`_pread               libc.so.1`_pread                  
libc.so.1`pread+0x85           libc.so.1`pread+0x85           
oracle`skgfqio+0x284           oracle`skgfqio+0x284           
oracle`ksfd_skgfqio+0x195      oracle`ksfd_skgfqio+0x195      
oracle`ksfd_io+0x2e79          oracle`ksfd_io+0x2e79          
oracle`ksfdread+0x746          oracle`ksfdread+0x746          
a.out`kccrhd+0x208             a.out`kccrbp+0x279             
a.out`kccgft_refresh_hdr+0x68  a.out`kccrec_rbl+0x1c2         
a.out`kccgftcs+0x2a2           a.out`kccrec_read_write+0x19b  
a.out`kccxdi2+0x8c             a.out`kccgftcs+0x36a           
a.out`qerfxFetch+0x5df         a.out`kccxdi2+0x8c             
a.out`qersoProcessULS+0x26f    a.out`qerfxFetch+0x5df         

libc.so.1`_pread               libc.so.1`_pread
libc.so.1`pread+0x85           libc.so.1`pread+0x85
oracle`skgfqio+0x284           oracle`skgfqio+0x284
oracle`ksfd_skgfqio+0x195      oracle`ksfd_skgfqio+0x195
oracle`ksfd_io+0x2e79          oracle`ksfd_io+0x2e79
oracle`ksfdread+0x746          oracle`ksfdread+0x746
a.out`kccrbp+0x279             a.out`kccrbp+0x279
a.out`kccsed_rbl+0x1dc         a.out`kccsed_rbl+0xfc
a.out`kccgft_refresh_hdr+0x141 a.out`kccgft_refresh_hdr+0x141
a.out`kccgftcs+0x2a2           a.out`kccgftcs+0x2a2
a.out`kccxdi2+0x8c             a.out`kccxdi2+0x8c
a.out`qerfxFetch+0x5df         a.out`qerfxFetch+0x5df     

The above output shows all 7 I/O reads of first control file (fd: 257), among which, there are 2 Calls of subroutine "kccrhd", and 5 Calls of subroutine"kccrbp".

The xplan in Event 10046 trace contains two different row sources: "X$KCCDI" and "X$KCCDI2", Dtrace shows the respective Calls; 3 "kccxdi", and 4 "kccxdi2".

All are finalized by function "ksfdread", which probably denotes file direct read.

Since each select on v$database is implemented by a few disk I/O Reads (7 in above example, 14 if select all columns), concurrently accesses can entail severe wait event on control file sequential read, which often appears as one of AWR Top Wait Events.


2. Other control file related Objects


There are a few control files based views, which can be listed by:

select * from v$fixed_view_definition where lower(view_definition) like '%x$kcc%'; 

for example, gv$archive, v$block_change_tracking, gv$deleted_object. Any access to them will lead to similar effect as v$database.

There are also indirect control file dependent objects, for example,
  dba_scheduler_jobs
  dba_scheduler_running_jobs
whose definitions containing v$database. They can be listed by:

  select * from dba_dependencies where referenced_name = 'V$DATABASE';

Further more, there are also Oracle applications, which is using v$database, for example, MMON Slave Process.

Monday, July 10, 2017

Getting Oracle Transaction Commit SCN

This Blog demonstrates one approach to get exact Commit SCN and compare it with other methods. It has not only (Oracle) academic interest, but also practical demand, for example, data replication (The COMMIT SCN - an undocumented feature).

Note: all tests are done in Oracle 12.1.0.2.0.


1. Setup



drop table test_tab;
drop table commitscn_gtt;
create table test_tab(id number, sid number);

create global temporary table commitscn_gtt(dummy)
on commit preserve rows
as select -1 from dual;

create or replace procedure push_commitscn as
begin
  delete from commitscn_gtt;
  insert into commitscn_gtt (dummy) values (-1);
end;
/

create or replace function get_commitscn return number as
 l_commitscn number;
begin
  select ora_rowscn into l_commitscn from commitscn_gtt where rownum=1;
  return l_commitscn;
end;
/


2. Test



insert into test_tab (id, sid) values (1, sys.dbms_support.mysid);

-- run immediately before commit
exec push_commitscn;

commit;

set numformat 999,999,999,999,999

-- get exact commitscn after commit
select get_commitscn from dual;

       GET_COMMITSCN
--------------------
   9,183,757,165,446


3. Comparing with Other Approaches


Test below comprises 5 different commit scn getting methods.

drop table test_tab2;
create table test_tab2(id number, sid number, scn number) rowdependencies;
insert into test_tab2 (id, sid, scn) values (1, sys.dbms_support.mysid, userenv('commitscn'));
exec push_commitscn;
commit;

set numformat 999,999,999,999,999

select scn from test_tab2 where id = 1;
                 SCN
--------------------
   9,183,757,165,468
   
select ora_rowscn from test_tab2 where id = 1;
          ORA_ROWSCN
--------------------
   9,183,757,165,469
   
select get_commitscn from dual;
       GET_COMMITSCN
--------------------
   9,183,757,165,469

select dbms_flashback.get_system_change_number from dual;
GET_SYSTEM_CHANGE_NUMBER
------------------------
   9,183,757,165,471
       
select current_scn from v$database;
         CURRENT_SCN
--------------------
   9,183,757,165,472

Let's look their differences.


Method 1. USERENV('COMMITSCN')

select scn from test_tab2 where id = 1;
→ USERENV('COMMITSCN') is the actual COMMIT SCN minus 1, i.e immediately scn before commit.
    Each commit creates 1 new number (for commit Record).
→ Undocumented
→ 12c USERENV deprecated


Method 2. ORA_ROWSCN

select ora_rowscn from test_tab2 where id = 1;
→ Oracle Database SQL Language Reference - ORA_ROWSCN Pseudocolumn said:
    Whether at the block level or at the row level, the ORA_ROWSCN should not be considered to be an exact SCN.
    If a block is queried twice, then it is possible for the value of ORA_ROWSCN to change between the queries
    even though rows have not been updated in the time between the queries. The only guarantee is that the value of
    ORA_ROWSCN in both queries is greater than the commit SCN of the transaction that last modified that row.
   (Note: "greater than" seems an Oracle Document error. It should be "not less than")

    So ORA_ROWSCN is not deterministic. It can increase, or even decrease between two queries as demonstrated in
    How can ORA_ROWSCN change between queries when no update? at Jul 8, 2017 9:20 PM.
→ For each row, ORA_ROWSCN returns the conservative upper bound SCN of the most recent change to the row.
    For example, "delayed block cleanout".
→ It increases the size of each row by 6 bytes.
→ Oracle BUG: INSERT to a Table With ROWDEPENDENCIES Failed With ORA-00600 [kdtgsph-row] (Doc ID 2210391.1)


Method 3. Commit SCN of this Blog

select get_commitscn from dual;
→ Exact commit SCN.
    Once a commit is executed, this single row (single block) is stamped with that commit SCN.
    Since the one-row GTT is session local, it can never be selected by other sessions
    and is hardly to imagine a "delayed block cleanout". Therefore it never be changed.


Method 4. System functions

select dbms_flashback.get_system_change_number from dual;

select current_scn from v$database;
→ Upper bound system change number (SCN), not precise.


4. Commit SCN exposed


Blog: PL/SQL Function Result Cache Invalidation observed that commit accomplishes invalidating Result Cache before returns, and interpreted:

    The above Stack Trace shows that when a transaction user session calls commit command,
    commit takes a detour to visit Result Cache along its code path in order to perform
    the invalidation before publishing the confirmed and consistent news to the world.

The following test will demonstrate that Commit SCN is exposed into V$RESULT_CACHE_OBJECTS.SCN during Result Cache Invalidation.

drop table rc_tab;
create table rc_tab (id number, val number);
insert into rc_tab select level, level*10 from dual connect by level <= 3;
commit;

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

create or replace procedure run_test as
  l_val number;
begin
  for i in 1 .. 3 loop
    l_val := get_val(i);
  end loop;
end;
/

exec dbms_result_cache.flush;

exec run_test;

column name format a13

select id, type, status, name, namespace, creation_timestamp, scn
  from v$result_cache_objects ro
order by scn desc, type, id;

ID TYPE       STATUS    NAME          NAMESPACE  CREATION_TIMESTAMP                    SCN
-- ---------- --------- ------------- ---------- -------------------- --------------------
 0 Dependency Published K.GET_VAL                2017*JUL*12 07:06:43    9,198,309,753,651
 2 Dependency Published K.RC_TAB                 2017*JUL*12 07:06:43    9,198,309,753,651
 1 Result     Published "K"."GET_VAL" PLSQL      2017*JUL*12 07:06:43    9,198,309,753,651
 3 Result     Published "K"."GET_VAL" PLSQL      2017*JUL*12 07:06:43    9,198,309,753,651
 4 Result     Published "K"."GET_VAL" PLSQL      2017*JUL*12 07:06:43    9,198,309,753,651

update rc_tab set val = -2 where id = 2;

exec push_commitscn;

commit;

select get_commitscn from dual;

     GET_COMMITSCN
------------------
 9,198,309,753,654

select id, type, status, name, namespace, creation_timestamp, scn
  from v$result_cache_objects ro
order by scn desc, type, id;

ID TYPE       STATUS    NAME          NAMESPACE  CREATION_TIMESTAMP                    SCN
-- ---------- --------- ------------- ---------- -------------------- --------------------
 2 Dependency Published K.RC_TAB                 2017*JUL*12 07:06:43    9,198,309,753,654
 0 Dependency Published K.GET_VAL                2017*JUL*12 07:06:43    9,198,309,753,651
 1 Result     Invalid   "K"."GET_VAL" PLSQL      2017*JUL*12 07:06:43    9,198,309,753,651
 3 Result     Invalid   "K"."GET_VAL" PLSQL      2017*JUL*12 07:06:43    9,198,309,753,651
 4 Result     Invalid   "K"."GET_VAL" PLSQL      2017*JUL*12 07:06:43    9,198,309,753,651

The above test shows that Commit SCN:
    9,198,309,753,654
is exposed in V$RESULT_CACHE_OBJECTS.SCN as invalidation SCN.

Oracle 12c Database Reference said about V$RESULT_CACHE_OBJECTS.SCN:
    Build SCN (TYPE = Result) or invalidation SCN (TYPE = Dependency)

There are also a few Oracle Tables/Views containing "commitscn" or "commit_scn" columns, which could point to its usage.

Wednesday, May 24, 2017

JDBC, Oracle object/collection, dbms_pickler, NOPARALLEL sys.type$ query

When using the JDBC Thin driver to invoke PL/SQL programs with Oracle objects / collections, we can observe dbms_pickler calls, and two NOPARALLEL hinted sys.type$ queries having the same number of executions as dbms_pickler. These can result in intermittent performance degradation.

Note: All tests are done with java 8 and ojdbc7.jar on Oracle 12.1.0.2.0.
          See appended Test Code.


1. Test and Reasoning


Run:
   java OracleJDBC "jdbc:oracle:thin:k/s@testDB:1521:testDB" 3 5

then execute query below, watch its output:

select executions, sql_text, v.* 
  from v$sql v 
 where lower(sql_text) like '%dbms_pickler%' 
    or sql_text like '%NOPARALLEL%'; 
    
2 begin :1 := dbms_pickler.get_type_shape(:2,:3,:4,:5,:6,:7,:8,:9,:10); end;
2 SELECT /*+ NOPARALLEL */ 1, A.NAME, A.ATTRIBUTE#, ..., SO.NAME 
    FROM SYS.ATTRIBUTE$ A, SYS.TYPE$ T, SYS.TYPE$ AT, SYS. "_CURRENT_EDITION_OBJ" ATO, 
         SYS.USER$ ATU, SYS. "_CURRENT_EDITION_OBJ" SO, SYS.USER$ SU 
   WHERE T.TVOID = :B1 AND A.ATTR_TOID = ATO.OID$ ...
   ORDER BY ATTRIBUTE#

Since we have one call of StructDescriptor for Oracle Object "TEST_OBJ", and one call of ArrayDescriptor for Oracle Object Collection (nested table) "TEST_OBJ_ARRAY":

  StructDescriptor structDP = StructDescriptor.createDescriptor("TEST_OBJ", conn);
  ArrayDescriptor  arrayDP  = ArrayDescriptor.createDescriptor("TEST_OBJ_ARRAY", conn);

so there are two respective calls of dbms_pickler.get_type_shape to lookup their metadata in Oracle database.

Whereas with ojdbc5.jar, it looks like:
    dbms_pickler.get_type_shape(:2,:3,:4,:5,:6,:7)
and there are no two NOPARALLEL hinted sys.type$ queries because there are no calls of dbms_pickler.get_metadata.

Further tested in Oracle 11g dbms_pickler or 12cR1 with ojdbc5.jar, it is not able to observe this behavior.

Comparing output of
    SQL > describe dbms_pickler
between 11g and 12cR1, we can see that 11g two APIs dbms_pickler.get_type_shape have 6 parameters; whereas 12cR1 APIs are enhanced with two more overloaded functions having 9 parameters. That could explain the difference:
    11g   dbms_pickler.get_type_shape(:2,:3,:4,:5,:6,:7)
    12cR1 dbms_pickler.get_type_shape(:2,:3,:4,:5,:6,:7,:8,:9,:10)
Hence it is possible the regression was introduced in 12cR1 with ojdbc7.jar.

For each oracle connection, the created instances of StructDescriptor and ArrayDescriptor are cached, the subsequent repeated call gets the cached result (one optimization). That is why even we have a loop calls, only two calls of dbms_pickler.get_type_shape are sent to database.

As a further test, we can provoke a java dump by:
   SQL> drop type test_obj force;
and get an exception call stack:

java.sql.SQLException: Fail to construct descriptor: Unable to resolve type "TEST_OBJ"
        at oracle.sql.TypeDescriptor.getTypeDescriptor(TypeDescriptor.java:1042)
        at oracle.sql.StructDescriptor.isValidObject(StructDescriptor.java:89)
        at oracle.sql.StructDescriptor.createDescriptor(StructDescriptor.java:114)
        at oracle.sql.StructDescriptor.createDescriptor(StructDescriptor.java:74)
        at OracleJDBC.dbcall(OracleJDBC.java:60)
        at OracleJDBC.main(OracleJDBC.java:43)

Here the code path:

OracleJDBC.java
 StructDescriptor sDescr = StructDescriptor.createDescriptor("TEST_OBJ", connection);
--->
oracle.sql.StructDescriptor.java
  structdescriptor = new StructDescriptor(sqlname, connection);
--->
oracle.jdbc.oracore.OracleTypeADT
 init(OracleConnection oracleconnection)
  -> initMetadata(oracleconnection);
    -> initMetadata12(OracleConnection oracleconnection)
--->
dbms_pickler
   -> get_type_shape  
      -> get_metadata

The above test is performed with 12c deprecated oracle.sql.STRUCT and oracle.sql.ARRAY (first Java Test Code).

Run the same test with new wrapped API (second Java Test Code), and provoke the same exception. We can see both implementations are internally identical, but the deprecated API looks more obvious.


java.sql.SQLException: Fail to construct descriptor: Unable to resolve type "TEST_OBJ"
        at oracle.sql.TypeDescriptor.getTypeDescriptor(TypeDescriptor.java:1042)
        at oracle.sql.StructDescriptor.isValidObject(StructDescriptor.java:89)
        at oracle.sql.StructDescriptor.createDescriptor(StructDescriptor.java:114)
        at oracle.sql.StructDescriptor.createDescriptor(StructDescriptor.java:74)
        at oracle.jdbc.driver.PhysicalConnection.createStruct(PhysicalConnection.java:8732)
        at OracleJDBC.dbcall(OracleJDBC.java:61)
        at OracleJDBC.main(OracleJDBC.java:42)

Also tested with Java Stored Procedure in Oracle RDBMS embedded JVM (see Test Code: Java Stored Procedure) by:
   SQL > exec dbcallCtrl(3, 5);

It has the same behavior.


2. Trace file and HProfile


In the Test Code, we also make the Event 10046 Trace and HProfile, here excerpted outputs:


(a). Row Trace File



begin :1 := dbms_pickler.get_type_shape(:2,:3,:4,:5,:6,:7,:8,:9,:10); end;
 Bind#0
  oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00         <--- oacdty=02:  SQLT_NUM: number
  oacflg=03 fl2=1000000 frm=01 csi=873 siz=24 off=0
  kxsbbbfp=fffffd7ffbe8afe8  bln=22  avl=00  flg=05
 Bind#1
  oacdty=01 mxl=32767(32767) mxlc=00 mal=00 scl=00 pre=00   <--- oacdty=01:  SQLT_CHR: varchar2
  oacflg=03 fl2=1000010 frm=01 csi=873 siz=32767 off=0
  kxsbbbfp=fffffd7ffbe81fe8  bln=32767  avl=08  flg=05
  value="TEST_OBJ"

...
 Bind#1
  oacdty=01 mxl=32767(32767) mxlc=00 mal=00 scl=00 pre=00
  oacflg=03 fl2=1000010 frm=01 csi=873 siz=32767 off=0
  kxsbbbfp=fffffd7ffbea3000  bln=32767  avl=14  flg=05
  value="TEST_OBJ_ARRAY"


(b). TKPROF Trace File



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        2      0.00       0.00          0          0          0           0
Execute      2      0.01       0.01          0         59          0           2
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      0.01       0.01          0         59          0           2


SELECT /*+ NOPARALLEL */ 1, A.NAME, A.ATTRIBUTE#, DECODE(AT.TYPECODE, 9, 
  DECODE(A.CHARSETFORM, 2, 'NVARCHAR2', ATO.NAME), 96, DECODE(A.CHARSETFORM, 
  2, 'NCHAR', ATO.NAME), 112, DECODE(A.CHARSETFORM, 2, 'NCLOB', ATO.NAME), 
  ATO.NAME), DECODE(BITAND(AT.PROPERTIES, 64), 64, NULL, ATU.NAME), NULL, 
  A.ATTR_TOID, DECODE(BITAND(T.PROPERTIES, 65536), 65536, 'NO', 'YES'), 
  SU.NAME, SO.NAME 
FROM
 SYS.ATTRIBUTE$ A, SYS.TYPE$ T, SYS.TYPE$ AT, SYS. "_CURRENT_EDITION_OBJ" ATO,
   SYS.USER$ ATU, SYS. "_CURRENT_EDITION_OBJ" SO, SYS.USER$ SU WHERE T.TVOID =
   :B1 AND A.ATTR_TOID = ATO.OID$ AND ATO.OWNER# = ATU.USER# AND A.TOID = 
  T.TVOID AND T.PACKAGE_OBJ# IS NULL AND AT.TVOID = A.ATTR_TOID AND 
  AT.SUPERTOID = SO.OID$ (+) AND SO.OWNER# = SU.USER# (+) ORDER BY ATTRIBUTE#

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        2      0.00       0.00          0          0          0           0
Execute      2      0.00       0.00          0          0          0           0
Fetch        2      0.00       0.00          0         37          0           2
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        6      0.00       0.00          0         37          0           2
     

SELECT /*+ NOPARALLEL */ 1, U.NAME, O.NAME, O.OID$ 
FROM
 SYS. "_CURRENT_EDITION_OBJ" O, SYS.USER$ U, SYS.TYPE$ T WHERE T.SUPERTOID = 
  :B1 AND T.TVOID = O.OID$ AND O.SUBNAME IS NULL AND O.OWNER# = U.USER#

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        2      0.00       0.00          0          0          0           0
Execute      2      0.00       0.00          0          0          0           0
Fetch        2      0.00       0.00          0          6          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        6      0.00       0.00          0          6          0           0

Note that sys.USER$ is a very thick declared table. For each row, it can requires 3 8-KB Blocks
(See Blog: Redo/Undo explosion from thick declared table insert)

SQL> select count(*) col_cnt, sum(data_length) max_rowsize, max(data_length) max_col_len 
       from dba_tab_cols 
      where owner='SYS' and table_name='USER$';
     
  COL_CNT MAX_ROWSIZE MAX_COL_LEN
  ------- ----------- -----------
       30       18670        4000    


(c). HProfile


Function Elapsed Time (microsecs) Data sorted by Total Subtree Elapsed Time (microsecs) for 'dbms_pickler_hpf_15_09_56'

Function Elapsed Time (microsecs) Data sorted by Total Subtree Elapsed Time (microsecs)

10517 microsecs (elapsed time) & 20 function calls

Subtree Ind% Function Ind% Descendants Ind% Calls Ind% Function Name
10517 100% 11 0.1% 10506 99.9% 3 15.0% __plsql_vm
10506 99.9% 374 3.6% 10132 96.3% 3 15.0% __anonymous_block
10112 96.1% 3945 37.5% 6167 58.6% 2 10.0% SYS.DBMS_PICKLER.GET_TYPE_SHAPE (Line 384)
1708 16.2% 1708 16.2% 0 0.0% 2 10.0% SYS.DBMS_PICKLER.__static_sql_exec_line141 (Line 141)
1263 12.0% 1263 12.0% 0 0.0% 2 10.0% SYS.DBMS_PICKLER.__static_sql_exec_line236 (Line 236)
1094 10.4% 1094 10.4% 0 0.0% 2 10.0% SYS.DBMS_PICKLER.__static_sql_exec_line175 (Line 175)
1067 10.1% 1067 10.1% 0 0.0% 2 10.0% SYS.DBMS_PICKLER.__static_sql_exec_line211 (Line 211)
1035 9.8% 1035 9.8% 0 0.0% 2 10.0% SYS.DBMS_PICKLER.__sql_fetch_line186 (Line 186)
20 0.2% 20 0.2% 0 0.0% 1 5.0% K.TRC_STOP.TRC_STOP (Line 1)
0 0.0% 0 0.0% 0 0.0% 1 5.0% SYS.DBMS_HPROF.STOP_PROFILING (Line 63)

3. Type Descriptor Retrieval Performance Fix


Comparing code of 12c deprecated APIs,

StructDescriptor structDP = StructDescriptor.createDescriptor("TEST_OBJ", conn);
ArrayDescriptor  arrayDP  = ArrayDescriptor.createDescriptor("TEST_OBJ_ARRAY", conn);

oneObj   = new STRUCT(structDP, conn, objField);
objArray = new ARRAY(arrayDP, conn, objVector.toArray()); 
with that of new APIs,

objStruct[i] = conn.createStruct("TEST_OBJ", objField);
objArray     = conn.createOracleArray("TEST_OBJ_ARRAY", objStruct);
and refer to the implementation of new APIs in PhysicalConnection.java of ojdbc7.jar:

oracle.jdbc.driver.PhysicalConnection.java
    ...
    public Struct createStruct(String s, Object aobj[])
    {
        StructDescriptor structdescriptor = StructDescriptor.createDescriptor(s, this);
        return new STRUCT(structdescriptor, this, aobj);
    }
    
    public Array createOracleArray(String s, Object obj)
    {
        return createARRAY(s, obj);
    }    
    
    public ARRAY createARRAY(String s, Object obj)
    {
        ArrayDescriptor arraydescriptor = ArrayDescriptor.createDescriptor(s, this);
        return new ARRAY(arraydescriptor, this, obj);
    }  
we can see that new API createStruct / createARRAY enclose both createDescriptor and constructor of deprecated API as one call.

From code path (call stack), we know the performance is caused by an execution of

 "begin :1 := dbms_pickler.get_type_shape(:2,:3,:4,:5,:6,:7,:8,:9,:10); end;"
located in OracleTypeADT.java, which is invoked by TypeDescriptor.getTypeDescriptor following the call of StructDescriptor.createDescriptor.

Oracle MOS:
    Intermittent Poor Performance Retrieving PL/SQL Object Types (Doc ID 1222553.1)
reveals 3 new API functions in PhysicalConnection.java:

 getAllTypeDescriptorsInCurrentSchema()
  getTypeDescriptorsFromListInCurrentSchema()
  getTypeDescriptorsFromList()
which return TypeDescriptors for the given Objects. In fact, it is a call of query:

"SELECT schema_name, typename, typoid, typecode, version, tds FROM TABLE(private_jdbc.Get_Type_Shape_Info(?))"
where private_jdbc.Get_Type_Shape_Info is implemented as:

dbms_pickler.get_type_shape(schema_name, v_in.typename, v_out.typoid, v_out.version, v_out.tds, lds_temp)
It has only 6 parameters, and is exact the same call as ojdbc5.jar.
private_jdbc is probably the MOS mentioned internal PL/SQL package introduced in RDBMS 11.

MOS Doc ID 1222553.1 claims:
    Only when using the new API methods will Get_Type_Shape_Info be used behind the scenes rather than DBMS_PICKLER.
however test shows that DBMS_PICKLER is still called because PRIVATE_JDBC.Get_Type_Shape_Info delegates the call to DBMS_PICKLER.get_type_shape, but only with 6 parameters same as with ojdbc5.jar. It can be confirmed with HProfile.

Therefore, if we use the deprecated API with getTypeDescriptorsFromList(), the perfromance is back to ojdbc5.jar.
See appended Java Code:
    Test Code: Java (Type Descriptor Retrieval Performance Fix by getTypeDescriptorsFromList)

However, with 12c new API createStruct / createARRAY, there seems no way to call getTypeDescriptorsFromList() because both createDescriptor and constructor are cemented in one single call.

One can also use dtrace to get more info about subroutine: pckltds in the call:

dbms_pickler.get_type_shape
---> dbms_pickler.get_descriptors
     ---> external name "pckltds"

dtrace -w -n 'pid$target::*pckltds*:entry {@[pid, ustack(20, 0)] = count() ; stop(); exit(0);}' -p 28016


4. Test Code: DB



drop table test_obj_tab;
drop type test_obj_array force;
drop type test_obj force;

create or replace type test_obj as object (
  id    number(8)
 ,name  varchar2(100));
/

create or replace type test_obj_array as table of test_obj;
/

create table test_obj_tab(id number(8), name varchar2(100), ins_time date);

select * from test_obj_tab order by ins_time desc;

create or replace procedure trc_start as
  l_ident_trc varchar2(100);
  l_ident_hpf varchar2(100);
begin
  l_ident_trc := 'dbms_pickler_trc_'||to_char(sysdate, 'HH24_MI_SS');
  l_ident_hpf := 'dbms_pickler_hpf_'||to_char(sysdate, 'HH24_MI_SS')||'.hpf';
  dbms_application_info.set_module('ksun_mod1', 'ksun_act1');
  execute immediate 'alter session set tracefile_identifier=''' || l_ident_trc || '''';
  dbms_monitor.session_trace_enable(waits=>true, binds=>true);
  sys.dbms_hprof.start_profiling('HPROF_DIR', l_ident_hpf);
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 'alter session set session_cached_cursors = '||l_intval;
end;
/

create or replace function ins_tab(p_array test_obj_array) return number as
  l_rowcount integer;
begin
  insert into test_obj_tab select t.id, t.name, sysdate from table(cast (p_array as test_obj_array)) t;
  l_rowcount := sql%rowcount;
  commit;
  return l_rowcount;
end;
/


5. Test Code: Java (12c deprecated oracle.sql.STRUCT, oracle.sql.ARRAY)



import java.sql.DriverManager;
import java.sql.Connection;
import java.sql.CallableStatement;
import java.sql.SQLException;
import java.util.Vector;
import oracle.sql.ARRAY;
import oracle.sql.ArrayDescriptor;
import oracle.sql.STRUCT;
import oracle.sql.StructDescriptor;
import oracle.jdbc.OracleTypes;

// OracleJDBC  jdbcURL  loopCNT  objCNT
// OracleJDBC "jdbc:oracle:thin:k/s@testDB:1521:testDB" 3 5 

public class OracleJDBC {
  static String TRCSTART = "begin trc_start; end;";
  static String TRCSTOP  = "begin trc_stop; end;";
  static String INSTAB   = "begin :1 := ins_tab(:2); end;";
   
  public static void main(String[] args) {
    String jdbcURL = args[0];
    int loopCNT    = Integer.parseInt(args[1]);
    int objCNT     = Integer.parseInt(args[2]);
    CallableStatement cStmt;
    
    try {
      Class.forName("oracle.jdbc.driver.OracleDriver");
    } catch (ClassNotFoundException e) {
      System.out.println("Where is your Oracle JDBC Driver ?");
      e.printStackTrace();
      return;
    }
    
    Connection conn = null;
    try {
      conn = DriverManager.getConnection(jdbcURL);
      
      cStmt = conn.prepareCall(TRCSTART);
      cStmt.execute();
      cStmt.close();  
          
      for(int p=0; p < loopCNT; p++){
        dbcall(conn, p+1, objCNT);
      }
      
      cStmt = conn.prepareCall(TRCSTOP);
      cStmt.execute();
      cStmt.close();      
    } catch (SQLException e) {
      System.out.println("Connection Failed! Check output console");
      e.printStackTrace();
      return;
    }
  }
 
  static void dbcall(Connection conn, int loopNo, int objCNT) {
    CallableStatement cStmt;
    
    Object [] objField = new Object[2];
    STRUCT oneObj = null;
    Vector objVector = new Vector();
    ARRAY objArray = null;
    
    if (conn != null) {
      System.out.println("You made it, call DBMS_PICKLER to select TYPE info from sys.type$ !");
      try {
        StructDescriptor structDP = StructDescriptor.createDescriptor("TEST_OBJ", conn);
        ArrayDescriptor  arrayDP  = ArrayDescriptor.createDescriptor("TEST_OBJ_ARRAY", conn);
        for(int i=0; i < objCNT; i++){
          objField[0] = i;       
          objField[1] = "Name_" + i; 
          oneObj = new STRUCT(structDP, conn, objField);
          objVector.add(oneObj);
        }
        objArray = new ARRAY(arrayDP, conn, objVector.toArray()); 
        cStmt = conn.prepareCall(INSTAB);
        cStmt.registerOutParameter(1, OracleTypes.INTEGER);
        cStmt.setArray(2, objArray);
        cStmt.execute();
        int insRows = cStmt.getInt(1);
        cStmt.close();
        System.out.println("ARRAY Size = " + objArray.length() + ", DB Inserted Rows = " + insRows + ", loops = " + loopNo);
      } catch (SQLException e) {
        System.out.println("Connection Failed! Check output console");
        e.printStackTrace();
      }
      System.out.println("END");
    } else {
      System.out.println("Failed to make connection!");
    }
  }
}


6. Test Code: Java (12c new API)



import java.sql.DriverManager;
import java.sql.Connection;
import java.sql.CallableStatement;
import java.sql.Struct;
import java.sql.Array;
import java.sql.SQLException;
import java.util.Vector;
import oracle.jdbc.OracleTypes;
import oracle.jdbc.OracleConnection;

// OracleJDBC  jdbcURL  loopCNT  objCNT
// OracleJDBC "jdbc:oracle:thin:k/s@testDB:1521:testDB" 3 5

public class OracleJDBC {
  static String TRCSTART = "begin trc_start; end;";
  static String TRCSTOP  = "begin trc_stop; end;";
  static String INSTAB   = "begin :1 := ins_tab(:2); end;";
   
  public static void main(String[] args) {
   String jdbcURL = args[0];
   int loopCNT    = Integer.parseInt(args[1]);
   int objCNT     = Integer.parseInt(args[2]);
   CallableStatement cStmt;
   
   try {
     Class.forName("oracle.jdbc.driver.OracleDriver");
   } catch (ClassNotFoundException e) {
     System.out.println("Where is your Oracle JDBC Driver ?");
     e.printStackTrace();
     return;
   }
   
   Connection conn = null;
   try {
     conn = DriverManager.getConnection(jdbcURL);
     cStmt = conn.prepareCall(TRCSTART);
     cStmt.execute();
     cStmt.close();  
         
     for(int p=0; p < loopCNT; p++){
       dbcall(conn, p+1, objCNT);
     }
     
     cStmt = conn.prepareCall(TRCSTOP);
     cStmt.execute();
     cStmt.close();      
   } catch (SQLException e) {
     System.out.println("Connection Failed! Check output console");
     e.printStackTrace();
     return;
   }
  }
 
  static void dbcall(Connection conn, int loopNo, int objCNT) {
    CallableStatement cStmt;
    
    Object [] objField = new Object[2];
    Struct[] objStruct = new Struct[objCNT];
    Array objArray = null;
    
    if (conn != null) {
      System.out.println("You made it, call DBMS_PICKLER to select TYPE info from sys.type$ !");
      try {
        for(int i=0; i < objCNT; i++){
          objField[0] = i;       
          objField[1] = "Name_" + i; 
          objStruct[i] = conn.createStruct("TEST_OBJ", objField);
        }
        objArray = ((OracleConnection) conn).createOracleArray("TEST_OBJ_ARRAY", objStruct);
        
        cStmt = conn.prepareCall(INSTAB);
        cStmt.registerOutParameter(1, OracleTypes.INTEGER);
        cStmt.setArray(2, objArray);
        cStmt.execute();
        int insRows = cStmt.getInt(1);
        cStmt.close();
        //Object[] objArrayIns = (Object[])objArray.getArray();
        System.out.println("ARRAY Size = " + ((Object[])objArray.getArray()).length + ", DB Inserted Rows = " + insRows + ", loops = " + loopNo);
      } catch (SQLException e) {
        System.out.println("Connection Failed! Check output console");
        e.printStackTrace();
      }
      System.out.println("SUC END");
    } else {
      System.out.println("Failed to make connection!");
    }
  }
}


7. Test Code: Java (Java Stored Procedure in Oracle RDBMS embedded JVM)



create or replace java source named "OracleJDBC" as

import java.sql.DriverManager;
import java.sql.Connection;
import java.sql.CallableStatement;
import java.sql.Struct;
import java.sql.Array;
import java.sql.SQLException;
import java.util.Vector;
import oracle.jdbc.OracleTypes;
import oracle.jdbc.OracleConnection;
import oracle.jdbc.driver.OracleDriver;

// dbcallCtrl (3, 5)

public class OracleJDBC {
  static String TRCSTART = "begin trc_start; end;";
  static String TRCSTOP  = "begin trc_stop; end;";
  static String INSTAB   = "begin :1 := ins_tab(:2); end;";
   
  public static void dbcallCtrl(int loopCNT, int objCNT) throws SQLException{
    Connection conn = new OracleDriver().defaultConnection();
    CallableStatement cStmt;
    try {
      cStmt = conn.prepareCall(TRCSTART);
      cStmt.execute();
      cStmt.close();  
        
      for(int p=0; p < loopCNT; p++){
        dbcall(conn, p+1, objCNT);
      }
      
      cStmt = conn.prepareCall(TRCSTOP);
      cStmt.execute();
      cStmt.close(); 
    } catch (SQLException e) {
      System.out.println("Connection Failed! Check output console");
      e.printStackTrace();
    }         
  }
 
  static void dbcall(Connection conn, int loopNo, int objCNT) {
    CallableStatement cStmt;
    
    Object [] objField = new Object[2];
    Struct[] objStruct = new Struct[objCNT];
    Array objArray = null;
    
    if (conn != null) {
      System.out.println("You made it, call DBMS_PICKLER to select TYPE info from sys.type$ !");
      try {
        for(int i=0; i < objCNT; i++){
          objField[0] = i;       
          objField[1] = "Name_" + i; 
          objStruct[i] = conn.createStruct("TEST_OBJ", objField);
        }
        objArray = ((OracleConnection) conn).createOracleArray("TEST_OBJ_ARRAY", objStruct);
        
        cStmt = conn.prepareCall(INSTAB);
        cStmt.registerOutParameter(1, OracleTypes.INTEGER);
        cStmt.setArray(2, objArray);
        cStmt.execute();
        int insRows = cStmt.getInt(1);
        cStmt.close();
        //Object[] objArrayIns = (Object[])objArray.getArray();
        System.out.println("ARRAY Size = " + ((Object[])objArray.getArray()).length + ", DB Inserted Rows = " + insRows + ", loops = " + loopNo);
      } catch (SQLException e) {
        System.out.println("Connection Failed! Check output console");
        e.printStackTrace();
      }
     System.out.println("SUC END");
   } else {
    System.out.println("Failed to make connection!");
   }
 }
}
/

create or replace procedure dbcallCtrl(loopNo number, objCNT number) as 
language java name 'OracleJDBC.dbcallCtrl(int, int)';
/

--set serveroutput on size 50000
--exec dbms_java.set_output(50000); 
--exec dbcallCtrl(3, 5);


8. Test Code: Java (Type Descriptor Retrieval Performance Fix by getTypeDescriptorsFromList)



import java.sql.DriverManager;
import java.sql.Connection;
import java.sql.CallableStatement;
import java.sql.SQLException;
import java.util.Vector;
import oracle.sql.ARRAY;
import oracle.sql.ArrayDescriptor;
import oracle.sql.STRUCT;
import oracle.sql.StructDescriptor;
import oracle.sql.TypeDescriptor;
import oracle.jdbc.OracleTypes;
import oracle.jdbc.OracleConnection;

// OracleJDBC  jdbcURL  loopCNT  objCNT
// OracleJDBC "jdbc:oracle:thin:k/s@testDB:1521:testDB" 3 5 

public class OracleJDBC {
  static String TRCSTART = "begin trc_start; end;";
  static String TRCSTOP  = "begin trc_stop; end;";
  static String INSTAB   = "begin :1 := ins_tab(:2); end;";
   
  public static void main(String[] args) {
    String jdbcURL = args[0];
    int loopCNT    = Integer.parseInt(args[1]);
    int objCNT     = Integer.parseInt(args[2]);
    CallableStatement cStmt;
    
    try {
      Class.forName("oracle.jdbc.driver.OracleDriver");
    } catch (ClassNotFoundException e) {
      System.out.println("Where is your Oracle JDBC Driver ?");
      e.printStackTrace();
      return;
    }
    
    Connection conn = null;
    try {
      conn = DriverManager.getConnection(jdbcURL);
      
      cStmt = conn.prepareCall(TRCSTART);
      cStmt.execute();
      cStmt.close();  
      
      String[][] schemaAndTypeNamePairs = {{"K","TEST_OBJ"}, {"K","TEST_OBJ_ARRAY"}};
      TypeDescriptor[] sqlTypes = ((OracleConnection) conn).getTypeDescriptorsFromList(schemaAndTypeNamePairs);
          
      for(int p=0; p < loopCNT; p++){
        dbcall(conn, p+1, objCNT, sqlTypes);
      }
      
      cStmt = conn.prepareCall(TRCSTOP);
      cStmt.execute();
      cStmt.close();      
    } catch (SQLException e) {
      System.out.println("Connection Failed! Check output console");
      e.printStackTrace();
      return;
    }
  }
 
  static void dbcall(Connection conn, int loopNo, int objCNT, TypeDescriptor[] sqlTypes) {
    CallableStatement cStmt;
    
    Object [] objField = new Object[2];
    STRUCT oneObj = null;
    Vector objVector = new Vector();
    ARRAY objArray = null;

    if (conn != null) {
      System.out.println("You made it, call DBMS_PICKLER to select TYPE info from sys.type$ !");
      try {
        StructDescriptor structDP = (StructDescriptor)sqlTypes[0];
        ArrayDescriptor  arrayDP  = (ArrayDescriptor)sqlTypes[1];
        
        for(int i=0; i < objCNT; i++){
          objField[0] = i;       
          objField[1] = "Name_" + i; 
          oneObj = new STRUCT(structDP, conn, objField);
          objVector.add(oneObj);
        }
        objArray = new ARRAY(arrayDP, conn, objVector.toArray()); 
        cStmt = conn.prepareCall(INSTAB);
        cStmt.registerOutParameter(1, OracleTypes.INTEGER);
        cStmt.setArray(2, objArray);
        cStmt.execute();
        int insRows = cStmt.getInt(1);
        cStmt.close();
        System.out.println("ARRAY Size = " + objArray.length() + ", DB Inserted Rows = " + insRows + ", loops = " + loopNo);
      } catch (SQLException e) {
        System.out.println("Connection Failed! Check output console");
        e.printStackTrace();
      }
      System.out.println("END");
    } else {
      System.out.println("Failed to make connection!");
    }
  }
}