library cache lock caused by wrong password login

Well mostly when DBA’s got called, conversation start with “everything is running slow”. Sometime back got same type of call from client that, we are not able to login to the system and calls are not processed.  Well started investigation and found that lot’s of session are waiting for library cache lock wait and here is ASH report which pretty much gives the reason for this locks


          Analysis Begin Time:   08-Jun-15 09:00:00
            Analysis End Time:   08-Jun-15 09:22:00
                 Elapsed Time:        22.0 (mins)
            Begin Data Source:   V$ACTIVE_SESSION_HISTORY
              End Data Source:   V$ACTIVE_SESSION_HISTORY
                 Sample Count:     206,434
      Average Active Sessions:      156.39
  Avg. Active Session per CPU:        6.52
                Report Target:   None specified

                                                               Avg Active
Event                               Event Class        % Event   Sessions
----------------------------------- --------------- ---------- ----------
library cache lock                  Concurrency          99.36     155.39

Top Event P1/P2/P3 Values     DB/Inst: PCHGCH/PCHGCH1  (Jun 08 09:00 to 09:22)

Event                          % Event  P1 Value, P2 Value, P3 Value % Activity
------------------------------ ------- ----------------------------- ----------
Parameter 1                Parameter 2                Parameter 3
-------------------------- -------------------------- --------------------------
library cache lock               99.36 "33699225536","3006886000","5       0.43
handle address             lock address               100*mode+namespace

Top Phases of Execution       DB/Inst: PCHGCH/PCHGCH1  (Jun 08 09:00 to 09:22)

                                          Avg Active
Phase of Execution             % Activity   Sessions
------------------------------ ---------- ----------
Connection Management               99.57     155.71

Top Call Types                DB/Inst: PCHGCH/PCHGCH1  (Jun 08 09:00 to 09:22)

Call Type                                     Count % Activity Avg Active
---------------------------------------- ---------- ---------- ----------
OAUTH                                       205,543      99.57     155.71

                         Slot                                   Event
Slot Time (Duration)    Count Event                             Count % Event
-------------------- -------- ------------------------------ -------- -------
09:00:00   (2.0 min)   18,508 library cache lock               18,290    8.86
                              CPU + Wait for CPU                  123    0.06
                              enq: JS - queue lock                 65    0.03
09:02:00   (2.0 min)   18,934 library cache lock               18,768    9.09
                              CPU + Wait for CPU                  107    0.05
                              row cache lock                       21    0.01
09:04:00   (2.0 min)   18,105 library cache lock               18,001    8.72
                              CPU + Wait for CPU                   96    0.05
                              library cache pin                     3    0.00
09:06:00   (2.0 min)   16,978 library cache lock               16,853    8.16
                              CPU + Wait for CPU                  118    0.06
                              Disk file Mirror Read                 3    0.00
09:08:00   (2.0 min)   19,685 library cache lock               19,591    9.49
                              CPU + Wait for CPU                   88    0.04
                              ADR block file read                   1    0.00
09:10:00   (2.0 min)   20,215 library cache lock               20,088    9.73
                              CPU + Wait for CPU                  111    0.05
                              Streams AQ: qmn coordinator wa        6    0.00
09:12:00   (2.0 min)   19,816 library cache lock               19,696    9.54
                              CPU + Wait for CPU                  120    0.06
09:14:00   (2.0 min)   17,866 library cache lock               17,812    8.63
                              CPU + Wait for CPU                   49    0.02
                              reliable message                      4    0.00
09:16:00   (2.0 min)   17,419 library cache lock               17,318    8.39
                              CPU + Wait for CPU                   85    0.04
                              control file sequential read          6    0.00
09:18:00   (2.0 min)   19,683 library cache lock               19,582    9.49
                              CPU + Wait for CPU                  100    0.05
                              ADR block file read                   1    0.00
09:20:00   (2.0 min)   19,225 library cache lock               19,117    9.26
                              CPU + Wait for CPU                   92    0.04
                              direct path read                      6    0.00

So, as you can see from above output 155 AAS was waiting for this lock which explains why call are not completing and from line 30 and 36 we can say that something is going wrong with the authentication. Well further we can see something same in AWR also.


                                                           Avg
                                                          wait   % DB
Event                                 Waits     Time(s)   (ms)   time Wait Class
------------------------------ ------------ ----------- ------ ------ ----------
library cache lock                    3,158     751,422 2.E+05   99.6 Concurrenc
DB CPU                                            1,735            .2
inactive session                         60          57    951     .0 Other
control file sequential read         73,205          34      0     .0 System I/O
enq: PS - contention                 21,631          30      1     .0 Other

Statistic Name                                       Time (s) % of DB Time
------------------------------------------ ------------------ ------------
connection management call elapsed time             752,541.7         99.7
sql execute elapsed time                              1,814.3           .2
DB CPU                                                1,734.6           .2
PL/SQL execution elapsed time                           266.5           .0
parse time elapsed                                        8.7           .0

So, connection management was consuming majority of DB time. Unfortunately we haven’t enabled auditing due to some other issues. But, here is output from Tanel’s awesome tool.

dashtop

Well further investigating found out that this may caused because of

High “Library Cache Locks” Wait Time Due to Invalid Login Attempts (Doc ID 1309738.1)

Bug 19637855 : LIBRARY CACHE LOCK CAUSED BY WRONG PASSWORD LOGIN

Advertisements

Consider Reverse Key Index

Well this post was inspired by seeing some reverse index in our environment to avoid contention (May be tested with small set of data and might not have observed issues), which was pretty good but as we know this has very ugly side effects. Most of us know about it but this is just an reminder to myself and use reverse key indexes with extreme caution otherwise can lead to wild wild west.

So, as mention earlier there are few very nasty side effects of reverse key index and let’s start with some test. 1st performance test case with select queries based on reverse index, oh by the way i am not going to mention that reverse key index can’t be used with range predicates as we know.

Let’s start by creating a test table from dba_objects


create table REV_TEST parallel 4 tablespace soe as
select rownum id,x.owner,x.object_name,x.object_id,x.object_type,x.created
from dba_objects x ,(select rownum from dual connect by level <=100) y;

create unique index IX_REV_TEST on REV_TEST(ID) ;
exec dbms_Stats.gather_table_stats(null,'REV_TEST',cascade=>true,degree=>4);

declare
name rev_test.object_name%type;
begin
for i in 50000..60000 loop
select object_name into name from REV_TEST where id=i;
end loop;
end;
/

Now With first test case without reverse index, here are the details for that for loop with first showing size, leaf blocks and clustering factor


Non Reverse

SEGMENT_NAME                 MB     BLOCKS
-------------------- ---------- ----------
IX_REV_TEST                1472     188416
REV_TEST              5634.4375     721208

