Identify heaviest plan_line_id for a given execution plan (Oracle 11g)

I think the most mysterious question to me (well, as far as Oracle was the subject) was always that:
For a given SQL and its execution plan, where does Oracle spend most of its time?

Oracle 11g revealed this mystery by exposing Real Time SQL Monitoring, v$sql_monitor, and v$sql_plan_monitor. However, these performance views will only show information either for relatively long running queries ("when it has consumed at least 5 seconds of CPU or I/O time") or for all parallel queries. Suppose you have SQL with shorter execution time, running many times? You won't be able to find it there...
And before Oracle 11g was released, things were a bit harder...

In the following session I will demonstrate how to find, for a particular execution plan, in which execution plan step and on which object Oracle spends most of it time.

Oracle used is 11.1.0.7
Application is running the following SQL 600k times each day:

 select *
 from t1
 where ID= :1
 order by SEQ;

Let's find sql_id of this SQL:

 SQL> select sql_id,plan_hash_value,sql_text from v$sql where sql_text like 'select * from t1 where ID= :1 order by SEQ';

 SQL_ID        PLAN_HASH_VALUE SQL_TEXT
 ------------- --------------- --------------------------------------------------------------
 b652k1fnuqz5w       406502908 select * from t1 where ID= :1 order by SEQ

Let's find execution plan used:

 SQL> SELECT * FROM TABLE(dbms_xplan.display_cursor('b652k1fnuqz5w'));

 PLAN_TABLE_OUTPUT
 --------------------------------------------------------------------------------------------------------------------------------------------
 SQL_ID  b652k1fnuqz5w, child number 0
 -------------------------------------
 select * from t1 where ID= :1 order by SEQ

 Plan hash value: 406502908

 ----------------------------------------------------------------------------------
 | Id  | Operation                                                | Name               | Rows  | Bytes | Cost  |
 ----------------------------------------------------------------------------------
 |   0 | SELECT STATEMENT                         |                    |        |          |     1 |
 |   1 |  TABLE ACCESS BY INDEX ROWID| T1              |     4 |   512 |     1 |
 |*  2 |   INDEX RANGE SCAN                       | T1_IX1     |     4 |          |     1 |
 ----------------------------------------------------------------------------------

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

    2 - access("ID"=:1)
         filter("ID"=:1)

 Note
 -----
    - cpu costing is off (consider enabling it)

 24 rows selected.

Execution plan is very simple. Oracle is using INDEX RANGE SCAN on T1_IX1, applying predicate "ID = :1", then, it is using rowids stored in the index to fetch requested data " select * ".

How can we tell where does Oracle spend its time?

Let's have a look at v$active_session_history. This magnificent view was introduced in 10g, though in Oracle 11g several valuable columns were added to it. Execution plan step information is one example. For each sample and for each row added to this view (which reflect session's activity), it states to which step this activity is related.

Therefore, if we select all samples for the given sql_id, and group all those returned rows by
sql_plan_operation, sql_plan_option, sql_plan_line_id, current_obj# and event, we will be able to see the breakdown of sql_plan_line_id and find the heaviest step in the plan.

The step with the most samples will be the heaviest execution plan step, and our tuning efforts should be focused there.

Of course, for a simple plan it's quite easy, but go figure an execution plan with several dozens of steps without knowing which step is problematic.

With this technique mystery can be revealed.

 SQL> select sql_plan_operation operation, sql_plan_options options, sql_plan_line_id line_id, current_obj# obj#, event, count(*)
   2  from v$active_session_history
   3  where sql_id='b652k1fnuqz5w'
   4  and sql_plan_hash_value=406502908
   5  group by sql_plan_operation, sql_plan_options, sql_plan_line_id, current_obj#,event;


 OPERATION          OPTIONS                 LINE_ID       OBJ#   EVENT                         COUNT(*)
 ---------------              ---------------                ----------   ----------    -------------------------         ----------
 INDEX                     RANGE SCAN                 2       3657730    db file sequential read             44
 TABLE ACCESS    BY INDEX ROWID         1        302302     db file sequential read           110

We can see that most of the time is spent on fetching the data (select *) from the table. 110 samples out of 154 (44+110) samples (71.4%) were captured on TABLE ACCESS BY INDEX ROWID, while only 44 samples out of 156 samples (28.6%) were captured on INDEX RANGE SCAN. In other words fetching * from the table using rowid brought by the index is very expensive.

Let's examine table (current_obj#=302302):

 SQL> select table_name, num_rows, blocks
   2  from dba_tables
   3  where (owner,table_name) =
   4  ( select owner,object_name from dba_objects where object_id=302302);

 TABLE_NAME  NUM_ROWS     BLOCKS
 ---------------------- -------------------    ------------
 T1                                   25019183        479813

Let's examine index (current_obj#=3657730):

 SQL> select i.table_name,i.index_name,i.column_name,i.column_position ,c.num_distinct
   2  from dba_ind_columns i,dba_tab_columns c
   3  where (index_owner,index_name) =
   4  ( select owner,object_name from dba_objects where object_id=3657730)
   5  and i.table_owner = c.owner
   6  and i.table_name = c.table_name
   7  and i.column_name = c.column_name
   8  order by column_position;

 TABLE_NAME     INDEX_NAME  COLUMN_NAME   COLUMN_POSITION NUM_DISTINCT
 ----------------------  ---------------------   --------------------------- ---------------------------    --------------------------
 T1                             T1_IX1                ID                                 1                                    5733888
 T1                             T1_IX1                SEQ                              2                                    236

Looking at the index definition and statistics of the used index T1_IX1(ID,SEQ), we see that the index is well suited for this statement (where id = :1 order by seq).

Saying that, we need to go back with that to the Application and find out whether they do need to " select * " from the table (table T1 has 31 columns).
In case needed columns list is much narrow than "select *", application should eliminate "select *" use, and replace it with only needed columns. Then, if only a small set of columns are fetched, those columns can be added to the index (covering index), and Oracle can fetch needed data only from the index, without accessing the table.

Few notes:
1) v$active_session_history  is part of Oracle Diagnostics Pack, therefore requires Oracle Diagnostics Pack license. v$sql_monitor and v$sql_plan_monitor are part of Oracle Tuning Pack, therefore requires Oracle Tuning Pack license.
2)  Regardless the cost of fetching all columns, selecting * is never recommended. Suppose that someone added a column to the table without notifying all applications and one application is using select * in its code. Suddenly an extra unexpected column is returned back to the application.

3)  sql_plan_operation and sql_plan_options are new columns added to v$active_session_history on version 11g. These two columns do not exist in v$active_session_history in version 10g. Nevertheless, there are ways to located heavy steps in 10g also. This will be covered on next session.
To be continued...

Merav Kedem,

Founder of

DB OPTimize

Oracle Performance Tuning & DBA Consulting

http://www.dboptimize.co.il/
merav@dboptimize.co.il