On Tuning by Tracing

Our technologist does a tune-up with SQL_TRACE.

January/February 2008

My all-time favorite presentation is called "All About Binds." It takes me about three hours to do the entire talk—which covers performance, memory utilization, scalability, security, bind mismatches, bind variable peeking, and cursor sharing—from start to finish.

Today, I got this message on Ask Tom:

I have a query that runs slowly (it takes about two minutes). So what do I do? I turn on tracing (SQL_TRACE=TRUE) before running the query, and consistently, 100 percent of the time, without my changing anything else, when I enable tracing the query comes back instantly!

This message on Ask Tom shows exactly what I demonstrate in the "All About Binds" presentation, during which 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 slowly, 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 you'll observe that the query performance and resource utilization are dramatically affected—all for the better!"

I know exactly what is happening in the Ask Tom scenario—it is a combination of two things:

• When you set SQL_TRACE=TRUE, you set up a new "parse environment" (a made-up term). You have changed your session in such a way that it 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.

Let's start with the setup script to demonstrate this phenomenon. I'll set up a very skewed set of data for emphasis:

SQL> create table t
  2    as
  3    select case when rownum = 1
  4    then 1 else 99 end id, a.*
  5      from all_objects a
  6    /
Table created.
SQL> create index t_idx on t(id);
Index created.
SQL> begin
  2    dbms_stats.gather_table_stats
  3    ( user, 'T',
  4     method_opt=>
  5    'for all'||
  6    'indexed columns'||
  7    'size 254' );
  8    end;
  9    /
PL/SQL procedure successfully completed.

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, because of the histograms in place, and if we parse by using literals, we can definitely see different plans for different inputs, as shown in Listing 1.

Code Listing 1: Different inputs, different plans

SQL> set autotrace traceonly explain
SQL> select * from t where id = 1;
Execution Plan
-------------------------------------------------------------------------------------------------------
|  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  |
-------------------------------------------------------------------------------------------------------
SQL> select * from t where id = 99;
Execution Plan
-------------------------------------------------------------------------------------------------------
|  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   |
-------------------------------------------------------------------------------------------------------

But what happens when we bind the ID input—when we issue SELECT * FROM t WHERE ID = :ID? Well, the answer depends on which release of Oracle Database is being used. With Oracle8i Database Release 3 and earlier, the optimizer will more or less "guess." It will not have any information about the WHERE ID = :ID clause. The information it has is

• ID has two values in the table: 1 and 99.

• There are 50,000 records in the table.

And because ID has only two values, this old optimizer will guess that for any query on ID, about half of the table on average will be selected. And the database would come up with one plan, regardless of the inputs. In this case, it would likely do a full scan of the table.

From Oracle9i Database Release 1 through Oracle Database 10g Release 2, Oracle Database will wait until 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. This is called bind variable peeking , when the optimizer first looks at the bind values and then optimizes the query. In this case, however, depending on which inputs are used to first run the query, the database will either choose a full scan or an index range scan plus table access by index rowid. And in Oracle9i Database Release 1 through Oracle Database 10g Release 2, that is the plan that will be used to execute the SELECT * FROM t WHERE ID = :ID query, regardless of the subsequent bind values, until the query is hard-parsed and optimized again.

I'll address what happens in Oracle Database 11g Release 1 in a minute, but first let's take a look at what is happening to the person whose scenario on Ask Tom inspired this discussion:

1. Someone hard-parsed the query in question, and the inputs used resulted in "Plan A."

2. Plan A was the best plan for that person, given the inputs—it was the most efficient plan.

3. Later, someone else executed the same query. Using shared SQL, this person reused the plan generated by the other person (Plan A in No. 1), but the new bind variable inputs were different and the plan generated for No. 1 was not the best plan for these inputs. In fact, the plan was miserable for these new inputs.

4. The person in No. 3 turned on SQL_TRACE and executed the query with inputs from No. 3 again, but because SQL_TRACE was on, the query did not share the SQL. The query was hard-parsed—with the new inputs—and this resulted in a very different plan, "Plan B," and given these inputs, Plan B was much better than Plan A.

Using Oracle Database 10g Release 2, we can observe this easily. Consider the following:

SQL> variable id number
SQL> set autotrace traceonly statistics
SQL> exec :id := 99
PL/SQL procedure successfully completed.
SQL> 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 the optimizer chose a full scan (you can prove that via TKPROF by looking at the row source operation if you wish; I did. . . .) Therefore, regardless of the bind value, the database will execute a full scan from now on. For example,