CLUSTERING_FACTOR
-----------------
           900381

   LF_BLKS   PCT_USED
---------- ----------
    182577         90

Before Any Query

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute  10001      0.51       0.56          0          0          0           0
Fetch    10001      0.14       0.12        113      40004          0       10001
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total    20003      0.66       0.69        113      40004          0       10001

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         1          1          1  TABLE ACCESS BY INDEX ROWID REV_TEST (cr=4 pr=4 pw=0 time=1808 us cost=3 size=31 card=1)
         1          1          1   INDEX UNIQUE SCAN IX_REV_TEST (cr=3 pr=3 pw=0 time=1323 us cost=2 size=0 card=1)(object id 109599)

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  Disk file operations I/O                        2        0.00          0.00
  db file sequential read                       113        0.00          0.

As, you can see that we did approximately same amount of IO to get that equality key. Now, let’s drop this table and recreate same data but using reverse key index.


SEGMENT_NAME                 MB     BLOCKS
-------------------- ---------- ----------
IX_REV_TEST                1472     188416
REV_TEST              5634.4375     721208

CLUSTERING_FACTOR
-----------------
         83834113

   LF_BLKS   PCT_USED
---------- ----------
    182716         90

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute  10001      0.04       0.58          0          0          0           0
Fetch    10001      2.49       4.72      10342      40004          0       10001
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total    20003      2.54       5.31      10342      40004          0       10001

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         1          1          1  TABLE ACCESS BY INDEX ROWID REV_TEST (cr=4 pr=4 pw=0 time=3668 us cost=3 size=31 card=1)
         1          1          1   INDEX UNIQUE SCAN IX_REV_TEST (cr=3 pr=3 pw=0 time=3171 us cost=2 size=0 card=1)(object id 109598)

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  db file sequential read                     10342        0.01          4.13

As, you can see from above output you’r clustering factor went to the roof, and now all your key are scattered all over the place and you have to do more IO’s to get that same work done and if this grows beyond your cache imagine what would happen, you’r cache will constantly flush in flush out blocks and even good blocks.

This is one case what about insert performance, because all we did this to avoid right hand tree contention reduction. While doing this let’s see what we have introduced here. First without reverse key


insert into rev_test select 82221812+rownum id,x.owner,x.object_name,x.object_id,x.object_type,x.created
    from dba_objects x

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.01       0.02          0          0          0           0
Execute      1      0.47       0.52       1622       5355      13497       91156
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      0.49       0.54       1622       5355      13497       91156

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  db file sequential read                       100        0.00          0.04
  db file scattered read                          1        0.00          0.00
  direct path read                                6        0.00          0.01
  SQL*Net message to client                       1        0.00          0.00
  SQL*Net message from client                     1        7.43          7.43

SEGMENT I/O WAIT SUMMARY
~~~~~~~~~~~~~~~~~~~~~~~~
                                                                 Wait   Times    Average        Max          Average
 #      Obj  Type  Segment Name(1)         Event Name         Time(2)  Waited  Wait Time  Wait Time  Blocks   Blocks
--- ------- ------ ---------------- ------------------------ -------- ------- ---------- ---------- ------- --------
 1:  109593 TABLE  TARAL.REV_TEST   db file sequential read     0.032      72   0.000441   0.002966      72        1
 2:      18 TABLE  SYS.OBJ$         direct path read            0.011       6   0.001901   0.006582      87     14.5

As, you can see we have inserted about 91k rows and our top io wait just not that bad, let’s see if we have reverse key index


insert into rev_test select 82312968+rownum id,x.owner,x.object_name,x.object_id,x.object_type,x.created
	from dba_objects x 

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.01       0.02          0          0          0           0
Execute      1      4.76      12.94      27508       4778     282675       91156
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      4.78      12.97      27508       4778     282675       91156

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  db file sequential read                     25986        0.05          9.99
  db file scattered read                          1        0.00          0.00
  direct path read                                6        0.00          0.00
  log file switch completion                      1        0.01          0.01
  SQL*Net message to client                       1        0.00          0.00
  SQL*Net message from client                     1        3.02          3.02

SEGMENT I/O WAIT SUMMARY
~~~~~~~~~~~~~~~~~~~~~~~~
                                                                   Wait   Times    Average        Max          Average
 #      Obj  Type   Segment Name(1)          Event Name         Time(2)  Waited  Wait Time  Wait Time  Blocks   Blocks
--- ------- ------ ------------------ ------------------------ -------- ------- ---------- ---------- ------- --------
 1:  109603 INDEX  TARAL.IX_REV_TEST  db file sequential read     9.966   25917   0.000385   0.053896   25917        1
 2:  109593 TABLE  TARAL.REV_TEST     db file sequential read     0.023      59   0.000385   0.001039      59        1

Now we have introduced much bigger problem with this. So, next time if you think of reverse key index consider all this issues. If anyone have anything more to say or can provide more information then i will be happy to include it

Oracle 12c TABLE ACCESS BY INDEX ROWID BATCHED


Few days back exploring 12c DB on my small VM found this little new feature. Here is the output from 11gR2

SQL_ID 3a936zyv7jupf, child number 0
-------------------------------------
SELECT w.WAREHOUSE_NAME, w.LOCATION_ID, i.PRODUCT_ID,i.QUANTITY_ON_HAND
 FROM WAREHOUSES w, INVENTORIES i WHERE i.PRODUCT_ID IN (10,5,1)
 AND w.WAREHOUSE_ID = i.WAREHOUSE_ID

Plan hash value: 2661993828

---------------------------------------------------------------------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows |E-Bytes| Cost (%CPU)| E-Time | A-Rows | A-Time | Buffers | Reads | OMem | 1Mem | Used-Mem |
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | | | 61 (100)| | 2604 |00:00:00.09 | 40 | 30 | | | |
|* 1 | HASH JOIN | | 1 | 2700 | 105K| 61 (2)| 00:00:01 | 2604 |00:00:00.09 | 40 | 30 | 947K| 947K| 1298K (0)|
| 2 | TABLE ACCESS FULL | WAREHOUSES | 1 | 1000 | 26000 | 2 (0)| 00:00:01 | 1000 |00:00:00.01 | 6 | 6 | | | |
| 3 | INLIST ITERATOR | | 1 | | | | | 2604 |00:00:00.07 | 34 | 24 | | | |
| 4 | TABLE ACCESS BY INDEX ROWID| INVENTORIES | 3 | 2700 | 37800 | 58 (0)| 00:00:01 | 2604 |00:00:00.07 | 34 | 24 | | | |
|* 5 | INDEX RANGE SCAN | INV_PROD_IX | 3 | 2700 | | 8 (0)| 00:00:01 | 2604 |00:00:00.05 | 17 | 10 | | | |
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------

Read more of this post

Oracle Partition Index in 11GR2

