Friday, July 21, 2017

Blog List

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".

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 Views


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.

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 invoking JDBC call of Oracle objects and collections (for example, nested table), we can observe dbms_pickler calls and two NOPARALLEL hinted sys.type$ queries, which have the same number of executions as dbms_pickler.

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. 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;
/


4. 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!");
    }
  }
}


5. 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!");
    }
  }
}


6. 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);

Tuesday, May 16, 2017

PLSQL Context Switch Functions and Cost

This Blog will try to investigate the cost of PLSQL context switch on the (speculated) Oracle internal function calls:
    (1) plsql_run
    (2) pfrrun
    (3) evapls
    (4) kgiPinObject
We will use Dtrace to acquire call count and duration in case of different 12c PLSQL features.

Blog: Oracle 12c: PRAGMA UDF – the truth debugs plsql_run calls of 12c PRAGMA UDF, and claims the impact of fetch size.

Blog: PL/SQL context switch calls Linux SystemTap to get stacktraces of first 3 functions, and applies perf to sample stacktraces, finally generates flamegraph. Because of sampling, it does not have an exact call counter, and Nyquist sampling theorem requires the sampling should be double fast.

The last function is discussed in Blog: Blog: Using DTrace to understand why PL/SQL packages can be faster than stored procedures . It uses Dtrace to compare PL/SQL packages and stored procedures performance, and demonstrates PL/SQL packages prevails the performance of stored procedures. Probably because PL/SQL packages are stateful objects, they have to be pinned in Library Cache. Whereas stored procedures are stateless, they can be freely discarded and re-loaded if necessary.

Even 4 popular PL/SQL errors are designated hereinafter for package state:
  ORA-04068: existing state of packages has been discarded
  ORA-04061: existing state of package %s has been invalidated
  ORA-04065: not executed, altered or dropped package %s
  ORA-06508: PL/SQL: could not find program unit being called:%s
This Blog will try to demonstrate that plsql_run, pfrrun and kgiPinObject are hardly to be the deciding factors of PLSQL context switch cost because lowing the calls and elapsed time of these 3 functions to an ignorable value does not produce the proportional benefits. Only evapls keeps constant and hence probably stays in the critical code path.

But all the above approaches only discuss context switch from SQL to PLSQL. It is still open to see how to investigate the inverse context switch from PLSQL to SQL.


1. Test


Run run_test_all (see appended code), we get the following result.

Note that 'base_sql_only' is an implementation in pure SQL, 'base_plsql_only' is one in pure PLSQL. Both will be served as base for context switch comparisons.
   
SQL > exec run_test_all(10000);
  base_sql_only      Elaplsed (ms) =       60
  base_plsql_only    Elaplsed (ms) =      790
  get_sql_cnt        Elaplsed (ms) =     2140
  get_udf_cnt        Elaplsed (ms) =     2130
  get_bulk_cnt       Elaplsed (ms) =     1130
  get_with_cnt       Elaplsed (ms) =     1100  
  update_loop_cnt    Elaplsed (ms) =     2940
  update_forall_cnt  Elaplsed (ms) =     2040

'get_with_cnt' is coded in 12c WITH Clause PL/SQL Function, which seems double fast. 'get_bulk_cnt' is also faster due to bulk collect.


2. Test with Dtrace


Run the similar test case in Sqlplus Window, and call Dtrace script (see appended code) to trace the process (pid 5678) by:
   ./plsql_cost.d -p 5678
we get the result as follows.

SQL > exec run_test('base_sql_only'      , 10000);
  plsql_run    Count = 2,     Total_time (ms) = 61,   Elpased (ms) = 71
  pfrrun       Count = 2,     Total_time (ms) = 61,   Elpased (ms) = 71
  evapls       Count = 0,     Total_time (ms) = 0,    Elpased (ms) = 0
  kgiPinObject Count = 10,    Total_time (ms) = 0,    Elpased (ms) = 70

SQL > exec run_test('base_plsql_only'   , 10000);
  plsql_run    Count = 2,     Total_time (ms) = 760,  Elpased (ms) = 763
  pfrrun       Count = 2,     Total_time (ms) = 760,  Elpased (ms) = 763
  evapls       Count = 0,     Total_time (ms) = 0,    Elpased (ms) = 0
  kgiPinObject Count = 9,     Total_time (ms) = 0,    Elpased (ms) = 763

SQL > exec run_test('get_sql_cnt'      , 10000);
  plsql_run    Count = 10001, Total_time (ms) = 1296, Elpased (ms) = 2860
  pfrrun       Count = 10001, Total_time (ms) = 1175, Elpased (ms) = 2860
  evapls       Count = 10000, Total_time (ms) = 1770, Elpased (ms) = 2859
  kgiPinObject Count = 10009, Total_time (ms) = 112,  Elpased (ms) = 2860

