Sunday, April 8, 2018

Blog List

TM lock and no transaction commit

Oracle Document wrote:
COMMIT
  Use the COMMIT statement to end your current transaction and make permanent all changes performed in the transaction. 
  A transaction is a sequence of SQL statements that Oracle Database treats as a single unit. 
  This statement also erases all savepoints in the transaction and releases transaction locks.

ROLLBACK
  Use the ROLLBACK statement to undo work done in the current transaction or to manually undo the work done by an in-doubt distributed transaction.
It looks like that COMMIT / ROLLBACK are for transactions.

This Blog will show that COMMIT / ROLLBACK has to be executed even without any transactions.

The test code is also trying to reproduce and study MOS:
    Bug 26965236 : DELETE FROM TSDP_SENSITIVE_DATA$ CAUSING ENQ: TM - CONTENTION WAITS

Note: All tests are done in Oracle 12.1.0.2.

------------------ T0: Test SetUp ------------------ 
drop table tt1;

create table tt1 (x number, c1 number, c2 number);

------------------ T1: Session_1------------------ 
SQL(sid 190) > delete from sys.tsdp_sensitive_data$ where 1=2; 
  0 rows deleted.

------------------ T2: Session_2 ------------------ 
SQL(sid 290) > alter table tt1 drop column c2;

-- Session 290 hanging, blocked by 190.
-- same for   alter table k.tt1 set unused (c1);

------------------ T3: Monitor Session_3 ------------------ 
SQL(sid 390) > select o.object_name, k.* from v$lock k, dba_objects o where k.type in ('TM') and k.ID1 = o.object_id;
 
  OBJECT_NAME                    SID  TYPE  ID1      ID2  LMODE  REQUEST  CTIME  BLOCK
  -----------------------------  ---  ----  -------  ---  -----  -------  -----  -----
  TSDP_SENSITIVE_DATA$           190  TM    1576498  0    3      0        14     0    
  TSDP_SUBPOL$                   190  TM    1578689  0    3      0        14     0    
  TSDP_PROTECTION$               190  TM    1578695  0    3      0        14     1    
  TT1                            290  TM    2321087  0    6      0        9      0    
  WRI$_OPTSTAT_HISTHEAD_HISTORY  290  TM    601844   0    3      0        9      0    
  WRI$_OPTSTAT_HISTGRM_HISTORY   290  TM    601856   0    3      0        9      0    
  COM$                           290  TM    136      0    3      0        9      0    
  COL_USAGE$                     290  TM    456      0    3      0        9      0    
  OBJAUTH$                       290  TM    61       0    3      0        9      0    
  TSDP_SENSITIVE_DATA$           290  TM    1576498  0    3      0        9      0    
  TSDP_SUBPOL$                   290  TM    1578689  0    3      0        9      0    
  TSDP_PROTECTION$               290  TM    1578695  0    0      5        9      0    

--TSDP_PROTECTION$  REQUEST = 5
--Session_2 blocked by Session_1 in 'enq: TM - contention' Lock Mode 5 (SSX/SRX)

SQL(sid 390) > select * from v$transaction;
  0 rows selected.
  
  -- no TRX

SQL(sid 390) > select chain_signature, sid, blocker_sid, wait_event_text, p1, p1_text, p2, p2_text, p3, p3_text from v$wait_chains;

  CHAIN_SIGNATURE                                        SID  BLOCKER_SID  WAIT_EVENT_TEXT              P1          P1_TEXT    P2       P2_TEXT   P3  P3_TEXT
  -----------------------------------------------------  ---  -----------  ---------------------------  ----------  ---------  -------  --------  --  ---------------
  'SQL*Net message from client'<='enq: TM - contention'  290  190          enq: TM - contention         1414332421  name|mode  1578695  object #  0   table/partition
  'SQL*Net message from client'<='enq: TM - contention'  190               SQL*Net message from client  1413697536  driver id  1        #bytes    0


SQL(sid 390) > select * from dba_constraints where constraint_name = 'TSDP_PROTECTION$FKSD';

  OWNER  CONSTRAINT_NAME       CONSTRAINT_TYPE  TABLE_NAME        R_CONSTRAINT_NAME       DELETE_RULE  STATUS
  -----  --------------------  ---------------  ----------------  ----------------------  -----------  ------
  SYS    TSDP_PROTECTION$FKSD  R                TSDP_PROTECTION$  TSDP_SENSITIVE_DATA$PK  CASCADE      ENABLED


-- Suspending LGWR will not block commit in Session_1
--SQL> oradebug setorapid 13
--  Oracle pid: 13, Unix process pid: 18482, image: oracle@testdb (LGWR)
--SQL> oradebug suspend
--SQL> oradebug resume

------------------ T4: Session_1, Release TM Locks to deblock ------------------ 
SQL(sid 290) > commit;
One quick workaround is to disable the foreign key constraint if Transparent Sensitive Data Protection is not used.

  alter table sys.tsdp_protection$ disable constraint tsdp_protection$fksd;
If we suspend LGWR in Session_3 (see commented-out code), and repeat the whole test, the "commit" in Session_1 will not be blocked. It indicates no "commit record" written to redo log for this "commit" execution, in other words, not every "commit" generates a "commit record".

With event 10704, we can list all triggered TM Locks. (see Blog: Investigating Oracle lock issues with event 10704 )

SQL(sid 290) > alter session set events='10046 trace name context forever, level 1 : 10704 trace name context forever, level 3' tracefile_identifier='ForeignKey';

SQL(sid 290) > alter table tt1 drop column c1;

SQL(sid 290) > alter session set events='10046 trace name context off : 10704 trace name context off ';


ksqgtl *** TM-00236ABF-00000000-00000000-00000000 mode=6 flags=0x400 timeout=5 ***
...
ksqgtl *** TM-001816C7-00000000-00000000-00000000 mode=5 flags=0x400 timeout=21474836 ***
ksqcnv: TM-001816C7-00000000-00000000-00000000 mode=3 timeout=21474836
ksqcmi: TM-001816C7-00000000-00000000-00000000 mode=3 timeout=21474836
ksqrcl: TM-001816C7-00000000-00000000-00000000
...
ksqrcl: TM-00236ABF-00000000-00000000-00000000

  -- 00236ABF (2321087) = TT1
  -- 001816C7 (1578695) = SYS.TSDP_PROTECTION$
  
  -- ksqgtl: get lock 
  -- ksqcnv: convert lock
  -- ksqcmi: 
  -- ksqrcl: release lock
We can see that DDL_LOCK_TIMEOUT = 5 seconds has no effect in this case (line with "TM-00236ABF" for TT1). TM lock on SYS.TSDP_PROTECTION$ ("TM-001816C7") is first obtained in MODE 5 (SRX), then converted to 3 (RX).

Tuesday, March 6, 2018

'enq: RO - fast object reuse' and 'enq: KO - fast object checkpoint' Final Blocker

In Wait Event: 'enq: RO - fast object reuse' and 'enq: KO - fast object checkpoint', CKPT is shown as final_blocking_session when one DBWR is suspended.

V$ENQUEUE_STATISTICS gives detailed information (several rows for same enqueues with different reasons) and statistics.

select * from v$enqueue_statistics where eq_type in ('RO', 'KO');

