Performance After Streams Disabling

Yesterday, user running report called and told that his report is taking too much time. Previously it do completed in 10-15 Minutes approximately but today it ran for almost 1hr 30 minutes. Before going further a brief history on this database.

We were using bi-directional streams for replication but for few reasons to test we had drop stream’s configuration. We didn’t drop entirely just disabled apply and capture process. So, this was the only change we made nothing else was changed for this and reports started running slow.

Meanwhile asked user to run report again and saw some sequential reads nothing much. But, read time was high then it used to be. Other thing i though let’s see what’s happening with all other session

USERX@XXXXXX > @sw  196
    SID STATE   EVENT                                          SEQ# SEC_IN_WAIT P1                 P2                 P3                 P1TRANSL
------- ------- ---------------------------------------- ---------- ----------- ------------------ ------------------ ------------------ ------------------------------------------
    196 WORKING On CPU / runqueue                               994      629680 file#= 59          block#= 9591       blocks= 1

USERX@XXXXXX > @sw  196
    SID STATE   EVENT                                          SEQ# SEC_IN_WAIT P1                 P2                 P3                 P1TRANSL
------- ------- ---------------------------------------- ---------- ----------- ------------------ ------------------ ------------------ ------------------------------------------
    196 WORKING On CPU / runqueue                               994      629682 file#= 59          block#= 9591       blocks= 1
USERX@XXXXXX > @sw  196

    SID STATE   EVENT                                          SEQ# SEC_IN_WAIT P1                 P2                 P3                 P1TRANSL
------- ------- ---------------------------------------- ---------- ----------- ------------------ ------------------ ------------------ ------------------------------------------
    196 WORKING On CPU / runqueue                               994      629729 file#= 59          block#= 9591       blocks= 1

USERX@XXXXXX > @sw  196
    SID STATE   EVENT                                          SEQ# SEC_IN_WAIT P1                 P2                 P3                 P1TRANSL
------- ------- ---------------------------------------- ---------- ----------- ------------------ ------------------ ------------------ ------------------------------------------
    196 WORKING On CPU / runqueue                               994      629925 file#= 59          block#= 9591       blocks= 1

Strange, May be something is wrong. Let’s Look at all session (Mostly All connected User)

    SID STATE   EVENT                                          SEQ# SEC_IN_WAIT P1                 P2                 P3                 P1TRANSL
------- ------- ---------------------------------------- ---------- ----------- ------------------ ------------------ ------------------ ------------------------------------------
    117 WORKING On CPU / runqueue                               397      531751 file#= 59          block#= 9591       blocks= 1
     96 WORKING On CPU / runqueue                               685      191592 file#= 59          block#= 9591       blocks= 1
    251 WORKING On CPU / runqueue                               989       22991 file#= 59          block#= 9591       blocks= 1
    105 WORKING On CPU / runqueue                               966      197314 file#= 59          block#= 9591       blocks= 1
    113 WORKING On CPU / runqueue                               494      539386 file#= 59          block#= 9591       blocks= 1
    115 WORKING On CPU / runqueue                               427      189900 file#= 59          block#= 9591       blocks= 1
    117 WORKING On CPU / runqueue                               397      531763 file#= 59          block#= 9591       blocks= 1
    119 WORKING On CPU / runqueue                               547      520586 file#= 59          block#= 9591       blocks= 1
    126 WORKING On CPU / runqueue                               586        7956 file#= 59          block#= 9591       blocks= 1
    127 WORKING On CPU / runqueue                               348      710021 file#= 59          block#= 9591       blocks= 1
    132 WORKING On CPU / runqueue                              1087       18968 file#= 59          block#= 9591       blocks= 1
    104 WORKING On CPU / runqueue                               583      454268 file#= 59          block#= 9591       blocks= 1
    245 WORKING On CPU / runqueue                               669      454299 file#= 59          block#= 9591       blocks= 1
    237 WORKING On CPU / runqueue                              1085      438102 file#= 59          block#= 9591       blocks= 1
    236 WORKING On CPU / runqueue                              1168      453030 file#= 59          block#= 9591       blocks= 1
    231 WORKING On CPU / runqueue                               548      454175 file#= 59          block#= 9591       blocks= 1
    227 WORKING On CPU / runqueue                               600      526299 file#= 59          block#= 9591       blocks= 1
    215 WORKING On CPU / runqueue                               378      515927 file#= 59          block#= 9591       blocks= 1
    211 WORKING On CPU / runqueue                               265        7486 file#= 59          block#= 9591       blocks= 1
    198 WORKING On CPU / runqueue                              1186       21824 file#= 59          block#= 9591       blocks= 1
    196 WORKING On CPU / runqueue                               994      630006 file#= 59          block#= 9591       blocks= 1
    184 WORKING On CPU / runqueue                              1077      449734 file#= 59          block#= 9591       blocks= 1
    182 WORKING On CPU / runqueue                               372      713555 file#= 59          block#= 9591       blocks= 1
    178 WORKING On CPU / runqueue                              1206      454466 file#= 59          block#= 9591       blocks= 1
    175 WORKING On CPU / runqueue                               988      543158 file#= 59          block#= 9591       blocks= 1
    150 WORKING On CPU / runqueue                               595      452974 file#= 59          block#= 9591       blocks= 1
    151 WORKING On CPU / runqueue                               957       22541 file#= 59          block#= 9591       blocks= 1
    157 WORKING On CPU / runqueue                               234        3261 file#= 59          block#= 9591       blocks= 1
    163 WORKING On CPU / runqueue                               582      452932 file#= 59          block#= 9591       blocks= 1
    170 WORKING On CPU / runqueue                               650      449652 file#= 59          block#= 9591       blocks= 1
    202 WORKING On CPU / runqueue                              1093      716105 file#= 59          block#= 9592       blocks= 5