Here is the little new enhancement in 11gR2 11.2.0.2.0 regarding partition. Let’s say we have a partition table with monthly range partition. Mostly, customer query last month and current month data others partition are just rarely used. In 11gr2 you just have to maintain few local indexes others can be compromise. Here is little test case.

drop table test purge;
create table test (col1 number not null, col2 varchar2(100) not null, col3 date not null)
	partition by range(col3) (
	partition p_01_2011 values less than(to_date('01-JAN-2011','DD-MON-YYYY')),
	partition p_02_2011 values less than(to_date('01-FEB-2011','DD-MON-YYYY')),
	partition p_03_2011 values less than(to_date('01-MAR-2011','DD-MON-YYYY')),
	partition p_04_2011 values less than(to_date('01-APR-2011','DD-MON-YYYY')),
	partition p_05_2011 values less than(to_date('01-MAY-2011','DD-MON-YYYY')),
	partition p_06_2011 values less than(to_date('01-JUN-2011','DD-MON-YYYY')),
	partition p_07_2011 values less than(to_date('01-JUL-2011','DD-MON-YYYY')),
	partition p_08_2011 values less than(to_date('01-AUG-2011','DD-MON-YYYY')),
	partition p_09_2011 values less than(to_date('01-SEP-2011','DD-MON-YYYY')));

create index test_idx on test (col3) local UNUSABLE;

insert into test
	select rownum, rpad(rownum,100,'X'), to_date('01-DEC-2010','DD-MON-YYYY') + mod(rownum,28) from dual connect by level <= 10000
	union all
	select rownum, rpad(rownum,100,'X'), to_date('01-JAN-2011','DD-MON-YYYY') + mod(rownum,28) from dual connect by level <= 10000
	union all
	select rownum, rpad(rownum,100,'X'), to_date('01-FEB-2011','DD-MON-YYYY') + mod(rownum,28) from dual connect by level <= 10000
	union all
	select rownum, rpad(rownum,100,'X'), to_date('01-MAR-2011','DD-MON-YYYY') + mod(rownum,28) from dual connect by level <= 10000
	union all
	select rownum, rpad(rownum,100,'X'), to_date('01-APR-2011','DD-MON-YYYY') + mod(rownum,28) from dual connect by level <= 10000
	union all
	select rownum, rpad(rownum,100,'X'), to_date('01-MAY-2011','DD-MON-YYYY') + mod(rownum,28) from dual connect by level <= 10000
	union all
	select rownum, rpad(rownum,100,'X'), to_date('01-JUN-2011','DD-MON-YYYY') + mod(rownum,28) from dual connect by level <= 10000
	union all
	select rownum, rpad(rownum,100,'X'), to_date('01-JUL-2011','DD-MON-YYYY') + mod(rownum,28) from dual connect by level <= 10000
	union all
	select rownum, rpad(rownum,100,'X'), to_date('01-AUG-2011','DD-MON-YYYY') + mod(rownum,28) from dual connect by level <= 10000;

commit;
exec dbms_stats.gather_table_stats(user, 'TEST');

Now let’s start with different scenarios

linux6:TARAL.ORALINUX>select partition_name, status from user_ind_partitions where index_name ='TEST_IDX' order by 1;

PARTITION_NAME                 STATUS
------------------------------ --------
P_01_2011                      UNUSABLE
P_02_2011                      UNUSABLE
P_03_2011                      UNUSABLE
P_04_2011                      UNUSABLE
P_05_2011                      UNUSABLE
P_06_2011                      UNUSABLE
P_07_2011                      UNUSABLE
P_08_2011                      UNUSABLE
P_09_2011                      UNUSABLE

9 rows selected.

linux6:TARAL.ORALINUX>set autotrace on
linux6:TARAL.ORALINUX>select count(*) from test where col3 > to_date('01-JUN-2011', 'DD-MON-YYYY');

  COUNT(*)
----------
     29643

Execution Plan
----------------------------------------------------------
Plan hash value: 3670302319

--------------------------------------------------------------------------------------------------
| Id  | Operation                 | Name | Rows  | Bytes | Cost (%CPU)| Time     | Pstart| Pstop |
--------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT          |      |     1 |     8 |   144   (1)| 00:00:02 |       |       |
|   1 |  SORT AGGREGATE           |      |     1 |     8 |            |          |       |       |
|   2 |   PARTITION RANGE ITERATOR|      | 29333 |   229K|   144   (1)| 00:00:02 |     7 |     9 |
|*  3 |    TABLE ACCESS FULL      | TEST | 29333 |   229K|   144   (1)| 00:00:02 |     7 |     9 |
--------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   3 - filter("COL3">TO_DATE(' 2011-06-01 00:00:00', 'syyyy-mm-dd hh24:mi:ss'))

Statistics
----------------------------------------------------------
          1  recursive calls
          0  db block gets
        525  consistent gets
          0  physical reads
          0  redo size
        348  bytes sent via SQL*Net to client
        364  bytes received via SQL*Net from client
          2  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
          1  rows processed

linux6:TARAL.ORALINUX>set autotrace off
linux6:TARAL.ORALINUX>alter index test_idx rebuild partition p_09_2011 ;

Index altered.

linux6:TARAL.ORALINUX>alter index test_idx rebuild partition p_08_2011 ;

Index altered.

linux6:TARAL.ORALINUX>select partition_name, status from user_ind_partitions where index_name ='TEST_IDX' order by 1;

PARTITION_NAME                 STATUS
------------------------------ --------
P_01_2011                      UNUSABLE
P_02_2011                      UNUSABLE
P_03_2011                      UNUSABLE
P_04_2011                      UNUSABLE
P_05_2011                      UNUSABLE
P_06_2011                      UNUSABLE
P_07_2011                      UNUSABLE
P_08_2011                      USABLE
P_09_2011                      USABLE

9 rows selected.

linux6:TARAL.ORALINUX>set autotrace on
linux6:TARAL.ORALINUX>select count(*) from test where col3 > to_date('01-JUN-2011', 'DD-MON-YYYY');

  COUNT(*)
----------
     29643

Execution Plan
----------------------------------------------------------
Plan hash value: 1824872575