SQL > exec run_test('get_udf_cnt'      , 10000);
  plsql_run    Count = 10001, Total_time (ms) = 1291, Elpased (ms) = 3175
  pfrrun       Count = 10001, Total_time (ms) = 1170, Elpased (ms) = 3175
  evapls       Count = 10000, Total_time (ms) = 1773, Elpased (ms) = 3173
  kgiPinObject Count = 10009, Total_time (ms) = 116,  Elpased (ms) = 3175

SQL > exec run_test('get_bulk_cnt'     , 10000);
  plsql_run    Count = 10001, Total_time (ms) = 1252, Elpased (ms) = 1720
  pfrrun       Count = 10001, Total_time (ms) = 1145, Elpased (ms) = 1720
  evapls       Count = 10000, Total_time (ms) = 1529, Elpased (ms) = 1708
  kgiPinObject Count = 10010, Total_time (ms) = 49,   Elpased (ms) = 1720

SQL > exec run_test('get_with_cnt'     , 10000);
  plsql_run    Count = 2,     Total_time (ms) = 0,    Elpased (ms) = 1664
  pfrrun       Count = 10001, Total_time (ms) = 1141, Elpased (ms) = 1664
  evapls       Count = 10000, Total_time (ms) = 1244, Elpased (ms) = 1653
  kgiPinObject Count = 10,    Total_time (ms) = 0,    Elpased (ms) = 1664
      
SQL > exec run_test('update_loop_cnt'  , 10000);
  plsql_run    Count = 10001, Total_time (ms) = 1352, Elpased (ms) = 3760
  pfrrun       Count = 10001, Total_time (ms) = 1229, Elpased (ms) = 3760
  evapls       Count = 10000, Total_time (ms) = 1859, Elpased (ms) = 3756
  kgiPinObject Count = 10007, Total_time (ms) = 123,  Elpased (ms) = 3760

SQL > exec run_test('update_forall_cnt', 10000);
  plsql_run    Count = 10001, Total_time (ms) = 1352, Elpased (ms) = 3083
  pfrrun       Count = 10001, Total_time (ms) = 1231, Elpased (ms) = 3083
  evapls       Count = 10000, Total_time (ms) = 1661, Elpased (ms) = 3077
  kgiPinObject Count = 10008, Total_time (ms) = 57,   Elpased (ms) = 3083


3. PLSQL_CODE_TYPE NATIVE


Changing plsql_code_type from default INTERPRETED to NATIVE
   alter system set plsql_code_type=native;
recompile the PLSQL Test Code, and repeat the same tests with Dtrace.

(check NATIVE comipled source by:
   select * from dba_stored_settings where object_name = 'BASE_SQL_ONLY';)

Run all test cases:

SQL > exec run_test_all(10000);
  base_sql_only      Elaplsed (ms) =       60
  base_plsql_only    Elaplsed (ms) =      800
  get_sql_cnt        Elaplsed (ms) =     2130
  get_udf_cnt        Elaplsed (ms) =     2110
  get_bulk_cnt       Elaplsed (ms) =     1110
  get_with_cnt       Elaplsed (ms) =     1040
  update_loop_cnt    Elaplsed (ms) =     2920
  update_forall_cnt  Elaplsed (ms) =     2040

There seems not much difference compared to INTERPRETED code.

Then test with Dtrace:

SQL > exec run_test('base_sql_only'   , 10000);
  plsql_run    Count = 2,     Total_time (ms) = 64,   Elpased (ms) = 73
  pfrrun       Count = 5,     Total_time (ms) = 0,    Elpased (ms) = 73
  evapls       Count = 0,     Total_time (ms) = 0,    Elpased (ms) = 0
  kgiPinObject Count = 7,     Total_time (ms) = 0,    Elpased (ms) = 73
  
SQL > exec run_test('base_plsql_only'   , 10000);
  plsql_run    Count = 2,     Total_time (ms) = 760,  Elpased (ms) = 763
  pfrrun       Count = 2,     Total_time (ms) = 760,  Elpased (ms) = 763
  evapls       Count = 0,     Total_time (ms) = 0,    Elpased (ms) = 0
  kgiPinObject Count = 9,     Total_time (ms) = 0,    Elpased (ms) = 763

SQL > exec run_test('get_sql_cnt'      , 10000);
  plsql_run    Count = 10001, Total_time (ms) = 1171, Elpased (ms) = 2639
  pfrrun       Count = 4,     Total_time (ms) = 0,    Elpased (ms) = 2639
  evapls       Count = 10000, Total_time (ms) = 1604, Elpased (ms) = 2636
  kgiPinObject Count = 10002, Total_time (ms) = 111,  Elpased (ms) = 2639
  
SQL > exec run_test('get_udf_cnt'      , 10000);
  plsql_run    Count = 10001, Total_time (ms) = 1175, Elpased (ms) = 3056
  pfrrun       Count = 4,     Total_time (ms) = 0,    Elpased (ms) = 3056
  evapls       Count = 10000, Total_time (ms) = 1642, Elpased (ms) = 3055
  kgiPinObject Count = 10004, Total_time (ms) = 110,  Elpased (ms) = 3056
  
