Autotrace in SQL*PLus is a handy tool when I want to see the execuion plan of SQL statements. However, one of the main disadvantages of autotrace is that it will generate incorrect execution plan, especially when the SQL statements use bind variables. Recently I have encountered this incorrect execution plan issue when I was going to tune a SQL statement.
Here is the simplified version of my test case:
SQL> create table t1 as select level id, rpad('*',4000,'*') data from dual connect by level <= 40000;
SQL> create index t1_idx on t1(id);
SQL> exec dbms_stats.gather_table_stats(ownname=>'TEST',tabname=>'T1',cascade=>true)
Basically, the above SQL statements a table with about 45000 rows and an index t1_idx on the column object_id in user TEST
SQL> set autotrace on explain SQL> var i number SQL> exec :i := 42 SQL> select * from t1 where id<:i; -------------------------------------------------------------------------------------- | Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time | -------------------------------------------------------------------------------------- | 0 | SELECT STATEMENT | | 1995 | 7802K| 362 (0)| 00:00:05 | | 1 | TABLE ACCESS BY INDEX ROWID| T1 | 1995 | 7802K| 362 (0)| 00:00:05 | |* 2 | INDEX RANGE SCAN | T1_IDX | 360 | | 2 (0)| 00:00:01 | -------------------------------------------------------------------------------------- SQL> exec :i := 60000 SQL> select * from t1 where id<:i; -------------------------------------------------------------------------------------- | Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time | -------------------------------------------------------------------------------------- | 0 | SELECT STATEMENT | | 1995 | 7802K| 362 (0)| 00:00:05 | | 1 | TABLE ACCESS BY INDEX ROWID| T1 | 1995 | 7802K| 362 (0)| 00:00:05 | |* 2 | INDEX RANGE SCAN | T1_IDX | 360 | | 2 (0)| 00:00:01 | -------------------------------------------------------------------------------------- SQL> select * from t1 where id<=40000 -------------------------------------------------------------------------- | Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time | -------------------------------------------------------------------------- | 0 | SELECT STATEMENT | | 39908 | 152M| 8775 (1)| 00:01:46 | |* 1 | TABLE ACCESS FULL| T1 | 39908 | 152M| 8775 (1)| 00:01:46 | --------------------------------------------------------------------------
There are three parts in the above example:
1. When I run the first select statement with bind variable :i=42, the optimizer chooses to return the result by scanning the index t1_idx. This looks good as the optimizer know that we have an index on object_id column and since only small amount of rows ( 42 rows)are returned.
2. The second statement is similar to the first one, except that the bind variable i is set to 40000 this time. We can see that the optimizer generate a plan identical to the first one, using the index to access the rows. Is this plan correct? Let's third sql statement.
3. In the third sql statement, I modified the second select statement and replaced the bind variable with literal,i.e. id <=40000. The explain plan changed. The optimizer has chosen a FTS(Full Table Scan) to return the result. This plan is a correct plan as when id<=40000, all the rows of the table are return. It is more beneficial use a full table scan than using the index t1_idx.
Why we got the wrong plan when using bind variable in autotrace in SQL*Plus?
When using "autotrace" or explaing plan command, the plan generated is an estimation. It is the bind variables contained in the sql statement cause the problem.
How could we find the correct when we use bind variables?
There are two ways to use find the actual plan used when a sql statement contains bind variables:
1. Enable the sql trace function when we run the SQL statement.
2. Find the actual execution plan from v$sql_plan dynamic view.
Here is an demonstration of finding the actual execution plan using SQL Trace
SQL> alter session set events '10046 trace name context forever, level 12'; SQL> var i number; SQL> exec :i := 40000; SQL> select * from t1 where id <= :i; SQL> select * from t1 where id <= 40000; SQL> select * from dual; SQL> alter session set events '10046 trace name context off';
Then we run tkprof utility on the trace file to generate a formated output
$ tkprof tracefile.trc output.txt select * from t1 where object_id <= 40000 BEGIN :i := 40000; END; call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 1 0.00 0.00 0 0 0 0 Execute 1 0.01 0.01 0 0 0 1 Fetch 0 0.00 0.00 0 0 0 0 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 2 0.01 0.02 0 0 0 1 select * from t1 where id <= :i call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 1 0.00 0.00 0 0 0 0 Execute 1 0.00 0.02 0 0 0 0 Fetch 2668 4.46 6.84 37728 40014 0 40000 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 2670 4.47 6.86 37728 40014 0 40000 Misses in library cache during parse: 1 Optimizer mode: ALL_ROWS Parsing user id: SYS Rows Row Source Operation ------- --------------------------------------------------- 40000 TABLE ACCESS FULL T1 (cr=40014 pr=37728 pw=0 time=2840825 us) select * from t1 where id <= 40000 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 2668 2.43 4.20 37295 40014 0 40000 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 2670 2.43 4.21 37295 40014 0 40000 Misses in library cache during parse: 1 Optimizer mode: ALL_ROWS Parsing user id: SYS Rows Row Source Operation ------- --------------------------------------------------- 40000 TABLE ACCESS FULL T1 (cr=40014 pr=37295 pw=0 time=4040301 us)
From the tkprof, we can find that both select statements ,either using literal or bind variables, generated the same execution plan. These are also the actual plans used by optimizer when we run the sql statements.
Filed under:
Oracle