Tuning with sql_trace=true...

My all time favorite seminar topic is my talk on "All about Binds".  It takes about 3 hours to do the entire talk from start to finish and covers performance, memory utilization, scalability, security, bind mismatches, bind variable peeking and cursor sharing.

Today, I got a question on asktom that I answer - no, I actually demonstrate the answer to - in that presentation.  During the presentation - I say

"I'm going to show you how to tune by setting sql_trace=true.  You are probably all thinking that I'm going to run a query, observe it running slow, trace it and then tune it.  Well, I'm not going to do that - all I'm going to do is set sql_trace=true and we'll observe the query performance and resource utilization to be dramatically affected - all for the better!"

The question on asktom is identical to what I demonstrate - they wrote:

"I have a query that runs slow (2 minutes) So what do I do? Turn on tracing (both sql_trace=true and event 10046) before running the query. But consistently, 100% of the time, without changing anything else, when I enable tracing, the query comes back instantly!!"

I know exactly what is happening...  It is a combination of two things

• The fact that when you set sql_trace=true, you set up a new 'parse' environment (made up term).  You have changed your session in such a way that you will not share any existing SQL that was not parsed with sql_trace enabled.  So, it is highly likely that you will either hard parse a new version of the query - or use some existing child cursor that is different from the one you would use with sql_trace disabled.
• Bind variable peeking happens at hard parse time and may affect the plan chosen by the optimizer.

So, first for the setup script to demonstrate this phenomena - I'll set up a very skewed set of data for emphasis:

ops$tkyte%ORA10GR2> create table t
  2  as
  3  select case when rownum = 1 then 1 else 99 end id, a.*
  4    from all_objects a
  5  /
Table created.

ops$tkyte%ORA10GR2> alter table t modify object_id null;
Table altered.

ops$tkyte%ORA10GR2> create index t_idx on t(id);
Index created.

ops$tkyte%ORA10GR2> begin
  2      dbms_stats.gather_table_stats
  3      ( user, 'T',
  4        method_opt=> 'for all indexed columns size 254' );
  5  end;
  6  /
PL/SQL procedure successfully completed.

So, it is quite clear that WHERE ID=1 will return one record and WHERE ID=99 will return all of the rest (about 50,000 records). Also, the optimizer is very aware of this fact due to the histograms in place and if we parse using literals - we can definitely see different plans for different inputs:

ops$tkyte%ORA10GR2> set autotrace traceonly explain
ops$tkyte%ORA10GR2> select * from t where id = 1;

Execution Plan
----------------------------------------------------------
Plan hash value: 470836197

-------------------------------------------------------------------------------------
| Id  | Operation                   | Name  | Rows  | Bytes | Cost (%CPU)| Time     |
-------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |       |     1 |    96 |     2   (0)| 00:00:01 |
|   1 |  TABLE ACCESS BY INDEX ROWID| T     |     1 |    96 |     2   (0)| 00:00:01 |
|*  2 |   INDEX RANGE SCAN          | T_IDX |     1 |       |     1   (0)| 00:00:01 |
-------------------------------------------------------------------------------------

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

   2 - access("ID"=1)

ops$tkyte%ORA10GR2> select * from t where id = 99;

Execution Plan
----------------------------------------------------------
Plan hash value: 1601196873

--------------------------------------------------------------------------
| Id  | Operation         | Name | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |      | 50244 |  4710K|   235   (4)| 00:00:02 |
|*  1 |  TABLE ACCESS FULL| T    | 50244 |  4710K|   235   (4)| 00:00:02 |
--------------------------------------------------------------------------

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

   1 - filter("ID"=99)

ops$tkyte%ORA10GR2> set autotrace off

But, what happens when we issue "select * from t where id = :id" - when we bind the ID input?  Well, on the first hard parse - Oracle will wait till the cursor is opened to do the actual optimization of the query - it will wait for the bind variable value to be supplied by the application before figuring out the right way to optimize the query.  That is called "bind variable peeking", when the optimizer looks at the bind values and then optimizes the query.  In this case however, depending on what inputs are used to first run the query - we'll either get a full scan or an index range scan plus table access by index rowid - and that is the plan that will be used to execute the query "select * from t where id = :id" regardless of the bind values from now on.

What is happening to the poster on asktom is that

1. Someone hard parsed the query in question and when they did so, the inputs they used resulted in "plan A"
   
2. Plan A was the best plan for that person given their inputs - it was the most efficient plan
   
3. Later, someone else executed the same query, using shared sql they reused the plan generated by the other person - but their bind variable inputs where different and the plan that was generated for #1 was not the best plan for these inputs, in fact the plan was miserable for these inputs
   
4. They turned on sql_trace and executed the query with inputs from #3 again - but because sql-trace was on - they did not share the sql statement - they hard parsed - with their inputs - and this resulted in a very different plan