SQL > exec run_test('get_bulk_cnt'     , 10000);
  plsql_run    Count = 10001, Total_time (ms) = 1162, Elpased (ms) = 1953
  pfrrun       Count = 5,     Total_time (ms) = 0,    Elpased (ms) = 1953
  evapls       Count = 10000, Total_time (ms) = 1435, Elpased (ms) = 1942
  kgiPinObject Count = 10007, Total_time (ms) = 47,   Elpased (ms) = 1953
    
SQL > exec run_test('get_with_cnt'     , 10000);
  plsql_run    Count = 2,     Total_time (ms) = 0,    Elpased (ms) = 1655
  pfrrun       Count = 10005, Total_time (ms) = 1138, Elpased (ms) = 1655
  evapls       Count = 10000, Total_time (ms) = 1238, Elpased (ms) = 1644
  kgiPinObject Count = 5,     Total_time (ms) = 0,    Elpased (ms) = 1655
        
SQL > exec run_test('update_loop_cnt'  , 10000);
  plsql_run    Count = 10001, Total_time (ms) = 1227, Elpased (ms) = 4377
  pfrrun       Count = 4,     Total_time (ms) = 0,    Elpased (ms) = 4377
  evapls       Count = 10000, Total_time (ms) = 1730, Elpased (ms) = 4373
  kgiPinObject Count = 10004, Total_time (ms) = 121,  Elpased (ms) = 4377
  
SQL > exec run_test('update_forall_cnt', 10000);
  plsql_run    Count = 10001, Total_time (ms) = 1235, Elpased (ms) = 3568
  pfrrun       Count = 5,     Total_time (ms) = 0,    Elpased (ms) = 3568
  evapls       Count = 10000, Total_time (ms) = 1549, Elpased (ms) = 3564
  kgiPinObject Count = 10004, Total_time (ms) = 59,   Elpased (ms) = 3568

By the way, changing optimization level from default 2 to 1 by
   alter system set plsql_optimize_level=1;
seems no impact.


4. Reasoning


Look all above test result, we can conclude the facts below:
(a). All approaches except 'get_with_cnt' have similar behavior, but different between INTERPRETED and NATIVE.

(b). NATIVE Compile eliminates pfrrun to the level of base tests in all cases except 'get_with_cnt'.

(c). 'get_with_cnt' has plsql_run and kgiPinObject close to base tests, and behaves same in NATIVE and INTERPRETED.
      Probably it is implemented as NATIVE compiled.

(d). 'kgiPinObject' has a comparable call count as that of plsql_run, but its duration is less than 10% of total elapsed time.
      Therefore, it alone seems having not so much contribution.

(e). Comparing all tests with base tests, we can see only evapls keeps constant 
      and hence probably stays in the critical code path.


5. PLSQL Test Code



drop table test_tab;
drop table test_tab2;

create table test_tab as select level id, rpad('ABC_'||level, 1000, 'x') name from dual connect by level <= 10000; 

create index test_tab#ix_id on test_tab(id);

select count(*) from test_tab;

create table test_tab2 as select * from test_tab;

create index test_tab2#ix_id on test_tab2(id);


create or replace function get_sql (p_id in number) return varchar2 is
  l_name varchar2(1000);
begin
  select name into l_name from test_tab where id = p_id;
  return l_name;
end;
/

create or replace function get_udf (p_id in number) return varchar2 is
  l_name varchar2(1000);
  PRAGMA UDF;
begin
  select name into l_name from test_tab where id = p_id;
  return l_name;
end;
/

create or replace procedure base_sql_only (p_cnt number) is
 type t_name_tab is table of test_tab.name%type;
 l_name_tab         t_name_tab   := t_name_tab();
begin
  select name bulk collect into l_name_tab from test_tab where rownum <= p_cnt;
  dbms_output.put_line('get_bulk_cnt.count = '||l_name_tab.count);
end;
/

create or replace procedure base_plsql_only (p_cnt number) is
 l_name varchar2(1000);
begin
 for i in 1 .. p_cnt loop
    l_name := rpad('ABC_'||i, 1000, 'x');
  end loop;
end;
/

create or replace procedure get_sql_cnt (p_cnt number) is
  l_name varchar2(1000);
begin
 for i in 1 .. p_cnt loop
    select get_sql(i) into l_name from test_tab where id = i;
  end loop;
end;
/

create or replace procedure get_udf_cnt (p_cnt number) is
  l_name varchar2(1000);
begin
 for i in 1 .. p_cnt loop
    select get_udf(i) into l_name from test_tab where id = i;
  end loop;
end;
/

create or replace procedure get_bulk_cnt (p_cnt number) is
 type t_name_tab is table of test_tab.name%type;
 l_name_tab         t_name_tab   := t_name_tab();
begin
  select get_sql(id) bulk collect into l_name_tab from test_tab where rownum <= p_cnt;
  dbms_output.put_line('get_bulk_cnt.count = '||l_name_tab.count);