This is Strange. Something must be going on. Also, tried to see what other stats are there picking up any one session but no luck. Nothing was happening. But Yes CPU usage was much high. It’s time to look more

Start dump data blocks tsn: 101 file#: 59 minblk 9591 maxblk 9591
buffer tsn: 101 rdba: 0x0ec02577 (59/9591)
scn: 0x057c.82828596 seq: 0x02 flg: 0x04 tail: 0x85962302
frmt: 0x02 chkval: 0x56c5 type: 0x23=PAGETABLE SEGMENT HEADER
Hex dump of block: st=0, typ_found=1

USERX@XXXXXX > @oid 114474

owner                     object_name                    object_type        CREATED    LAST_DDL_T status    DATA_OBJECT_ID
------------------------- ------------------------------ ------------------ ---------- ---------- --------- --------------
XDB                       XDB$SCHEMA                     TABLE              11/23/2006 11/23/2006 VALID             114474

USERX@XXXXXX > select segment_name,header_file, header_block from dba_segments where owner='XDB' and segment_name='XDB$SCHEMA';

SEGMENT_NAME                                                                      HEADER_FILE HEADER_BLOCK
--------------------------------------------------------------------------------- ----------- ------------
XDB$SCHEMA                                                                                 59         9591

And this object is nothing but table of xmltype. Looking at this it seems like a corruption issue. Verified and this is not the case. Hmmm let’s see what sessions are doing.

USERX@XXXXXX > @usql 117

HASH_VALUE   CH#  PLAN_HASH SQL_TEXT
---------- ----- ---------- --------------------------------------------------------------------------------------------------------------
3767872888     0  677615252 select s.synonym_name object_name, o.object_type from all_synonyms s,      sys.all_objects o where s.owner in
                            ('PUBLIC', :schema) and o.owner = s.table_owner and o.object_name = s.table_name and o.object_type in
                            ('TABLE', 'VIEW', 'PACKAGE','TYPE', 'PROCEDURE', 'FUNCTION', 'SEQUENCE')

3767872888     1  677615252 select s.synonym_name object_name, o.object_type from all_synonyms s,      sys.all_objects o where s.owner in
                            ('PUBLIC', :schema) and o.owner = s.table_owner and o.object_name = s.table_name and o.object_type in
                            ('TABLE', 'VIEW', 'PACKAGE','TYPE', 'PROCEDURE', 'FUNCTION', 'SEQUENCE')

Tried to run this query manually.

USERX@XXXXXX > select s.synonym_name object_name, o.object_type
  2    from all_synonyms s, sys.all_objects o
  3   where s.owner in ('PUBLIC', 'USERX') <<-- This Bind Variable is Replaced
  4     and o.owner = s.table_owner
  5     and o.object_name = s.table_name
  6     and o.object_type in ('TABLE',
  7                           'VIEW',
  8                           'PACKAGE',
  9                           'TYPE',
 10                           'PROCEDURE',
 11                           'FUNCTION',
 12                           'SEQUENCE');

It hangs And session spins on CPU

USERX@XXXXXX > @sw  176

    SID STATE   EVENT                                          SEQ# SEC_IN_WAIT P1                 P2                 P3                 P1TRANSL
------- ------- ---------------------------------------- ---------- ----------- ------------------ ------------------ ------------------ ------------------------------------------
    176 WORKING On CPU / runqueue                              1049          66 file#= 59          block#= 9591       blocks= 1

And here is the actual Query which is hanging

 select count(*)  from user$ u, xdb.xdb$schema s  where u.user# = :1  and   u.name  = s.xmldata.schema_owner  and
 (xdb.xdb$Extname2Intname(s.xmldata.schema_url, s.xmldata.schema_owner) = :2)

We are not getting anywhere and still our original problem regarding reports still we haven’t touch itself. Let’s see what our report is doing. The reason why we are leaving this alone is just to solve first user issue and investigate this latter. Also, the report session is not experiencing this thing. I let the system as it is for 1.5 hrs till report complete. Here is the one SQL from report which is running slow and many more.

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        0      0.00       0.00          0          0          0           0
Execute    335      0.85       0.81          0          0          0           0
Fetch      335    222.43    2452.93     608516   10434554          0         335
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total      670    223.28    2453.75     608516   10434554          0         335

Misses in library cache during parse: 0
Optimizer mode: CHOOSE
Parsing user id: 1094     (recursive depth: 1)

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  db file sequential read                    607989        0.37       2272.88
  gc cr grant 2-way                            7435        0.04          4.63
  latch: cache buffers chains                    21        0.00          0.00
  latch: library cache                            2        0.00          0.00
  latch: gcs resource hash                       17        0.00          0.00

So, Sequential read is the culprit. This what this says. May be we can rewrite or throw some more better index to resolve this. Also, Let’s see statspack report also as we  are having other problem too.

Top 5 Timed Events                                         Avg %Total
~~~~~~~~~~~~~~~~~~                                        wait   Call
Event                                 Waits    Time (s)   (ms)   Time Wait Class
------------------------------ ------------ ----------- ------ ------ ----------
db file scattered read            1,834,168       3,321      2  167.2   User I/O
db file sequential read             383,394       1,443      4   72.7   User I/O
CPU time                                            370          18.6
gc current block 2-way              166,656         122      1    6.2    Cluster
os thread startup                     1,375          79     58    4.0 Concurrenc

cache buffer handles              2,746    0.0    N/A      0            0    N/A
cache buffers chains         77,966,867    0.0    0.0      0   28,852,899    0.0
cache buffers lru chain          10,382    0.5    0.0      0   30,691,321    0.1
cache table scan latch                0    N/A    N/A      0    1,833,334    0.0
channel handle pool latc          2,934    0.0    N/A      0            0    N/A
channel operations paren        326,804    0.0    0.0      0            0    N/A
checkpoint queue latch          105,819    0.0    N/A      0        2,036    0.0

           Tablespace                      Subobject  Obj.      Physical
Owner         Name    Object Name            Name     Type         Reads  %Total
---------- ---------- -------------------- ---------- ----- ------------ -------
STRM       USERS      AQ$_CAPTURE_SDOLTS01            TABLE   14,149,682   92.99
xxxxx      DATA_      AF                              TABLE      726,962    4.78

What wait’s are showing and statspack is showing are somehow different. After looking many other things found that streams’s propagation was still enable and there were lot’s of failed attempt to ping remote server.

So, Disabled and dropped that propagation. Voila, wait on that block was gone and CPU came down instantly. So, called user to try and run report again without changing anything. Same SQL took very less time.

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute    636      1.79       1.67          0          0          0           0
Fetch      636    185.53     386.00     264380   18954114          0         636
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total     1273    187.32     387.67     264380   18954114          0         636

Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: CHOOSE
Parsing user id: 1094     (recursive depth: 1)

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  row cache lock                                  1        0.00          0.00
  gc cr grant 2-way                            6449        0.00          2.88
  db file sequential read                    264013        0.13        178.93
  gc cr multi block request                       1        0.00          0.00
  db file scattered read                          1        0.00          0.00
  gc current block 2-way                      51453        0.64         39.90

And, report ran in 12 Minutes. Good Lesson learn.

Advertisements

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

  • TKPROF in 11gR2 – New Rows Columns

    In one of OTN thread I asked information about new columns in rowsource operation and Charles Hooper and Tom Kyte give some insight on this. I didn’t got chance to run test case provided by charles.

    In my previous post I had mention same thing and here are some more things which i tried today.

    I am using 11.2.0.1.0 Version and will update this page if i find something different in 11.2.0.2. Also, using windows 32 bit environment and Charles test case. Let’s get started.

    Here is the test setup

    drop table t1 purge;
    drop table t2 purge;
    CREATE TABLE T1(C1 NUMBER NOT NULL,C2 NUMBER NOT NULL,C3 VARCHAR2(100));
    CREATE TABLE T2(C1 NUMBER NOT NULL,C2 NUMBER NOT NULL,C3 VARCHAR2(100));
    
    INSERT INTO T1 SELECT ROWNUM C1,V2.RN C2,RPAD(TO_CHAR(ROWNUM),10,'A') C3 FROM
      (SELECT ROWNUM RN FROM DUAL CONNECT BY LEVEL<=1000) V1,
      (SELECT ROWNUM RN FROM DUAL CONNECT BY LEVEL<=1000) V2 WHERE MOD(V1.RN,1000)>=V2.RN;
    
    INSERT INTO T2 SELECT * FROM T1;
    COMMIT;
    
    CREATE INDEX IND_T1_C1_C2 ON T1(C1,C2);
    CREATE INDEX IND_T2_C1_C2 ON T2(C1,C2);
    
    EXEC DBMS_STATS.GATHER_TABLE_STATS(OWNNAME=>USER,TABNAME=>'T1',CASCADE=>TRUE);
    EXEC DBMS_STATS.GATHER_TABLE_STATS(OWNNAME=>USER,TABNAME=>'T2',CASCADE=>TRUE);
    

    This is test script

    
    VARIABLE N1 NUMBER
    EXEC :N1:=1
    
    ALTER SESSION SET TRACEFILE_IDENTIFIER = 'SQL_10046_ROW_TEST';
    ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT FOREVER, LEVEL 16';
    
    SELECT /*+ GATHER_PLAN_STATISTICS */ COUNT(*) FROM T1,T2 WHERE T1.C2=T2.C2 AND T1.C2= :N1;
    SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST'));
    
    EXEC :N1:=5
    
    SELECT /*+ GATHER_PLAN_STATISTICS */ COUNT(*) FROM T1,T2 WHERE T1.C2=T2.C2 AND T1.C2= :N1;
    
    SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST'));
    
    EXEC :N1:=95
    
    SELECT /*+ GATHER_PLAN_STATISTICS */ COUNT(*) FROM T1,T2 WHERE T1.C2=T2.C2 AND T1.C2= :N1;
    SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST'));
    
    EXEC :N1:=995
    
    SELECT /*+ GATHER_PLAN_STATISTICS */ COUNT(*) FROM T1,T2 WHERE T1.C2=T2.C2 AND T1.C2= :N1;
    SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST'));
    
    ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT OFF';
    
    

    This is the output

    TARAL@taral > SELECT /*+ GATHER_PLAN_STATISTICS */ COUNT(*) FROM T1,T2 WHERE T1.C2=T2.C2 AND T1.C2= :N1;
    
      COUNT(*)
    ----------
        998001
    
    TARAL@taral > SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST'));
    
    PLAN_TABLE_OUTPUT
    ------------------------------------------------------------------------------------------------------------------------------
    SQL_ID  8ygbsrkt6sqd9, child number 0
    -------------------------------------
    SELECT /*+ GATHER_PLAN_STATISTICS */ COUNT(*) FROM T1,T2 WHERE
    T1.C2=T2.C2 AND T1.C2= :N1
    
    Plan hash value: 765688747
    
    ------------------------------------------------------------------------------------------------------------------------------
    | Id  | Operation              | Name         | Starts | E-Rows | A-Rows |   A-Time   | Buffers | Reads  |  OMem |  1Mem | Use
    ------------------------------------------------------------------------------------------------------------------------------
    |   0 | SELECT STATEMENT       |              |      1 |        |      1 |00:00:00.34 |    2780 |      4 |       |       |
    |   1 |  SORT AGGREGATE        |              |      1 |      1 |      1 |00:00:00.34 |    2780 |      4 |       |       |
    |*  2 |   HASH JOIN            |              |      1 |    250K|    998K|00:00:00.66 |    2780 |      4 |  1066K|  1066K|  42
    |*  3 |    INDEX FAST FULL SCAN| IND_T1_C1_C2 |      1 |    500 |    999 |00:00:00.04 |    1390 |      2 |       |       |
    |*  4 |    INDEX FAST FULL SCAN| IND_T2_C1_C2 |      1 |    500 |    999 |00:00:00.04 |    1390 |      2 |       |       |
    ------------------------------------------------------------------------------------------------------------------------------
    
    Predicate Information (identified by operation id):
    ---------------------------------------------------
    
       2 - access("T1"."C2"="T2"."C2")
       3 - filter("T1"."C2"=:N1)
       4 - filter("T2"."C2"=:N1)
    
    24 rows selected.
    
    TARAL@taral >
    TARAL@taral > EXEC :N1:=5
    
    PL/SQL procedure successfully completed.
    
    TARAL@taral >
    TARAL@taral > SELECT /*+ GATHER_PLAN_STATISTICS */ COUNT(*) FROM T1,T2 WHERE T1.C2=T2.C2 AND T1.C2= :N1;
    
      COUNT(*)
    ----------
        990025
    
    TARAL@taral >
    TARAL@taral > SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST'));
    
    PLAN_TABLE_OUTPUT
    ------------------------------------------------------------------------------------------------------------------------------
    SQL_ID  8ygbsrkt6sqd9, child number 0
    -------------------------------------
    SELECT /*+ GATHER_PLAN_STATISTICS */ COUNT(*) FROM T1,T2 WHERE
    T1.C2=T2.C2 AND T1.C2= :N1
    
    Plan hash value: 765688747
    
    ----------------------------------------------------------------------------------------------------------------------------
    | Id  | Operation              | Name         | Starts | E-Rows | A-Rows |   A-Time   | Buffers |  OMem |  1Mem | Used-Mem |
    ----------------------------------------------------------------------------------------------------------------------------
    |   0 | SELECT STATEMENT       |              |      1 |        |      1 |00:00:00.30 |    2780 |    |  |          |
    |   1 |  SORT AGGREGATE        |              |      1 |      1 |      1 |00:00:00.30 |    2780 |    |  |          |
    |*  2 |   HASH JOIN            |              |      1 |    250K|    990K|00:00:00.65 |    2780 |  1066K|  1066K|  395K (0)|
    |*  3 |    INDEX FAST FULL SCAN| IND_T1_C1_C2 |      1 |    500 |    995 |00:00:00.04 |    1390 |    |  |          |
    |*  4 |    INDEX FAST FULL SCAN| IND_T2_C1_C2 |      1 |    500 |    995 |00:00:00.04 |    1390 |    |  |          |
    ----------------------------------------------------------------------------------------------------------------------------
    
    Predicate Information (identified by operation id):
    ---------------------------------------------------
    
       2 - access("T1"."C2"="T2"."C2")
       3 - filter("T1"."C2"=:N1)
       4 - filter("T2"."C2"=:N1)
    
    24 rows selected.
    
    TARAL@taral >
    TARAL@taral > EXEC :N1:=95
    
    PL/SQL procedure successfully completed.
    
    TARAL@taral >
    TARAL@taral > SELECT /*+ GATHER_PLAN_STATISTICS */ COUNT(*) FROM T1,T2 WHERE T1.C2=T2.C2 AND T1.C2= :N1;
    
      COUNT(*)
    ----------
        819025
    
    TARAL@taral > SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST'));
    
    PLAN_TABLE_OUTPUT
    ------------------------------------------------------------------------------------------------------------------------------
    SQL_ID  8ygbsrkt6sqd9, child number 0
    -------------------------------------
    SELECT /*+ GATHER_PLAN_STATISTICS */ COUNT(*) FROM T1,T2 WHERE
    T1.C2=T2.C2 AND T1.C2= :N1
    
    Plan hash value: 765688747
    
    ----------------------------------------------------------------------------------------------------------------------------
    | Id  | Operation              | Name         | Starts | E-Rows | A-Rows |   A-Time   | Buffers |  OMem |  1Mem | Used-Mem |
    ----------------------------------------------------------------------------------------------------------------------------
    |   0 | SELECT STATEMENT       |              |      1 |        |      1 |00:00:00.28 |    2780 |    |  |          |
    |   1 |  SORT AGGREGATE        |              |      1 |      1 |      1 |00:00:00.28 |    2780 |    |  |          |
    |*  2 |   HASH JOIN            |              |      1 |    250K|    819K|00:00:00.57 |    2780 |  1066K|  1066K|  379K (0)|
    |*  3 |    INDEX FAST FULL SCAN| IND_T1_C1_C2 |      1 |    500 |    905 |00:00:00.05 |    1390 |    |  |          |
    |*  4 |    INDEX FAST FULL SCAN| IND_T2_C1_C2 |      1 |    500 |    905 |00:00:00.05 |    1390 |    |  |          |
    ----------------------------------------------------------------------------------------------------------------------------
    
    Predicate Information (identified by operation id):
    ---------------------------------------------------
    
       2 - access("T1"."C2"="T2"."C2")
       3 - filter("T1"."C2"=:N1)
       4 - filter("T2"."C2"=:N1)
    
    24 rows selected.
    
    TARAL@taral >
    TARAL@taral > EXEC :N1:=995
    
    PL/SQL procedure successfully completed.
    
    TARAL@taral >
    TARAL@taral > SELECT /*+ GATHER_PLAN_STATISTICS */ COUNT(*) FROM T1,T2 WHERE T1.C2=T2.C2 AND T1.C2= :N1;
    
      COUNT(*)
    ----------
            25
    
    TARAL@taral > SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST'));
    
    PLAN_TABLE_OUTPUT
    ------------------------------------------------------------------------------------------------------------------------------
    SQL_ID  8ygbsrkt6sqd9, child number 0
    -------------------------------------
    SELECT /*+ GATHER_PLAN_STATISTICS */ COUNT(*) FROM T1,T2 WHERE
    T1.C2=T2.C2 AND T1.C2= :N1
    
    Plan hash value: 765688747
    
    ----------------------------------------------------------------------------------------------------------------------------
    | Id  | Operation              | Name         | Starts | E-Rows | A-Rows |   A-Time   | Buffers |  OMem |  1Mem | Used-Mem |
    ----------------------------------------------------------------------------------------------------------------------------
    |   0 | SELECT STATEMENT       |              |      1 |        |      1 |00:00:00.10 |    2780 |    |  |          |
    |   1 |  SORT AGGREGATE        |              |      1 |      1 |      1 |00:00:00.10 |    2780 |    |  |          |
    |*  2 |   HASH JOIN            |              |      1 |    250K|     25 |00:00:00.10 |    2780 |  1036K|  1036K|  351K (0)|
    |*  3 |    INDEX FAST FULL SCAN| IND_T1_C1_C2 |      1 |    500 |      5 |00:00:00.05 |    1390 |    |  |          |
    |*  4 |    INDEX FAST FULL SCAN| IND_T2_C1_C2 |      1 |    500 |      5 |00:00:00.06 |    1390 |    |  |          |
    ----------------------------------------------------------------------------------------------------------------------------
    
    Predicate Information (identified by operation id):
    ---------------------------------------------------
    
       2 - access("T1"."C2"="T2"."C2")
       3 - filter("T1"."C2"=:N1)
       4 - filter("T2"."C2"=:N1)
    
    24 rows selected.
    
    

    So, from tkprof output here are the results which perfectely shows average rows as it had captured 4 occurences of the statement.

    SQL ID: 8ygbsrkt6sqd9
    Plan Hash: 765688747
    SELECT /*+ GATHER_PLAN_STATISTICS */ COUNT(*)
    FROM
     T1,T2 WHERE T1.C2=T2.C2 AND T1.C2= :N1
    
    call     count       cpu    elapsed       disk      query    current        rows
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    Parse        4      0.00       0.00          0          0          0           0
    Execute      4      0.00       0.01          0          0          0           0
    Fetch        8      0.98       1.02          4      11120          0           4
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    total       16      0.98       1.03          4      11120          0           4
    
    Misses in library cache during parse: 1
    Misses in library cache during execute: 1
    Optimizer mode: ALL_ROWS
    Parsing user id: 89
    Number of plan statistics captured: 4
    
    Rows (1st) Rows (avg) Rows (max)  Row Source Operation
    ---------- ---------- ----------  ---------------------------------------------------
             1          1          1  SORT AGGREGATE (cr=2780 pr=1 pw=0 time=0 us)
        998001     701769     998001   HASH JOIN  (cr=2780 pr=1 pw=0 time=429843 us cost=761 size=2000000 card=250000)
           999        726        999    INDEX FAST FULL SCAN IND_T1_C1_C2 (cr=1390 pr=1 pw=0 time=33406 us cost=380 size=2000 card=500)(object id 74359)
           999        726        999    INDEX FAST FULL SCAN IND_T2_C1_C2 (cr=1390 pr=1 pw=0 time=33505 us cost=380 size=2000 card=500)(object id 74360)
    
    

    As, default aggregation is turned on if we make it off and then see tkprof output it display all 4 execution

    SQL ID: 8ygbsrkt6sqd9
    Plan Hash: 765688747
    SELECT /*+ GATHER_PLAN_STATISTICS */ COUNT(*)
    FROM
     T1,T2 WHERE T1.C2=T2.C2 AND T1.C2= :N1
    
    call     count       cpu    elapsed       disk      query    current        rows
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    Parse        1      0.00       0.00          0          0          0           0
    Execute      1      0.00       0.01          0          0          0           0
    Fetch        2      0.31       0.33          4       2780          0           1
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    total        4      0.31       0.35          4       2780          0           1
    
    Misses in library cache during parse: 1
    Misses in library cache during execute: 1
    Optimizer mode: ALL_ROWS
    Parsing user id: 89
    Number of plan statistics captured: 1
    
    Rows (1st) Rows (avg) Rows (max)  Row Source Operation
    ---------- ---------- ----------  ---------------------------------------------------
             1          1          1  SORT AGGREGATE (cr=2780 pr=4 pw=0 time=0 us)
        998001     998001     998001   HASH JOIN  (cr=2780 pr=4 pw=0 time=596598 us cost=761 size=2000000 card=250000)
           999        999        999    INDEX FAST FULL SCAN IND_T1_C1_C2 (cr=1390 pr=2 pw=0 time=42664 us cost=380 size=2000 card=500)(object id 74359)
           999        999        999    INDEX FAST FULL SCAN IND_T2_C1_C2 (cr=1390 pr=2 pw=0 time=42415 us cost=380 size=2000 card=500)(object id 74360)
    
    SQL ID: 8ygbsrkt6sqd9
    Plan Hash: 765688747
    SELECT /*+ GATHER_PLAN_STATISTICS */ COUNT(*)
    FROM
     T1,T2 WHERE T1.C2=T2.C2 AND T1.C2= :N1
    
    call     count       cpu    elapsed       disk      query    current        rows
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    Parse        1      0.00       0.00          0          0          0           0
    Execute      1      0.00       0.00          0          0          0           0
    Fetch        2      0.29       0.30          0       2780          0           1
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    total        4      0.29       0.30          0       2780          0           1
    
    Misses in library cache during parse: 0
    Optimizer mode: ALL_ROWS
    Parsing user id: 89
    Number of plan statistics captured: 1
    
    Rows (1st) Rows (avg) Rows (max)  Row Source Operation
    ---------- ---------- ----------  ---------------------------------------------------
             1          1          1  SORT AGGREGATE (cr=2780 pr=0 pw=0 time=0 us)
        990025     990025     990025   HASH JOIN  (cr=2780 pr=0 pw=0 time=596958 us cost=761 size=2000000 card=250000)
           995        995        995    INDEX FAST FULL SCAN IND_T1_C1_C2 (cr=1390 pr=0 pw=0 time=42866 us cost=380 size=2000 card=500)(object id 74359)
           995        995        995    INDEX FAST FULL SCAN IND_T2_C1_C2 (cr=1390 pr=0 pw=0 time=42866 us cost=380 size=2000 card=500)(object id 74360)
    
    SQL ID: 8ygbsrkt6sqd9
    Plan Hash: 765688747
    SELECT /*+ GATHER_PLAN_STATISTICS */ COUNT(*)
    FROM
     T1,T2 WHERE T1.C2=T2.C2 AND T1.C2= :N1
    
    call     count       cpu    elapsed       disk      query    current        rows
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    Parse        1      0.00       0.00          0          0          0           0
    Execute      1      0.00       0.00          0          0          0           0
    Fetch        2      0.26       0.27          0       2780          0           1
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    total        4      0.26       0.27          0       2780          0           1
    
    Misses in library cache during parse: 0
    Optimizer mode: ALL_ROWS
    Parsing user id: 89
    Number of plan statistics captured: 1
    
    Rows (1st) Rows (avg) Rows (max)  Row Source Operation
    ---------- ---------- ----------  ---------------------------------------------------
             1          1          1  SORT AGGREGATE (cr=2780 pr=0 pw=0 time=0 us)
        819025     819025     819025   HASH JOIN  (cr=2780 pr=0 pw=0 time=525793 us cost=761 size=2000000 card=250000)
           905        905        905    INDEX FAST FULL SCAN IND_T1_C1_C2 (cr=1390 pr=0 pw=0 time=47686 us cost=380 size=2000 card=500)(object id 74359)
           905        905        905    INDEX FAST FULL SCAN IND_T2_C1_C2 (cr=1390 pr=0 pw=0 time=48364 us cost=380 size=2000 card=500)(object id 74360)
    
    SQL ID: 8ygbsrkt6sqd9
    Plan Hash: 765688747
    SELECT /*+ GATHER_PLAN_STATISTICS */ COUNT(*)
    FROM
     T1,T2 WHERE T1.C2=T2.C2 AND T1.C2= :N1
    
    call     count       cpu    elapsed       disk      query    current        rows
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    Parse        1      0.00       0.00          0          0          0           0
    Execute      1      0.00       0.00          0          0          0           0
    Fetch        2      0.10       0.10          0       2780          0           1
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    total        4      0.10       0.10          0       2780          0           1
    
    Misses in library cache during parse: 0
    Optimizer mode: ALL_ROWS
    Parsing user id: 89
    Number of plan statistics captured: 1
    
    Rows (1st) Rows (avg) Rows (max)  Row Source Operation
    ---------- ---------- ----------  ---------------------------------------------------
             1          1          1  SORT AGGREGATE (cr=2780 pr=0 pw=0 time=0 us)
            25         25         25   HASH JOIN  (cr=2780 pr=0 pw=0 time=24 us cost=761 size=2000000 card=250000)
             5          5          5    INDEX FAST FULL SCAN IND_T1_C1_C2 (cr=1390 pr=0 pw=0 time=408 us cost=380 size=2000 card=500)(object id 74359)
             5          5          5    INDEX FAST FULL SCAN IND_T2_C1_C2 (cr=1390 pr=0 pw=0 time=376 us cost=380 size=2000 card=500)(object id 74360)
    
    

    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
    

    Rowsource For Each Execution

    When you trace SQL statement sometimes what happens is if it’s already parsed then you will not get rowsource operation for each execution in trace. This might need to re-parse that statement.  And its more problematic when application is involved where most SQL’s are parsed already.

    Let’s see simple example.

  • 1st Example
  • exec dbms_monitor.session_trace_enable(NULL, NULL, TRUE, TRUE);
    select count(*) from scott.emp;
    select count(*) from scott.emp;
    select count(*) from scott.emp;
    exec dbms_monitor.session_trace_disable();
    
  • 2nd Example
  • exec dbms_monitor.session_trace_enable(plan_stat=>'ALL_EXECUTIONS');
    select count(*) from scott.emp;
    select count(*) from scott.emp;
    select count(*) from scott.emp;
    exec dbms_monitor.session_trace_disable();
    
  • From 1st Trace File
  • SQL ID: abj9tmfcs15bm
    Plan Hash: 2937609675
    select count(*) from scott.emp
    
    call     count       cpu    elapsed       disk      query    current        rows
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    Parse        3      0.00       0.01          0          0          0           0
    Execute      3      0.00       0.00          0          0          0           0
    Fetch        6      0.00       0.02          1          3          0           3
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    total       12      0.00       0.03          1          3          0           3
    
    Misses in library cache during parse: 1
    Optimizer mode: ALL_ROWS
    Parsing user id: 89 
    Number of plan statistics captured: 3
    
    Rows (1st) Rows (avg) Rows (max)  Row Source Operation
    ---------- ---------- ----------  ---------------------------------------------------
             1          1          1  SORT AGGREGATE (cr=1 pr=0 pw=0 time=0 us)
            14         14         14   INDEX FULL SCAN PK_EMP (cr=1 pr=0 pw=0 time=13 us cost=1 size=0 card=14)(object id 73197)
    
  • From 2nd Trace File
  • SQL ID: abj9tmfcs15bm
    Plan Hash: 2937609675
    select count(*) from scott.emp
    
    call     count       cpu    elapsed       disk      query    current        rows
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    Parse        3      0.00       0.00          0          0          0           0
    Execute      3      0.00       0.00          0          0          0           0
    Fetch        6      0.00       0.03          1          3          0           3
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    total       12      0.00       0.03          1          3          0           3
    
    Misses in library cache during parse: 0
    Optimizer mode: ALL_ROWS
    Parsing user id: 89
    Number of plan statistics captured: 1
    
    Rows (1st) Rows (avg) Rows (max)  Row Source Operation
    ---------- ---------- ----------  ---------------------------------------------------
             1          1          1  SORT AGGREGATE (cr=1 pr=1 pw=0 time=0 us)
            14         14         14   INDEX FULL SCAN PK_EMP (cr=1 pr=1 pw=0 time=13 us cost=1 size=0 card=14)(object id 73197)
    

    AMDU Utility For ASM

    This utility from 11g can help to get ASM information and also can dump other information while asm instance is not running. For example you can get files from asm disk even  though asm is not running. To get help amdu -help. There is no official documentation available for this so careful while doing other than just querying.

    When you give amdu without any parameter it will create one folder and inside that report.txt. Here is the sample output

    ******************************* AMDU Settings ********************************
    ORACLE_HOME = /u01/app/oracle/product/11.2.0/grid
    System name:    Linux
    Node name:      taral.localdomain
    Release:        2.6.32-100.20.1.el5
    Version:        #1 SMP Fri Oct 1 16:37:36 EDT 2010
    Machine:        x86_64
    amdu run:       08-OCT-10 19:07:11
    Endianess:      1
    --------------------------------- Operations ---------------------------------
    ------------------------------- Disk Selection -------------------------------
    -diskstring ''
    ------------------------------ Reading Control -------------------------------
    
    ------------------------------- Output Control -------------------------------
    ********************************* DISCOVERY **********************************
    ----------------------------- DISK REPORT N0001 ------------------------------
    Disk Path: ORCL:ASMDISK1
    Unique Disk ID:
    Disk Label: ASMDISK1
    Physical Sector Size: 512 bytes
    Disk Size: 9773 megabytes
    Group Name: ASMDATA
    Disk Name: ASMDISK1
    Failure Group Name: ASMDISK1
    Disk Number: 0
    Header Status: 3
    Disk Creation Time: 2010/09/15 12:08:52.229000
    Last Mount Time: 2010/10/08 17:26:26.671000
    Compatibility Version: 0x0b200000(11020000)
    Disk Sector Size: 512 bytes
    Disk size in AUs: 9773 AUs
    Group Redundancy: 2
    Metadata Block Size: 4096 bytes
    AU Size: 1048576 bytes
    Stride: 113792 AUs
    Group Creation Time: 2010/09/15 12:08:52.109000
    File 1 Block 1 location: AU 2
    OCR Present: NO
    ----------------------------- DISK REPORT N0002 ------------------------------
    Disk Path: ORCL:ASMDISK2
    Unique Disk ID:
    Disk Label: ASMDISK2
    Physical Sector Size: 512 bytes
    Disk Size: 9773 megabytes
    Group Name: ASMDATA
    Disk Name: ASMDISK2
    Failure Group Name: ASMDISK2
    Disk Number: 1
    Header Status: 3
    Disk Creation Time: 2010/09/15 12:08:52.229000
    Last Mount Time: 2010/10/08 17:26:26.671000
    Compatibility Version: 0x0b200000(11020000)
    Disk Sector Size: 512 bytes
    Disk size in AUs: 9773 AUs
    Group Redundancy: 2
    Metadata Block Size: 4096 bytes
    AU Size: 1048576 bytes
    Stride: 113792 AUs
    Group Creation Time: 2010/09/15 12:08:52.109000
    File 1 Block 1 location: AU 2
    OCR Present: NO
    ----------------------------- DISK REPORT N0003 ------------------------------
    Disk Path: ORCL:ASMDISK3
    Unique Disk ID:
    Disk Label: ASMDISK3
    Physical Sector Size: 512 bytes
    Disk Size: 9773 megabytes
    Group Name: ASMDATA
    Disk Name: ASMDISK3
    Failure Group Name: ASMDISK3
    Disk Number: 2
    Header Status: 3
    Disk Creation Time: 2010/09/15 12:08:52.229000
    Last Mount Time: 2010/10/08 17:26:26.671000
    Compatibility Version: 0x0b200000(11020000)
    Disk Sector Size: 512 bytes
    Disk size in AUs: 9773 AUs
    Group Redundancy: 2
    Metadata Block Size: 4096 bytes
    AU Size: 1048576 bytes
    Stride: 113792 AUs
    Group Creation Time: 2010/09/15 12:08:52.109000
    File 1 Block 1 location: AU 2
    OCR Present: NO
    ----------------------------- DISK REPORT N0004 ------------------------------
    Disk Path: ORCL:ASMDISK4
    Unique Disk ID:
    Disk Label: ASMDISK4
    Physical Sector Size: 512 bytes
    Disk Size: 19539 megabytes
    Group Name: DATA
    Disk Name: ASMDISK4
    Failure Group Name: ASMDISK4
    Disk Number: 0
    Header Status: 3
    Disk Creation Time: 2010/09/15 12:34:10.144000
    Last Mount Time: 2010/10/08 17:26:26.793000
    Compatibility Version: 0x0b200000(11020000)
    Disk Sector Size: 512 bytes
    Disk size in AUs: 4884 AUs
    Group Redundancy: 1
    Metadata Block Size: 4096 bytes
    AU Size: 4194304 bytes
    Stride: 454272 AUs
    Group Creation Time: 2010/09/15 12:34:09.836000
    File 1 Block 1 location: AU 2
    OCR Present: NO
    ******************************* END OF REPORT ********************************