--------------------------------------------------------------------------------------------------------
| Id  | Operation                   | Name     | Rows  | Bytes | Cost (%CPU)| Time     | Pstart| Pstop |
--------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |          |     1 |     8 |    49   (0)| 00:00:01 |       |       |
|   1 |  SORT AGGREGATE             |          |     1 |     8 |            |          |       |       |
|   2 |   VIEW                      | VW_TE_2  | 29333 |       |    49   (0)| 00:00:01 |       |       |
|   3 |    UNION-ALL                |          |       |       |            |          |       |       |
|   4 |     PARTITION RANGE ITERATOR|          | 19690 |   153K|     0   (0)| 00:00:01 |     8 |     9 |
|*  5 |      INDEX RANGE SCAN       | TEST_IDX | 19690 |   153K|     0   (0)| 00:00:01 |     8 |     9 |
|   6 |     PARTITION RANGE SINGLE  |          |  9643 | 77144 |    49   (0)| 00:00:01 |     7 |     7 |
|*  7 |      TABLE ACCESS FULL      | TEST     |  9643 | 77144 |    49   (0)| 00:00:01 |     7 |     7 |
--------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   5 - access("TEST"."COL3">=TO_DATE(' 2011-07-01 00:00:00', 'syyyy-mm-dd hh24:mi:ss') AND
              "TEST"."COL3"<TO_DATE(' 2011-09-01 00:00:00', 'syyyy-mm-dd hh24:mi:ss'))
   7 - filter("COL3">TO_DATE(' 2011-06-01 00:00:00', 'syyyy-mm-dd hh24:mi:ss'))

Statistics
----------------------------------------------------------
          1  recursive calls
          0  db block gets
        231  consistent gets
         54  physical reads
          0  redo size
        348  bytes sent via SQL*Net to client
        364  bytes received via SQL*Net from client
          2  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
          1  rows processed

As, you can see from this it use nice union all transformation for this query where it use index for indexed partition and full table scan for unusable index partition. This is due to TE transformation that CBO does.