end;
/

create or replace procedure get_with_cnt (p_cnt number) is
 type t_name_tab is table of test_tab.name%type;
 l_name_tab         t_name_tab   := t_name_tab();
begin
  execute immediate q'[
    with function get (p_id in number) return varchar2 is
      l_name varchar2(1000);
    begin
      select name into l_name from test_tab where id = p_id;
      return l_name;
    end;
    select get(id) from test_tab where rownum <= :p_cnt]'
    bulk collect into l_name_tab
    using p_cnt;
  dbms_output.put_line('get_with_cnt.count = '||l_name_tab.count);
end;
/

create or replace procedure update_loop_cnt (p_cnt number) is
  type t_id_tab is table of test_tab.id%type;
  l_id_tab         t_id_tab   := t_id_tab();
begin
 select id bulk collect into l_id_tab from test_tab where id <= p_cnt;
  for i in 1 .. p_cnt loop
    update test_tab2 set name = get_sql(id) where id = l_id_tab(i);
  end loop;
  commit;    
end;
/

create or replace procedure update_forall_cnt (p_cnt number) is
  type t_id_tab is table of test_tab.id%type;
  l_id_tab         t_id_tab   := t_id_tab();
begin
  select id bulk collect into l_id_tab from test_tab where id <= p_cnt;
    forall i in 1 .. p_cnt
      update test_tab2 set name = get_sql(id) where id = l_id_tab(i);
    dbms_output.put_line('update_forall_cnt.sql%rowcount = '||sql%rowcount);
    commit;    
end;
/

create or replace procedure run_test (p_case varchar2, p_cnt number) as
 l_start  number := dbms_utility.get_time;
begin
  case p_case
    when 'base_sql_only'     then base_sql_only(p_cnt);
    when 'base_plsql_only'   then base_plsql_only(p_cnt); 
    when 'get_sql_cnt'       then get_sql_cnt(p_cnt); 
    when 'get_udf_cnt'       then get_udf_cnt(p_cnt); 
    when 'get_bulk_cnt'      then get_bulk_cnt(p_cnt);
    when 'get_with_cnt'      then get_with_cnt(p_cnt);
    when 'update_loop_cnt'   then update_loop_cnt(p_cnt);
    when 'update_forall_cnt' then update_forall_cnt(p_cnt);     
  end case;
  dbms_output.put_line(rpad(p_case, 18)||' Elaplsed (ms) = '||lpad((dbms_utility.get_time - l_start)*10, 8));   
end;
/

create or replace procedure run_test_all(p_cnt number) as
begin
  run_test('base_sql_only'    , p_cnt);
  run_test('base_plsql_only'  , p_cnt);
  run_test('get_sql_cnt'      , p_cnt);
  run_test('get_udf_cnt'      , p_cnt);
  run_test('get_with_cnt'     , p_cnt);
  run_test('get_bulk_cnt'     , p_cnt);
  run_test('update_loop_cnt'  , p_cnt);
  run_test('update_forall_cnt', p_cnt);
end;
/


6. Dtrace Script: plsql_cost.d



#!/usr/sbin/dtrace -s

/* plsql_cost.d
 * chmod u+x plsql_cost.d
 * ./plsql_cost.d -p 
*/

BEGIN  {
  ttime_sr = 0; stime_sr = timestamp; etime_sr = timestamp;  /** plsql_run    **/
  ttime_pr = 0; stime_pr = timestamp; etime_pr = timestamp;  /** pfrrun       **/
  ttime_er = 0; stime_er = timestamp; etime_er = timestamp;  /** evapls       **/
  ttime_kp = 0; stime_kp = timestamp; etime_kp = timestamp;  /** kgiPinObject **/
} 

pid$target::plsql_run:entry { self->t_sr = timestamp; }
 
pid$target::pfrrun:entry    { self->t_pr = timestamp; } 
 
pid$target::evapls:entry    { self->t_er = timestamp; } 

pid$target::kgiPinObject:entry    { self->t_kp = timestamp; } 
  
pid$target::plsql_run:return /self->t_sr != 0/ { 
  @CNT_SR[probefunc] = count(); 
  ttime_sr   = ttime_sr + (timestamp - self->t_sr)/1000;
  self->t_sr = 0;
  etime_sr   = timestamp;
}
 
pid$target::pfrrun:return /self->t_pr != 0/ { 
  @CNT_PR[probefunc] = count(); 
  ttime_pr   = ttime_pr + (timestamp - self->t_pr)/1000;
  self->t_pr = 0;
  etime_pr   = timestamp;
} 
 
pid$target::evapls:return /self->t_er != 0/ { 
  @CNT_ER[probefunc] = count(); 
  ttime_er   = ttime_er + (timestamp - self->t_er)/1000;
  self->t_er = 0;
  etime_er   = timestamp;
}  
 
pid$target::kgiPinObject:return /self->t_kp != 0/ { 
  @CNT_KP[probefunc] = count(); 
  ttime_kp   = ttime_kp + (timestamp - self->t_kp)/1000;
  self->t_kp = 0;
  etime_kp   = timestamp;
}  
 
END { 
  /** plsql_run **/
  printa("\n%s    Count = %@d"     ,@CNT_SR);  
  printf(", Total_time (ms) = %d"  ,ttime_sr/1000);
  printf(", Elpased (ms) = %d\n"   ,(etime_sr - stime_sr)/1000000);
  
  /** pfrrun **/
  printa("%s       Count = %@d"    ,@CNT_PR);  
  printf(", Total_time (ms) = %d"  ,ttime_pr/1000);
  printf(", Elpased (ms) = %d\n"   ,(etime_pr - stime_pr)/1000000);
  
  /** evapls **/
  printa("%s       Count = %@d"    ,@CNT_ER);
  printf("%s", ttime_er == 0 ? "evapls       Count = 0":"");   
  printf(", Total_time (ms) = %d"  ,ttime_er/1000);
  printf(", Elpased (ms) = %d\n"   ,(etime_er - stime_er)/1000000); 
  
  /** kgiPinObject **/
  printa("%s Count = %@d"       ,@CNT_KP);   
  printf(", Total_time (ms) = %d"  ,ttime_kp/1000);
  printf(", Elpased (ms) = %d\n"   ,(etime_kp - stime_kp)/1000000);  
}


7. References


(1). The Joy of Low Hanging Fruit, Part 2: the Dismay and the Delight Steven Feuerstein  

(2). Oracle 12c: PRAGMA UDF – the truth Kamil Stawiarski

(3). PL/SQL context switch Frits Hoogland
 
(4). Using DTrace to understand why PL/SQL packages can be faster than stored procedures Kamil Stawiarski

Tuesday, May 2, 2017

Oracle Datetime (6) - PLSQL Arithmetic

(1)-Concepts      (2)-Examples      (3)-Assignments      (4)-Comparisons      (5)-SQL Arithmetic      (6)-PLSQL Arithmetic


PLSQL Datetime Arithmetic operators include:
    (1) One operand is datetime, another is number of interval, for example, Addition
    (2) Both operands are datetime, for example, Subtraction
For each case, run the Test Code and look the Output.

1. Number and Interval Arithmetic


Run code below:

--------------- Test Code --------------- 

create or replace procedure test_arithmetic_plsql as
  l_timestp_base      TIMESTAMP;   
  l_timestp_ltz_base  TIMESTAMP WITH LOCAL TIME ZONE;
  l_timestp_tz_base   TIMESTAMP WITH TIME ZONE;
  
  l_timestp           TIMESTAMP;   
  l_timestp_ltz       TIMESTAMP WITH LOCAL TIME ZONE;
  l_timestp_tz        TIMESTAMP WITH TIME ZONE;
  l_intv              INTERVAL DAY TO SECOND;
  l_num               NUMBER;
  l_dump              varchar2(100);
begin
  l_num              := 5/1440;
  l_intv             := numtodsinterval(7,  'Minute');
  l_timestp_base     := to_timestamp('2017-04-05 02:52:00', 'yyyy-mm-dd hh24:mi:ss');
  l_timestp_ltz_base := (l_timestp_base at time zone sessiontimezone);
  l_timestp_tz_base  := to_timestamp_tz('2017-04-05 02:52:00 Europe/Zurich', 'yyyy-mm-dd hh24:mi:ss TZR TZD');
  
  dbms_output.put_line('------ 1. TIMESTAMP Arithmetics ------');
  l_timestp := l_timestp_base;
  
  dbms_output.put_line('l_timestp               = '||to_char(l_timestp, 'DD*MON*YYYY HH24:MI:SS TZR TZD'));
  select (dump(l_timestp, 1016)) into l_dump from dual;
  dbms_output.put_line('l_timestp DUMP          : '||l_dump);
  dbms_output.put_line('');
  
  l_timestp := l_timestp_base + l_num;
  dbms_output.put_line('l_timestp+l_num         = '||to_char(l_timestp, 'DD*MON*YYYY HH24:MI:SS TZR TZD'));
  select (dump((l_timestp), 1016)) into l_dump from dual;
  dbms_output.put_line('(l_timestp+l_num) DUMP  : '||l_dump); 
  dbms_output.put_line('');
  
  l_timestp := l_timestp_base + l_intv;
  dbms_output.put_line('l_timestp+l_intv        = '||to_char((l_timestp), 'DD*MON*YYYY HH24:MI:SS TZR TZD'));
  select (dump((l_timestp), 1016)) into l_dump from dual;
  dbms_output.put_line('(l_timestp+l_intv) DUMP : '||l_dump); 
  dbms_output.put_line(''); 
  
  dbms_output.put_line('------ 2. TIMESTAMP WITH LOCAL TIME ZONE Arithmetics ------');
  l_timestp_ltz := l_timestp_ltz_base;
  
  dbms_output.put_line('l_timestp_ltz               = '||to_char(l_timestp_ltz, 'DD*MON*YYYY HH24:MI:SS TZR TZD'));
  select (dump(l_timestp_ltz, 1016)) into l_dump from dual;
  dbms_output.put_line('l_timestp_ltz DUMP          : '||l_dump);
  dbms_output.put_line('');
  
  l_timestp_ltz := l_timestp_ltz_base+5/1440;
  dbms_output.put_line('l_timestp_ltz               = '||to_char((l_timestp_ltz), 'DD*MON*YYYY HH24:MI:SS TZR TZD'));
  select (dump((l_timestp_ltz), 1016)) into l_dump from dual;
  dbms_output.put_line('(l_timestp_ltz+l_num) DUMP  : '||l_dump); 
  dbms_output.put_line('');
  
  l_timestp_ltz := l_timestp_ltz_base+l_intv;
  dbms_output.put_line('l_timestp_ltz               = '||to_char((l_timestp_ltz), 'DD*MON*YYYY HH24:MI:SS TZR TZD'));
  select (dump((l_timestp_ltz), 1016)) into l_dump from dual;
  dbms_output.put_line('(l_timestp_ltz+l_intv) DUMP : '||l_dump); 
  dbms_output.put_line('');   
  
  dbms_output.put_line('------ 3. TIMESTAMP WITH TIME ZONE Arithmetics ------');
  l_timestp_tz := l_timestp_tz_base;
  
  dbms_output.put_line('l_timestp_tz               = '||to_char(l_timestp_tz, 'DD*MON*YYYY HH24:MI:SS TZR TZD'));
  select (dump(l_timestp_tz, 1016)) into l_dump from dual;
  dbms_output.put_line('l_timestp_tz DUMP          : '||l_dump);
  dbms_output.put_line('');
  
  l_timestp_tz := l_timestp_tz_base+5/1440;
  dbms_output.put_line('l_timestp_tz               = '||to_char((l_timestp_tz), 'DD*MON*YYYY HH24:MI:SS TZR TZD'));
  select (dump((l_timestp_tz), 1016)) into l_dump from dual;
  dbms_output.put_line('(l_timestp_tz+l_num) DUMP  : '||l_dump); 
  dbms_output.put_line('');
  
  l_timestp_tz := l_timestp_tz_base+l_intv;
  dbms_output.put_line('l_timestp_tz               = '||to_char((l_timestp_tz), 'DD*MON*YYYY HH24:MI:SS TZR TZD'));
  select (dump((l_timestp_tz), 1016)) into l_dump from dual;
  dbms_output.put_line('(l_timestp_tz+l_intv) DUMP : '||l_dump); 
  dbms_output.put_line('');  
end;
/

alter session set time_zone = 'Europe/Zurich';

exec test_arithmetic_plsql;

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

  ------ 1. TIMESTAMP Arithmetics ------
  l_timestp               = 05*APR*2017 02:52:00 +00:00
  l_timestp DUMP          : Typ=180 Len=7: 78,75,4,5,3,35,1
  
  l_timestp+l_num         = 05*APR*2017 02:57:00 +00:00
  (l_timestp+l_num) DUMP  : Typ=180 Len=7: 78,75,4,5,3,3a,1
  
  l_timestp+l_intv        = 05*APR*2017 02:59:00 +00:00
  (l_timestp+l_intv) DUMP : Typ=180 Len=7: 78,75,4,5,3,3c,1
  
  ------ 2. TIMESTAMP WITH LOCAL TIME ZONE Arithmetics ------
  l_timestp_ltz               = 05*APR*2017 02:52:00 EUROPE/ZURICH CEST
  l_timestp_ltz DUMP          : Typ=231 Len=7: 78,75,4,5,2,35,1
  
  l_timestp_ltz               = 05*APR*2017 02:57:00 EUROPE/ZURICH CEST
  (l_timestp_ltz+l_num) DUMP  : Typ=231 Len=7: 78,75,4,5,2,3a,1
  
  l_timestp_ltz               = 05*APR*2017 02:59:00 EUROPE/ZURICH CEST
  (l_timestp_ltz+l_intv) DUMP : Typ=231 Len=7: 78,75,4,5,2,3c,1
  
  ------ 3. TIMESTAMP WITH TIME ZONE Arithmetics ------
  l_timestp_tz               = 05*APR*2017 02:52:00 EUROPE/ZURICH CEST
  l_timestp_tz DUMP          : Typ=181 Len=13: 78,75,4,5,1,35,1,0,0,0,0,86,58
  
  l_timestp_tz               = 05*APR*2017 02:57:00 EUROPE/ZURICH CEST
  (l_timestp_tz+l_num) DUMP  : Typ=181 Len=13: 78,75,4,5,1,3a,1,0,0,0,0,86,58
  
  l_timestp_tz               = 05*APR*2017 02:59:00 EUROPE/ZURICH CEST
  (l_timestp_tz+l_intv) DUMP : Typ=181 Len=13: 78,75,4,5,1,3c,1,0,0,0,0,86,58