EQ_NAME                    EQ REQ_REASON             TOTAL_REQ# TOTAL_WAIT# SUCC_REQ# FAILED_REQ# CUM_WAIT_TIME REQ_DESCRIPTION                         
-------------------------- -- ---------------------- ---------- ----------- --------- ----------- ------------- ----------------------------------------
Multiple Object Reuse      RO fast object reuse           1,039          82     1,038           0     1,040,219 Coordinates fast object reuse
Multiple Object Reuse      RO contention                      0           0         0           0             0 Coordinates flushing of multiple objects   
Multiple Object Checkpoint KO fast object checkpoint         60           6        60           0       870,104 Coordinates fast object checkpoint        
Reuse Block Range          CR block range reuse ckpt      1,848          15     1,848           0            20 Coordinates fast block range reuse ckpt
If (TOTAL_REQ# - SUCC_REQ# > 0 and FAILED_REQ# = 0), there exists on-going EQ requests.

Note: All tests are done in Oracle 12.1.0.2 on Solaris.


1. Test Setup



--Test DB is configured with:
--  db_writer_processes=2
   
drop table tab1;

create table tab1 as select level x, rpad('ABC', 100, 'X') y from dual connect by level < 1000000; 


2. 'enq: KO - fast object checkpoint' Test


Suspend one of DB WRITERs, for example, DBW1:

SQL> oradebug setorapid 12
Oracle pid: 12, Unix process pid: 19980, image: oracle@s5d00003 (DBW1)
SQL> oradebug suspend
Statement processed.
Run query:

SQL (543) > select /*+ parallel(t 4) */ count(*) from tab1 t where x < 100000;
Both blocker_sid and final_blocking_session are same, that is, CKPT (SID: 361):

SQL (123) > select c.chain_id, c.chain_signature, c.sid, c.blocker_sid bsid, final_blocking_session final_bsid, s.program, s.sql_id, s.event
            from v$wait_chains c, v$session s
            where c.sid = s.sid order by c.chain_id, s.program;

CHAIN_ID CHAIN_SIGNATURE                                         SID BSID FINAL_BSID PROGRAM     SQL_ID        EVENT
-------- ------------------------------------------------------- --- ---- ---------- ----------- ------------- -------------------------------
       1 'rdbms ipc message'<='enq: KO - fast object checkpoint' 361                 (CKPT)                    rdbms ipc message
       1 'rdbms ipc message'<='enq: KO - fast object checkpoint' 543 361         361 sqlplus.exe 4wwzmhypuvnc6 enq: KO - fast object checkpoint

SQL (123) > select sql_id, executions, substr(sql_text, 1, 60) sql_text from v$sql v where sql_id = '4wwzmhypuvnc6';

SQL_ID        EXECUTIONS SQL_TEXT
------------- ---------- ------------------------------------------------------------
4wwzmhypuvnc6          0 select /*+ parallel(t 4) */ count(*) from tab1 t where x < 1
After test, resume DBW1:

SQL> oradebug resume
By the way, to make above behavior repeatable, each time tab1 has to be dropped and recreated.


3. 'enq: RO - fast object reuse' Test


Again suspend DBW1:

SQL> oradebug setorapid 12
Oracle pid: 12, Unix process pid: 19980, image: oracle@s5d00003 (DBW1)
SQL> oradebug suspend
Statement processed.
Run statement:

SQL (543) > truncate table tab1;
Both blocker_sid and final_blocking_session are same, that is, CKPT (SID: 361):

SQL (123) > select c.chain_id, c.chain_signature, c.sid, c.blocker_sid bsid, final_blocking_session final_bsid, s.program, s.sql_id, s.event
            from v$wait_chains c, v$session s
            where c.sid = s.sid order by c.chain_id, s.program;
            
CHAIN_ID CHAIN_SIGNATURE                                    SID BSID FINAL_BSID PROGRAM     SQL_ID        EVENT
-------- -------------------------------------------------- --- ---- ---------- ----------- ------------- ---------------------------
       1 'rdbms ipc message'<='enq: RO - fast object reuse' 361                 (CKPT)                    rdbms ipc message
       1 'rdbms ipc message'<='enq: RO - fast object reuse' 543  361        361 sqlplus.exe 83w7b0h5ug6ph enq: RO - fast object reuse  
       
SQL (123) > select sql_id, executions, substr(sql_text, 1, 60) sql_text from v$sql v where sql_id = '83w7b0h5ug6ph';         

SQL_ID        EXECUTIONS SQL_TEXT
------------- ---------- -------------------
83w7b0h5ug6ph          0 truncate table tab1     
After test, resume DBW1:

SQL> oradebug resume  
By the way, we observed: "enq: CR - block range reuse ckpt", also blocked by CKPT, when running PL/SQL bulk SQL "forall insert into values".


4. FINAL_BLOCKING_SESSION


In both above tests, CKPT is shown as final_blocking_session, but in reality, that is DBW1 suspended. The reason is probably because Foreground process only communicates with CKPT, and has no direct IPC call of DB WRITER processes.

Oracle MOS documented this behavior:
    MOS Resolving Issues Where 'enq: RO - fast object reuse' Contention Seen During Drop or Truncate Operations (Doc ID 1475659.1)
The RO enqueue known as "Multiple object reuse" enqueue, is used to synchronise operations between foreground process 
and a background process such as DBWR or CKPT. It is typically used when dropping objects or truncating tables.
Following is the sequence of events When a truncate/drop occurs:
  1.Foreground process acquires the "RO" enqueue in exclusive mode
  2.Cross instance calls (or one call if it is a single object) are issued ("CI" enqueue is acquired)
  3.CKPT Processes on each of instances requests the DBWR to write the dirty buffers to the disk and invalidate all the clean buffers.
  4.After DBWR completes writing all blocks, the foreground process releases the RO enqueue.


5. Discussions


KO enqueue is triggered by SELECT table FULL scan, which requires writing all dirty buffer blocks into disk datafiles and updating Extent Bitmap in Segment Header Extent.

RO enqueue is triggered by TRUNCATE table, which requires cleaning up (write) segment header (bitmap info), that is the 2nd Block (Extent Bitmap) in Segment Header Extent for small table.

When both enqueues appear in top Wait Events, following Events can be also observed:
  free buffer waits
  buffer busy waits
  local write wait
  write complete waits
For "free buffer waits", P3 (set-id#) reveals the responsible DBWR.

Blog: ASSM Truncate demonstrated RO enqueue when truncating table with big "INITIAL", and explained that the blocks written were the space management bitmap blocks for the extent(s) that remained after the truncate (storage_clause "INITIAL" specifies the size of the first extent of the object. Oracle allocates space for this extent when you create the schema object).


6. row cache lock


In 'enq: RO - fast object reuse' Test, if we open one more Sqlplus Session (SID=726) and perform the same tab1 truncate, we observe "row cache lock" with "cache id = 8" (dc_objects/dc_object_grants).

drop table tab1;
create table tab1 as select level x, rpad('ABC', 100, 'X') y from dual connect by level < 1000000; 

SQL> oradebug setorapid 12
Oracle pid: 12, Unix process pid: 19980, image: oracle@s5d00003 (DBW1)
SQL> oradebug suspend
Statement processed.

SQL (543) > truncate table tab1;

SQL (726) > truncate table tab1;

select c.wait_event_text, c.sid, c.blocker_sid bsid, s.final_blocking_session final_bsid, 
       s.program, s.sql_id, s.p1text, s.p1, s.p2text, s.p2, s.p3text, s.p3
from v$wait_chains c, v$session s
where c.sid = s.sid order by c.chain_id, s.program;

WAIT_EVENT_TEXT             SID BSID FINAL_BSID PROGRAM      SQL_ID        P1TEXT               P1  P2TEXT      P2  P3TEXT  P3
--------------------------- --- ---- ---------- ------------ ------------- --------- -------------  ------  ------  ------  --
rdbms ipc message           361                  (CKPT)                    timeout             300              0            0
row cache lock              726  543        361  sqlplus.exe 83w7b0h5ug6ph cache id              8  mode        0   request  3
enq: RO - fast object reuse 543  361        361  sqlplus.exe 83w7b0h5ug6ph name|mode 1,380,909,062  2       65,563  0        1
If we create one second table (tab2), and let new Sqlplus Session (SID=726) truncate tab2, both sessions are on "enq: RO - fast object reuse", no more "row cache lock" observed.

drop table tab1;
create table tab1 as select level x, rpad('ABC', 100, 'X') y from dual connect by level < 1000000; 

drop table tab2;
create table tab2 as select level x, rpad('ABC', 100, 'X') y from dual connect by level < 1000000; 

SQL> oradebug setorapid 12
Oracle pid: 12, Unix process pid: 19980, image: oracle@s5d00003 (DBW1)
SQL> oradebug suspend
Statement processed.

SQL (543) > truncate table tab1;

SQL (726) > truncate table tab2;

select c.wait_event_text, c.sid, c.blocker_sid bsid, s.final_blocking_session final_bsid, 
       s.program, s.sql_id, s.p1text, s.p1, s.p2text, s.p2, s.p3text, s.p3
from v$wait_chains c, v$session s
where c.sid = s.sid order by c.chain_id, s.program;

WAIT_EVENT_TEXT             SID BSID FINAL_BSID PROGRAM      SQL_ID        P1TEXT               P1  P2TEXT      P2  P3TEXT  P3
--------------------------- --- ---- ---------- ------------ ------------- --------- -------------  ------  ------  ------  --
rdbms ipc message           361                  (CKPT)                    timeout             300              0            0
enq: RO - fast object reuse 543  361        361  sqlplus.exe 83w7b0h5ug6ph name|mode 1,380,909,062  2       65,563  0        1
enq: RO - fast object reuse 726  361        361  sqlplus.exe 2wdshw3gfd81s name|mode 1,380,909,062  2       65,564  0        1

select sql_id, executions, substr(sql_text, 1, 60) sql_text 
from v$sql v where sql_id in ('83w7b0h5ug6ph', '2wdshw3gfd81s');

SQL_ID        EXECUTIONS SQL_TEXT
------------- ---------- -------------------
2wdshw3gfd81s          0 truncate table tab2
83w7b0h5ug6ph          0 truncate table tab1

Oracle 12.1 Wait Event: 'log file sync: SCN ordering' Demo

Oracle MOS Document:
         What is the Difference Between 'log File Sync: SCN Ordering' and 'log File Sync' (Doc ID 2363231.1)
    Log file sync: SCN ordering is a new wait event introduced in 12.1.
    
    This wait event is triggered when an operation such as a direct path load compares the current SCN against the last on-disk commit SCN.
      
    Before an SCN can be written to a datafile, a check is performed to ensure that an SCN larger than 
    the SCN needed to maintain "crash delta" has already been written to redo.
      
    If the check determines that the SCN to be written to the datafile is greater than that currently needed in the redo logs, 
    LGWR will be posted to force some redo to disk, independent of a commit.
      
    If no actual redo with an appropriate SCN is available in the log buffer, it is possible that an empty redo record may be written 
    to the redo logs to satisfy the need to have the higher SCN.
      
    Prior to 12.1, the time spent waiting for redo being written by LGWR for this purpose was included in the main "log file sync" wait.
    
    Starting in 12.1, it is now tracked separately as "log file sync: SCN ordering". It was separated out 
    because it is not related to transaction commit wait for log file write.
In short, 'log File Sync: SCN Ordering' is 'log File Sync' not triggered by transaction commit.
There exists one non-commit SCN to be written to a datafile, which is bigger than last LGWR SCN.
LGWR is in charge of sequentially ("ordering") writing all SCN between last LGWR SCN and non-commit SCN to Redo Log.

In this Blog, we will try to demonstrate Wait Event: 'log file sync: SCN ordering' without any COMMIT (ROLLBACK) statements.

Note: All tests are done in Oracle 12.1.0.2 on Solaris with 6 CPUs.


1. Test


Test DB is configured as:
   shared_pool_size=1408M
   log_buffer=128M       (note: real allocated is 140M)
   db_cache_size=2000M
   db_writer_processes=2
   cpu_count=6
Launch Test (see appended Test Code):

exec test_upd_no_commit_job(4);
exec test_load_as_select_job(2);
When all 6 Jobs are visible in dba_jobs_running, we can see 6 transactions, 2 of which are select statements with materialized subquery factoring clause (WITH clause).

SQL > select s.sid, s.program, s.sql_id, t.addr, t.status, t.start_time, t.start_scn 
      from v$transaction t, v$session s where t.addr = s.taddr order by s.program;

SID  PROGRAM               SQL_ID         ADDR              STATUS  START_TIME                   START_SCN
---  --------------------  -------------  ----------------  ------  -------------------  -----------------
 15  oracle@testdb (J000)  5h3nqwh6fdw66  0000000184EBA498  ACTIVE  2018-03-06 07:17:16  9,332,237,391,411
727  oracle@testdb (J001)  a3376g221j75v  0000000184FA3B38  ACTIVE  2018-03-06 07:31:22  9,332,237,491,530
370  oracle@testdb (J002)  5h3nqwh6fdw66  0000000184EBBBD8  ACTIVE  2018-03-06 07:17:16  9,332,237,391,419
549  oracle@testdb (J003)  5h3nqwh6fdw66  0000000186A2C818  ACTIVE  2018-03-06 07:17:16  9,332,237,391,757
192  oracle@testdb (J004)  a3376g221j75v  0000000184FA46D8  ACTIVE  2018-03-06 07:31:22  9,332,237,491,538
545  oracle@testdb (J005)  5h3nqwh6fdw66  0000000186BB3778  ACTIVE  2018-03-06 07:17:16  9,332,237,392,203
  
SQL > select sql_id, executions, substr(sql_text, 1, 50) sql_text 
      from v$sql where sql_id in ('a3376g221j75v', '5h3nqwh6fdw66');

SQL_ID        EXECUTIONS  SQL_TEXT
------------- ----------- --------------------------------------------------
a3376g221j75v      11,254 WITH SQ1 AS (SELECT /*+ materialize */ LEVEL X FRO
5h3nqwh6fdw66     392,362 UPDATE TEST_TAB SET VAL = 'Upd_'||:B2 WHERE ID = :  
Suspend LGWR:

SQL> oradebug setorapid 13
Oracle pid: 13, Unix process pid: 18482, image: oracle@testdb (LGWR)
SQL> oradebug suspend
after about 10 minutes, we can see blocking chains:

select c.chain_id, c.chain_signature, c.sid, c.blocker_sid bsid, final_blocking_session final_bsid, s.program, s.sql_id, s.event
from v$wait_chains c, v$session s
where c.sid = s.sid order by c.chain_id, s.program;

CHAIN_ID CHAIN_SIGNATURE                                                         SID  BSID  FINAL_BSID PROGRAM SQL_ID        EVENT
-------- ----------------------------------------------------------------------- ---- ----- ---------- ------- ------------ ---------------------------
       1 'rdbms ipc message'<='log file sync'                                       8 181          181 (J010)               log file sync
       1 'rdbms ipc message'<='log file sync'                                     181                  (LGWR)               rdbms ipc message
       2 'rdbms ipc message'<='log file sync: SCN ordering'<='buffer busy waits'   15 545          181 (J000) 5h3nqwh6fdw66 buffer busy waits
       2 'rdbms ipc message'<='log file sync: SCN ordering'<='buffer busy waits'  545 181          181 (J005) 5h3nqwh6fdw66 log file sync: SCN ordering
       3 'rdbms ipc message'<='log file sync'                                     189 181          181 (J011)               log file sync
       4 'rdbms ipc message'<='log file sync: SCN ordering'                       192 181          181 (J004) a3376g221j75v log file sync: SCN ordering
       5 'rdbms ipc message'<='log file sync: SCN ordering'<='buffer busy waits'  370 545          181 (J002) 5h3nqwh6fdw66 buffer busy waits
       6 'rdbms ipc message'<='log file sync'                                     548 181          181 (J007)               log file sync
       7 'rdbms ipc message'<='log file sync: SCN ordering'<='buffer busy waits'  549 545          181 (J003) 5h3nqwh6fdw66 buffer busy waits
       8 'rdbms ipc message'<='log file sync: SCN ordering'<='buffer busy waits'  719 545          181 (SMON)               buffer busy waits
       9 'rdbms ipc message'<='log file sync'                                     726 181          181 (J008)               log file sync
      10 'rdbms ipc message'<='log file sync: SCN ordering'                       727 181          181 (J001) a3376g221j75v log file sync: SCN ordering
      11 'rdbms ipc message'<='log file sync'                                     899 181          181 (J006)               log file sync
      12 'rdbms ipc message'<='log file sync'                                     903 181          181 (J009)               log file sync
Look 'sync scn':
                                                                                                           
select distinct * from (
  select event, min(p2) over (partition by event) min_scn, max(p2) over (partition by event) max_scn
  from v$session 
  where p2text = 'sync scn' and event in ('log file sync',  'log file sync: SCN ordering')
) order by min_scn;

EVENT                             MIN_SCN        MAX_SCN
--------------------------- -------------  -------------
log file sync               3,568,537,824  3,568,549,488
log file sync: SCN ordering 3,568,549,406  3,568,549,406
which shows that SCN of 'log file sync: SCN ordering' falls between min and max SCN of 'log file sync' (3,568,537,824 < 3,568,549,406 < 3,568,549,488), in other words, there exists one SCN of 'log file sync' which is smaller than that of 'log file sync: SCN ordering' and one SCN of 'log file sync' which is bigger than that of 'log file sync: SCN ordering'. Probably that is the reason and result of 'SCN ordering'.

After the test, resume LGWR and clean up all Jobs:

SQL> oradebug resume
SQL> exec clean_jobs;
Collect AWR and ASH reports for the test interval, we can see:

Top 10 Foreground Events by Total Wait Time

Event Waits Total Wait Time (sec) Avg wait (ms) % DB time Wait Class
log file sync 14 7986.1 570437.20 29.5 Commit
buffer busy waits 23,544 4142.6 175.95 15.3 Concurrency
log file sync: SCN ordering 3 4139.8 1.4E+06 15.3 Concurrency
DB CPU 2184.4 8.1

Top SQL with Top Events

SQL ID %Activity Event %Event Top Row Source SQL Text
5h3nqwh6fdw66 32.83 buffer busy waits 19.35 UPDATE UPDATE TEST_TAB SET VAL = 'Upd..
CPU + Wait for CPU 7.03 TABLE ACCESS - FULL
log file sync: SCN ordering 6.45 UPDATE
a3376g221j75v 16.40 log file sync: SCN ordering 12.90 TEMP TABLE TRANSFORMATION WITH SQ1 AS (SELECT /*+ materi...
CPU + Wait for CPU 3.45 CONNECT BY - WITHOUT FILTERING

Occasionally we also observed statement:

  SQL ID:   g4gp07gt2z920 
  SQL Text: update sys.scheduler$_job set last_start_date = :1, running_instance = :2, running_slave = :3, job_status = :4 where obj# = :5
is blocked by 'log file sync: SCN ordering'.

In the above test, log_buffer is purposely set as a large value (128M). If we reduce it to a small value, for example, 2M (note: real allocated is 12M)

SQL> alter system set log_buffer=2M scope=spfile; 
SQL> startup force;
Repeat the same test by suspending LGWR. The blocking chains will be:

select c.chain_id, c.chain_signature, c.sid, c.blocker_sid bsid, final_blocking_session final_bsid, s.program, s.sql_id, s.event
from v$wait_chains c, v$session s
where c.sid = s.sid order by c.chain_id, s.program;

CHAIN_ID CHAIN_SIGNATURE                                              SID  BSID FINAL_BSID PROGRAM SQL_ID        EVENT
-------- ------------------------------------------------------------ ---- ---- ---------- ------- ------------- -----------------
       1 'rdbms ipc message'<='log buffer space'                      186  181         181 (J001)  a3376g221j75v log buffer space 
       1 'rdbms ipc message'<='log buffer space'                      181                  (LGWR)                rdbms ipc message
       2 'rdbms ipc message'<='log buffer space'<='buffer busy waits' 367  547         181 (J002)  5h3nqwh6fdw66 buffer busy waits
       2 'rdbms ipc message'<='log buffer space'<='buffer busy waits' 547  181         181 (J003)  5h3nqwh6fdw66 log buffer space 
       3 'rdbms ipc message'<='log buffer space'<='buffer busy waits' 724  181         181 (J004)  a3376g221j75v log buffer space 
       3 'rdbms ipc message'<='log buffer space'<='buffer busy waits' 542  724         181 (MMON)                buffer busy waits
       4 'rdbms ipc message'<='log buffer space'<='buffer busy waits' 545  547         181 (J000)  5h3nqwh6fdw66 buffer busy waits
       5 'rdbms ipc message'<='log buffer space'<='buffer busy waits' 719  724         181 (SMON)                buffer busy waits
       6 'rdbms ipc message'<='log buffer space'<='buffer busy waits' 902    8         181 (CJQ0)  c96x1j3nt4suf buffer busy waits
       6 'rdbms ipc message'<='log buffer space'<='buffer busy waits'   8  181         181 (J006)  g4gp07gt2z920 log buffer space 
       7 'rdbms ipc message'<='log buffer space'<='buffer busy waits' 905  547         181 (J005)  5h3nqwh6fdw66 buffer busy waits
No 'log file sync: SCN ordering' is visible because sessions are blocked by 'log buffer space' at first, and no more 'log file sync: SCN ordering' occurs.

From above blocking chains, we can see SMON, MMON and CJQ0 are also blocked by Job sessions, but all final_blocking_session are LGWR.

As a tradition, in Oracle, all popular terms are named twice, log_buffer is not an exception:
  V$SGAINFO.name='Redo Buffers'
  V$SGASTAT.name='log_buffer'


2. MMON ORA_12751_DUMP


During test, we also observed MMON ORA-12751 errors dump:

Unix process pid: 19998, image: oracle@testdb (MMON)
----- START DDE Action: 'ORA_12751_DUMP' (Sync) -----
Runtime exceeded 300 seconds
Time limit violation detected at:
ksedsts()+439<-kspol_12751_dump()+81<-dbgdaExecuteAction()+384<-dbgerRunAction()+105<-dbgerRunActions()+2117<-dbgexProcessError()+2271
<-dbgePostErrorKGE()+2169<-dbkePostKGE_kgsf()+58<-kgeade()+369<-kgeselv()+94<-ksesecl0()+181<-kcbzwb()+8821<-kcbgtcr()+84390
<-ktucloUsMinScn()+527<-ktucloUsegScan()+1017<-ksb_run_managed_action()+456<-ksbcti()+2029<-ksbabs()+2231<-ksbrdp()+1734<-opirip()+844
<-opidrv()+651<-sou2o()+122<-opimai_real()+317<-ssthrdmain()+558<-main()+164<-_start()+123Current Wait Stack:
 0: waiting for 'buffer busy waits'
    file#=0x3, block#=0x23c0, class#=0x11
    wait_id=1873 seq_num=1874 snap_id=1
    wait times: snap=5 min 6 sec, exc=5 min 6 sec, total=5 min 6 sec
    wait times: max=infinite, heur=5 min 6 sec
    wait counts: calls=306 os=306
    in_wait=1 iflags=0x15a2
There is at least one session blocking this session.
  Dumping 1 direct blocker(s):
    inst: 1, sid: 724, ser: 1289
  Dumping final blocker:
    inst: 1, sid: 181, ser: 52654
...
sample interval: 1 sec, max history 120 sec
---------------------------------------------------
  [121 samples,                                            09:07:49 - 09:09:49]
    waited for 'buffer busy waits', seq_num: 1874
      p1: 'file#'=0x3
      p2: 'block#'=0x23c0
      p3: 'class#'=0x11
      time_waited: >= 120 sec (still in wait)
---------------------------------------------------
Sampled Session History Summary:
  longest_non_idle_wait: 'buffer busy waits'
  [121 samples, 09:07:49 - 09:09:49]
      time_waited: >= 120 sec (still in wait)
---------------------------------------------------
----- END DDE Action: 'ORA_12751_DUMP' (SUCCESS, 3 csec) -----
----- END DDE Actions Dump (total 3 csec) -----
KEBM: MMON action policy violation. 'Block Cleanout Optim, Undo Segment Scan' viol=1; err=12751                                                                  
where 'class#'=0x11 (Decimal 17) indicates that MMON is 'buffer busy waits' on 'undo header'.

'ORA_12751_DUMP' is mentioned in MOS Docu:
    AWR Snapshots Fail to Generate With Associated "Suspending MMON action '%s' for 82800 seconds" alert log messages and Underlying ORA-12751 Errors (Doc ID 2043531.1)

As we know MMON (MMNL) is responsible to flush 1 out of 10 V$ACTIVE_SESSION_HISTORY (memory Circular Buffer in SGA) into disk DBA_HIST_ACTIVE_SESS_HISTORY each Snapshot interval or out-of-space by a direct path load (insert), which matches precisely what Doc ID 2363231.1 mentioned.


3. Test Code



drop table test_tab;
              
create table test_tab 
   INITRANS   26           -- prevent Segments ITL Waits and Deadlocks. 
as select level id, rpad('ABC', 100, 'X') val from dual connect by level <= 100;

create or replace procedure test_upd_no_commit(p_id number) is
begin
 for i in 1..1000000 loop
   update test_tab set val = 'Upd_'||i where id = p_id;
 end loop;
end;
/

create or replace procedure test_upd_no_commit_job(p_job_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 test_upd_no_commit('||i||'); end loop; end;');
  end loop;
  commit;
end;    
/

create or replace procedure test_load_as_select is
  type  num_tab is table of number;
 l_tab num_tab;
begin
  for i in 1..1000000 loop
   with sq1 as (select /*+ materialize */ level x from dual connect by level <= 1000000)
       ,sq2 as (select /*+ materialize */ x from sq1 where x <= 999999)
       ,sq3 as (select /*+ materialize */ x from sq1 where x <= 888888)
   select x bulk collect into l_tab from sq3
   where x <= 3; 
 end loop;
end;
/

create or replace procedure test_load_as_select_job(p_job_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 test_load_as_select; 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;
/

Tuesday, February 20, 2018

SYS.LOADER_DIR_OBJS Query: Privileges and Performance

Oracle Query On External Table and Data Pump hit performance problem when missing "Create/Drop Any Directory" Privileges. The triggered slow query is on SYS.LOADER_DIR_OBJS located in an Oracle internal package.

Oracle MOS has one matching Documentation:
    Slow Query On External Table If User Executing the Select Does Not Have "Create/Drop Any Directory" Privileges (Doc ID 2034938.1)
  Symptoms
    . Query against external tables perform slowly
    . User executing the select does not have "create any directory" or "drop any directory" privileges
    . The slowest query from the 10046 trace is the following recursive SQL:
        SELECT NAME, PATH, READ, WRITE, EXECUTE FROM SYS.LOADER_DIR_OBJS;
      
  Solution
    1. The solution is to gather statistics for the KZSROROL column as follows:
         exec dbms_stats.gather_table_stats(null,'X$KZSRO',method_opt=>'for columns KZSROROL',no_invalidate => false);
    2. Afterwards to make sure that these statistics will not get deleted by future runs of 
       DBMS_STATS.GATHER_FIXED_OBJECTS_STATS command, lock the statistics:
         exec dbms_stats.lock_table_stats('SYS','X$KZSRO');
This performance problem is worth of studying because it is directly related to System Privileges.

We will set up one System privilege and one Object privilege. Toggling both privileges, make 5 different tests:
  Test-1: Object privilege: YES; System privilege: YES
  Test-2: Object privilege: YES; System privilege: NO
  Test-3: Object privilege: NO;  System privilege: YES
  Test-4: Object privilege: NO;  System privilege: NO
  Test-5: Object privilege: NO;  System privilege: NO, and SQL Patch
The first two Tests are querying one external table; the next three are querying SYS.LOADER_DIR_OBJS. Test-5 is same as Test-4, but with SQL Patch applied.

Oracle 12.1 introduced SQL Patch (unofficial, undocumented) to tune packaged SQL Statements. Although it is possible to manipulate xplan with SQL Patch, but it cannot detour Oracle security to influence query result.

There is another related MOS Docu: Diagnosing a High Number of Executions Against Table SYS.DIR$ (Doc ID 2230171.1)

Note: All tests are done in Oracle 12.1.0.2 on Solaris.


1. Test Setup



sqlplus admin/admin123@TESTDB

drop user ksun cascade;

create user ksun identified by test123;

grant select any table, create any table, drop any table, create session, execute any procedure to ksun;

grant create any directory to ksun;
--revoke create any directory from ksun; 

create or replace directory test_dir as '/oradata/app/oracle/admin/testdb/io';

grant read, write on directory test_dir to ksun;
--revoke read, write on directory test_dir from ksun; 

exec dbms_stats.unlock_table_stats('SYS','X$KZSRO');

exec dbms_stats.gather_table_stats('SYS','X$KZSRO',method_opt=>'for columns KZSROROL',no_invalidate => false);

exec dbms_stats.lock_table_stats('SYS','X$KZSRO');

drop table testt1_ext;

create table testt1_ext
  organization external
    (type oracle_datapump 
     default directory test_dir 
     location ('testt1_ext.txt'))
  as select 321 x from dual;


2. Test-1: Object privilege: YES; System privilege: YES



sqlplus admin/admin123@TESTDB

grant read, write on directory test_dir to ksun;
grant create any directory to ksun;

select * from sys.dba_sys_privs where grantee = 'KSUN';

  GRAN PRIVILEGE              ADMIN_OPTION COMMON
  ---- ---------------------- ------------ ------
  KSUN CREATE TABLE           NO           NO
  KSUN EXECUTE ANY PROCEDURE  NO           NO
  KSUN DROP ANY TABLE         NO           NO
  KSUN CREATE ANY TABLE       NO           NO
  KSUN CREATE ANY DIRECTORY   NO           NO
  KSUN SELECT ANY TABLE       NO           NO
  KSUN CREATE SESSION         NO           NO

select grantee, table_name, privilege, type from sys.dba_tab_privs where grantee = 'KSUN';

  GRANTEE TABLE_NAME PRIVILEGE TYPE
  ------- ---------- --------- ---------
  KSUN    TEST_DIR   READ      DIRECTORY
  KSUN    TEST_DIR   WRITE     DIRECTORY
The query takes less than 1 second.

sqlplus ksun/test123@TESTDB

select sql_id, executions, rows_processed, buffer_gets, elapsed_time, cpu_time, last_load_time   --,v.* 
 from v$sql v where sql_id = 'f5ra7dru5fk5n';
 
  SQL_ID        EXECUTIONS ROWS_PROCESSED BUFFER_GETS ELAPSED_TIME   CPU_TIME LAST_LOAD_TIME
  ------------- ---------- -------------- ----------- ------------ ---------- -------------------
  f5ra7dru5fk5n          5           5660       32729       198104     198283 2018-02-19/08:38:40 

select * from testt1_ext;
  
           X
  ----------
         321
  
1 row selected.
Elapsed: 00:00:00.03

select sql_id, executions, rows_processed, buffer_gets, elapsed_time, cpu_time, last_load_time   --,v.* 
 from v$sql v where sql_id = 'f5ra7dru5fk5n';
 
   SQL_ID        EXECUTIONS ROWS_PROCESSED BUFFER_GETS ELAPSED_TIME   CPU_TIME LAST_LOAD_TIME
  ------------- ---------- -------------- ----------- ------------ ---------- -------------------
  f5ra7dru5fk5n          6           6792       37343       217328     217563 2018-02-19/08:38:40

(delta BUFFER_GETS=37343-32729=4,614, ELAPSED_TIME=217328-198104=19,224)

alter session set tracefile_identifier = 'ksun_trc_test1';
exec dbms_monitor.session_trace_enable(waits=>true, binds=>false, plan_stat=>'all_executions');
select * from testt1_ext;
exec dbms_monitor.session_trace_disable;

********************************************************************************

SQL ID: f5ra7dru5fk5n Plan Hash: 1161458834

SELECT NAME, PATH, READ, WRITE, EXECUTE FROM SYS.LOADER_DIR_OBJS

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     1133      0.05       0.05          0       3474          0        1132
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total     1135      0.05       0.05          0       3474          0        1132

Rows (avg) Row Source Operation
---------- ---------------------------------------------------
      1132 VIEW  LOADER_DIR_OBJS (cr=4614 pr=0 pw=0 time=53950 us cost=1189 size=2381728 card=1132)
      1132  UNION-ALL  (cr=4614 pr=0 pw=0 time=53093 us)
      1132   NESTED LOOPS  (cr=4614 pr=0 pw=0 time=51662 us cost=1131 size=99528 card=1131)
      1132    NESTED LOOPS  (cr=3482 pr=0 pw=0 time=48085 us cost=1131 size=99528 card=1131)
      1132     FIXED TABLE FULL X$DIR (cr=1140 pr=0 pw=0 time=39002 us cost=0 size=65598 card=1131)
      1132     INDEX RANGE SCAN I_OBJ1 (cr=2342 pr=0 pw=0 time=3597 us cost=1 size=0 card=1)(object id 1591123)
      1132    TABLE ACCESS BY INDEX ROWID OBJ$ (cr=1132 pr=0 pw=0 time=2996 us cost=1 size=30 card=1)
         1     FIXED TABLE FULL X$KZSPR (cr=0 pr=0 pw=0 time=29 us cost=0 size=7 card=1)
         0   HASH GROUP BY (cr=0 pr=0 pw=0 time=411 us cost=58 size=105 card=1)
         0    FILTER  (cr=0 pr=0 pw=0 time=29 us)
         0     NESTED LOOPS  (cr=0 pr=0 pw=0 time=0 us cost=57 size=105 card=1)
         0      NESTED LOOPS  (cr=0 pr=0 pw=0 time=0 us cost=57 size=47 card=1)
         0       HASH JOIN RIGHT SEMI (cr=0 pr=0 pw=0 time=0 us cost=56 size=17 card=1)
         0        VIEW  VW_NSO_1 (cr=0 pr=0 pw=0 time=0 us cost=0 size=60 card=15)
         0         FIXED TABLE FULL X$KZSRO (cr=0 pr=0 pw=0 time=0 us cost=0 size=60 card=15)
         0        TABLE ACCESS FULL OBJAUTH$ (cr=0 pr=0 pw=0 time=0 us cost=56 size=120471 card=9267)
         0       TABLE ACCESS BY INDEX ROWID BATCHED OBJ$ (cr=0 pr=0 pw=0 time=0 us cost=1 size=30 card=1)
         0        INDEX RANGE SCAN I_OBJ1 (cr=0 pr=0 pw=0 time=0 us cost=1 size=0 card=1)(object id 1591123)
         0      FIXED TABLE FIXED INDEX X$DIR (ind:1) (cr=0 pr=0 pw=0 time=0 us cost=0 size=58 card=1)
         1     FIXED TABLE FULL X$KZSPR (cr=0 pr=0 pw=0 time=27 us cost=0 size=7 card=1)

********************************************************************************


3. Test-2: Object privilege: YES; System privilege: NO



sqlplus admin/admin123@TESTDB

grant read, write on directory test_dir to ksun;
revoke create any directory from ksun; 
The query takes about 17 seconds because of subquery TABLE FULL X$KZSRO.

sqlplus ksun/test123@TESTDB

select sql_id, executions, rows_processed, buffer_gets, elapsed_time, cpu_time, last_load_time   --,v.* 
 from v$sql v where sql_id = 'f5ra7dru5fk5n';
 
   SQL_ID        EXECUTIONS ROWS_PROCESSED BUFFER_GETS ELAPSED_TIME   CPU_TIME LAST_LOAD_TIME
  ------------- ---------- -------------- ----------- ------------ ---------- -------------------
  f5ra7dru5fk5n          6           6792       37343       217328     217563 2018-02-19/08:38:40

select * from testt1_ext;

           X
  ----------
         321

1 row selected.
Elapsed: 00:00:17.93

select sql_id, executions, rows_processed, buffer_gets, elapsed_time, cpu_time, last_load_time   --,v.* 
 from v$sql v where sql_id = 'f5ra7dru5fk5n';

  SQL_ID        EXECUTIONS ROWS_PROCESSED BUFFER_GETS ELAPSED_TIME   CPU_TIME LAST_LOAD_TIME
  ------------- ---------- -------------- ----------- ------------ ---------- -------------------
  f5ra7dru5fk5n          7           6793      109986     18108955   18104124 2018-02-19/08:38:40

(delta BUFFER_GETS=109986-37343=72,643, ELAPSED_TIME=18108955-217328=17,891,627)

alter session set max_dump_file_size = UNLIMITED;
alter session set tracefile_identifier = 'ksun_trc_test2';
exec dbms_monitor.session_trace_enable(waits=>true, binds=>false, plan_stat=>'all_executions');
select * from testt1_ext;
alter session set session_cached_cursors = 0;
exec dbms_monitor.session_trace_disable;

alter session set session_cached_cursors = 200;

********************************************************************************

SQL ID: f5ra7dru5fk5n Plan Hash: 1161458834

SELECT NAME, PATH, READ, WRITE, EXECUTE FROM SYS.LOADER_DIR_OBJS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        2      0.03       0.03          0        235          0           0
Execute      2      0.00       0.00          0          0          0           0
Fetch        4     38.11      38.10          0      13750          0           2
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        8     38.15      38.13          0      13985          0           2

Rows (avg) Row Source Operation
---------- ---------------------------------------------------
         1 VIEW  LOADER_DIR_OBJS (cr=77167 pr=0 pw=0 time=19800468 us cost=1189 size=2381728 card=1132)
         1  UNION-ALL  (cr=77167 pr=0 pw=0 time=19800465 us)
         0   NESTED LOOPS  (cr=5776 pr=0 pw=0 time=124426 us cost=1131 size=99528 card=1131)
      1132    NESTED LOOPS  (cr=5747 pr=0 pw=0 time=125176 us cost=1131 size=99528 card=1131)
      1132     FIXED TABLE FULL X$DIR (cr=5664 pr=0 pw=0 time=120445 us cost=0 size=65598 card=1131)
      1132     INDEX RANGE SCAN I_OBJ1 (cr=83 pr=0 pw=0 time=1644 us cost=1 size=0 card=1)(object id 1591123)
         0    TABLE ACCESS BY INDEX ROWID OBJ$ (cr=29 pr=0 pw=0 time=964 us cost=1 size=30 card=1)
         0     FIXED TABLE FULL X$KZSPR (cr=0 pr=0 pw=0 time=30 us cost=0 size=7 card=1)
         1   HASH GROUP BY (cr=71391 pr=0 pw=0 time=19676026 us cost=58 size=105 card=1)
         2    FILTER  (cr=71391 pr=0 pw=0 time=19675276 us)
         2     NESTED LOOPS  (cr=71391 pr=0 pw=0 time=19675254 us cost=57 size=105 card=1)
     32313      NESTED LOOPS  (cr=6763 pr=0 pw=0 time=363426 us cost=57 size=47 card=1)
     32313       HASH JOIN RIGHT SEMI (cr=196 pr=0 pw=0 time=65194 us cost=56 size=17 card=1)
         2        VIEW  VW_NSO_1 (cr=0 pr=0 pw=0 time=10 us cost=0 size=60 card=15)
         2         FIXED TABLE FULL X$KZSRO (cr=0 pr=0 pw=0 time=6 us cost=0 size=60 card=15)
     43515        TABLE ACCESS FULL OBJAUTH$ (cr=196 pr=0 pw=0 time=45666 us cost=56 size=120471 card=9267)
     32313       TABLE ACCESS BY INDEX ROWID BATCHED OBJ$ (cr=6567 pr=0 pw=0 time=227682 us cost=1 size=30 card=1)
     32313        INDEX RANGE SCAN I_OBJ1 (cr=4851 pr=0 pw=0 time=118484 us cost=1 size=0 card=1)(object id 1591123)
         2      FIXED TABLE FIXED INDEX X$DIR (ind:1) (cr=64628 pr=0 pw=0 time=19318193 us cost=0 size=58 card=1)
         0     FIXED TABLE FULL X$KZSPR (cr=0 pr=0 pw=0 time=16 us cost=0 size=7 card=1)

********************************************************************************


4. Test-3: Object privilege: NO; System privilege: YES



sqlplus admin/admin123@TESTDB

revoke read, write on directory test_dir from ksun; 
grant create any directory to ksun;
Make the test:

sqlplus ksun/test123@TESTDB

SELECT NAME, PATH, READ, WRITE, EXECUTE FROM SYS.LOADER_DIR_OBJS

  NAME       PATH                                READ   WRITE  EXECUTE
  ---------- ----------------------------------- ------ ------ -------
  TEST_DIR   /oradata/app/oracle/admin/testdb/io TRUE   TRUE   TRUE

1 row selected.
Elapsed: 00:00:00.04
The select returns 1 row, and takes less than 1 second.

Here the xplan:

sqlplus admin/admin123@TESTDB

select * from table(dbms_xplan.display_cursor('f5ra7dru5fk5n', null, 'ADVANCED ALLSTATS LAST'));

SQL_ID  f5ra7dru5fk5n, child number 0
-------------------------------------
SELECT NAME, PATH, READ, WRITE, EXECUTE FROM SYS.LOADER_DIR_OBJS
 
Plan hash value: 1161458834
 
--------------------------------------------------------------------------------------------------------------
| Id  | Operation                                 | Name            | E-Rows |E-Bytes| Cost (%CPU)| E-Time   |
--------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                          |                 |        |       |  1189 (100)|          |
|   1 |  VIEW                                     | LOADER_DIR_OBJS |   1132 |  2325K|  1189   (1)| 00:00:01 |
|   2 |   UNION-ALL                               |                 |        |       |            |          |
|   3 |    NESTED LOOPS                           |                 |   1131 | 99528 |  1131   (0)| 00:00:01 |
|   4 |     NESTED LOOPS                          |                 |   1131 | 99528 |  1131   (0)| 00:00:01 |
|   5 |      FIXED TABLE FULL                     | X$DIR           |   1131 | 65598 |     0   (0)|          |
|*  6 |      INDEX RANGE SCAN                     | I_OBJ1          |      1 |       |     1   (0)| 00:00:01 |
|*  7 |     TABLE ACCESS BY INDEX ROWID           | OBJ$            |      1 |    30 |     1   (0)| 00:00:01 |
|*  8 |      FIXED TABLE FULL                     | X$KZSPR         |      1 |     7 |     0   (0)|          |
|   9 |    HASH GROUP BY                          |                 |      1 |   105 |    58   (2)| 00:00:01 |
|* 10 |     FILTER                                |                 |        |       |            |          |
|  11 |      NESTED LOOPS                         |                 |      1 |   105 |    57   (0)| 00:00:01 |
|  12 |       NESTED LOOPS                        |                 |      1 |    47 |    57   (0)| 00:00:01 |
|* 13 |        HASH JOIN RIGHT SEMI               |                 |      1 |    17 |    56   (0)| 00:00:01 |
|  14 |         VIEW                              | VW_NSO_1        |     15 |    60 |     0   (0)|          |
|  15 |          FIXED TABLE FULL                 | X$KZSRO         |     15 |    60 |     0   (0)|          |
|* 16 |         TABLE ACCESS FULL                 | OBJAUTH$        |   9267 |   117K|    56   (0)| 00:00:01 |
|  17 |        TABLE ACCESS BY INDEX ROWID BATCHED| OBJ$            |      1 |    30 |     1   (0)| 00:00:01 |
|* 18 |         INDEX RANGE SCAN                  | I_OBJ1          |      1 |       |     1   (0)| 00:00:01 |
|* 19 |       FIXED TABLE FIXED INDEX             | X$DIR (ind:1)   |      1 |    58 |     0   (0)|          |
|* 20 |      FIXED TABLE FULL                     | X$KZSPR         |      1 |     7 |     0   (0)|          |
--------------------------------------------------------------------------------------------------------------


5. Test-4: Object privilege: NO; System privilege: NO


Revoke both privileges:

sqlplus admin/admin123@TESTDB

revoke read, write on directory test_dir from ksun; 
revoke create any directory from ksun;
Make the test:

sqlplus ksun/test123@TESTDB

SELECT NAME, PATH, READ, WRITE, EXECUTE FROM SYS.LOADER_DIR_OBJS

no rows selected
Elapsed: 00:00:12.49
no rows selected, and takes about 12 seconds.

Here the xplan (same as Test-3):

sqlplus admin/admin123@TESTDB

select * from table(dbms_xplan.display_cursor('f5ra7dru5fk5n', null, 'ADVANCED ALLSTATS LAST'));

SQL_ID  f5ra7dru5fk5n, child number 0
-------------------------------------
SELECT NAME, PATH, READ, WRITE, EXECUTE FROM SYS.LOADER_DIR_OBJS
 
Plan hash value: 1161458834
 
-----------------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                                 | Name            | E-Rows |E-Bytes| Cost (%CPU)| E-Time   |  OMem |  1Mem | Used-Mem |
-----------------------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                          |                 |        |       |  1189 (100)|          |       |       |          |
|   1 |  VIEW                                     | LOADER_DIR_OBJS |   1132 |  2325K|  1189   (1)| 00:00:01 |       |       |          |
|   2 |   UNION-ALL                               |                 |        |       |            |          |       |       |          |
|   3 |    NESTED LOOPS                           |                 |   1131 | 99528 |  1131   (0)| 00:00:01 |       |       |          |
|   4 |     NESTED LOOPS                          |                 |   1131 | 99528 |  1131   (0)| 00:00:01 |       |       |          |
|   5 |      FIXED TABLE FULL                     | X$DIR           |   1131 | 65598 |     0   (0)|          |       |       |          |
|*  6 |      INDEX RANGE SCAN                     | I_OBJ1          |      1 |       |     1   (0)| 00:00:01 |       |       |          |
|*  7 |     TABLE ACCESS BY INDEX ROWID           | OBJ$            |      1 |    30 |     1   (0)| 00:00:01 |       |       |          |
|*  8 |      FIXED TABLE FULL                     | X$KZSPR         |      1 |     7 |     0   (0)|          |       |       |          |
|   9 |    HASH GROUP BY                          |                 |      1 |   105 |    58   (2)| 00:00:01 |   831K|   831K|          |
|* 10 |     FILTER                                |                 |        |       |            |          |       |       |          |
|  11 |      NESTED LOOPS                         |                 |      1 |   105 |    57   (0)| 00:00:01 |       |       |          |
|  12 |       NESTED LOOPS                        |                 |      1 |    47 |    57   (0)| 00:00:01 |       |       |          |
|* 13 |        HASH JOIN RIGHT SEMI               |                 |      1 |    17 |    56   (0)| 00:00:01 |  2293K|  2293K|  709K (0)|
|  14 |         VIEW                              | VW_NSO_1        |     15 |    60 |     0   (0)|          |       |       |          |
|  15 |          FIXED TABLE FULL                 | X$KZSRO         |     15 |    60 |     0   (0)|          |       |       |          |
|* 16 |         TABLE ACCESS FULL                 | OBJAUTH$        |   9267 |   117K|    56   (0)| 00:00:01 |       |       |          |
|  17 |        TABLE ACCESS BY INDEX ROWID BATCHED| OBJ$            |      1 |    30 |     1   (0)| 00:00:01 |       |       |          |
|* 18 |         INDEX RANGE SCAN                  | I_OBJ1          |      1 |       |     1   (0)| 00:00:01 |       |       |          |
|* 19 |       FIXED TABLE FIXED INDEX             | X$DIR (ind:1)   |      1 |    58 |     0   (0)|          |       |       |          |
|* 20 |      FIXED TABLE FULL                     | X$KZSPR         |      1 |     7 |     0   (0)|          |       |       |          |
-----------------------------------------------------------------------------------------------------------------------------------------


6. Test-5: Object privilege: NO; System privilege: NO, and SQL Patch


Since the recursive query is located in Oracle internal packaged application, SQL Patch is used to add hints.

One similar test was done by Blog: Slow external table access.

Revoke both privileges and create SQL Patch:

sqlplus admin/admin123@TESTDB

revoke read, write on directory test_dir from ksun; 
revoke create any directory from ksun;

begin
  sys.dbms_sqldiag_internal.i_create_patch(
    sql_text  => 'SELECT NAME, PATH, READ, WRITE, EXECUTE FROM SYS.LOADER_DIR_OBJS'
   ,hint_text => 'CARDINALITY(@"SEL$2" "D"@"SEL$2", 2) CARDINALITY(@"SEL$2" "O"@"SEL$2", 3) '||
                 'CARDINALITY(@"SEL$0C7B6CF6" "D"@"SEL$6" 4) '||
                 'USE_HASH(@"SEL$2" "D"@"SEL$2" O@SEL$2) USE_HASH(@"SEL$0C7B6CF6" "D"@"SEL$6")'
   ,name      => 'SQLPATCH123');
end;
/

select name, created, status from dba_sql_patches where name in ('SQLPATCH123');

  NAME        CREATED             STATUS
  ----------- ------------------- -------
  SQLPATCH123 9-FEB-2018 11:15:22 ENABLED

select dbms_lob.substr(comp_data, 80, 1) hint, signature from sys.SQLOBJ$DATA t;

  HINT                                                                                         SIGNATURE
  -------------------------------------------------------------------------------- ---------------------
  <outline_data><hint><![CDATA[CARDINALITY(@"SEL$2" "D"@"SEL$2", 2) CARDINALITY(@"    516452634368408982
  <outline_data><hint><![CDATA[      IGNORE_OPTIM_EMBEDDED_HINTS                     9073911181602513588

alter system flush shared_pool;
Make the test:

sqlplus ksun/test123@TESTDB

SELECT NAME, PATH, READ, WRITE, EXECUTE FROM SYS.LOADER_DIR_OBJS;

no rows selected
Elapsed: 00:00:00.29
Although query is fast (less than 1 second), but no rows selected. Therefore, it is not possible to bypass Oracle Security by SQL Patch.

Xplan confirms that the SQL Patch was applied (also indicated in Note: SQL patch "SQLPATCH123") because it is different with that of Test-4.

sqlplus admin/admin123@TESTDB

select * from table(dbms_xplan.display_cursor('f5ra7dru5fk5n', null, 'ADVANCED ALLSTATS LAST'));

SQL_ID  f5ra7dru5fk5n, child number 0
-------------------------------------
SELECT NAME, PATH, READ, WRITE, EXECUTE FROM SYS.LOADER_DIR_OBJS
 
Plan hash value: 153645881
 
------------------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                                  | Name            | E-Rows |E-Bytes| Cost (%CPU)| E-Time   |  OMem |  1Mem | Used-Mem |
------------------------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                           |                 |        |       |  3522 (100)|          |       |       |          |
|   1 |  VIEW                                      | LOADER_DIR_OBJS |      3 |  6312 |  3522   (1)| 00:00:01 |       |       |          |
|   2 |   UNION-ALL                                |                 |        |       |            |          |       |       |          |
|*  3 |    HASH JOIN                               |                 |      2 |   176 |  3515   (0)| 00:00:01 |   964K|   964K| 1297K (0)|
|   4 |     FIXED TABLE FULL                       | X$DIR           |      2 |   116 |     0   (0)|          |       |       |          |
|*  5 |     INDEX FAST FULL SCAN                   | I_OBJ2          |      3 |    90 |  3515   (0)| 00:00:01 |       |       |          |
|*  6 |      FIXED TABLE FULL                      | X$KZSPR         |      1 |     7 |     0   (0)|          |       |       |          |
|   7 |    HASH GROUP BY                           |                 |      1 |   105 |     7  (15)| 00:00:01 |   831K|   831K|          |
|*  8 |     FILTER                                 |                 |        |       |            |          |       |       |          |
|*  9 |      HASH JOIN SEMI                        |                 |      1 |   105 |     6   (0)| 00:00:01 |  1927K|  1186K| 2361K (0)|
|  10 |       NESTED LOOPS                         |                 |      1 |   101 |     6   (0)| 00:00:01 |       |       |          |
|  11 |        NESTED LOOPS                        |                 |      4 |   352 |     4   (0)| 00:00:01 |       |       |          |
|  12 |         FIXED TABLE FULL                   | X$DIR           |      4 |   232 |     0   (0)|          |       |       |          |
|  13 |         TABLE ACCESS BY INDEX ROWID BATCHED| OBJ$            |      1 |    30 |     1   (0)| 00:00:01 |       |       |          |
|* 14 |          INDEX RANGE SCAN                  | I_OBJ1          |      1 |       |     1   (0)| 00:00:01 |       |       |          |
|* 15 |        INDEX RANGE SCAN                    | I_OBJAUTH1      |      1 |    13 |     1   (0)| 00:00:01 |       |       |          |
|  16 |       VIEW                                 | VW_NSO_1        |     15 |    60 |     0   (0)|          |       |       |          |
|  17 |        FIXED TABLE FULL                    | X$KZSRO         |     15 |    60 |     0   (0)|          |       |       |          |
|* 18 |      FIXED TABLE FULL                      | X$KZSPR         |      1 |     7 |     0   (0)|          |       |       |          |
------------------------------------------------------------------------------------------------------------------------------------------
 
Query Block Name / Object Alias (identified by operation id):
-------------------------------------------------------------
 
   1 - SET$1        / LOADER_DIR_OBJS@SEL$1
   2 - SET$1       
   3 - SEL$2       
   4 - SEL$2        / D@SEL$2
   5 - SEL$2        / O@SEL$2
   6 - SEL$C8360722 / X$KZSPR@SEL$5
   7 - SEL$0C7B6CF6
  12 - SEL$0C7B6CF6 / D@SEL$6
  13 - SEL$0C7B6CF6 / O@SEL$6
  14 - SEL$0C7B6CF6 / O@SEL$6
  15 - SEL$0C7B6CF6 / OA@SEL$6
  16 - SEL$3C459230 / VW_NSO_1@SEL$0C7B6CF6
  17 - SEL$3C459230 / X$KZSRO@SEL$7
  18 - SEL$2F35337B / X$KZSPR@SEL$10

Note
-----
   - SQL patch "SQLPATCH123" used for this statement
After above test, drop used SQL patch:

sqlplus admin/admin123@TESTDB

exec dbms_sqldiag.drop_sql_patch('SQLPATCH123');


6. Discussions


In summary:
    With System privilege (Test-1 and Test-3), queries on external table and SYS.LOADER_DIR_OBJS are fast.
    Without System privilege (Test-2 and Test-4), queries are slow.
    Without System privilege (Test-5), but with SQL Patch, query is fast, but no rows selected.
Therefore, above 5 Tests showed that query result and performance depend on faultless System privilege.

Looking the difference of SQL Trace xplan between Test-1 (fast) and Test-2 (slow), we can see that subquery on X$KZSRO in fast xplan returns 0 rows, but in slow xplan returns 2 rows, and hence generates expensive NESTED LOOPS.

Here the definition of SYS.LOADER_DIR_OBJS:

create or replace force view sys.loader_dir_objs (name, path, read, write, execute) bequeath definer as
  select o.name, d.os_path, 'TRUE', 'TRUE', 'TRUE'
    from sys.obj$ o, sys.x$dir d
   where     o.obj# = d.obj#
         and (   o.owner# = uid
              or exists (select null from v$enabledprivs where priv_number in (-177, -178)))
  union all
    select o.name,
           d.os_path,
           decode (sum (decode (oa.privilege#, 17, 1, 0)), 0, 'FALSE', 'TRUE'),
           decode (sum (decode (oa.privilege#, 18, 1, 0)), 0, 'FALSE', 'TRUE'),
           decode (sum (decode (oa.privilege#, 12, 1, 0)), 0, 'FALSE', 'TRUE')
      from sys.obj$ o, sys.x$dir d, sys.objauth$ oa
     where     o.obj# = d.obj#
           and oa.obj# = o.obj#
           and oa.privilege# in (12, 17, 18)
           and oa.grantee# in (select kzsrorol from x$kzsro)
           and not (   o.owner# = uid
                    or exists (select null from v$enabledprivs where priv_number in (-177, -178)))
  group by o.name, d.os_path;

Wednesday, January 24, 2018

Oracle Logical Read: Current Gets Access Path and Cost

Oracle Logical Reads (Buffer Gets) fetch data from Buffer Cache (Memory) in two different Modes: Current Mode Get (DB Block Gets) and Consistent Mode Get (Consistent Gets). Blocks in Consistent Mode are the memory versions at the POINT IN TIME the query started, whereas Blocks in Current Mode are the versions at CURRENT TIME (right now). Each block can have multiversion Clones in Consistent Mode, but maximum one single version in Current Mode.

Following the discussions of Blog: Oracle Physical Read Access Path and Cost, and Oracle Logical Read: Consistent Gets Access Path and Cost, now is the time to look into second part of Logical Reads: Current Mode Gets.

We will use SQL Trace Event 10046 to display the statistics, and dtrace script: dtracelio.d published in Blog: Dynamic tracing of Oracle logical I/O to show block read details and sequence. Ideally Oracle could provide one Event to trace Current Mode Get, which is similar to Event 10200 ("consistent read buffer status") for Consistent Mode Get.

Blog: Dynamic tracing of Oracle logical I/O: part 2. Dtrace LIO v2 is released includes a detail description of Oracle internal functions:
Consistent gets:
    kcbgtcr   – Kernel Cache Buffer Get Consistent Read. This is general entry point for consistent read.
    kcbldrget – Kernel Cache Buffer Load Direct-Read Get. The function performing direct-path read. 
                Interesting detail: 10.2 the function kcbldrget is called just after kcbgtcr, 
                in 11.2 by (from) kcbgtcr.

Current gets (db block gets):
    kcbgcur – Kernel Cache Buffer Get Current Read
    kcbget  – Kernel Cache Buffer Get Buffer. This is analogue of kcbgcur function, 
              as I observed this function is called for index branch and leaf blocks
    kcbnew  – Kernel Cache Buffer New Buffer
    kcblnb (kcblnb_dscn in 11.2) – Kernel Cache Buffer Load New Buffer. 
              The function performing direct-path load. 
              Decoding of block coordinates is not supported for this function 
              in the current version of DTraceLIO. 
              The parameters such as object_id, data_object_id will be shown as 0 (zero)
Note: All tests are done in Oracle 12.1.0.2 on Solaris with 6 physical processors.


1. Test Setup



drop tablespace ksun_tts  including contents and datafiles;
drop tablespace ksun_its1 including contents and datafiles;
drop tablespace ksun_its2 including contents and datafiles;

create tablespace ksun_tts  datafile '/oratestdb/oradata/testdb/ksun_tts.dbf'  size 200m online;
create tablespace ksun_its1 datafile '/oratestdb/oradata/testdb/ksun_its1.dbf' size 200m online;
create tablespace ksun_its2 datafile '/oratestdb/oradata/testdb/ksun_its2.dbf' size 200m online;

drop table ksun_tab;

create table ksun_tab tablespace ksun_tts 
    as select trunc(level/1000) type_id, mod(level, 100) id1, trunc(mod(level, 1000)/100) id2, -1234 dummy 
  from dual connect by level <= 4099;

create unique index ksun_tab#u#1 on ksun_tab (type_id, id1, id2, dummy) tablespace ksun_its1;
create unique index ksun_tab#u#2 on ksun_tab (type_id, id2, id1)        tablespace ksun_its2;

exec dbms_stats.gather_table_stats(null, 'KSUN_TAB', cascade=>true);

select name, ts# from v$tablespace  where name like '%KSUN%' or ts# in (2, 1999);
  --UNDO         2
  --U1        1999
  --KSUN_TTS  2231
  --KSUN_ITS1 2232
  --KSUN_ITS2 2233

select rfile#, name, v.* from  v$datafile v where name like '%ksun%';
  --917 /oratestdb/oradata/testdb/ksun_tts.dbf
  --931 /oratestdb/oradata/testdb/ksun_its1.dbf
  --101 /oratestdb/oradata/testdb/ksun_its2.dbf

select object_name, object_id from dba_objects where object_name like 'KSUN_TAB%' or object_id in (1577349);
  --RMTAB$       1577349
  --KSUN_TAB     2286270
  --KSUN_TAB#U#1 2286271
  --KSUN_TAB#U#2 2286272
  
select segment_name, blocks, v.* from dba_segments v where segment_name like 'KSUN_TAB%';
  --KSUN_TAB     16
  --KSUN_TAB#U#1 24
  --KSUN_TAB#U#2 16

select 'KSUN_TAB', count(distinct dbms_rowid.rowid_relative_fno (rowid)||'-'||dbms_rowid.rowid_block_number (rowid)) used_blocks from KSUN_TAB;
  --KSUN_TAB     11

select 'KSUN_TAB#U#1', count(distinct dbms_rowid.rowid_block_number(sys_op_lbid (2286271, 'L', t.rowid))) used_blocks from KSUN_TAB t;
  --KSUN_TAB#U#1 14

select 'KSUN_TAB#U#2', count(distinct dbms_rowid.rowid_block_number(sys_op_lbid (2286272, 'L', t.rowid))) used_blocks from KSUN_TAB t;
  -- KSUN_TAB#U#2 11

-- list different functions used to perform different types of logical I/O
select indx, kcbwhdes from x$kcbwh where indx in (799, 1060, 1062, 1066, 1153, 1199);
  --799   ktewh26:  kteinpscan
  --1060  kdiwh15:  kdifxs
  --1062  kdiwh17:  kdifind
  --1066  kdiwh22:  kdifind
  --1153  kdiwh169: skipscan
  --1199  kddwh01:  kdddel


2. Tests


We will perform 3 Tests, the first one uses 2 different indexes, the second uses only one index, and the last one uses the same index twice.


2.1 Test_1



--******************************* SQL Trace *******************************--
delete /*+ test_1 use_concat index_ss(@DEL$1 T@DEL$1 ksun_tab#u#2) 
  index_ss(@DEL$1_2 T@DEL$1_2 ksun_tab#u#1) */ ksun_tab t where 99 in (id2, id1)

-- rollback; -- make test repeatable

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         12        211          41
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      0.00       0.00          0         12        211          41

Rows (avg) Row Source Operation
---------- ---------------------------------------------------
         0 DELETE  KSUN_TAB (cr=12 pr=0 pw=0 time=1569 us)
        41  CONCATENATION  (cr=12 pr=0 pw=0 time=356 us)
         0   INDEX SKIP SCAN KSUN_TAB#U#2 (cr=6 pr=0 pw=0 time=82 us cost=3 size=14 card=1)(object id 2286272)
        41   INDEX SKIP SCAN KSUN_TAB#U#1 (cr=6 pr=0 pw=0 time=228 us cost=8 size=574 card=41)(object id 2286271)


--******************************* dtrace *******************************--
SQL> delete /*+ test_1 use_concat index_ss(@DEL$1 T@DEL$1 ksun_tab#u#2) 
       index_ss(@DEL$1_2 T@DEL$1_2 ksun_tab#u#1) */ ksun_tab t where 99 in (id2, id1);
   41 rows deleted.

     -- rollback; -- make test repeatable


$ > dtracelio.d 23585

Dynamic tracing of Oracle logical I/O v2.1 by Alexander Anokhin ( http://alexanderanokhin.wordpress.com )

  108075: 108075 kcbgtcr(0xFFFFFD7FFAE17D58,0,1153,0) [tsn: 2233 rdba: 0x19400083 (101/131) obj: 2286272 dobj: 2286272] where: 1153 exam: 0
  124990:   4336 kcbgtcr(0xFFFFFD7FFAE17D58,0,1153,0) [tsn: 2233 rdba: 0x19400083 (101/131) obj: 2286272 dobj: 2286272] where: 1153 exam: 0
    --Repeated lines removed--
    
  424351:   4783 kcbgtcr(0xFFFFFD7FFA0EF830,0,1153,0) [tsn: 2232 rdba: 0xe8c00083 (931/131) obj: 2286271 dobj: 2286271] where: 1153 exam: 0
  428303:   2234 kcbgtcr(0xFFFFFD7FFA0EF830,0,1153,0) [tsn: 2232 rdba: 0xe8c00083 (931/131) obj: 2286271 dobj: 2286271] where: 1153 exam: 0
    --Repeated lines removed--
    
  511748:  21448 kcbgcur(0xFFFFFD7FFAED0EB0,2,1199,0) [tsn: 2231 rdba: 0xe5400083 (917/131) obj: 2286270 dobj: 2286270] where: 1199 mode_held: 2
  524191:   3355 kcbgcur(0xFFFFFD7FFAED0EB0,2,1199,0) [tsn: 2231 rdba: 0xe5400083 (917/131) obj: 2286270 dobj: 2286270] where: 1199 mode_held: 2
  658937:   5220 kcbgcur(0xFFFFFD7FFFDF4660,1,1062,0) [tsn: 2232 rdba: 0xe8c00083 (931/131) obj: 2286271 dobj: 2286271] where: 1062 mode_held: 1
  663567:   2134 kcbgcur(0xFFFFFD7FFFDF4660,1,1062,0) [tsn: 2232 rdba: 0xe8c00083 (931/131) obj: 2286271 dobj: 2286271] where: 1062 mode_held: 1
  695708:  18720 kcbget(0xFFFFFD7FFFDF4660,2,1066,0) [tsn: 2232 rdba: 0xe8c00087 (931/135) obj: 2286271 dobj: 2286271] where: 1066 mode_held: 2
  707668:   2415 kcbget(0xFFFFFD7FFFDF4660,2,1066,0) [tsn: 2232 rdba: 0xe8c00087 (931/135) obj: 2286271 dobj: 2286271] where: 1066 mode_held: 2
  745953:   5864 kcbgcur(0xFFFFFD7FFFDF4660,1,1062,0) [tsn: 2233 rdba: 0x19400083 (101/131) obj: 2286272 dobj: 2286272] where: 1062 mode_held: 1
  750657:   2105 kcbgcur(0xFFFFFD7FFFDF4660,1,1062,0) [tsn: 2233 rdba: 0x19400083 (101/131) obj: 2286272 dobj: 2286272] where: 1062 mode_held: 1
  759713:   4981 kcbget(0xFFFFFD7FFFDF4660,2,1066,0) [tsn: 2233 rdba: 0x19400084 (101/132) obj: 2286272 dobj: 2286272] where: 1066 mode_held: 2
  764240:   1989 kcbget(0xFFFFFD7FFFDF4660,2,1066,0) [tsn: 2233 rdba: 0x19400084 (101/132) obj: 2286272 dobj: 2286272] where: 1066 mode_held: 2
  
  784175:   3267 kcbgcur(0xFFFFFD7FFAED0EB0,2,1199,0) [tsn: 2231 rdba: 0xe5400083 (917/131) obj: 2286270 dobj: 2286270] where: 1199 mode_held: 2
  789056:   2245 kcbgcur(0xFFFFFD7FFAED0EB0,2,1199,0) [tsn: 2231 rdba: 0xe5400083 (917/131) obj: 2286270 dobj: 2286270] where: 1199 mode_held: 2
  806713:   2546 kcbgcur(0xFFFFFD7FFFDF4660,1,1062,0) [tsn: 2232 rdba: 0xe8c00083 (931/131) obj: 2286271 dobj: 2286271] where: 1062 mode_held: 1
  811388:   2215 kcbgcur(0xFFFFFD7FFFDF4660,1,1062,0) [tsn: 2232 rdba: 0xe8c00083 (931/131) obj: 2286271 dobj: 2286271] where: 1062 mode_held: 1
  818717:   3387 kcbget(0xFFFFFD7FFFDF4660,2,1066,0) [tsn: 2232 rdba: 0xe8c00087 (931/135) obj: 2286271 dobj: 2286271] where: 1066 mode_held: 2
  823620:   2283 kcbget(0xFFFFFD7FFFDF4660,2,1066,0) [tsn: 2232 rdba: 0xe8c00087 (931/135) obj: 2286271 dobj: 2286271] where: 1066 mode_held: 2
  833734:   2543 kcbgcur(0xFFFFFD7FFFDF4660,1,1062,0) [tsn: 2233 rdba: 0x19400083 (101/131) obj: 2286272 dobj: 2286272] where: 1062 mode_held: 1
  838017:   1949 kcbgcur(0xFFFFFD7FFFDF4660,1,1062,0) [tsn: 2233 rdba: 0x19400083 (101/131) obj: 2286272 dobj: 2286272] where: 1062 mode_held: 1
  843481:   2253 kcbget(0xFFFFFD7FFFDF4660,2,1066,0) [tsn: 2233 rdba: 0x19400084 (101/132) obj: 2286272 dobj: 2286272] where: 1066 mode_held: 2
  847875:   1988 kcbget(0xFFFFFD7FFFDF4660,2,1066,0) [tsn: 2233 rdba: 0x19400084 (101/132) obj: 2286272 dobj: 2286272] where: 1066 mode_held: 2
  --Repeated lines removed (40 Repeats)--    


Pick one line:  
  524191:   3355 kcbgcur(0xFFFFFD7FFAED0EB0,2,1199,0) [tsn: 2231 rdba: 0xe5400083 (917/131) obj: 2286270 dobj: 2286270] where: 1199 mode_held: 2
You can see here:
  timestamp  - 524191, 
  delta time - 3355 (from last timestamp to current timestamp),
  kcbgcur(0xFFFFFD7FFAED0EB0,2,1199,0) – it is function call with 3 arguments,
  tsn: 2231        – a tablespace number, ts# from v$tablespace for KSUN_TTS,
  rdba: 0xe5400083 – a relative dba (data block address)
  (917/131)        – file 917 (ksun_tts.dbf) block 131
  obj: 2286270     – dictionary object number, object_id from dba_objects for KSUN_TAB,
  dobj: 2286270    – data object number, data_object_id from dba_objects for KSUN_TAB,
  where: 1199      – location from function (kcbgcur in this case) was executed. This is INDX from x$kcbwf for "kddwh01: kdddel".

===================== Logical I/O Summary (grouped by object/function) ==============
 function    stat   object_id   data_object_id   mode_held   where     bufs     calls
--------- ------- ----------- ---------------- ----------- ------- -------- ---------
  kcbgcur      cu           0               -1           2      53        2         2
  kcbgcur      cu           0               -1           2      88        2         2
  kcbgcur      cu           0               -1           2      86        4         4
   kcbnew      cu           0               -1                  47        4         4
  kcbgtcr      cr     2286271          2286271                1153       12        12
  kcbgtcr      cr     2286272          2286272                1153       12        12
  kcbgcur      cu     2286270          2286270           2    1199       82        82
  kcbgcur      cu     2286271          2286271           1    1062       82        82
  kcbgcur      cu     2286272          2286272           1    1062       82        82
   kcbget      cu     2286271          2286271           2    1066       82        82
   kcbget      cu     2286272          2286272           2    1066       82        82
=====================================================================================

================================= Logical I/O Summary (grouped by object) ==========================================
 object_id  data_object_id       lio        cr    cr (e)    cr (d)        cu    cu (d) ispnd (Y) ispnd (N)   pin rls
---------- --------------- --------- --------- --------- --------- --------- --------- --------- --------- ---------
         0              -1        12         0         0         0        12         0         0         0         4
   2286270         2286270        82         0         0         0        82         0         0         0        82
   2286271         2286271       176        12         0         0       164         0         0         0        12
   2286272         2286272       176        12         0         0       164         0         0         0        12
---------- --------------- --------- --------- --------- --------- --------- --------- --------- --------- ---------
     total                       446        24         0         0       422         0         0         0       110
====================================================================================================================

Legend
  lio      : logical gets (cr + cu)
  cr       : consistent gets
  cr (e)   : consistent gets - examination
  cr (d)   : consistent gets direct
  cu       : db block gets
  cu (d)   : db block gets direct
  ispnd (Y): buffer is pinned count
  ispnd (N): buffer is not pinned count
  pin rls  : pin releases


2.2 Test_2



--******************************* SQL Trace *******************************--
delete /*+ test_2 index(t ksun_tab#U#2)  */ ksun_tab t where 99 in (id2, id1)

-- rollback; -- make test repeatable

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         12         75          41
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      0.00       0.00          0         12         75          41

Rows (avg) Row Source Operation
---------- ---------------------------------------------------
         0 DELETE  KSUN_TAB (cr=12 pr=0 pw=0 time=1025 us)
        41  INDEX FULL SCAN KSUN_TAB#U#2 (cr=12 pr=0 pw=0 time=405 us cost=6 size=574 card=41)(object id 2286272)


--******************************* dtrace *******************************--
SQL > delete /*+ test_2 index(t ksun_tab#U#2) */ ksun_tab t where 99 in (id2, id1);
   41 rows deleted.
   
      -- rollback; -- make test repeatable
   
$ > dtracelio.d 23585

Dynamic tracing of Oracle logical I/O v2.1 by Alexander Anokhin ( http://alexanderanokhin.wordpress.com )

  233462:  22641 kcbgcur(0xFFFFFD7FFAED9270,2,1199,0) [tsn: 2231 rdba: 0xe5400083 (917/131) obj: 2286270 dobj: 2286270] where: 1199 mode_held: 2
  245054:   2829 kcbgcur(0xFFFFFD7FFAED9270,2,1199,0) [tsn: 2231 rdba: 0xe5400083 (917/131) obj: 2286270 dobj: 2286270] where: 1199 mode_held: 2
  365187:   2913 kcbgcur(0xFFFFFD7FFAED9270,2,1199,0) [tsn: 2231 rdba: 0xe5400083 (917/131) obj: 2286270 dobj: 2286270] where: 1199 mode_held: 2
  369681:   1947 kcbgcur(0xFFFFFD7FFAED9270,2,1199,0) [tsn: 2231 rdba: 0xe5400083 (917/131) obj: 2286270 dobj: 2286270] where: 1199 mode_held: 2
  404103:   2826 kcbgcur(0xFFFFFD7FFAED9270,2,1199,0) [tsn: 2231 rdba: 0xe5400083 (917/131) obj: 2286270 dobj: 2286270] where: 1199 mode_held: 2
  408598:   2029 kcbgcur(0xFFFFFD7FFAED9270,2,1199,0) [tsn: 2231 rdba: 0xe5400083 (917/131) obj: 2286270 dobj: 2286270] where: 1199 mode_held: 2
  429972:   2233 kcbgcur(0xFFFFFD7FFAED9270,2,1199,0) [tsn: 2231 rdba: 0xe5400083 (917/131) obj: 2286270 dobj: 2286270] where: 1199 mode_held: 2
  434528:   2212 kcbgcur(0xFFFFFD7FFAED9270,2,1199,0) [tsn: 2231 rdba: 0xe5400083 (917/131) obj: 2286270 dobj: 2286270] where: 1199 mode_held: 2
  453201:   6922 kcbgtcr(0xFFFFFD7FFAED1730,0,1060,0) [tsn: 2233 rdba: 0x19400085 (101/133) obj: 2286272 dobj: 2286272] where: 1060 exam: 0
  458011:   2301 kcbgtcr(0xFFFFFD7FFAED1730,0,1060,0) [tsn: 2233 rdba: 0x19400085 (101/133) obj: 2286272 dobj: 2286272] where: 1060 exam: 0 
  479314:   2777 kcbgcur(0xFFFFFD7FFAED9270,2,1199,0) [tsn: 2231 rdba: 0xe5400084 (917/132) obj: 2286270 dobj: 2286270] where: 1199 mode_held: 2
  484221:   2266 kcbgcur(0xFFFFFD7FFAED9270,2,1199,0) [tsn: 2231 rdba: 0xe5400084 (917/132) obj: 2286270 dobj: 2286270] where: 1199 mode_held: 2
  506878:   2334 kcbgcur(0xFFFFFD7FFAED9270,2,1199,0) [tsn: 2231 rdba: 0xe5400084 (917/132) obj: 2286270 dobj: 2286270] where: 1199 mode_held: 2
  511463:   2202 kcbgcur(0xFFFFFD7FFAED9270,2,1199,0) [tsn: 2231 rdba: 0xe5400084 (917/132) obj: 2286270 dobj: 2286270] where: 1199 mode_held: 2
  532201:   2334 kcbgcur(0xFFFFFD7FFAED9270,2,1199,0) [tsn: 2231 rdba: 0xe5400084 (917/132) obj: 2286270 dobj: 2286270] where: 1199 mode_held: 2
  536500:   1965 kcbgcur(0xFFFFFD7FFAED9270,2,1199,0) [tsn: 2231 rdba: 0xe5400084 (917/132) obj: 2286270 dobj: 2286270] where: 1199 mode_held: 2
  556552:   2244 kcbgcur(0xFFFFFD7FFAED9270,2,1199,0) [tsn: 2231 rdba: 0xe5400084 (917/132) obj: 2286270 dobj: 2286270] where: 1199 mode_held: 2
  560690:   1834 kcbgcur(0xFFFFFD7FFAED9270,2,1199,0) [tsn: 2231 rdba: 0xe5400084 (917/132) obj: 2286270 dobj: 2286270] where: 1199 mode_held: 2
  577493:   3208 kcbgtcr(0xFFFFFD7FFAED1730,0,1060,0) [tsn: 2233 rdba: 0x19400086 (101/134) obj: 2286272 dobj: 2286272] where: 1060 exam: 0
  581798:   2276 kcbgtcr(0xFFFFFD7FFAED1730,0,1060,0) [tsn: 2233 rdba: 0x19400086 (101/134) obj: 2286272 dobj: 2286272] where: 1060 exam: 0
    --Repeated lines removed--
  
  1786824:   5448 kcbgcur(0xFFFFFD7FFFDF3200,1,1062,0) [tsn: 2233 rdba: 0x19400083 (101/131) obj: 2286272 dobj: 2286272] where: 1062 mode_held: 1
  1791226:   2020 kcbgcur(0xFFFFFD7FFFDF3200,1,1062,0) [tsn: 2233 rdba: 0x19400083 (101/131) obj: 2286272 dobj: 2286272] where: 1062 mode_held: 1
  1830860:  17280 kcbget(0xFFFFFD7FFFDF3200,2,1066,0) [tsn: 2233 rdba: 0x19400084 (101/132) obj: 2286272 dobj: 2286272] where: 1066 mode_held: 2
  1841407:   2737 kcbget(0xFFFFFD7FFFDF3200,2,1066,0) [tsn: 2233 rdba: 0x19400084 (101/132) obj: 2286272 dobj: 2286272] where: 1066 mode_held: 2
  1885701:   3609 kcbgcur(0xFFFFFD7FFFDF3200,1,1062,0) [tsn: 2233 rdba: 0x19400083 (101/131) obj: 2286272 dobj: 2286272] where: 1062 mode_held: 1
  1890635:   1952 kcbgcur(0xFFFFFD7FFFDF3200,1,1062,0) [tsn: 2233 rdba: 0x19400083 (101/131) obj: 2286272 dobj: 2286272] where: 1062 mode_held: 1
  1904651:   3127 kcbget(0xFFFFFD7FFFDF3200,2,1066,0) [tsn: 2233 rdba: 0x19400085 (101/133) obj: 2286272 dobj: 2286272] where: 1066 mode_held: 2
  1909925:   2340 kcbget(0xFFFFFD7FFFDF3200,2,1066,0) [tsn: 2233 rdba: 0x19400085 (101/133) obj: 2286272 dobj: 2286272] where: 1066 mode_held: 2
   --Repeated lines removed--   
     
     
  2202041:   5066 kcbgcur(0xFFFFFD7FFFDF3200,1,1062,0) [tsn: 2232 rdba: 0xe8c00083 (931/131) obj: 2286271 dobj: 2286271] where: 1062 mode_held: 1
  2206643:   2018 kcbgcur(0xFFFFFD7FFFDF3200,1,1062,0) [tsn: 2232 rdba: 0xe8c00083 (931/131) obj: 2286271 dobj: 2286271] where: 1062 mode_held: 1
  2220344:   5196 kcbget(0xFFFFFD7FFFDF3200,2,1066,0) [tsn: 2232 rdba: 0xe8c00087 (931/135) obj: 2286271 dobj: 2286271] where: 1066 mode_held: 2
  2224948:   2136 kcbget(0xFFFFFD7FFFDF3200,2,1066,0) [tsn: 2232 rdba: 0xe8c00087 (931/135) obj: 2286271 dobj: 2286271] where: 1066 mode_held: 2
  2242122:   2441 kcbgcur(0xFFFFFD7FFFDF3200,1,1062,0) [tsn: 2232 rdba: 0xe8c00083 (931/131) obj: 2286271 dobj: 2286271] where: 1062 mode_held: 1
  2246527:   2011 kcbgcur(0xFFFFFD7FFFDF3200,1,1062,0) [tsn: 2232 rdba: 0xe8c00083 (931/131) obj: 2286271 dobj: 2286271] where: 1062 mode_held: 1
  2255942:   2484 kcbget(0xFFFFFD7FFFDF3200,2,1066,0) [tsn: 2232 rdba: 0xe8c0008a (931/138) obj: 2286271 dobj: 2286271] where: 1066 mode_held: 2
  2260392:   1987 kcbget(0xFFFFFD7FFFDF3200,2,1066,0) [tsn: 2232 rdba: 0xe8c0008a (931/138) obj: 2286271 dobj: 2286271] where: 1066 mode_held: 2
   --Repeated lines removed--   


===================== Logical I/O Summary (grouped by object/function) ==============
 function    stat   object_id   data_object_id   mode_held   where     bufs     calls
--------- ------- ----------- ---------------- ----------- ------- -------- ---------
  kcbgcur      cu           0               -1           2      53        2         2
  kcbgcur      cu           0               -1           2      86        2         2
  kcbgcur      cu           0               -1           2      88        2         2
  kcbgtcr      cr     2286272          2286272                1298        2         2
  kcbgtcr      cr     2286272          2286272                1299        2         2
   kcbnew      cu           0               -1                  47        2         2
  kcbgcur      cu     2286271          2286271           1    1062        8         8
   kcbget      cu     2286271          2286271           2    1066        8         8
  kcbgtcr      cr     2286272          2286272                1060       20        20
  kcbgcur      cu     2286272          2286272           1    1062       22        22
   kcbget      cu     2286272          2286272           2    1066       22        22
  kcbgcur      cu     2286270          2286270           2    1199       82        82
=====================================================================================

================================= Logical I/O Summary (grouped by object) ==========================================
 object_id  data_object_id       lio        cr    cr (e)    cr (d)        cu    cu (d) ispnd (Y) ispnd (N)   pin rls
---------- --------------- --------- --------- --------- --------- --------- --------- --------- --------- ---------
         0              -1         8         0         0         0         8         0         0         0         2
   2286270         2286270        82         0         0         0        82         0         0         0        82         
   2286271         2286271        16         0         0         0        16         0         0         0         0
   2286272         2286272        68        24         2         0        44         0         0         2        18
---------- --------------- --------- --------- --------- --------- --------- --------- --------- --------- ---------
     total                       174        24         2         0       150         0         0         2       102
====================================================================================================================


2.3 Test_3



--******************************* SQL Trace *******************************--
delete /*+ test_3 use_concat index_ss(@DEL$1_1 T@DEL$1 ksun_tab#u#2) 
  index_ffs(@DEL$1_2 T@DEL$1_2 ksun_tab#u#2) */ ksun_tab t where 99 in (id2, id1)


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         23        211          41
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      0.00       0.00          0         23        211          41

ows (avg)  Row Source Operation
---------  ---------------------------------------------------
        0  DELETE  KSUN_TAB (cr=23 pr=0 pw=0 time=1180 us)
       41   CONCATENATION  (cr=23 pr=0 pw=0 time=398 us)
        0    INDEX SKIP SCAN KSUN_TAB#U#2 (cr=6 pr=0 pw=0 time=72 us cost=3 size=14 card=1)(object id 2286272)
       41    INDEX FAST FULL SCAN KSUN_TAB#U#2 (cr=17 pr=0 pw=0 time=242 us cost=5 size=574 card=41)(object id 2286272)
           

--******************************* dtrace *******************************--
  131208:   3788 kcbgtcr(0xFFFFFD7FFFDE5230,0,798,0) [tsn: 0 rdba: 0x5133b8 (1/1127352) obj: 1577349 dobj: 1577349] where: 798 exam: 0
  181969:   3256 kcbgtcr(0xFFFFFD7FFFDE4E40,0,798,0) [tsn: 0 rdba: 0x5133b8 (1/1127352) obj: 1577349 dobj: 1577349] where: 798 exam: 0
    --Repeated lines removed -- 
    
  2537995:   2950 kcbgcur(0xFFFFFD7FFA0FB028,2,1199,0) [tsn: 2231 rdba: 0xe5400085 (917/133) obj: 2286270 dobj: 2286270] where: 1199 mode_held: 2
  2543063:   2038 kcbgcur(0xFFFFFD7FFA0FB028,2,1199,0) [tsn: 2231 rdba: 0xe5400085 (917/133) obj: 2286270 dobj: 2286270] where: 1199 mode_held: 2
  2557738:   2324 kcbgcur(0xFFFFFD7FFFDF4660,1,1062,0) [tsn: 2232 rdba: 0xe8c00083 (931/131) obj: 2286271 dobj: 2286271] where: 1062 mode_held: 1
  2562180:   2074 kcbgcur(0xFFFFFD7FFFDF4660,1,1062,0) [tsn: 2232 rdba: 0xe8c00083 (931/131) obj: 2286271 dobj: 2286271] where: 1062 mode_held: 1
  2569550:   3515 kcbget(0xFFFFFD7FFFDF4660,2,1066,0) [tsn: 2232 rdba: 0xe8c00087 (931/135) obj: 2286271 dobj: 2286271] where: 1066 mode_held: 2
  2575512:   2290 kcbget(0xFFFFFD7FFFDF4660,2,1066,0) [tsn: 2232 rdba: 0xe8c00087 (931/135) obj: 2286271 dobj: 2286271] where: 1066 mode_held: 2
  2584580:   2492 kcbgcur(0xFFFFFD7FFFDF4660,1,1062,0) [tsn: 2233 rdba: 0x19400083 (101/131) obj: 2286272 dobj: 2286272] where: 1062 mode_held: 1
  2589073:   2002 kcbgcur(0xFFFFFD7FFFDF4660,1,1062,0) [tsn: 2233 rdba: 0x19400083 (101/131) obj: 2286272 dobj: 2286272] where: 1062 mode_held: 1
  2594662:   2312 kcbget(0xFFFFFD7FFFDF4660,2,1066,0) [tsn: 2233 rdba: 0x19400086 (101/134) obj: 2286272 dobj: 2286272] where: 1066 mode_held: 2
  2599288:   1901 kcbget(0xFFFFFD7FFFDF4660,2,1066,0) [tsn: 2233 rdba: 0x19400086 (101/134) obj: 2286272 dobj: 2286272] where: 1066 mode_held: 2
    --Repeated lines removed (40 Repeats)--   

===================== Logical I/O Summary (grouped by object/function) ==============
 function    stat   object_id   data_object_id   mode_held   where     bufs     calls
--------- ------- ----------- ---------------- ----------- ------- -------- ---------
  kcbgcur      cu           0               -1           2      53        2         2
  kcbgcur      cu           0               -1           2      88        2         2
  kcbgtcr      cr     1577349          1577349                 799        2         2
  kcbgtcr      cr     2286272          2286272                 798        2         2
  kcbgcur      cu           0               -1           2      86        4         4
  kcbgtcr      cr     1577349          1577349                 798        4         4
  kcbgtcr      cr     2286272          2286272                 799        4         4
  kcbgtcr      cr     2286272          2286272                 800        4         4
   kcbnew      cu           0               -1                  47        4         4
  kcbgtcr      cr     2286272          2286272                1153       12        12
  kcbgtcr      cr     2286272          2286272                1118       24        24
  kcbgcur      cu     2286270          2286270           2    1199       82        82
  kcbgcur      cu     2286271          2286271           1    1062       82        82
  kcbgcur      cu     2286272          2286272           1    1062       82        82
   kcbget      cu     2286271          2286271           2    1066       82        82
   kcbget      cu     2286272          2286272           2    1066       82        82
=====================================================================================

================================= Logical I/O Summary (grouped by object) ==========================================
 object_id  data_object_id       lio        cr    cr (e)    cr (d)        cu    cu (d) ispnd (Y) ispnd (N)   pin rls
---------- --------------- --------- --------- --------- --------- --------- --------- --------- --------- ---------
   1577349         1577349         6         6         0         0         0         0         0         0         6
         0              -1        12         0         0         0        12         0         0         0         4
   2286270         2286270        82         0         0         0        82         0         0         0        82
   2286271         2286271       164         0         0         0       164         0         0         0         0
   2286272         2286272       210        46         0         0       164         0         0         0        46
---------- --------------- --------- --------- --------- --------- --------- --------- --------- --------- ---------
     total                       474        52         0         0       422         0         0         0       138
====================================================================================================================


3. Discussions


Note that Dtrace Script statistics are double counted, which will be discussed in next Section: Dtrace Script double counted Statistics.
(a). Looking execution statistics of all 3 Tests, which delete the same 41 rows:

         Test    Consistent Gets  Current Gets
         ------  ---------------  ------------
         Test_1               12           211
         Test_1               12            75
         Test_1               23           211
         
     the majority of Logical Read is generated from Current Gets.

(b). Test_1 makes 211 Current Mode Gets, whereas Test_2 does 75 Current Mode Gets.

     In Test_1, dtrace shows that each Current Get(kcbgcur) of KSUN_TAB (obj: 2286270) 
     follows by two Current Gets (kcbgcur and kcbgcur) of KSUN_TAB#U#1 (obj: 2286271) 
     and two Current Gets (kcbgcur and kcbgcur) of KSUN_TAB#U#2 (obj: 2286272). 
     41 deleted Rows results in:
     
           41 (KSUN_TAB)  + 2*41 (KSUN_TAB#U#1) + 2*41 (KSUN_TAB#U#2) = 205 Current Gets
           
     plus 4 Current Gets (kcbgcur) and 2 Current Gets (kcbnew) of UNDO Segments (dobj: -1). 
     So in total, 205 + 4 + 2 = 211.
     
     In Test_2, at first, 41 Current Gets (kcbgcur) of KSUN_TAB (obj: 2286270) for 41 deleted Rows, 
     then 8 Current Gets (kcbgcur and kcbgcur) of KSUN_TAB#U#2 (obj: 2286272), 
     and 22 Current Gets (kcbgcur and kcbgcur) of KSUN_TAB#U#1 (obj: 2286271):
     
           41 (KSUN_TAB)  + 8 (KSUN_TAB#U#2) + 22 (KSUN_TAB#U#1) = 71 Current Gets
           
     plus 3 Current Gets (kcbgcur) and 1 Current Gets (kcbnew) of UNDO Segments (dobj: -1). 
     So in total, 71 + 3 + 1 = 75.

(c). SQL Trace xplan contains only Consistent Mode Gets ("cr=xxx"), but not Current Mode Gets.
     However, Current Mode Gets is included in xplan statistics under Column current.

(d). Test_3 makes 211 Current Mode Gets, same as Test_1 although only one single Index: 
     KSUN_TAB#U#2 is involved in xplan.
     
     Dtrace shows that it follows the same access pattern as Test_1 to read both KSUN_TAB#U#1 
     and KSUN_TAB#U#2 in Current Mode, but SQL Trace is not able to point out KSUN_TAB#U#1 Gets.

(e). Test_3 SQL Trace published 23 Consistent Mode Gets (query=23), but Dtrace shows 26 (=52/2). 
     The 3 (=26-23) is to read RMTAB$ (object_id = 1577349), which are not disclosed in SQL Trace.
     (See MOS: Bug 20853821 - HIgh number of executions for queries on rmtab$ (Doc ID 20853821.8))
     
     Therefore, SQL Trace is not able to disclose all Logical Reads.
     
     Probably they stem from recursive calls, which can be visible in Sqlplus Autotrace.


4. Dtrace Script double counted Statistics


Comparing dtracelio.d output with SQL Trace:
    Test1: SQL Trace  query = 12 current = 211
           Dtrace     cr    = 24 cu      = 422    
           
    Test2: SQL Trace  query = 12 current =  75
           Dtrace     cr    = 24 cu      = 150             
it seems that Dtrace double counts cr and cu (also verified with Sqlplus Autotrace, v$sql.buffer_gets, and sys.dbms_sqltune.report_sql_monitor). In all tests, we purposely deleted and selected odd number of rows (41), but all number in dtrace Summary are even number.

We can observe this double counting when comparing 3 different Traces: one Sql Trace, one 10200 trace, and one dtrace for the same query.

At first, a small dtrace command shows us that each kcbgtcr is called by ktrget2, so in 10200 Trace, there is almost a 1-to-1 mapping between kcbgtcr and ktrget2.

SQL Trace shows that the query made cr=15 on KSUN_TAB#U#2 (object id 2286272), and 28-15=13 on KSUN_TAB (object id 2286270). dtracelio.d shows that cr=30 on object_id=2286272, cr=26 on object_id= 2286270.

10200 Trace contains two rows for each ktrget2 (which is immediate parent of kcbgtcr) call, first is "started", second is "completed", which probably caused this double counting.

--*************************** kcbgtcr is called by ktrget2 ***************************--
SQL > select/*+ test_2 index(t ksun_tab#U#2) */ * from ksun_tab t where 99 in (id2, id1);

$ dtrace -n 'pid$target::kcbgtcr:entry {ustack(2, 0); @[pid, ustack(2, 0)] = count();}' -p 23585
    oracle`kcbgtcr
    oracle`ktrgtc2+0x332
    
    oracle`kcbgtcr
    oracle`ktrgtc2+0x332
    
    oracle`kcbgtcr
    oracle`ktrget2+0x2b7    
  --53 Repeated lines removed-- 
    
    oracle`kcbgtcr
    oracle`ktrgtc2+0x332
      2
      
    oracle`kcbgtcr
    oracle`ktrget2+0x2b7
     54


--******************************* SQL Trace *******************************--
select /*+ test_2 index(t ksun_tab#U#2) */ * from ksun_tab t where 99 in (id2, id1)

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        4      0.00       0.00          0         28          0          41
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        6      0.00       0.00          0         28          0          41

Rows (avg)  Row Source Operation
----------  ---------------------------------------------------
        41  TABLE ACCESS BY INDEX ROWID BATCHED KSUN_TAB (cr=28 pr=0 pw=0 time=49 us cost=7 size=574 card=41)
        41   INDEX FULL SCAN KSUN_TAB#U#2 (cr=15 pr=0 pw=0 time=636 us cost=6 size=0 card=41)(object id 2286272)


--******************************* 10200 Trace *******************************--
alter session set tracefile_identifier = 'test_2_10200_trace';
alter session set events '10200 trace name context forever,level 10';
  select/*+ test_2 index(t ksun_tab#U#2) */ * from ksun_tab t where 99 in (id2, id1);
alter session set events '10200 trace name context off'; 
 
   ktrget2(): started   for block <0x08b7 : 0xe5400083> objd: 0x0022e2be (KSUN_TAB)
   ktrget2(): completed for block <0x08b7 : 0xe5400083> objd: 0x0022e2be (KSUN_TAB)
       
   ktrget2(): started   for block <0x08b9 : 0x1940008e> objd: 0x0022e2c0 (KSUN_TAB#U#2)
   ktrget2(): completed for block <0x08b9 : 0x1940008e> objd: 0x0022e2c0 (KSUN_TAB#U#2)
 --Repeated lines removed-- 
 
 
--******************************* dtrace *******************************--
SQL > select/*+ test_2 index(t ksun_tab#U#2) */ * from ksun_tab t where 99 in (id2, id1);
   
$ > dtracelio.d 23585

  1365716:  10444 kcbgtcr(0xFFFFFD7FFAEE4798,0,1061,0) [tsn: 2233 rdba: 0x19400084 (101/132) obj: 2286272 dobj: 2286272] where: 1061 exam: 0
  1372023:   2458 kcbgtcr(0xFFFFFD7FFAEE4798,0,1061,0) [tsn: 2233 rdba: 0x19400084 (101/132) obj: 2286272 dobj: 2286272] where: 1061 exam: 0
  1399863:   2673 kcbgtcr(0xFFFFFD7FFA0FA518,0,1007,0) [tsn: 2231 rdba: 0xe5400083 (917/131) obj: 2286270 dobj: 2286270] where: 1007 exam: 0
  1403855:   2116 kcbgtcr(0xFFFFFD7FFA0FA518,0,1007,0) [tsn: 2231 rdba: 0xe5400083 (917/131) obj: 2286270 dobj: 2286270] where: 1007 exam: 0
  1457916:   5590 kcbgtcr(0xFFFFFD7FFAEE4798,0,1060,0) [tsn: 2233 rdba: 0x19400085 (101/133) obj: 2286272 dobj: 2286272] where: 1060 exam: 0
  1462033:   2347 kcbgtcr(0xFFFFFD7FFAEE4798,0,1060,0) [tsn: 2233 rdba: 0x19400085 (101/133) obj: 2286272 dobj: 2286272] where: 1060 exam: 0
  1493378:   2493 kcbgtcr(0xFFFFFD7FFA0FA518,0,1007,0) [tsn: 2231 rdba: 0xe5400084 (917/132) obj: 2286270 dobj: 2286270] where: 1007 exam: 0
  1497338:   2096 kcbgtcr(0xFFFFFD7FFA0FA518,0,1007,0) [tsn: 2231 rdba: 0xe5400084 (917/132) obj: 2286270 dobj: 2286270] where: 1007 exam: 0    
   --Repeated lines removed-- 
     
===================== Logical I/O Summary (grouped by object/function) ==============
 function    stat   object_id   data_object_id   mode_held   where     bufs     calls
--------- ------- ----------- ---------------- ----------- ------- -------- ---------
  kcbgtcr      cr     2286272          2286272                1298        2         2
  kcbgtcr      cr     2286272          2286272                1299        2         2
  kcbgtcr      cr     2286272          2286272                1061        6         6
  kcbgtcr      cr     2286272          2286272                1060       20        20
  kcbgtcr      cr     2286270          2286270                1007       26        26
=====================================================================================

================================= Logical I/O Summary (grouped by object) ==========================================
 object_id  data_object_id       lio        cr    cr (e)    cr (d)        cu    cu (d) ispnd (Y) ispnd (N)   pin rls
---------- --------------- --------- --------- --------- --------- --------- --------- --------- --------- ---------
         0               0         0         0         0         0         0         0         0         2         0
   2286270         2286270        26        26         0         0         0         0       130        32        26
   2286272         2286272        30        30         2         0         0         0         0         8        28
---------- --------------- --------- --------- --------- --------- --------- --------- --------- --------- ---------
     total                        56        56         2         0         0         0       130        42        54
====================================================================================================================


5. Performance Test


Run above 3 Tests 10000 times and watch their statistics difference.

alter system flush shared_pool; 

declare
 p_cnt number := 10000;
begin
  for i in 1..p_cnt loop
    delete /*+ test_1 use_concat index_ss(@DEL$1 T@DEL$1 ksun_tab#u#2) index_ss(@DEL$1_2 T@DEL$1_2 ksun_tab#u#1) */ 
      ksun_tab t where 99 in (id2, id1);
    rollback;
  end loop;
  
  for i in 1..p_cnt loop
    delete /*+ test_2 index(t ksun_tab#U#2)  */ ksun_tab t where 99 in (id2, id1);
    rollback;
  end loop;  
  
  for i in 1..p_cnt loop
    delete /*+ test_3 use_concat index_ss(@DEL$1_1 T@DEL$1 ksun_tab#u#2) index_ffs(@DEL$1_2 T@DEL$1_2 ksun_tab#u#2) */ 
      ksun_tab t where 99 in (id2, id1);
    rollback;
  end loop;  
end;
/

select substr(sql_text, 1, 18) sql_text, buffer_gets, round(buffer_gets/10000) buffer_gets_per_exec
      ,rows_processed, physical_read_bytes, physical_write_bytes, elapsed_time, cpu_time, sql_id  --, v.*
from v$sql v where lower(sql_text) like 'delete%test%' order by v.sql_text;

SQL_TEXT          BUFFER_GETS BUFFER_GETS_PER_EXEC ROWS_PROCESSED PHYSICAL_READ_BYTES PHYSICAL_WRITE_BYTES ELAPSED_TIME CPU_TIME SQL_ID
----------------- ----------- -------------------- -------------- ------------------- -------------------- ------------ -------- -------------
DELETE /*+ test_1     2210823                  221         410000             1146880            210026496      7534494  7400730 g2267fmk9u39r
DELETE /*+ test_2      870403                   87         410000              786432            210026496      7802519  7755552 5xqavr92xbvw7
DELETE /*+ test_3     2320261                  232         410000              401408            105013248      9445604  9320234 66dw2ur1uakhn


6. dtracelio.d


Dtrace script is appended in the Blog for a quick reference. The script is extended with time stamp and time delta similar to truss (-d, -D options) prefixed in each output line.

#!/usr/sbin/dtrace -CZs

/* Add time stamp and time delta similar to truss (-d, -D options) */

/********************************************************************************************/
/*                                                                                          */
/*   File Name:    dtracelio.d                                                              */
/*   Version:      2.1                                                                     */
/*   Authors:      Alexander Anokhin ( http://alexanderanokhin.com )                        */
/*                 Andrey Nikolaev   ( http://andreynikolaev.wordpress.com )                */
/*   Dated:        Mar 2012                                                                 */
/*   Purpose:      The script shows calls of the functions                                  */
/*                 performing logical I/O in Oracle.                                        */
/*                                                                                          */
/*   Usage:        dtracelio.d  [show_each_call] [interval]                            */
/*                 PID: unix process ID                                                     */
/*                 show_each_call - Bitmask determining how functions calls will be shown   */
/*                                  1st bit - logical I/O functions                         */
/*                                  2nd bit - buffer pinning                                */
/*                                  Examples:                                               */
/*                                    0: output of each call will be disabled               */
/*                                    1: logical I/O functions will be shown                */
/*                                    3: logical I/O and buffer pinning functions           */
/*                                       will be shown                                      */
/*                                  Default value: 1                                        */
/*                 interval - Specifies the number of seconds over which                    */
/*                            Summary form with cumulative figures will be shown.           */
/*                            Works only when show_each_call is disabled.                   */
/*                                                                                          */
/*   Other:        Some bits of info in 8103.1                                              */
/*                 Note that data structures definitions are not full                       */
/*                 in current version of the script                                         */
/*                                                                                          */
/********************************************************************************************/

#pragma D option quiet
#pragma D option defaultargs
#pragma D option switchrate=10Hz

/*      0. Several standard oratype.h declarations */

typedef unsigned long long ub8; /* unsigned int of length 8 */
typedef unsigned int       ub4;
typedef unsigned short     ub2;
typedef unsigned char      ub1;
typedef int       sb4;

/*  */
typedef sb4 kobjd;
typedef sb4 kobjn;
typedef ub4 ktsn;
typedef ub4 krdba;

/* definition from MOS note 8103.1 */

typedef struct kdbafr /* full relative dba */ {
    ktsn tsn_kdbafr;  /* a tablespace number */
    krdba dba_kdbafr; /* a relative dba */ } kdbafr;

typedef struct ktid /* relative dba + objd */ {
    struct kdbafr dbr_ktid; /* a relative dba */
    kobjd objd_ktid; /* data object number */
    kobjn objn_ktid; /* dictionary object number */ } ktid;

typedef struct kcbds
{
    struct ktid kcbdstid; /* full relative DBA plus object number */
    /* Here unknown (yet ;-)) part of the structure */ } kcbds;

BEGIN
{
    show_each_call      = ($$2 == NULL) ? 1:$2;
    tick_time_interval  = ($$3 == NULL) ? 0:$3;
    trace_logical_io    = 1;
    trace_buf_pinning   = 1;
    show_lio_calls      = show_each_call & 1;
    show_buf_pins_calls = show_each_call & 2;
    printf("\nDynamic tracing of Oracle logical I/O v2.1 by Alexander Anokhin ( http://alexanderanokhin.wordpress.com )\n\n"); 
    t0 = 0;
}

pid$1::kcbgtcr:entry,
pid$1::kcbgcur:entry,
pid$1::kcbnew:entry,
pid$1::kcbrls:entry,
pid$1::kcbispnd:entry,
pid$1::kcbldrget:entry,
pid$1::kcbget:entry
{
    blk         = ((kcbds *) copyin(arg0, sizeof(kcbds)));
    tsn         = blk->kcbdstid.dbr_ktid.tsn_kdbafr;
    rdba        = blk->kcbdstid.dbr_ktid.dba_kdbafr;
    objd        = blk->kcbdstid.objd_ktid;
    objn        = blk->kcbdstid.objn_ktid;
    rdba_file   = rdba >> 22; /* for smallfile tablespaces */
    rdba_block  = rdba & 0x3FFFFF;
    t0 = (t0 == 0) ? timestamp:t0; t1 = timestamp;
}



pid$1::kcbgtcr:entry
/trace_logical_io/
{
    stat       = "cr";
    where      = arg2&0xFFFF;
    mode_held  = "";

    @func[probefunc,stat,objn,objd,mode_held,where] = count();
    @bufs[probefunc,stat,objn,objd,mode_held,where] = sum(1);

    @obj_cr[objn,objd] = sum(1);
    @total_cr = sum(1);

    @obj_cr_exam[objn,objd] = sum(arg1);
    @total_cr_exam = sum(arg1);

    @obj_lio[objn,objd] = sum(1);
    @total_lio = sum(1);
}

pid$1::kcbgtcr:entry
/trace_logical_io && show_lio_calls/
{   t2 = timestamp; printf("%10d: %6d ", t2-t0, t2-t1); t1 = t2;    /* Elapsed nanosecond from beginning: Elapsed delta from last printf */
    printf("%s(0x%X,%d,%d,%d) [tsn: %d rdba: 0x%x (%d/%d) obj: %d dobj: %d] where: %d exam: %d\n",probefunc,arg0,arg1,arg2,arg3,tsn, rdba,rdba_file,rdba_block,objn, objd, where, arg1); }


pid$1::kcbldrget:entry
/trace_logical_io/
{
    stat       = "cr (d)";
    where      = 0;
    mode_held  = "";

    @func[probefunc,stat,objn,objd,mode_held,where] = count();
    @bufs[probefunc,stat,objn,objd,mode_held,where] = sum(1);

    @obj_cr_d[objn,objd] = sum(1);
    @total_cr_d = sum(1);

    @obj_cr[objn,objd] = sum(-1);
    @total_cr = sum(-1);

  /* commented because incremented in kcbgtcr yet
    @obj_lio[objn,objd] = sum(1);
    @total_lio = sum(1);
  */
}

pid$1::kcbldrget:entry
/trace_logical_io && show_lio_calls/
{   t2 = timestamp; printf("%10d: %6d ", t2-t0, t2-t1); t1 = t2;
    printf("%s(0x%X,%d,%d,%d)\n",probefunc,arg0,arg1,arg2,arg3);
}


pid$1::kcbgcur:entry,
pid$1::kcbget:entry
/trace_logical_io/
{
    stat       = "cu";
    where      = arg2&0xFFFF;
    mode_held  = lltostr(arg1);

    @func[probefunc,stat,objn,objd,mode_held,where] = count();
    @bufs[probefunc,stat,objn,objd,mode_held,where] = sum(1);

    @obj_cu[objn,objd] = sum(1);
    @total_cu  = sum(1);

    @obj_lio[objn,objd] = sum(1);
    @total_lio = sum(1);
}

pid$1::kcbgcur:entry,
pid$1::kcbget:entry
/trace_logical_io && show_lio_calls/
{   t2 = timestamp; printf("%10d: %6d ", t2-t0, t2-t1); t1 = t2;
    printf("%s(0x%X,%d,%d,%d) [tsn: %d rdba: 0x%x (%d/%d) obj: %d dobj: %d] where: %d mode_held: %s\n",probefunc,arg0,arg1,arg2,arg3,tsn, rdba,rdba_file,rdba_block,objn, objd, where, mode_held); }

pid$1::kcbnew:entry
/trace_logical_io/
{
    stat       = "cu";
    where      = arg2&0xFFFF;
    mode_held  = "";
    blocks     = arg1;

    @func[probefunc,stat,objn,objd,mode_held,where] = count();
    @bufs[probefunc,stat,objn,objd,mode_held,where] = sum(blocks);

    @obj_cu[objn,objd] = sum(blocks);
    @total_cu = sum(blocks);

    @obj_lio[objn,objd] = sum(blocks);
    @total_lio = sum(blocks);
}

pid$1::kcbnew:entry
/trace_logical_io && show_lio_calls/
{   t2 = timestamp; printf("%10d: %6d ", t2-t0, t2-t1); t1 = t2;
    printf("%s(0x%X,%d,%d,%d) [tsn: %d rdba: 0x%x (%d/%d) obj: %d dobj: %d] where: %d mode_held: %s blocks: %d\n",probefunc,arg0,arg1,arg2,arg3,tsn, rdba,rdba_file,rdba_block,objn, objd, where, mode_held, blocks); }

pid$1::kcblnb:entry, pid$1::kcblnb_dscn:entry /trace_logical_io/ {
    stat = "cu (d)";
    @func[probefunc,stat,0,0,"",0] = count();
    @bufs[probefunc,stat,0,0,"",0] = sum(1);

    @obj_cu[objn,objd] = sum(1);
    @total_cu = sum(1);

    @obj_cu_d[objn,objd] = sum(1);
    @total_cu_d = sum(1);

    @obj_lio[objn,objd] = sum(1);
    @total_lio = sum(1);
}



pid$1::kcblnb:entry, pid$1::kcblnb_dscn:entry /trace_logical_io && show_lio_calls/ {
    t2 = timestamp; printf("%10d: %6d ", t2-t0, t2-t1); t1 = t2;
    printf("%s(0x%X,%d,%d,%d)\n",probefunc,arg0,arg1,arg2,arg3);
}



/* buffer pinning */

pid$1::kcbispnd:entry
/trace_buf_pinning && show_buf_pins_calls/ {
    t2 = timestamp; printf("%10d: %6d ", t2-t0, t2-t1); t1 = t2;
    printf("%s(0x%X,%d,%d,%d) [tsn: %d rdba: 0x%x (%d/%d) obj: %d dobj: %d]: ",probefunc,arg0,arg1,arg2,arg3,tsn, rdba,rdba_file,rdba_block,objn,objd);
}

pid$1::kcbispnd:return
/trace_buf_pinning && arg1 == 0/
{
    @obj_is_not_pnd[objn,objd] = sum(1);
    @total_is_not_pnd = sum(1);
}

pid$1::kcbispnd:return
/trace_buf_pinning && arg1 == 1/
{
    @obj_is_pnd[objn,objd] = sum(1);;
    @total_is_pnd = sum(1);
}

pid$1::kcbispnd:return
/trace_buf_pinning && show_buf_pins_calls/ {
    t2 = timestamp; printf("%10d: %6d ", t2-t0, t2-t1); t1 = t2;
    printf("%d\n",arg1);
}

pid$1::kcbrls:entry
/trace_buf_pinning/
{
    @obj_pinrls[objn,objd] = sum(1);
    @total_pinrls = sum(1);
}

pid$1::kcbrls:entry
/trace_buf_pinning && show_buf_pins_calls/ {
    t2 = timestamp; printf("%10d: %6d ", t2-t0, t2-t1); t1 = t2;
    printf("%s(0x%X,%d,%d,%d) [tsn: %d rdba: 0x%x (%d/%d) obj: %d dobj: %d]\n",probefunc,arg0,arg1,arg2,arg3,tsn, rdba,rdba_file,rdba_block,objn,objd);
}


tick-1sec
/show_each_call == 0 && tick_time_interval > 0 && ++ticks >= tick_time_interval/ {
    printf("\n\n");
    printf("\n================================= Logical I/O Summary (grouped by object) ==========================================\n");
    printf(" object_id  data_object_id       lio        cr    cr (e)    cr (d)        cu    cu (d) ispnd (Y) ispnd (N)   pin rls\n");
    printf("---------- --------------- --------- --------- --------- --------- --------- --------- --------- --------- ---------\n");
    printa("%10d %15d %9@d %9@d %9@d %9@d %9@d %9@d %9@d %9@d %9@d\n", 
            @obj_lio, @obj_cr, @obj_cr_exam, @obj_cr_d, @obj_cu, @obj_cu_d, @obj_is_pnd, @obj_is_not_pnd, @obj_pinrls);
    printf("---------- --------------- --------- --------- --------- --------- --------- --------- --------- --------- ---------\n");
    printa("     total %25@d %9@d %9@d %9@d %9@d %9@d %9@d %9@d %9@d\n", @total_lio, @total_cr, @total_cr_exam, @total_cr_d, @total_cu, @total_cu_d, @total_is_pnd, @total_is_not_pnd, @total_pinrls);
    printf("====================================================================================================================\n");
    ticks = 0;
}



END
{
    printf("\n===================== Logical I/O Summary (grouped by object/function) ==============\n");
    printf(" function    stat   object_id   data_object_id   mode_held   where     bufs     calls\n");
    printf("--------- ------- ----------- ---------------- ----------- ------- -------- ---------\n");
    printa("%9s %7s %11d %16d %11s %7d %@8d %@9d\n", @bufs, @func);
    printf("=====================================================================================\n");
}

END
{
    printf("\n================================= Logical I/O Summary (grouped by object) ==========================================\n");
    printf(" object_id  data_object_id       lio        cr    cr (e)    cr (d)        cu    cu (d) ispnd (Y) ispnd (N)   pin rls\n");
    printf("---------- --------------- --------- --------- --------- --------- --------- --------- --------- --------- ---------\n");
    printa("%10d %15d %9@d %9@d %9@d %9@d %9@d %9@d %9@d %9@d %9@d\n", 
            @obj_lio, @obj_cr, @obj_cr_exam, @obj_cr_d, @obj_cu, @obj_cu_d, @obj_is_pnd, @obj_is_not_pnd, @obj_pinrls);
    printf("---------- --------------- --------- --------- --------- --------- --------- --------- --------- --------- ---------\n");
    printa("     total %25@d %9@d %9@d %9@d %9@d %9@d %9@d %9@d %9@d\n", @total_lio, @total_cr, @total_cr_exam, @total_cr_d, @total_cu, @total_cu_d, @total_is_pnd, @total_is_not_pnd, @total_pinrls);
    printf("====================================================================================================================\n");
    printf("\n");
    printf("Legend\n");
    printf("lio      : logical gets (cr + cu)\n");
    printf("cr       : consistent gets\n");
    printf("cr (e)   : consistent gets - examination\n");
    printf("cr (d)   : consistent gets direct\n");
    printf("cu       : db block gets\n");
    printf("cu (d)   : db block gets direct\n");
    printf("ispnd (Y): buffer is pinned count\n");
    printf("ispnd (N): buffer is not pinned count\n");
    printf("pin rls  : pin releases\n");
}