***********************************
Cost-Based Table Expansion
***********************************
TE: Checking validity of TE for query block SEL$1 (#1)
TE: Checking validity of table expansion for query block SEL$1 (#1)

TE: Using search type: linear
Table expansion on query block SEL$1 (#1)
TE: Considering table expansion on query block SEL$1 (#1)
TE: Starting iteration 1, state space = (1) : (0)
FPD: Considering simple filter push in query block SEL$1 (#1)
"TEST"."COL3">TO_DATE(' 2011-06-01 00:00:00', 'syyyy-mm-dd hh24:mi:ss')
try to generate transitive predicate from check constraints for query block SEL$1 (#1)
finally: "TEST"."COL3">TO_DATE(' 2011-06-01 00:00:00', 'syyyy-mm-dd hh24:mi:ss')

TE: Costing transformed query.

....
....
....

TE: after table expansion:******* UNPARSED QUERY IS *******

*** 2011-08-18 16:24:21.660
SELECT COUNT(*) "COUNT(*)" FROM  ( (SELECT 0 FROM "TARAL"."TEST" "TEST" WHERE "TEST"."COL3">TO_DATE('01-JUN-2011','DD-MON-YYYY') AND ("TEST"."COL3">=TO_DATE(' 2011-07-01 00:00:00','SYYYY-MM-DD HH24:MI:SS','NLS_CALENDAR=GREGORIAN') AND "TEST"."COL3"<TO_DATE(' 2011-09-01 00:00:00','SYYYY-MM-DD HH24:MI:SS','NLS_CALENDAR=GREGORIAN'))) UNION ALL  (SELECT 0 FROM "TARAL"."TEST" "TEST" WHERE "TEST"."COL3">TO_DATE('01-JUN-2011','DD-MON-YYYY') AND ("TEST"."COL3"<TO_DATE(' 2011-07-01 00:00:00','SYYYY-MM-DD HH24:MI:SS','NLS_CALENDAR=GREGORIAN')))) "VW_TE_1"
Registered qb: SET$11B8F94D 0x7fbdd1e8 (TABLE EXPANSION SEL$1; SEL$1; "TEST"@"SEL$1")

This can be controlled by hidden parameter _optimizer_table_expansion

linux6:TARAL.ORALINUX>set autotrace off
linux6:TARAL.ORALINUX>alter session set "_optimizer_table_expansion" = FALSE;

Session altered.

linux6:TARAL.ORALINUX>set autotrace on
linux6:TARAL.ORALINUX>select count(*) from test where col3 > to_date('01-JUN-2011', 'DD-MON-YYYY');

  COUNT(*)
----------
     29643

Execution Plan
----------------------------------------------------------
Plan hash value: 3670302319

--------------------------------------------------------------------------------------------------
| Id  | Operation                 | Name | Rows  | Bytes | Cost (%CPU)| Time     | Pstart| Pstop |
--------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT          |      |     1 |     8 |   144   (1)| 00:00:02 |       |       |
|   1 |  SORT AGGREGATE           |      |     1 |     8 |            |          |       |       |
|   2 |   PARTITION RANGE ITERATOR|      | 29333 |   229K|   144   (1)| 00:00:02 |     7 |     9 |
|*  3 |    TABLE ACCESS FULL      | TEST | 29333 |   229K|   144   (1)| 00:00:02 |     7 |     9 |
--------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   3 - filter("COL3">TO_DATE(' 2011-06-01 00:00:00', 'syyyy-mm-dd hh24:mi:ss'))

Statistics
----------------------------------------------------------
          1  recursive calls
          0  db block gets
        525  consistent gets
          0  physical reads
          0  redo size
        348  bytes sent via SQL*Net to client
        364  bytes received via SQL*Net from client
          2  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
          1  rows processed

And Even this works

linux6:TARAL.ORALINUX>drop index test_idx;

Index dropped.

linux6:TARAL.ORALINUX>create index test_idx on test (col3) local UNUSABLE;

Index created.

linux6:TARAL.ORALINUX>alter index test_idx rebuild partition p_06_2011 ;

Index altered.

linux6:TARAL.ORALINUX>alter index test_idx rebuild partition p_07_2011 ;

Index altered.

linux6:TARAL.ORALINUX>set autotrace on
linux6:TARAL.ORALINUX>select count(*) from test where col3 > to_date('01-MAY-2011', 'DD-MON-YYYY');

  COUNT(*)
----------
     39643

Execution Plan
----------------------------------------------------------
Plan hash value: 4227256123

--------------------------------------------------------------------------------------------------------
| Id  | Operation                   | Name     | Rows  | Bytes | Cost (%CPU)| Time     | Pstart| Pstop |
--------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |          |     1 |     8 |    96   (0)| 00:00:02 |       |       |
|   1 |  SORT AGGREGATE             |          |     1 |     8 |            |          |       |       |
|   2 |   VIEW                      | VW_TE_2  | 40023 |       |    96   (0)| 00:00:02 |       |       |
|   3 |    UNION-ALL                |          |       |       |            |          |       |       |
|   4 |     PARTITION RANGE ITERATOR|          | 20333 |   158K|     0   (0)| 00:00:01 |     6 |     7 |
|*  5 |      INDEX RANGE SCAN       | TEST_IDX | 20333 |   158K|     0   (0)| 00:00:01 |     6 |     7 |
|   6 |     PARTITION RANGE ITERATOR|          | 19690 |   153K|    96   (0)| 00:00:02 |     8 |     9 |
|   7 |      TABLE ACCESS FULL      | TEST     | 19690 |   153K|    96   (0)| 00:00:02 |     8 |     9 |
--------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   5 - access("COL3">TO_DATE(' 2011-05-01 00:00:00', 'syyyy-mm-dd hh24:mi:ss') AND
              "TEST"."COL3"<TO_DATE(' 2011-07-01 00:00:00', 'syyyy-mm-dd hh24:mi:ss'))

Statistics
----------------------------------------------------------
          1  recursive calls
          0  db block gets
        406  consistent gets
         54  physical reads
          0  redo size
        348  bytes sent via SQL*Net to client
        364  bytes received via SQL*Net from client
          2  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
          1  rows processed

So, little new but useful feature.

Oracle Index Monitoring

Today someone asked how to Monitor Index usage. It’s simple to turn on monitoring on index. Oracle support told there is no easy way to do it and in some term that is right too.

But the funny thing is, object usage report might be wrong while you rebuild or gather statistics on index and some other things. Well, Sometimes monitoring is not the right way to identify index usage. Mostly, this whole exercise is done for some space gain or for performance. For example in warehouse for each load they disable index and then rebuild after load and at this point of time performance degradation takes place while rebuilding indexes. This is not the part of discussion but we will include this also little bit today.

Here are some examples of this.

Let’s start with how v$object_usage columns are.

  • Create two Different Users test1 & test2
  • TEST1@taral > @desc sys.v$object_usage;
    
    Col# SEG_COL_ID Column Name                    Null?      Type
    ---- ---------- ------------------------------ ---------- -------------------------
       1          1 INDEX_NAME                     NOT NULL   VARCHAR2(30)
       2          2 TABLE_NAME                     NOT NULL   VARCHAR2(30)
       3          3 MONITORING                                VARCHAR2(3)
       4          4 USED                                      VARCHAR2(3)
       5          5 START_MONITORING                          VARCHAR2(19)
       6          6 END_MONITORING                            VARCHAR2(19)
    
    6 rows selected.
    
    TEST1@taral > @view sys.v$object_usage;
    
    Owner      VIEW_NAME                      View Text
    ---------- ------------------------------ ----------------------------------------------------------------
    SYS        V$OBJECT_USAGE                 select io.name, t.name,
                                              decode(bitand(i.flags, 65536), 0, 'NO', 'YES'),
                                              decode(bitand(ou.flags, 1), 0, 'NO', 'YES'),
                                              ou.start_monitoring,
                                              ou.end_monitoring
                                              from sys.obj$ io, sys.obj$ t, sys.ind$ i, sys.object_usage ou
                                              where io.owner# = userenv('SCHEMAID')
                                              and i.obj# = ou.obj#
                                              and io.obj# = ou.obj#
                                              and t.obj# = i.bo#
    
    
    First Test Case With Two Different Users
    =========================================
    drop table test1.xx purge;
    create table test1.xx as select object_id,object_name from dba_objects;
    create index test1.xx_idx on test1.xx(object_id);
    select * from v$object_usage;
    
    TEST1@taral > select * from v$object_usage;
    
    no rows selected
    
    TEST1@taral > alter index test1.xx_idx MONITORING USAGE;
    
    TEST1@taral > select * from v$object_usage;
    
    INDEX_NAME                     TABLE_NAME                     MON USE START_MONITORING    END_MONITORING
    ------------------------------ ------------------------------ --- --- ------------------- -------------------
    XX_IDX                         XX                             YES NO  10/20/2010 10:57:15
    
    TEST1@taral > select * from test1.xx; --Lines Not Displayed
    
    TEST1@taral > select * from v$object_usage;
    
    INDEX_NAME                     TABLE_NAME                     MON USE START_MONITORING    END_MONITORING
    ------------------------------ ------------------------------ --- --- ------------------- -------------------
    XX_IDX                         XX                             YES NO  10/20/2010 10:57:15
    
    select * from test1.xx where object_id=41;
    
    TEST1@taral > select * from v$object_usage;
    
    INDEX_NAME                     TABLE_NAME                     MON USE START_MONITORING    END_MONITORING
    ------------------------------ ------------------------------ --- --- ------------------- -------------------
    XX_IDX                         XX                             YES YES 10/20/2010 10:57:15
    
    But if i tried from different User (Because o.owner# = userenv('SCHEMAID'))
    
    TEST2@taral > select * from v$object_usage;
    
    no rows selected
    
    
    Second Test Case With Explain Plan
    =========================================
    set autotrace off;
    drop table test1.xx purge;
    create table test1.xx as select object_id,object_name from dba_objects;
    create index test1.xx_idx on test1.xx(object_id);
    select * from v$object_usage;
    alter index test1.xx_idx MONITORING USAGE;
    select * from v$object_usage;
    SET AUTOTRACE TRACEONLY EXPLAIN;
    select * from test1.xx where object_id=41;
    set autotrace off;
    select * from v$object_usage;
    
    TEST1@taral > select * from v$object_usage;
    
    INDEX_NAME                     TABLE_NAME                     MON USE START_MONITORING    END_MONITORING
    ------------------------------ ------------------------------ --- --- ------------------- -------------------
    XX_IDX                         XX                             YES NO  10/20/2010 15:32:32
    
    TEST1@taral > SET AUTOTRACE TRACEONLY EXPLAIN;
    TEST1@taral > select * from test1.xx where object_id=41;
    
    Execution Plan
    ----------------------------------------------------------
    Plan hash value: 2275028263
    
    --------------------------------------------------------------------------------------
    | Id  | Operation                   | Name   | Rows  | Bytes | Cost (%CPU)| Time     |
    --------------------------------------------------------------------------------------
    |   0 | SELECT STATEMENT            |        |     1 |    79 |     2   (0)| 00:00:01 |
    |   1 |  TABLE ACCESS BY INDEX ROWID| XX     |     1 |    79 |     2   (0)| 00:00:01 |
    |*  2 |   INDEX RANGE SCAN          | XX_IDX |     1 |       |     1   (0)| 00:00:01 |
    --------------------------------------------------------------------------------------
    
    TEST1@taral > set autotrace off;
    TEST1@taral > select * from v$object_usage;
    
    INDEX_NAME                     TABLE_NAME                     MON USE START_MONITORING    END_MONITORING
    ------------------------------ ------------------------------ --- --- ------------------- -------------------
    XX_IDX                         XX                             YES YES 10/20/2010 15:32:32
    
    
    Third Test Case With Index Rebuild
    -----------------------------------
    set autotrace off;
    drop table test1.xx purge;
    create table test1.xx as select object_id,object_name from dba_objects;
    create index test1.xx_idx on test1.xx(object_id);
    select * from v$object_usage;
    alter index test1.xx_idx MONITORING USAGE;
    select * from v$object_usage;
    alter index test1.xx_idx rebuild;
    select * from v$object_usage;
    ALTER INDEX test1.xx_idx NOMONITORING USAGE;
    
    TEST1@taral > select * from v$object_usage;
    
    INDEX_NAME                     TABLE_NAME                     MON USE START_MONITORING    END_MONITORING
    ------------------------------ ------------------------------ --- --- ------------------- -------------------
    XX_IDX                         XX                             YES NO  10/20/2010 15:38:58
    
    TEST1@taral > alter index test1.xx_idx rebuild;
    
    Index altered.
    
    TEST1@taral > select * from v$object_usage;
    
    INDEX_NAME                     TABLE_NAME                     MON USE START_MONITORING    END_MONITORING
    ------------------------------ ------------------------------ --- --- ------------------- -------------------
    XX_IDX                         XX                             NO  YES 10/20/2010 15:38:58
    
    TEST1@taral > alter index test1.xx_idx MONITORING USAGE;
    
    Index altered.
    
    TEST1@taral > select * from v$object_usage;
    
    INDEX_NAME                     TABLE_NAME                     MON USE START_MONITORING    END_MONITORING
    ------------------------------ ------------------------------ --- --- ------------------- -------------------
    XX_IDX                         XX                             YES NO  10/20/2010 15:39:50
    
    So, this query will solve this issue
    
    SELECT * FROM v$object_usage WHERE (monitoring='YES' AND used='YES') OR (used='YES' AND end_monitoring IS NOT NULL) ;
    
    

    As, in starting i said we will see some examples of how this can’t be useful.

    Let’s say there are 5-6 indexes on one table and i had turned on monitoring for all this indexes. Some query only hit this index once and that change the status of index. So, my report from v$object_usage will say i have to keep this index even though it has been used only once. So, this won’t say how many times this index has been really used. Also, there is other danger involved with this is you might end up deleting some index which you might need as monitoring may not give you whole picture.

     

     

    
    set autotrace off;
    drop table test1.xxf purge;
    drop table test1.xx purge;
    create table test1.xx (object_id number constraint xx_pk primary key, object_name varchar2(128)) ;
    insert into test1.xx select rownum,object_name from dba_objects where rownum < 2001; commit; select * from v$object_usage; alter index test1.xx_pk MONITORING USAGE; set autotrace on; select * from test1.xx where object_id=41; select * from test1.xx where object_id=100; set autotrace off; select * from v$object_usage; TEST1@taral > set autotrace off;
    TEST1@taral > drop table test1.xxf purge;
    
    Table dropped.
    
    TEST1@taral > drop table test1.xx purge;
    
    Table dropped.
    
    TEST1@taral > create table test1.xx (object_id number constraint xx_pk primary key, object_name varchar2(128)) ;
    
    Table created.
    
    TEST1@taral > insert into test1.xx select rownum,object_name from dba_objects where rownum < 2001; 2000 rows created. TEST1@taral > commit;
    
    Commit complete.
    
    TEST1@taral > select * from v$object_usage;
    
    no rows selected
    
    TEST1@taral > alter index test1.xx_pk MONITORING USAGE;
    
    Index altered.
    
    TEST1@taral > set autotrace on;
    TEST1@taral > select * from test1.xx where object_id=41;
    
     OBJECT_ID OBJECT_NAME
    ---------- --------------------------------------------------------------------------------------------------------------------------------
            41 FET$
    
    Execution Plan
    ----------------------------------------------------------
    Plan hash value: 266797879
    
    -------------------------------------------------------------------------------------
    | Id  | Operation                   | Name  | Rows  | Bytes | Cost (%CPU)| Time     |
    -------------------------------------------------------------------------------------
    |   0 | SELECT STATEMENT            |       |     1 |    79 |     2   (0)| 00:00:01 |
    |   1 |  TABLE ACCESS BY INDEX ROWID| XX    |     1 |    79 |     2   (0)| 00:00:01 |
    |*  2 |   INDEX UNIQUE SCAN         | XX_PK |     1 |       |     1   (0)| 00:00:01 |
    -------------------------------------------------------------------------------------
    
    TEST1@taral > select * from test1.xx where object_id=100;
    
     OBJECT_ID OBJECT_NAME
    ---------- --------------------------------------------------------------------------------------------------------------------------------
           100 FIXED_OBJ$
    
    Execution Plan
    ----------------------------------------------------------
    Plan hash value: 266797879
    
    -------------------------------------------------------------------------------------
    | Id  | Operation                   | Name  | Rows  | Bytes | Cost (%CPU)| Time     |
    -------------------------------------------------------------------------------------
    |   0 | SELECT STATEMENT            |       |     1 |    79 |     2   (0)| 00:00:01 |
    |   1 |  TABLE ACCESS BY INDEX ROWID| XX    |     1 |    79 |     2   (0)| 00:00:01 |
    |*  2 |   INDEX UNIQUE SCAN         | XX_PK |     1 |       |     1   (0)| 00:00:01 |
    -------------------------------------------------------------------------------------
    
    TEST1@taral > set autotrace off;
    TEST1@taral > select * from v$object_usage;
    
    INDEX_NAME                     TABLE_NAME                     MON USE START_MONITORING    END_MONITORING
    ------------------------------ ------------------------------ --- --- ------------------- -------------------
    XX_PK                          XX                             YES YES 10/20/2010 16:50:20
    

    So, this is not telling you how many times this index has been used.

    
    create table test1.xxf (object_id number, object_type varchar2(128) , constraint xxf_fk foreign key(object_id ) references xx(object_id));
    insert into test1.xxf select decode(mod(rownum,1000),0,1,mod(rownum,1000)) object_id, stage.object_type from dba_objects stage;
    commit;
    create index test1.xxf_fk on test1.xxf(object_id);
    exec dbms_stats.gather_table_stats(user,'XX');
    exec dbms_stats.gather_table_stats(user,'XXF');
    alter index test1.xxf_fk monitoring usage;
    select * from v$object_usage;
    set autotrace on;
    delete test1.xx where object_id = 2000;
    commit;
    set autotrace off;
    select * from v$object_usage;
    
    TEST1@taral > create table test1.xxf (object_id number, object_type varchar2(128) , constraint xxf_fk foreign key(object_id ) references xx(object_id))
    
    Table created.
    
    TEST1@taral > insert into test1.xxf select decode(mod(rownum,1000),0,1,mod(rownum,1000)) object_id, stage.object_type from dba_objects stage;
    
    72302 rows created.
    
    TEST1@taral > commit;
    
    Commit complete.
    
    TEST1@taral > create index test1.xxf_fk on test1.xxf(object_id);
    
    Index created.
    
    TEST1@taral > exec dbms_stats.gather_table_stats(user,'XX');
    
    PL/SQL procedure successfully completed.
    
    TEST1@taral > exec dbms_stats.gather_table_stats(user,'XXF');
    
    PL/SQL procedure successfully completed.
    
    TEST1@taral > alter index test1.xxf_fk monitoring usage;
    
    Index altered.
    
    TEST1@taral > select * from v$object_usage;
    
    INDEX_NAME                     TABLE_NAME                     MON USE START_MONITORING    END_MONITORING
    ------------------------------ ------------------------------ --- --- ------------------- -------------------
    XXF_FK                         XXF                            YES NO  10/20/2010 16:50:23
    XX_PK                          XX                             YES YES 10/20/2010 16:50:20
    
    TEST1@taral > set autotrace on;
    TEST1@taral > delete test1.xx where object_id = 2000;
    
    1 row deleted.
    
    Execution Plan
    ----------------------------------------------------------
    Plan hash value: 203824999
    
    ----------------------------------------------------------------------------
    | Id  | Operation          | Name  | Rows  | Bytes | Cost (%CPU)| Time     |
    ----------------------------------------------------------------------------
    |   0 | DELETE STATEMENT   |       |     1 |     4 |     1   (0)| 00:00:01 |
    |   1 |  DELETE            | XX    |       |       |            |          |
    |*  2 |   INDEX UNIQUE SCAN| XX_PK |     1 |     4 |     1   (0)| 00:00:01 |
    ----------------------------------------------------------------------------
    
    Predicate Information (identified by operation id):
    ---------------------------------------------------
    
       2 - access("OBJECT_ID"=2000)
    
    Statistics
    ----------------------------------------------------------
            178  recursive calls
              7  db block gets
             35  consistent gets
              0  physical reads
            116  redo size
            679  bytes sent via SQL*Net to client
            611  bytes received via SQL*Net from client
              3  SQL*Net roundtrips to/from client
              6  sorts (memory)
              0  sorts (disk)
              1  rows processed
    
    TEST1@taral > commit;
    
    Commit complete.
    
    TEST1@taral > set autotrace off;
    TEST1@taral > select * from v$object_usage;
    
    INDEX_NAME                     TABLE_NAME                     MON USE START_MONITORING    END_MONITORING
    ------------------------------ ------------------------------ --- --- ------------------- -------------------
    XXF_FK                         XXF                            YES NO  10/20/2010 16:50:23
    XX_PK                          XX                             YES YES 10/20/2010 16:50:20
    
    

    If you see now foreign key index is not been used from v$object_usage. So, it’s safe to delete it.

    
    TEST1@taral > drop index test1.xxf_fk;
    
    Index dropped.
    
    TEST1@taral > set autotrace on;
    TEST1@taral > delete test1.xx where object_id = 1999;
    
    1 row deleted.
    
    Execution Plan
    ----------------------------------------------------------
    Plan hash value: 203824999
    
    ----------------------------------------------------------------------------
    | Id  | Operation          | Name  | Rows  | Bytes | Cost (%CPU)| Time     |
    ----------------------------------------------------------------------------
    |   0 | DELETE STATEMENT   |       |     1 |     4 |     1   (0)| 00:00:01 |
    |   1 |  DELETE            | XX    |       |       |            |          |
    |*  2 |   INDEX UNIQUE SCAN| XX_PK |     1 |     4 |     1   (0)| 00:00:01 |
    ----------------------------------------------------------------------------
    
    Predicate Information (identified by operation id):
    ---------------------------------------------------
    
       2 - access("OBJECT_ID"=1999)
    
    Statistics
    ----------------------------------------------------------
            190  recursive calls
              7  db block gets
            217  consistent gets
              0  physical reads
            732  redo size
            679  bytes sent via SQL*Net to client
            611  bytes received via SQL*Net from client
              3  SQL*Net roundtrips to/from client
              6  sorts (memory)
              0  sorts (disk)
              1  rows processed
    
    TEST1@taral > commit;
    
    Commit complete.
    
    TEST1@taral >
    

    See how much now more work we have to do after removing index which was useful. So, don’t rely on v$object_usage. It’s not a metric.



    Reference: 

  • Secrets of the Oracle Database – Norbert Debes
  • Tim Hall

  • Insert All and 11gr2

    If you have many single insert statements then you can wrap into insert all which can reduce parsing and thus loading of that many single insert would be much faster. But, sometime back i saw some slowness in this particularly in 11gr2 and today again that thing bother me. So, though to publish this information see someone might have insight on this. Oh, Sorry to mention who else then Mr. Tanel i think off.

     Here is the test case

      

    
    TARAL> @wait print 101 e123 10000
                                                                                                                      % Total  Total Event   Distinct   Avg time
        SID STATE   EVENT                               P1                         P2              P3            SEQ#    Time      Time ms     Events   ms/Event
    ------- ------- ----------------------------------- -------------------------- --------------- --------------- ---------- ------- ------------ ---------- ----------
        101 WORKING On CPU / runqueue                                                                                  100.00      150.000          1    150.000
    
    TARAL> @wait print 101 e123 10000
                                                                                                                      % Total  Total Event   Distinct   Avg time
        SID STATE   EVENT                               P1                         P2              P3            SEQ#    Time      Time ms     Events   ms/Event
    ------- ------- ----------------------------------- -------------------------- --------------- --------------- ---------- ------- ------------ ---------- ----------
        101 WORKING On CPU / runqueue                                                                                  100.00      150.000          1    150.000
    
    TARAL> @wait print 101 e123 20000
                                                                                                                      % Total  Total Event   Distinct   Avg time
        SID STATE   EVENT                               P1                         P2              P3            SEQ#    Time      Time ms     Events   ms/Event
    ------- ------- ----------------------------------- -------------------------- --------------- --------------- ---------- ------- ------------ ---------- ----------
        101 WORKING On CPU / runqueue                                                                                  100.00      300.000          1    300.000
    
    TARAL> @wait print 101 e123 20000
                                                                                                                      % Total  Total Event   Distinct   Avg time
        SID STATE   EVENT                               P1                         P2              P3            SEQ#    Time      Time ms     Events   ms/Event
    ------- ------- ----------------------------------- -------------------------- --------------- --------------- ---------- ------- ------------ ---------- ----------
        101 WORKING On CPU / runqueue                                                                                  100.00      310.000          1    310.000
    
    ----------------------------------------------------------------------------------------------------------------------
        SID, USERNAME  , TYPE, STATISTIC                               ,         DELTA, HDELTA/SEC,    %TIME, GRAPH
    ----------------------------------------------------------------------------------------------------------------------
        101, TARAL, STAT, opened cursors cumulative               ,             6,         .3,
        101, TARAL, STAT, recursive calls                         ,            85,       4.25,
        101, TARAL, STAT, session logical reads                   ,            13,        .65,
        101, TARAL, STAT, CPU used by this session                ,         18561,     928.05,
        101, TARAL, STAT, session pga memory                      ,      19267584,    963.38k,
        101, TARAL, STAT, consistent gets                         ,            13,        .65,
        101, TARAL, STAT, consistent gets from cache              ,            13,        .65,
        101, TARAL, STAT, consistent gets from cache (fastpath)   ,             6,         .3,
        101, TARAL, STAT, consistent gets - examination           ,             6,         .3,
        101, TARAL, STAT, shared hash latch upgrades - no wait    ,             1,        .05,
        101, TARAL, STAT, calls to get snapshot scn: kcmgss       ,             6,         .3,
        101, TARAL, STAT, no work - consistent read gets          ,             6,         .3,
        101, TARAL, STAT, index scans kdiixs1                     ,             7,        .35,
        101, TARAL, STAT, sql area evicted                        ,            20,          1,
        101, TARAL, STAT, session cursor cache hits               ,             2,         .1,
        101, TARAL, STAT, session cursor cache count              ,            -1,       -.05,
        101, TARAL, STAT, buffer is not pinned count              ,             7,        .35,
        101, TARAL, STAT, parse time elapsed                      ,             1,        .05,
        101, TARAL, STAT, parse count (total)                     ,             4,         .2,
        101, TARAL, STAT, execute count                           ,             6,         .3,
        101, TARAL, STAT, sorts (memory)                          ,             3,        .15,
        101, TARAL, TIME, hard parse elapsed time                 ,     185463811,      9.27s,   927.3%, |@@@@@@@@@@|
        101, TARAL, TIME, repeated bind elapsed time              ,             4,       .2us,      .0%, |          |
        101, TARAL, TIME, parse time elapsed                      ,     185477232,      9.27s,   927.4%, |@@@@@@@@@@|
        101, TARAL, TIME, DB CPU                                  ,     185430000,      9.27s,   927.2%, |@@@@@@@@@@|
        101, TARAL, TIME, sql execute elapsed time                ,           453,    22.65us,      .0%, |          |
        101, TARAL, TIME, DB time                                 ,     185655283,      9.28s,   928.3%, |@@@@@@@@@@|
    --  End of snap 1, end=2010-10-13 15:46:53, seconds=20
    
    --- Here are some output from trace which confirms above
    
    call     count       cpu    elapsed       disk      query    current        rows
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    Parse        1     19.64      19.64          0          0          0           0
    Execute      1      0.04       0.04          0        406       1225         406
    Fetch        0      0.00       0.00          0          0          0           0
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    total        2     19.68      19.68          0        406       1225         406
    
    Misses in library cache during parse: 1
    Optimizer mode: CHOOSE
    Parsing user id: 147
    
    Rows     Row Source Operation
    -------  ---------------------------------------------------
          0  MULTI-TABLE INSERT  (cr=406 pr=0 pw=0 time=0 us)
          1   FAST DUAL  (cr=0 pr=0 pw=0 time=0 us cost=2 size=0 card=1)
    
    call     count       cpu    elapsed       disk      query    current        rows
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    Parse        1     59.50      59.51          0          0          0           0
    Execute      1      0.05       0.04          0        493       1488         493
    Fetch        0      0.00       0.00          0          0          0           0
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    total        2     59.55      59.56          0        493       1488         493
    
    Misses in library cache during parse: 1
    Optimizer mode: CHOOSE
    Parsing user id: 147
    
    call     count       cpu    elapsed       disk      query    current        rows
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    Parse        1     66.20      66.21          0          0          0           0
    Execute      1      0.07       0.07          0        697       2100         696
    Fetch        0      0.00       0.00          0          0          0           0
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    total        2     66.27      66.28          0        697       2100         696
    
    Misses in library cache during parse: 1
    Optimizer mode: CHOOSE
    Parsing user id: 147
    
    Rows     Row Source Operation
    -------  ---------------------------------------------------
          0  MULTI-TABLE INSERT  (cr=697 pr=0 pw=0 time=0 us)
          1   FAST DUAL  (cr=0 pr=0 pw=0 time=0 us cost=2 size=0 card=1)
    
    Here is the interesting part
    
       <-audRegFro()+200<-audRegFro()+300<-audRegFro()+300<-audRegFro()+300<-audRegFro()+300
       <-audRegFro()+300<-audRegFro()+300<-audRegFro()+300<-audRegFro()+300<-audRegFro()+300
       <-audRegFro()+300<-audRegFro()+300<-audRegFro()+300<-audRegFro()+300<-audRegFro()+300<-audRegFro()+300
       <-audRegFro()+300<-audRegFro()+300<-audRegFro()+300<-audRegFro()+300<-audRegFro()+300<-audRegFro()+300
       <-audRegFro()+300<-audRegFro()+300<-audRegFro()+300<-audRegFro()+300<-audRegFro()+300<-kkmpfcbk()+56
       <-qcsprfro()+992<-qcsprfro_tree()+324<-qcsprfro_tree()+400<-qcspqbDescendents()+292<-qcspqb()+324<-kkmdrv()+292
       <-opiSem()+2200<-opiDeferredSem()+420<-opitca()+236<-kksFullTypeCheck()+16<-rpiswu2()+656<-kksLoadChild()+10056
       <-kxsGetRuntimeLock()+1804<-kksfbc()+7408<-kkspsc0()+1512<-kksParseCursor()+176
       <-opiosq0()+2388<-kpooprx()+196<-kpoal8()+588<-opiodr()+1424<-ttcpip()+1056<-opitsk()+1512<-opiino()+1000<-opiodr()+1424
       <-opidrv()+1096<-sou2o()+92<-opimai_real()+304<-ssthrdmain()+240<-main()+308<-_start()+380
    
    After turning off auditing it went as expected
    
    call     count       cpu    elapsed       disk      query    current        rows
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    Parse        1      0.21       0.21          0          0          0           0
    Execute      1      0.04       0.03          2        406       1227         406
    Fetch        0      0.00       0.00          0          0          0           0
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    total        2      0.25       0.25          2        406       1227         406
    
    Misses in library cache during parse: 1
    Optimizer mode: CHOOSE
    Parsing user id: 147
    
    Rows     Row Source Operation
    -------  ---------------------------------------------------
          0  MULTI-TABLE INSERT  (cr=406 pr=2 pw=0 time=0 us)
          1   FAST DUAL  (cr=0 pr=0 pw=0 time=0 us cost=2 size=0 card=1)
    
    call     count       cpu    elapsed       disk      query    current        rows
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    Parse        1      0.53       0.54          0          0          0           0
    Execute      1      0.06       0.06          3        697       2103         696
    Fetch        0      0.00       0.00          0          0          0           0
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    total        2      0.59       0.61          3        697       2103         696