SQL> exec :id : = 1
PL/SQL procedure successfully completed.
SQL> select * from t where id = :id;
Statistics
----------------------------------
        720  consistent gets
          1  rows processed

This result demonstrates that it was unlikely that an index range scan/table access by index rowid was executed. In such a case, we'd expect many fewer logical I/Os (consistent gets)—three or four against an index and one against the table. This result represents our "poorly performing query." Now we turn on SQL_TRACE to find the performance characteristics, and we observe

SQL> alter session set sql_trace = true;
Session altered.
SQL> select * from t where id = :id;
Statistics
-----------------------------------
          4  consistent gets
          1  rows processed

Apparently just setting SQL_TRACE=TRUE is our tuning mechanism! It isn't really—bind peeking and hard parsing are what's causing this result, but unless you know that SQL_TRACE sets up a child cursor and that bind peeking happens, this looks very mysterious, especially if you turn SQL_TRACE off:

SQL> alter session set sql_trace=false;
Session altered.
SQL> select * from t where id = :id;
Statistics
------------------------------------
        720  consistent gets
          1  rows processed

See it run slowly (720 consistent gets). And now that we've seen slow, turn SQL_TRACE on again:

SQL> alter session set sql_trace=true;
Session altered.
SQL> 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, as shown in Listing 2.

Code Listing 2: Using DBMS_XPLAN to show the plans for each child cursor

SQL> select sql_id from v$sql where sql_text = 'select * from t where id = :id';
SQL_ID
---------------------------------------
8s40hfjcbmxzk
8s40hfjcbmxzk
SQL> 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.
SQL> 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 and the SQL_ID from Listing 2 to see why you have multiple child cursors as well. For example,

SQL> select child_number,
  2         stats_row_mismatch
  3      from v$sql_shared_cursor
  4      where sql_id = '8s40hfjcbmxzk'
  5    /
CHILD_NUMBER   STATS_ROW_MISMATCH
-------------  ------------------
                   0 N
                   1 Y

That is what you would look for to verify that you were seeing an "it must be SQL_TRACE creating a new child cursor and a hard parse with different binds" result. (The queries you run to verify this in Oracle9i Database are slightly different from the Oracle Database 10g Release 2 queries above. If you are interested in the Oracle9i Database queries, you can review tkyte.blogspot.com/2007/09/sqltracetrue-part-two.html, where I worked the example through in that release.)

The current release of Oracle Database—Oracle Database 11g—changes the above behavior for the better. A new feature—intelligent cursor sharing—enables the optimizer to recognize that performance can be affected when a fixed, one-size-fits-all plan is used and come up with different plans for certain bind ranges. In the following example, I simply used the schema from above—the copy of ALL_OBJECTS, with one row having the value ID=1, the index in place, and statistics gathered. Then I ran a PL/SQL block that would open a cursor by using one of two inputs—either 1 or 99. This time, instead of just one plan being generated, we'll see two. The optimizer recognized that one plan was not sufficient for all inputs and allowed for multiple plans to be generated, as shown in Listing 3.

Code Listing 3: Multiple plans with intelligent cursor sharing (Oracle Database 11g)

SQL> select sql_id
  2      from v$sql
  3    where sql_text = 'select * from T where id = :x';
no rows selected
SQL> declare
  2    l_cursor sys_refcursor;
  3    type array is table of number;
  4    l_data  array := array(99,1);
  5    type data_array is table of T%rowtype;
  6    l_recs  data_array;
  7    begin
  8    for i in 1 .. l_data.count
  9    loop
 10       open l_cursor for 'select * from T where id = :x' using l_data( i );
 11       loop
 12          fetch l_cursor bulk collect into l_recs limit 500;
 13          exit when l_cursor%notfound;
 14       end loop;
 15       close l_cursor;
 16    end loop;
 17    end;
 18    /
PL/SQL procedure successfully completed.
SQL> select sql_id
  2    from v$sql
  3   where sql_text = 'select * from T where id = :x';
SQL_ID
-----------------------------------------------------------------------
gw1fks2wb4j2g
gw1fks2wb4j2g
SQL> select * from table(dbms_xplan.display_cursor('gw1fks2wb4j2g',0));
SQL_ID  gw1fks2wb4j2g, child number 0
-------------------------------------------------------------------------
select * from T where id = :x
---------------------------------------------------------------------------------------
|  Id   |  Operation            |  Name  |  Rows  |  Bytes |  Cost (%CPU)  |  Time    |
---------------------------------------------------------------------------------------
|   0   |  SELECT STATEMENT     |        |        |        |    292 (100)  |          |
|*  1   |    TABLE ACCESS FULL  |  T     |  68207 |  6927K |   292   (2)   | 00:00:04 |
---------------------------------------------------------------------------------------
SQL> select * from table(dbms_xplan.display_cursor('gw1fks2wb4j2g',1));
SQL_ID  gw1fks2wb4j2g, child number 1
-------------------------------------
select * from T where id = :x
---------------------------------------------------------------------------------------------------
|  Id   |  Operation                     |  Name  |  Rows  |  Bytes  |  Cost (%CPU)  |  Time      |
---------------------------------------------------------------------------------------------------
|   0   |  SELECT STATEMENT              |        |        |         |   2    (100)  |            |
|   1   |    TABLE ACCESS BY INDEX ROWID | T      |     1  |    104  |   2       (0) |  00:00:01  |
|*  2   |      INDEX RANGE SCAN          | T_IDX  |     1  |         |   1       (0) |  00:00:01  |
---------------------------------------------------------------------------------------------------

Most of the time—almost all of the time, in fact—bind variable peeking works as the designers of the feature intended: in a positive, helpful manner. The query in the application uses bind values that drive it to one plan or the other consistently. It is only when the plan flip-flops between two radically different execution paths, and for some segment of users, that you have a really bad plan. In such cases, Oracle Database 11g might be the right answer for you, because it accommodates multiple plans.

Don't bind that query. Yes, you read that correctly—don't use a bind variable (yes, I wrote that—do not use a bind variable!) In my example, ID has two values—1 and 99. Let's say ID wasn't ID but rather was PROCESSED_FLAG and had two values—Y and N. Most of the records are PROCESSED_FLAG=Y; some of them are N. Some people query the processed records (Y=yes). They want a full scan. Others query the unprocessed records in order to process them (N=no). They want an index range scan.

Here my suggestion would be not to bind against PROCESSED_FLAG; instead, use literals. That way we have two queries and two plans.

This is also why I do not like CURSOR_SHARING=FORCE, because when a programmer does this (uses literals) and the DBA turns on CURSOR_SHARING=FORCE, we are back to the original problem! Bind variable peeking comes into play once again—there is one plan for all, and it depends on who runs the query first. (By the way, CURSOR_SHARING=SIMILAR would not have this side effect. It would choose not to bind against PROCESSED_FLAG based on the statistics).

Don't gather statistics that cause the plan to flip-flop. If there is only one plan that the optimizer would ever choose, then bind variable peeking will have no effect. If you were to execute the above example without gathering histograms, the plan would not flip-flop.

Use your domain knowledge of the data. If you know that when a certain query is executed with a date that falls within the last 30 days, the volume of data would be small and indexes would be used and that if the date is way in the past, the volume of data would be large and full scans would be used, then just use if/then/else.

[[... if/then/else]]:
if ( p_date > sysdate-30 )
then
  open l_cursor for
  select * from t less_than_30 where ...
else
   open l_cursor for
   select * from t more_than_30 where ...
end if;
loop
   fetch l_cursor into ...;
...

This works when you have good knowledge of your data. This approach is similar to what Oracle Database 11g is doing with intelligent cursor sharing.

Use CURSOR_SHARING=SIMILAR. If you use CURSOR_SHARING=SIMILAR, you can let Oracle Database decide what to bind and what not to bind. For more details on that, with a full example, see tkyte.blogspot.com/2007/09/sqltracetrue-part-two.html.

Use stored outlines. Stored outlines are also known as query plan stability. In a test environment, you would exercise the application by using appropriate or representative inputs. Additionally, you would be capturing stored outlines into the outline tables. You would then move these into production and have the application issue ALTER SESSION to use these stored outlines.

Using stored outlines, you—in effect—freeze the plans. (And you can stop gathering statistics as well, because you just froze the plans.)

Disable the bind peeking feature. You can disable bind peeking by using an undocumented init.ora parameter, but—because this really affects you only if you have statistics that cause plans to flip-flop—I would say, instead, that you should stop gathering those statistics to save the time and resources it takes, and you'll have achieved basically the same goal.