11 May, 2009

Incorrectly using AUTOTRACE and EXPLAIN PLAN

Occassionally I see questions asking for help in tuning where the originator has used by AUTOTRACE and EXPLAIN PLAN together.
This can cause confusion.

Here, I pretend to be a novice using AUTOTRACE and EXPLAIN PLAN together :


SQL> set autotrace on
SQL> explain plan for select owner, created from test_query where owner = 'HEMANT';

Explained.

SQL> select * from table(dbms_xplan.display);

PLAN_TABLE_OUTPUT
------------------------------------------------------------------------------------------------------------------------------------
Plan hash value: 1390056125

------------------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 2109 | 29526 | 61 (0)| 00:00:01 |
| 1 | TABLE ACCESS BY INDEX ROWID| TEST_QUERY | 2109 | 29526 | 61 (0)| 00:00:01 |
|* 2 | INDEX RANGE SCAN | TEST_QUERY_NDX_1 | 2109 | | 5 (0)| 00:00:01 |
------------------------------------------------------------------------------------------------

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

2 - access("OWNER"='HEMANT')

14 rows selected.


Execution Plan
----------------------------------------------------------
Plan hash value: 2137789089

---------------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
---------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 8168 | 16336 | 29 (0)| 00:00:01 |
| 1 | COLLECTION ITERATOR PICKLER FETCH| DISPLAY | | | | |
---------------------------------------------------------------------------------------------


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

SQL>


I got TWO Explain Plan listings and one set of Statistics. Which is which ?
The first Explain Plan listing is, correctly, for the SQL that I am testing ("select ... from test_query ...."). The second Explain Plan (with the Plan Hash Value of '2137789089') is for the execution of dbms_xplan.display and this listing is generated because I had set AUTOTRACE ON ! And it shows a CARD (expected number of rows) of 8,168 rows. That is very high and difficult to explain ? How does it relate to the CARD of 2,109 for the test query ?!
Can you guess which operation the statistics are for ?

What I should have been doing is this in TWO Parts.

The first part is for the Explain Plan itself :


SQL> set autotrace off
SQL> explain plan for select owner, created from test_query where owner = 'HEMANT';

Explained.

SQL> select * from table(dbms_xplan.display);

PLAN_TABLE_OUTPUT
------------------------------------------------------------------------------------------------------------------------------------
Plan hash value: 1390056125

------------------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 2109 | 29526 | 61 (0)| 00:00:01 |
| 1 | TABLE ACCESS BY INDEX ROWID| TEST_QUERY | 2109 | 29526 | 61 (0)| 00:00:01 |
|* 2 | INDEX RANGE SCAN | TEST_QUERY_NDX_1 | 2109 | | 5 (0)| 00:00:01 |
------------------------------------------------------------------------------------------------

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

2 - access("OWNER"='HEMANT')

14 rows selected.

SQL>


This listing is quite clear now. I have the Explain Plan for my test query.


The second part is to get an AUTOTRACE. Here I use AUTOTRACE TRACEONLY STATISTICS. Thus, I get *only* the statistics !


SQL> set autotrace traceonly statistics
SQL> select owner, created from test_query where owner = 'HEMANT';


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

SQL>


These show me that the query actually fetched 4 rows, without having to view the output.

If the output had been 2,109 rows, I'd have to allow that many rows to scroll across my screen before I could see the statistics. Now, with AUTOTRACE TRACEONLY I can allow the query to execute and fetch the rows but SQLPlus will "discard" them and not show them on the screen. Database server side processing remains the same, as if the rows were displayed on-screen.
Similarly, with the STATISTICS keyword appended, I ask Oracle to only present the Statistics and NOT present the Explain Plan. I have already seen the Explain Plan and do not need to see it here again. (In my test above, the Plan has only 3 steps, but the query could have been a complex one with more than a few dozen steps !).
.
.
.

3 comments:

Anonymous said...

Nice Cameo.

Regards!

Anonymous said...

why not just:

SQL> set autotrace on
SQL> select owner, created from test_query where owner = 'HEMANT';

Hemant K Chitale said...

This post is about the case of using AUTOTRACE and EXPLAIN PLAN *together*.

Of course, you can use AUTOTRACE alone.

Hemant K Chitale