We can observe this easily, consider:

ops$tkyte%ORA10GR2> variable id number
ops$tkyte%ORA10GR2> set autotrace traceonly statistics
ops$tkyte%ORA10GR2> exec :id := 99
PL/SQL procedure successfully completed.

ops$tkyte%ORA10GR2> select * from t where id = :id;
50254 rows selected.

Statistics
----------------------------------------------------------
          ....
       4031  consistent gets
          ....
      50254  rows processed

 

So, we started off with id=99 as the bind, and a full scan was chosen (you can prove that via TKPROF by looking at the row source operation if you wish; I did...).  That means regardless of the bind value from now on - we will full scan - for example:

ops$tkyte%ORA10GR2> exec :id := 1
PL/SQL procedure successfully completed.

ops$tkyte%ORA10GR2> select * from t where id = :id;

Statistics
----------------------------------------------------------
          ...
        720  consistent gets
          ...
          1  rows processed

It is unlikely that was the index range scan/table access by index rowid - we'd expect a lot less logical IO, 3 or 4 IO's against an index and 1 against the table - we did a full scan for id=1.  That represents our "poorly performing query".  We turn on SQL_TRACE to find the performance characteristics of that and observe:

ops$tkyte%ORA10GR2> alter session set sql_trace=true;
Session altered.

ops$tkyte%ORA10GR2> select * from t where id = :id;

Statistics
----------------------------------------------------------
          ...
          4  consistent gets
          ...
          1  rows processed

 

That apparently just setting SQL_TRACE=TRUE is our tuning mechanism!  It isn't really - it is bind peeking and hard parsing that is causing this, but unless you know that a) sql_trace sets up a child cursor and b) bind peeking happens - this looks very mysterious, especially if you turn it off:

ops$tkyte%ORA10GR2> alter session set sql_trace=false;
Session altered.

ops$tkyte%ORA10GR2> select * from t where id = :id;

Statistics
----------------------------------------------------------
          ...
        720  consistent gets
          ...
          1  rows processed

 

See it run slow and turn it on again:

ops$tkyte%ORA10GR2> alter session set sql_trace=true;
Session altered.

ops$tkyte%ORA10GR2> select * from t where id = :id;

Statistics
----------------------------------------------------------
          ...
          4  consistent gets
          ...
          1  rows processed

And see it go fast...

It is not magic, it is bind peeking.  To see the real plans - you can query v$sql_plan / v$sql_plan_statistics or use DBMS_XPLAN to dump the plans for each child cursor:

ops$tkyte%ORA10GR2> select sql_id 
from v$sql 
where sql_text = 'select * from t where id = :id';

SQL_ID
-------------
8s40hfjcbmxzk
8s40hfjcbmxzk

ops$tkyte%ORA10GR2> select * 
from table( dbms_xplan.display_cursor( '8s40hfjcbmxzk', 0 ) );

PLAN_TABLE_OUTPUT
---------------------
SQL_ID  8s40hfjcbmxzk, child number 0
-------------------------------------
select * from t where id = :id

Plan hash value: 1601196873

--------------------------------------------------------------------------
| Id  | Operation         | Name | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |      |       |       |   235 (100)|          |
|*  1 |  TABLE ACCESS FULL| T    | 50250 |  4710K|   235   (4)| 00:00:02 |
--------------------------------------------------------------------------

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

   1 - filter("ID"=:ID)


18 rows selected.

ops$tkyte%ORA10GR2> select * 
from table( dbms_xplan.display_cursor( '8s40hfjcbmxzk', 1 ) );

PLAN_TABLE_OUTPUT
---------------------------
SQL_ID  8s40hfjcbmxzk, child number 1
-------------------------------------
select * from t where id = :id

Plan hash value: 470836197

-------------------------------------------------------------------------------------
| Id  | Operation                   | Name  | Rows  | Bytes | Cost (%CPU)| Time     |
-------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |       |       |       |     2 (100)|          |
|   1 |  TABLE ACCESS BY INDEX ROWID| T     |     1 |    96 |     2   (0)| 00:00:01 |
|*  2 |   INDEX RANGE SCAN          | T_IDX |     1 |       |     1   (0)| 00:00:01 |
-------------------------------------------------------------------------------------

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

   2 - access("ID"=:ID)


19 rows selected.

You can use v$sql_shared_cursor to see why you have multiple child cursors as well - for example:

ops$tkyte%ORA10GR2> select child_number, stats_row_mismatch
  2    from v$sql_shared_cursor
  3   where sql_id = '8s40hfjcbmxzk'
  4  /

CHILD_NUMBER S
------------ -
           0 N
           1 Y

That is what you would look for to verify you were having a "must be sql_trace creating a new child cursor and a hard parse with different binds" problem.