Friday, March 5, 2010

Explain Plan - The Oldest Bug in Oracle

Under what conditions, autotrace and Explain plan cannot give the correct explain plan of a Sql?

create table t as select a.*,1 as id from all_objects a where rownum = 1;
create index t_ind on t(id);
alter session set sql_trace = true;
select * from t where id = 1;
insert into t select a.*,1 as id from all_objects a;
select * from t where id = 1;
alter session set sql_trace = false;

********************************************************************************
select *
from t
where id = 1

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.01       0.04          0          2          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        2      0.00       0.00          0          2          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      0.01       0.04          0          4          0           1

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 54  (SCOTT)

Rows     Row Source Operation
-------  ---------------------------------------------------
      1  TABLE ACCESS BY INDEX ROWID T (cr=2 pr=0 pw=0 time=19 us)
      1   INDEX RANGE SCAN T_IND (cr=1 pr=0 pw=0 time=14 us)(object id 64947)


Rows     Execution Plan
-------  ---------------------------------------------------
      0  SELECT STATEMENT   MODE: ALL_ROWS
      1   TABLE ACCESS (FULL) OF 'T' (TABLE)

********************************************************************************
select *
from  t
where id = 1

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      344      0.10       0.11          0       1534          0       51396
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total      346      0.10       0.11          0       1534          0       51396

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 54  (SCOTT)

Rows     Row Source Operation
-------  ---------------------------------------------------
  51396  TABLE ACCESS BY INDEX ROWID T (cr=1534 pr=0 pw=0 time=102827 us)
  51396   INDEX RANGE SCAN T_IND (cr=474 pr=0 pw=0 time=25 us)(object id 64947)


Rows     Execution Plan
-------  ---------------------------------------------------
      0  SELECT STATEMENT   MODE: ALL_ROWS
  51396   TABLE ACCESS (FULL) OF 'T' (TABLE)

********************************************************************************

Now how the Row Source Operation (what is called reality) differ from Execution Plan (what is called estimation). what happened here was that the  Row Source Operation captured in the Trace file at the time of execution - reflects what REALLY took place as the query executed. The sequence of operation followed for the query is

1) Load a single row into the table T
2) ran the query against T - that did the hard parse using dynamic sampling sampled the table at run time and founded that using Index leads to efficient execution.
3) loaded more data with id =1 into table T
4) ran the same query from step#2 - that did soft parse and reused the plan generated back when only one row existed in the table. that leads to inefficient execution.
5) executing TKPROF with explain = / shows an entierly different execution plan. This is because explain plan always does hard parse - It dynamically sampled the table again - founded it to be large for id =1 - it would full scan. How ever the real execution of the query Index range scanned by using the plan available in shared pool.

An important note for this example - the placement of the ALTER SESSION SET SQL_TRACE=TRUE is important. As an exercise - move it to just be before the second execution of the query and you'll find the query is Hard parsed and the Row Source Operation in the Tkprof is Full table scan.

drop table t purge;
create table t as select a.*,1 as id from all_objects a where rownum = 1;
create index t_ind on t(id);
select * from t where id = 1;
insert into t select a.*,1 as id from all_objects a;
alter session set sql_trace = true;
select * from t where id = 1;
alter session set sql_trace = false;

********************************************************************************
select *
from
 t where id = 1


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          2          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch      344      0.10       0.06          0       1093          0       51397
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total      346      0.10       0.07          0       1095          0       51397

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 54  (SCOTT)

Rows     Row Source Operation
-------  ---------------------------------------------------
  51397  TABLE ACCESS FULL T (cr=1093 pr=0 pw=0 time=34 us)


Rows     Execution Plan
-------  ---------------------------------------------------
      0  SELECT STATEMENT   MODE: ALL_ROWS
  51397   TABLE ACCESS (FULL) OF 'T' (TABLE)

********************************************************************************

No comments:

Post a Comment