Mohamed Houri’s Oracle Notes

July 2, 2014

Execution plan of a cancelled query

Filed under: explain plan — hourim @ 2:47 pm

I have been reminded by this otn thread that I have to write something about the usefulness of an execution plan pulled from memory of a query that has been cancelled due to its long running execution time. Several months ago I have been confronted to the same issue where one of my queries was desperately running sufficiently slow so that I couldn’t resist the temptation to cancel it.

It is of course legitimate to ask in such a situation about the validity of the corresponding execution plan? Should we wait until the query has finished before starting investigating where things went wrong? What if the query takes more than 20 minutes to complete? Will we wait 20 minutes each time before getting an exploitable execution plan?

The answer of course is no. You shouldn’t wait until the end of the query. Once the query has started you could get its execution plan from memory using its sql_id. And you will be surprised that you might already be able to found a clue of what is wrong with your query even in this ‘’partial’’ execution plan.

Let me model an example and show you what I am meaning.

    create table t1
       as
       with generator as (
           select  --+ materialize
               rownum id
           from dual
           connect by
               level <= 10000)
       select
          rownum                  id,
          trunc(dbms_random.value(1,1000))    n1,
          lpad(rownum,10,'0') small_vc,
          rpad('x',100)       padding
      from
          generator   v1,
          generator   v2
      where
          rownum <= 1000000;

   create index t1_n1 on t1(id, n1);

   create table t2
       as
       with generator as (
           select  --+ materialize
               rownum id
           from dual
           connect by
               level <= 10000)
       select
          rownum                  id,
          trunc(dbms_random.value(10001,20001))   x1,
          lpad(rownum,10,'0') small_vc,
          rpad('x',100)       padding
      from
          generator   v1,
          generator   v2
      where
          rownum <= 1000000;
    
   create index t2_i1 on t2(x1);

   exec dbms_stats.gather_table_stats(user, 't2', method_opt => 'FOR ALL COLUMNS SIZE 1');
   exec dbms_stats.gather_table_stats(user, 't1', method_opt => 'FOR ALL COLUMNS SIZE 1');
   

I have two simple indexed tables t1 and t2 against which I engineered the following query

    select *
       from t1
        where id in
                (Select id from t2 where x1 = 17335)
       order by id ;
   

The above query contains an order by clause on an indexed column (id). In order to make this query running sufficiently slow so that I can cancel it I will change the optimizer mode from all_rows to first_rows so that the CBO will prefer doing an index full scan and avoid the order by operation whatever the cost of the index full scan operation is.

   SQL> alter session set statistics_level=all;

   SQL> alter session set optimizer_mode=first_rows;

   SQL> select *
       from t1
        where id in
                (Select id from t2 where x1 = 17335)
       order by id ;

   107 rows selected.

   Elapsed: 00:02:14.70 -- more than 2 minutes

   SQL> select * from table(dbms_xplan.display_cursor(null,null,'ALLSTATS LAST'));

   SQL_ID  9gv186ag1mz0c, child number 0
  -------------------------------------
  Plan hash value: 1518369540
  ------------------------------------------------------------------------------------------------
  | Id  | Operation                    | Name  | Starts | E-Rows | A-Rows |   A-Time   | Buffers |
  ------------------------------------------------------------------------------------------------
  |   0 | SELECT STATEMENT             |       |      1 |        |    107 |00:02:39.85 |     108M|
  |   1 |  NESTED LOOPS SEMI           |       |      1 |    100 |    107 |00:02:39.85 |     108M|
  |   2 |   TABLE ACCESS BY INDEX ROWID| T1    |      1 |   1000K|   1000K|00:00:01.03 |   20319 |
  |   3 |    INDEX FULL SCAN           | T1_N1 |      1 |   1000K|   1000K|00:00:00.31 |    2774 |
  |*  4 |   TABLE ACCESS BY INDEX ROWID| T2    |   1000K|      1 |    107 |00:02:37.70 |     108M|
  |*  5 |    INDEX RANGE SCAN          | T2_I1 |   1000K|    100 |    106M|00:00:30.73 |    1056K|
  ------------------------------------------------------------------------------------------------

  Predicate Information (identified by operation id):
  ---------------------------------------------------
     4 - filter("ID"="ID")
     5 - access("X1"=17335)
 

And the plan_hash_value2 of this query is:

  SQL> @phv2 9gv186ag1mz0c

  SQL_ID        PLAN_HASH_VALUE CHILD_NUMBER       PHV2
  ------------- --------------- ------------ ----------
  9gv186ag1mz0c      1518369540            0 2288661314
  

The query took more than 2 minutes to complete and for the purpose of this blog I didn’t cancelled it in order to get its final execution plan shown above. Now I am going to re-execute it again and cancel it after few seconds.

    SQL> select *
       from t1
        where id in
                (Select id from t2 where x1 = 17335)
       order by id ;

   ^C
   C:\>
   

And here below is the corresponding partial plan pulled from memory

  SQL> select * from table(dbms_xplan.display_cursor('9gv186ag1mz0c',0,'ALLSTATS LAST'));

  SQL_ID  9gv186ag1mz0c, child number 0
  -------------------------------------
  Plan hash value: 1518369540

  ------------------------------------------------------------------------------------------------
  | Id  | Operation                    | Name  | Starts | E-Rows | A-Rows |   A-Time   | Buffers |
  ------------------------------------------------------------------------------------------------
  |   0 | SELECT STATEMENT             |       |      1 |        |     17 |00:00:18.13 |      13M|
  |   1 |  NESTED LOOPS SEMI           |       |      1 |    100 |     17 |00:00:18.13 |      13M|
  |   2 |   TABLE ACCESS BY INDEX ROWID| T1    |      1 |   1000K|    129K|00:00:00.12 |    2631 |
  |   3 |    INDEX FULL SCAN           | T1_N1 |      1 |   1000K|    129K|00:00:00.04 |     361 |
  |*  4 |   TABLE ACCESS BY INDEX ROWID| T2    |    129K|      1 |     17 |00:00:18.26 |      13M|
  |*  5 |    INDEX RANGE SCAN          | T2_I1 |    129K|    100 |     13M|00:00:03.63 |     136K|
  ------------------------------------------------------------------------------------------------

  Predicate Information (identified by operation id):
  ---------------------------------------------------
     4 - filter("ID"="ID")
     5 - access("X1"=17335)

  SQL>  @phv2 9gv186ag1mz0c

  SQL_ID        PLAN_HASH_VALUE CHILD_NUMBER       PHV2
  ------------- --------------- ------------ ----------
  9gv186ag1mz0c      1518369540            0 2288661314
  

The main observations are:

  1.   Both queries followed the same plan hash value
  2.   Both queries have the same phv2
  3.   Both execution plans contain the same operations at the same order of execution
  4.   Both execution plans contain the same Estimations (E-Rows) which is a clear indication that this is obtained at hard parse time

Either from the complete plan or from the ”partial” one we can have the same clue of what is going wrong here (even thought that in this particular case the performance penalty is due to the first_rows mode which has the tendency to avoid an order by on an indexed column at any price). Indeed it is the operation number 4 which is the most time consuming operation and from where there is the most important deviation between the CBO estimations and the Actual rows

So there is nothing that impeaches hurried developers from cancelling a query and getting its execution plan from memory. They can end up with valuable information from the cancelled query plan as well as from the complete plan.

This article is also a reminder for experienced Oracle DBA performance specialists that, there are cases where a difference between estimations done by the CBO and the actual rows obtained during execution time, does not necessary imply an absence of fresh and representative statistics. This difference could be due to a plan coming from a cancelled query.

By the way, I know another situation where an excellent optimal plan is showing a value of Starts*E-Rows diverging greatly from A-Rows and where statistics are perfect.  That will be explained, I hope,  in a different blog article.

3 Comments »

  1. Hi Sir,

    When i am trying to see the execution plan of a query using select * from table(dbms_xplan.display_cursor(‘&sql_id’,0,’ALLSTATS LAST’)); i am only seeing the estimated rows but i am unable to see Actual rows what can be the reason for it. the output is like this

    PLAN_TABLE_OUTPUT
    ———————————————————————————————————————–
    SQL_ID 10yf53xj2pzp8, child number 0
    ————————————-
    select * from hr.employees where first_name=’Shelley’

    Plan hash value: 3033625502

    ——————————————————————————————–
    | Id | Operation | Name | E-Rows |E-Bytes| Cost (%CPU)| E-Time |
    ——————————————————————————————–
    | 0 | SELECT STATEMENT | | | | 2 (100)| |
    | 1 | TABLE ACCESS BY INDEX ROWID| EMPLOYEES | 1 | 69 | 2 (0)| 00:00:01 |
    |* 2 | INDEX SKIP SCAN | EMP_NAME_IX | 1 | | 1 (0)| 00:00:01 |
    ——————————————————————————————–

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

    2 – access(“FIRST_NAME”=’Shelley’)
    filter(“FIRST_NAME”=’Shelley’)

    Note
    —–
    – Warning: basic plan statistics not available. These are only collected when:
    * hint ‘gather_plan_statistics’ is used for the statement or
    * parameter ‘statistics_level’ is set to ‘ALL’, at session or system level

    What should i do to see the actual rows returned ?

    Thanks in advance

    Comment by visith — September 1, 2014 @ 8:33 pm | Reply

  2. Visith

    The reason behind the absence of A-Rows is indicated in the warning :

    “Warning: basic plan statistics not available. These are only collected when:
    * hint ‘gather_plan_statistics’ is used for the statement or
    * parameter ‘statistics_level’ is set to ‘ALL’, at session or system level”

    So you have two options (choose one of them)

    1) Alter session set statistics_level =all;
    2) Add the hint /*+ gather_plan_statistics */ to your original query

    You can find extra details in this blog article : https://hourim.wordpress.com/2011/12/29/getting-explain-plan/

    Best regards

    Comment by hourim — September 2, 2014 @ 7:46 am | Reply

    • Thank you so much for replying sir. I got the info i wanted.

      Regards,
      Visith

      Comment by visith — September 2, 2014 @ 10:11 am | Reply


RSS feed for comments on this post. TrackBack URI

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

Blog at WordPress.com.

Tony's Oracle Tips

Tony Hasler's light hearted approach to learning about Oracle

Richard Foote's Oracle Blog

Focusing Specifically On Oracle Indexes, Database Administration and Some Great Music

Hatem Mahmoud Oracle's blog

Just another Oracle blog : Database topics and techniques

Mohamed Houri’s Oracle Notes

Qui se conçoit bien s’énonce clairement

Oracle Diagnostician

Performance troubleshooting as exact science

Raheel's Blog

Things I have learnt as Oracle DBA

Coskan's Approach to Oracle

What I learned about Oracle

So Many Oracle Manuals, So Little Time

“Books to the ceiling, Books to the sky, My pile of books is a mile high. How I love them! How I need them! I'll have a long beard by the time I read them”—Lobel, Arnold. Whiskers and Rhymes. William Morrow & Co, 1988.

EU Careers info

Your career in the European Union

Carlos Sierra's Tools and Tips

Tools and Tips for Oracle Performance and SQL Tuning

Oracle Scratchpad

Just another Oracle weblog

OraStory

Dominic Brooks on Oracle Performance, Tuning, Data Quality & Sensible Design ... (Now with added Sets Appeal)

%d bloggers like this: