Home > Oracle, Performance > Autotrace

Autotrace


Happy New Year!

Oracle supplied various tools to trace the SQL and identify execution plans for the SQLs.  10046 Event, AUTOTRACE, DBMS.XPLAN etc are some of the most used tracing methods in DBAs daily life.  Sometimes, we need to be very careful while using these tools specially using bind variables.  Following are some test cases where wrong plans reported by the above tracing tools.

Most easiest method to get the execution plan is AUTOTRACE both estimate and actual after execution it.  For example I have below tables ABC


SQL> desc abc

 Name                                                                                      Null?    Type

 ----------------------------------------------------------------------------------------- -------- ------------------------------------------------------------

 OWNER                                                                                     NOT NULL VARCHAR2(30)

 OBJECT_NAME                                                                               NOT NULL VARCHAR2(30)

 SUBOBJECT_NAME                                                                                     VARCHAR2(30)

 OBJECT_ID                                                                                          NUMBER

 DATA_OBJECT_ID                                                                                     NUMBER

 OBJECT_TYPE                                                                                        VARCHAR2(19)

 CREATED                                                                                   NOT NULL DATE

 LAST_DDL_TIME                                                                             NOT NULL DATE

 TIMESTAMP                                                                                          VARCHAR2(19)

 STATUS                                                                                             VARCHAR2(7)

 TEMPORARY                                                                                          VARCHAR2(1)

 GENERATED                                                                                          VARCHAR2(1)

 SECONDARY                                                                                          VARCHAR2(1)

 NAMESPACE                                                                                 NOT NULL NUMBER

 EDITION_NAME                                                                                       VARCHAR2(30)



SQL> select OBJECT_ID,count(*) from abc group by OBJECT_ID;

 OBJECT_ID   COUNT(*)

---------- ----------

         1          1

         2     117455

ABC table got 1 row OBJECT_ID=1 and 117455 rows with OBJECT_ID=2.  Created an index OBJECT_ID, so that OBEJCT_ID=1 will always use and index while OBJECT_ID=2 a FTS.

My first test was using literals, and AUTOTRACE reported correct execution plans.


SQL>  select count(OBJECT_TYPE) from abc where object_id=2;

COUNT(OBJECT_TYPE)

------------------

            117455

Elapsed: 00:00:00.01

Execution Plan

---------------------------------------------------------

Plan hash value: 1045519631

---------------------------------------------------------------------------

| Id  | Operation          | Name | Rows  | Bytes | Cost (%CPU)| Time     |

---------------------------------------------------------------------------

|   0 | SELECT STATEMENT   |      |     1 |    11 |   447   (1)| 00:00:06 |

|   1 |  SORT AGGREGATE    |      |     1 |    11 |            |          |

|*  2 |   TABLE ACCESS FULL| ABC  |   118K|  1274K|   447   (1)| 00:00:06 |

---------------------------------------------------------------------------

Predicate Information (identified by operation id):

---------------------------------------------------

   2 - filter("OBJECT_ID"=2)

FTS for OBJECT_ID=2 and Index Range Scan for OBJECT_ID=1.


SQL> select count(OBJECT_TYPE) from abc where object_id=1;

COUNT(OBJECT_TYPE)

------------------

            1



Elapsed: 00:00:00.01

Execution Plan

----------------------------------------------------------

Plan hash value: 2627152604

--------------------------------------------------------------------------------------------

| Id  | Operation                    | Name        | Rows  | Bytes | Cost (%CPU)| Time     |

--------------------------------------------------------------------------------------------

|   0 | SELECT STATEMENT             |             |     1 |    11 |     4   (0)| 00:00:01 |

|   1 |  SORT AGGREGATE              |             |     1 |    11 |            |          |

|   2 |   TABLE ACCESS BY INDEX ROWID| ABC         |     1 |    11 |     4   (0)| 00:00:01 |

|*  3 |    INDEX RANGE SCAN          | I_OBJECT_ID |     1 |       |     3   (0)| 00:00:01 |

--------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):

---------------------------------------------------

   3 - access("OBJECT_ID"=1)

Then I moved to the next level – get the AUTOTRACE plans using BIND Variables.


SQL>  set autotrace traceonly

SQL> VARIABLE oid NUMBER;

SQL> EXECUTE :oid  := 1;

SQL> select count(OBJECT_TYPE) from abc where object_id=:oid ;SQL>

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.00

SQL>

Elapsed: 00:00:00.01



Execution Plan

----------------------------------------------------------

Plan hash value: 1045519631



---------------------------------------------------------------------------

| Id  | Operation          | Name | Rows  | Bytes | Cost (%CPU)| Time     |

---------------------------------------------------------------------------

|   0 | SELECT STATEMENT   |      |     1 |    11 |   448   (1)| 00:00:06 |

|   1 |  SORT AGGREGATE    |      |     1 |    11 |            |          |

|*  2 |   TABLE ACCESS FULL| ABC  |   118K|  1274K|   448   (1)| 00:00:06 |

---------------------------------------------------------------------------



Predicate Information (identified by operation id):

---------------------------------------------------

   2 - filter("OBJECT_ID"=TO_NUMBER(:OID))



Statistics

----------------------------------------------------------

          1  recursive calls

          0  db block gets

          4  consistent gets

          0  physical reads

          0  redo size

        536  bytes sent via SQL*Net to client

        520  bytes received via SQL*Net from client

          2  SQL*Net roundtrips to/from client

          0  sorts (memory)

          0  sorts (disk)

          1  rows processed

SQL> VARIABLE oid NUMBER;

SQL> EXECUTE :oid  := 2;

SQL> select count(OBJECT_TYPE) from abc where object_id=:oid ;SQL>

PL/SQL procedure successfully completed.



Elapsed: 00:00:00.00

SQL>



Elapsed: 00:00:00.04



Execution Plan

----------------------------------------------------------

Plan hash value: 1045519631

---------------------------------------------------------------------------

| Id  | Operation          | Name | Rows  | Bytes | Cost (%CPU)| Time     |

---------------------------------------------------------------------------

|   0 | SELECT STATEMENT   |      |     1 |    11 |   448   (1)| 00:00:06 |

|   1 |  SORT AGGREGATE    |      |     1 |    11 |            |          |

|*  2 |   TABLE ACCESS FULL| ABC  |   118K|  1274K|   448   (1)| 00:00:06 |

---------------------------------------------------------------------------

Predicate Information (identified by operation id):

---------------------------------------------------



   2 - filter("OBJECT_ID"=TO_NUMBER(:OID))



Statistics

----------------------------------------------------------

          0  recursive calls

          0  db block gets

       1964  consistent gets

          0  physical reads

          0  redo size

        538  bytes sent via SQL*Net to client

        520  bytes received via SQL*Net from client

          2  SQL*Net roundtrips to/from client

          0  sorts (memory)

          0  sorts (disk)</pre>
<ul>
	<li>rows processed</li>
</ul>
<pre>

The AUTOTRACE TRACEONLY reported both plans as FTS, though  OBJECT_ID-=1 is just reading one row from the table while OBJECT_ID is an indexed column.  I agree to the fact that, AUTOTRACE TRACEONLY is showing an estimated plan, so may be reporting the wrong plan.  Experts say that, AUTOTRACE TRACEONLY never a dependable way of plan generation.  Interestingly OBJECT_ID=1 reported just 4 consistent gets while OBJECT_ID=2 shows 1964 gets – so the estimation theory is not really going well here as I was expecting 1964 CR reads if the estimated plan is FTS.

Then moved to the next test – use AUTOTRACE EXPLAIN STAT.  I had some faith in this level as the SQL statement will get execute first and report the executed plan.  So the plan tends to be accurate.




SQL> set autotrace on exp stat

SQL> EXECUTE :oid  := 2;



PL/SQL procedure successfully completed.



Elapsed: 00:00:00.00

SQL> select count(OBJECT_TYPE) from abc where object_id=:oid ;



COUNT(OBJECT_TYPE)

------------------

            117455

Elapsed: 00:00:00.02

Execution Plan

----------------------------------------------------------

Plan hash value: 1045519631

---------------------------------------------------------------------------

| Id  | Operation          | Name | Rows  | Bytes | Cost (%CPU)| Time     |

---------------------------------------------------------------------------

|   0 | SELECT STATEMENT   |      |     1 |    11 |   448   (1)| 00:00:06 |

|   1 |  SORT AGGREGATE    |      |     1 |    11 |            |          |

|*  2 |   TABLE ACCESS FULL| ABC  |   118K|  1274K|   448   (1)| 00:00:06 |

---------------------------------------------------------------------------



Predicate Information (identified by operation id):

---------------------------------------------------



   2 - filter("OBJECT_ID"=TO_NUMBER(:OID))



Statistics

----------------------------------------------------------

          1  recursive calls

          0  db block gets

       1590  consistent gets

          0  physical reads

          0  redo size

        538  bytes sent via SQL*Net to client

        520  bytes received via SQL*Net from client

          2  SQL*Net roundtrips to/from client

          0  sorts (memory)

          0  sorts (disk)

          1  rows processed



SQL> EXECUTE :oid  := 1



PL/SQL procedure successfully completed.



Elapsed: 00:00:00.00

SQL> select count(OBJECT_TYPE) from abc where object_id=:oid ;