Contrary to SQL Arithmetic (see previous Blog), PLSQL keeps the same datatype for both arithmetic wiht NUMBER and INTERVAL.


2. Substract Arithmetic


Note 2017-03-26 [02:00 03:00) 'Europe/Zurich' is DST transit time.

Run code below:

--------------- Test Code --------------- 

create or replace procedure test_subtract_plsql as
  -- 2017-03-26 [02:00, 03:00) DST transit time
  l_a1              varchar2(100) := '2017-03-26 01:52:00'; 
  l_a2              varchar2(100) := '2017-03-26 03:55:00';
  l_timestp_a1      TIMESTAMP;   
  l_timestp_a2      TIMESTAMP;   
  l_timestp_ltz_a1  TIMESTAMP WITH LOCAL TIME ZONE;
  l_timestp_ltz_a2  TIMESTAMP WITH LOCAL TIME ZONE;
  l_timestp_tz_a1   TIMESTAMP WITH TIME ZONE;
  l_timestp_tz_a2   TIMESTAMP WITH TIME ZONE;
  
  l_timestp_ltz_b1  TIMESTAMP WITH LOCAL TIME ZONE;
  l_timestp_ltz_b2  TIMESTAMP WITH LOCAL TIME ZONE;
  l_interval        INTERVAL DAY TO SECOND;
  l_dump            varchar2(50);
begin
  dbms_output.put_line('a1 = '||l_a1); 
  dbms_output.put_line('a2 = '||l_a2); 
  dbms_output.put_line('');
  
  l_timestp_a1     := to_timestamp(l_a1, 'yyyy-mm-dd hh24:mi:ss');
  l_timestp_a2     := to_timestamp(l_a2, 'yyyy-mm-dd hh24:mi:ss');
  
  l_timestp_ltz_a1 := l_timestp_a1;
  l_timestp_ltz_a2 := l_timestp_a2;
  
  l_timestp_tz_a1  := to_timestamp_tz(l_a1||' Europe/Zurich CET',  'yyyy-mm-dd hh24:mi:ss TZR TZD');
  l_timestp_tz_a2  := to_timestamp_tz(l_a2||' Europe/Zurich CEST', 'yyyy-mm-dd hh24:mi:ss TZR TZD');
  
  dbms_output.put_line('------ l_timestp_a2 - l_timestp_a1 ------');
  l_interval := l_timestp_a2 - l_timestp_a1;
  dbms_output.put_line('TIMESTAMP Subtract = '||l_interval); 
  dbms_output.put_line('');
  
  dbms_output.put_line('------ l_timestp_ltz_a2 - l_timestp_ltz_a1 ------');
  l_interval := l_timestp_ltz_a2 - l_timestp_ltz_a1;
  dbms_output.put_line('LOCAL TIME ZONE (a2 - a1) = '||l_interval);
  
  dbms_output.put_line('  a1 = '||to_char(l_timestp_ltz_a1,'DD*MON*YYYY HH24:MI:SS TZR TZD'));
  select (dump(l_timestp_ltz_a1, 1016)) into l_dump from dual;
  dbms_output.put_line('     a1 Dump : '||l_dump);
  
  dbms_output.put_line('  a2 = '||to_char(l_timestp_ltz_a2,'DD*MON*YYYY HH24:MI:SS TZR TZD'));
  select (dump(l_timestp_ltz_a2, 1016)) into l_dump from dual;
  dbms_output.put_line('     a2 Dump : '||l_dump);
  
  select (dump(l_interval, 1016)) into l_dump from dual;
  dbms_output.put_line('  (a2 - a1) Dump : '||l_dump);
  dbms_output.put_line('');
  
  dbms_output.put_line('------ l_timestp_ltz_b2 - l_timestp_ltz_b1 by TSZ assign ------');
  l_timestp_ltz_b1  := l_timestp_tz_a1;
  l_timestp_ltz_b2  := l_timestp_tz_a2;
  l_interval        := l_timestp_ltz_b2 - l_timestp_ltz_b1;
  dbms_output.put_line('LOCAL TIME ZONE by TZ Assign (b2 - b1) = '||l_interval);
  
  dbms_output.put_line('  b1 = '||to_char(l_timestp_ltz_b1,'DD*MON*YYYY HH24:MI:SS TZR TZD'));
  select (dump(l_timestp_ltz_b1, 1016)) into l_dump from dual;
  dbms_output.put_line('     b1 Dump : '||l_dump);
  
  dbms_output.put_line('  b2 = '||to_char(l_timestp_ltz_b2,'DD*MON*YYYY HH24:MI:SS TZR TZD'));
  select (dump(l_timestp_ltz_b2, 1016)) into l_dump from dual;
  dbms_output.put_line('     b2 Dump : '||l_dump);
  
  select (dump(l_interval, 1016)) into l_dump from dual;
  dbms_output.put_line('  (b2 - b1) Dump : '||l_dump); 
  dbms_output.put_line('');
  
  dbms_output.put_line('------ l_timestp_ltz_a1 - l_timestp_ltz_b1, l_timestp_ltz_a2 - l_timestp_ltz_b2 ------');
  l_interval := l_timestp_ltz_a1 - l_timestp_ltz_b1;
  dbms_output.put_line('(a1 - b1) = '||l_interval);
  select (dump(l_interval, 1016)) into l_dump from dual;
  dbms_output.put_line('    (a1 - b1) Dump : '||l_dump);
  
  l_interval := l_timestp_ltz_a2 - l_timestp_ltz_b2;
  dbms_output.put_line('(a2 - b2) = '||l_interval);
  select (dump(l_interval, 1016)) into l_dump from dual;
  dbms_output.put_line('    (a2 - b2) Dump : '||l_dump);
  dbms_output.put_line('');
  
  dbms_output.put_line('------ l_timestp_tz_a2 - l_timestp_tz_a1 ------');
  l_interval := l_timestp_tz_a2 - l_timestp_tz_a1;
  dbms_output.put_line('TIME ZONE (a2 - a1) = '||l_interval);
  dbms_output.put_line(''); 
  
  dbms_output.put_line('------ l_timestp_tz_a2 - l_timestp_tz_a1 by TLZ assign ------');
  l_timestp_tz_a1  := l_timestp_ltz_a1;
  l_timestp_tz_a2  := l_timestp_ltz_a2;
  l_interval := l_timestp_tz_a2 - l_timestp_tz_a1;
  dbms_output.put_line('TIME ZONE by Local Assign (a2 - a1) = '||l_interval);
  
  dbms_output.put_line('  a1 = '||to_char(l_timestp_tz_a1,'DD*MON*YYYY HH24:MI:SS TZR TZD'));
  dbms_output.put_line('  a2 = '||to_char(l_timestp_tz_a2,'DD*MON*YYYY HH24:MI:SS TZR TZD'));  
end;
/

alter session set time_zone = 'Europe/Zurich';
exec test_subtract_plsql;

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

  a1 = 2017-03-26 01:52:00
  a2 = 2017-03-26 03:55:00
  
  ------ l_timestp_a2 - l_timestp_a1 ------
  TIMESTAMP Subtract = +00 02:03:00.000000
  
  ------ l_timestp_ltz_a2 - l_timestp_ltz_a1 ------
  LOCAL TIME ZONE (a2 - a1) = +00 02:03:00.000000
    a1 = 26*MAR*2017 01:52:00 EUROPE/ZURICH CET
       a1 Dump : Typ=231 Len=7: 78,75,3,1a,2,35,1
    a2 = 26*MAR*2017 03:55:00 EUROPE/ZURICH CEST
       a2 Dump : Typ=231 Len=7: 78,75,3,1a,3,38,1
    (a2 - a1) Dump : Typ=183 Len=11: 80,0,0,0,3e,3f,3c,80,0,0,0
  
  ------ l_timestp_ltz_b2 - l_timestp_ltz_b1 by TSZ assign ------
  LOCAL TIME ZONE by TZ Assign (b2 - b1) = +00 01:03:00.000000
    b1 = 26*MAR*2017 01:52:00 EUROPE/ZURICH CET
       b1 Dump : Typ=231 Len=7: 78,75,3,1a,2,35,1
    b2 = 26*MAR*2017 03:55:00 EUROPE/ZURICH CEST
       b2 Dump : Typ=231 Len=7: 78,75,3,1a,3,38,1
    (b2 - b1) Dump : Typ=183 Len=11: 80,0,0,0,3d,3f,3c,80,0,0,0
  
  ------ l_timestp_ltz_a1 - l_timestp_ltz_b1, l_timestp_ltz_a2 - l_timestp_ltz_b2
  (a1 - b1) = +00 00:00:00.000000
      (a1 - b1) Dump : Typ=183 Len=11: 80,0,0,0,3c,3c,3c,80,0,0,0
  (a2 - b2) = +00 00:00:00.000000
      (a2 - b2) Dump : Typ=183 Len=11: 80,0,0,0,3c,3c,3c,80,0,0,0
  
  ------ l_timestp_tz_a2 - l_timestp_tz_a1 ------
  TIME ZONE (a2 - a1) = +00 01:03:00.000000
  
  ------ l_timestp_tz_a2 - l_timestp_tz_a1 by TLZ assign ------
  TIME ZONE by Local Assign (a2 - a1) = +00 01:03:00.000000
    a1 = 26*MAR*2017 01:52:00 EUROPE/ZURICH CET
    a2 = 26*MAR*2017 03:55:00 EUROPE/ZURICH CEST

Above output shows that
  (a2 - a1) = +00 02:03:00.000000
  (b2 - b1) = +00 01:03:00.000000
although
  (a1 - b1) = +00 00:00:00.000000
  (a2 - b2) = +00 00:00:00.000000
and their dumps also confirmed the equivalence.