COUNT(OBJECT_TYPE)

------------------

                 1



Elapsed: 00:00:00.02



Execution Plan

----------------------------------------------------------

Plan hash value: 1045519631

---------------------------------------------------------------------------

| Id  | Operation          | Name | Rows  | Bytes | Cost (%CPU)| Time     |

---------------------------------------------------------------------------

|   0 | SELECT STATEMENT   |      |     1 |    11 |   448   (1)| 00:00:06 |

|   1 |  SORT AGGREGATE    |      |     1 |    11 |            |          |

|*  2 |   TABLE ACCESS FULL| ABC  |   118K|  1274K|   448   (1)| 00:00:06 |

---------------------------------------------------------------------------

Predicate Information (identified by operation id):

---------------------------------------------------



   2 - filter("OBJECT_ID"=TO_NUMBER(:OID))



Statistics

----------------------------------------------------------

          0  recursive calls

          0  db block gets

       1590  consistent gets

          0  physical reads

          0  redo size

        536  bytes sent via SQL*Net to client

        520  bytes received via SQL*Net from client

          2  SQL*Net roundtrips to/from client

          0  sorts (memory)

          0  sorts (disk)</pre>
<ul>
	<li>rows processed</li>
</ul>
<pre>

To my surprise, both plans reported FTS regardless of the selectivity.  10046 trace shows Oracle is doing index range scan for OBEJCT_ID=1.  Using BINDS, the plan may not report correctly in the AUTOTRACE as there may be multiple child cursors existing due to Bind Peeking.  So, using BIND values in AUTOTRACE is really not working at all when we have multiple child cursors.  I am not sure, why Oracle can’t fix this issue, as AUTOTRACE just need to report the last executed plan, not from the estimation.

Then I turn to DBMS_XPLAN, and the results were surprised me even more.  For OBJECT_ID=1 reported a FTS, as


SQL> select count(OBJECT_TYPE) from abc where object_id=:oid ;



COUNT(OBJECT_TYPE)

------------------

                 1



Elapsed: 00:00:00.01

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



PLAN_TABLE_OUTPUT

-------------------------------------------------------------------------------------------

SQL_ID  99pd5nyyb4gsz, child number 1

-------------------------------------

select count(OBJECT_TYPE) from abc where object_id=:oid



Plan hash value: 1045519631



--------------------------------------------

| Id  | Operation          | Name | E-Rows |

--------------------------------------------

|   0 | SELECT STATEMENT   |      |        |

|   1 |  SORT AGGREGATE    |      |      1 |

|*  2 |   TABLE ACCESS FULL| ABC  |    118K|

--------------------------------------------



Predicate Information (identified by operation id):

---------------------------------------------------



   2 - filter("OBJECT_ID"=:OID)

 

I was not really expecting FTS using DBMS_XPLAN for OBJECT_ID=1, that was bit shocking.  Then I changed the option to ‘ALLSTATS LAST +PEEKED_BINDS’ from ‘ALLSTATS LAST ‘ and started reporting correct plans.


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



PLAN_TABLE_OUTPUT

------------------------------------------------------------------------------------------

SQL_ID  am229vwtp1ppk, child number 0

-------------------------------------

 select count(OBJECT_TYPE) from abc where object_id=:oid



Plan hash value: 2627152604



-------------------------------------------------------------

| Id  | Operation                    | Name        | E-Rows |

-------------------------------------------------------------

|   0 | SELECT STATEMENT             |             |        |

|   1 |  SORT AGGREGATE              |             |      1 |

|   2 |   TABLE ACCESS BY INDEX ROWID| ABC         |      1 |

|*  3 |    INDEX RANGE SCAN          | I_OBJECT_ID |      1 |

-------------------------------------------------------------



Peeked Binds (identified by position):

--------------------------------------



   1 - :SYS_B_0 (NUMBER): 1



Predicate Information (identified by operation id):

---------------------------------------------------


</pre>
<ul>
	<li>- access("OBJECT_ID"=:OID)</li>
</ul>
<pre>

So, be careful when you use AUTOTRACE or any tools when you use BIND variables.  Oracle should put some more efforts to make it more dependable.  Always use 10046 event and tkprof to get a real picture.


SQL> select * from v$version;



BANNER

--------------------------------------------------------------------------------

Oracle Database 11g Enterprise Edition Release 11.2.0.4.0 - 64bit Production

PL/SQL Release 11.2.0.4.0 - Production

CORE    11.2.0.4.0      Production

TNS for Linux: Version 11.2.0.4.0 - Production

NLSRTL Version 11.2.0.4.0 – Production



Advertisements
  1. No comments yet.
  1. No trackbacks yet.

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

%d bloggers like this: