Archive for April 2009

Oracle 11g SQL Plan Management – SQL Plan Baselines

Note, this post applies to 11gR1 (specifically 11.1.0.7).

11g has a new method of dealing with plan instability (i.e. the tendency of a statement to flip flop between plans). The goal has always been to provide the best performance, but until 11g there has not been a mechanism that had as a design goal, the idea of eliminating backwards movement (“performance regressions” as the Oracle documentation calls them). That is, not allowing a statement to switch to a plan that is significantly slower than the one it has already been executing. This new mechanism depends on a construct called a Baseline. So for this post I am not going to focus on the process of evolving plans to prevent “performance regressions”, but rather on the Baselines themselves. (hopefully I’ll get to the plan management part soon)

Here’s a little excerpt from the 11gR1 documentation:

Each time a SQL statement is compiled, the optimizer first uses a cost-based search method to build a best-cost plan, then tries to find a matching plan in the SQL plan baseline. If a match is found, the optimizer will proceed using this plan. Otherwise, it evaluates the cost of each accepted plan in the SQL plan baseline and selects the plan with the lowest cost. The best-cost plan found by the optimizer that does not match any plans in the plan history for the SQL statement represents a new plan, and is added as a non-accepted plan to the plan history. The new plan is not used until it is verified to not cause a performance regression. However, if a change in the system (such as a dropped index) causes all accepted plans to become non-reproducible, the optimizer will select the best-cost plan. Thus, the presence of a SQL plan baseline causes the optimizer to use conservative plan selection strategy for the SQL statement.

Clear as mud?

Now my description:

Baselines are the latest evolution in Oracle’s efforts to allow a plan to be locked. The previous efforts were Outlines and SQL Profiles. Both of those efforts were based on the idea that hints could be applied to limit the optimizers choices down to one. That approach seems a little flawed. Why not just save the plan and be done with it? I believe that’s what Baselines are intended to do. Unfortunately, they don’t appear to do it yet. But they do have an advantage over Outlines and SQL Profiles in that they at least save the plan_hash_value, so they know if they are reproducing the correct plan or not. (see my previous post, Do Baselines Use Hints? – Take 2) And hopefully, they will evolve to the point where the actual plan is saved along with the hash value – we’ll see.

So anyway, here’s some basic housekeeping stuff on Baselines:

  • Baselines will be used by default in 11gR1, if they exist. There is a parameter to control whether they are used or not (OPTIMIZER_USE_SQL_PLAN_BASELINE). It is set to TRUE by default.
  • Baselines will not be created by default in 11gR1. So, much like with the older Outlines or SQL Profiles, you must do something to create them.
  • There is a view called DBA_SQL_PLAN_BASELINES that exposes the Baselines that have been created.
  • Just like Outlines and SQL Profiles, Baselines apply to all instances in a RAC environment (they are not localized to a specific instance).

Baselines can be created a couple of different ways. They can be created automatically by the database as it’s running by setting the OPTIMIZER_CAPTURE_SQL_PLAN_BASELINES parameter. They can also be created for statements in a SQL Tuning Set. But I’m not going to talk about either one of those approaches in this post, as I don’t think they really make much sense in the case where you want to use a Baseline to lock a plan for a specific statement. Instead, I am going to discuss creating a baseline for a statement that is in the shared pool via the DBMS_SPM.LOAD_PLANS_FROM_CURSOR_CACHE function.

All the function needs is a SQL_ID and a PLAN_HASH_VALUE. Optionally a parameter can be used to define the baseline as FIXED. If it’s FIXED then it gets priority over any other Baselines for that statement, except other FIXED Baselines. Confused? Well it’s not exactly the most straight forward setup. I’m kind of a simple guy, so at this point I’m thinking one FIXED Baseline is enough.

Before you get too bored, here’s a quick example:

SQL> select avg(pk_col) from kso.little_skew where col1 = 99320;

AVG(PK_COL)
-----------
     628922

SQL> @find_sql
Enter value for sql_text: %little%
Enter value for sql_id: 

SQL_ID         CHILD  PLAN_HASH      EXECS     AVG_ETIME      AVG_LIO SQL_TEXT
------------- ------ ---------- ---------- ------------- ------------ ------------------------------------------------------------
4dd2qjxbjav6u      0 2709260180          1           .02           89 select avg(pk_col) from kso.little_skew where col1 = 99320

SQL> @dplan
Enter value for sql_id: 4dd2qjxbjav6u
Enter value for child_no: 0

PLAN_TABLE_OUTPUT
------------------------------------------------------------------------------------------------------------------------------------------------------
SQL_ID  4dd2qjxbjav6u, child number 0
-------------------------------------
select avg(pk_col) from kso.little_skew where col1 = 99320

Plan hash value: 2709260180

-------------------------------------------------------------------------------------------------
| Id  | Operation                    | Name             | Rows  | Bytes | Cost (%CPU)| Time     |
-------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT             |                  |       |       |     4 (100)|          |
|   1 |  SORT AGGREGATE              |                  |     1 |     9 |            |          |
|   2 |   TABLE ACCESS BY INDEX ROWID| LITTLE_SKEW      |     1 |     9 |     4   (0)| 00:00:01 |
|*  3 |    INDEX RANGE SCAN          | LITTLE_SKEW_COL1 |     1 |       |     3   (0)| 00:00:01 |
-------------------------------------------------------------------------------------------------

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

   3 - access("COL1"=99320)

20 rows selected.

SQL> !cat create_baseline.sql
var ret number
exec :ret := dbms_spm.load_plans_from_cursor_cache(-
    sql_id=>'&sql_id', -
    plan_hashvalue=>&plan_hash_value,-
    fixed=>'&fixed');

SQL> @create_baseline
Enter value for sql_id: 4dd2qjxbjav6u
Enter value for plan_hash_value: 2709260180
Enter value for fixed: NO

PL/SQL procedure successfully completed.

SQL> !cat baselines.sql
set lines 155
col sql_text for a50 trunc
col last_executed for a28
col enabled for a7
col plan_hash_value for a16
col last_executed for a16
select spb.sql_handle, spb.plan_name, spb.sql_text,
spb.enabled, spb.accepted, spb.fixed,
to_char(spb.last_executed,'dd-mon-yy HH24:MI') last_executed
from
dba_sql_plan_baselines spb
where spb.sql_text like nvl('%'||'&sql_text'||'%',spb.sql_text)
and spb.sql_handle like nvl('&name',spb.sql_handle)
and spb.plan_name like nvl('&plan_name',spb.plan_name)
/

SQL> @baselines
Enter value for sql_text: %little%
Enter value for name:
Enter value for plan_name: 

SQL_HANDLE                     PLAN_NAME                      SQL_TEXT                                           ENABLED ACC FIX LAST_EXECUTED
------------------------------ ------------------------------ -------------------------------------------------- ------- --- --- ----------------
SYS_SQL_b77256b604589dec       SYS_SQL_PLAN_04589dec2fdfd157  select avg(pk_col) from kso.little_skew where col1 YES     YES NO

SQL> select avg(pk_col) from kso.little_skew where col1 = 99320;

AVG(PK_COL)
-----------
     628922

SQL> select avg(pk_col) from kso.little_skew where col1 = 99320;

AVG(PK_COL)
-----------
     628922

SQL> @find_sql
Enter value for sql_text:
Enter value for sql_id: 4dd2qjxbjav6u

SQL_ID         CHILD  PLAN_HASH      EXECS     AVG_ETIME      AVG_LIO SQL_TEXT
------------- ------ ---------- ---------- ------------- ------------ ------------------------------------------------------------
4dd2qjxbjav6u      0 2709260180          1           .02           89 select avg(pk_col) from kso.little_skew where col1 = 99320
4dd2qjxbjav6u      1 2709260180          1           .00            5 select avg(pk_col) from kso.little_skew where col1 = 99320

SQL> @dplan
Enter value for sql_id: 4dd2qjxbjav6u
Enter value for child_no: 1

PLAN_TABLE_OUTPUT
------------------------------------------------------------------------------------------------------------------------------------------------------
SQL_ID  4dd2qjxbjav6u, child number 1
-------------------------------------
select avg(pk_col) from kso.little_skew where col1 = 99320

Plan hash value: 2709260180

-------------------------------------------------------------------------------------------------
| Id  | Operation                    | Name             | Rows  | Bytes | Cost (%CPU)| Time     |
-------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT             |                  |       |       |     4 (100)|          |
|   1 |  SORT AGGREGATE              |                  |     1 |     9 |            |          |
|   2 |   TABLE ACCESS BY INDEX ROWID| LITTLE_SKEW      |     1 |     9 |     4   (0)| 00:00:01 |
|*  3 |    INDEX RANGE SCAN          | LITTLE_SKEW_COL1 |     1 |       |     3   (0)| 00:00:01 |
-------------------------------------------------------------------------------------------------

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

   3 - access("COL1"=99320)

Note
-----
   - SQL plan baseline SYS_SQL_PLAN_04589dec2fdfd157 used for this statement

24 rows selected.

So that’s a quick example of how easy it is to create a Baseline. Once a Baseline is created it behaves much like an Outline or SQL Profile, in that it will be applied to any SQL statement where the normalized text matches. It’s interesting to note that even though Outlines are way outdated in 11g, they still take precedence over Baselines. So if you have an Outline and a Baseline on the same statement, the Outline will be used. Here’s an example of that behavior:
Continue reading ‘Oracle 11g SQL Plan Management – SQL Plan Baselines’ »

Do SQL Plan Baselines Use Hints? – Take 2

Warning – This post is almost pure speculation!

You may have read a previous post where I said I thought Baselines didn’t use hints. We’ll I’ve changed my mind. I no longer think that Baselines store an actual plan for a SQL statement. (See my previous post – Do SQL Plan Baselines Use Hints?) I never could find a place where the plan data was stored (only the plan_hash_value). So I had a closer look at some more 10053 trace files. Here’s a quick run down of what I found. First the set up:

SQL> @flush_pool

System altered.

SQL> select avg(pk_col) from kso.little_skew where col1 = 1;

AVG(PK_COL)
-----------
 310999.357

SQL> @find_sql
Enter value for sql_text: %little%
Enter value for sql_id: 

SQL_ID         CHILD  PLAN_HASH      EXECS     AVG_ETIME      AVG_LIO SQL_TEXT
------------- ------ ---------- ---------- ------------- ------------ ------------------------------------------------------------
9df852xw86wxt      0 3498336203          1           .18        3,437 select avg(pk_col) from kso.little_skew where col1 = 1

SQL> @dplan
Enter value for sql_id: 9df852xw86wxt
Enter value for child_no: 0

PLAN_TABLE_OUTPUT
------------------------------------------------------------------------------------------------------------------------------------------------------
SQL_ID  9df852xw86wxt, child number 0
-------------------------------------
select avg(pk_col) from kso.little_skew where col1 = 1

Plan hash value: 3498336203

----------------------------------------------------------------------------------
| Id  | Operation          | Name        | Rows  | Bytes | Cost (%CPU)| Time     |
----------------------------------------------------------------------------------
|   0 | SELECT STATEMENT   |             |       |       |   907 (100)|          |
|   1 |  SORT AGGREGATE    |             |     1 |     9 |            |          |
|*  2 |   TABLE ACCESS FULL| LITTLE_SKEW |   620K|  5449K|   907   (2)| 00:00:11 |
----------------------------------------------------------------------------------

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

   2 - filter("COL1"=1)


19 rows selected.

SQL> select /*+ index (a little_skew_col1) */ avg(pk_col) from kso.little_skew a where col1 = 1;

AVG(PK_COL)
-----------
 310999.357

SQL> @find_sql
Enter value for sql_text: %little%
Enter value for sql_id: 

SQL_ID         CHILD  PLAN_HASH      EXECS     AVG_ETIME      AVG_LIO SQL_TEXT
------------- ------ ---------- ---------- ------------- ------------ ------------------------------------------------------------
9df852xw86wxt      0 3498336203          1           .18        3,437 select avg(pk_col) from kso.little_skew where col1 = 1
fbnx1bws6n4xu      0 2709260180          1           .86        5,278 select /*+ index (a little_skew_col1) */ avg(pk_col) from ks
                                                                      o.little_skew a where col1 = 1


SQL> @dplan
Enter value for sql_id: fbnx1bws6n4xu
Enter value for child_no: 0

PLAN_TABLE_OUTPUT
------------------------------------------------------------------------------------------------------------------------------------------------------
SQL_ID  fbnx1bws6n4xu, child number 0
-------------------------------------
select /*+ index (a little_skew_col1) */ avg(pk_col) from
kso.little_skew a where col1 = 1

Plan hash value: 2709260180

-------------------------------------------------------------------------------------------------
| Id  | Operation                    | Name             | Rows  | Bytes | Cost (%CPU)| Time     |
-------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT             |                  |       |       | 20835 (100)|          |
|   1 |  SORT AGGREGATE              |                  |     1 |     9 |            |          |
|   2 |   TABLE ACCESS BY INDEX ROWID| LITTLE_SKEW      |   620K|  5449K| 20835   (1)| 00:04:11 |
|*  3 |    INDEX RANGE SCAN          | LITTLE_SKEW_COL1 |   620K|       |  3213   (1)| 00:00:39 |
-------------------------------------------------------------------------------------------------

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

   3 - access("COL1"=1)


21 rows selected.

SQL> -- need to create baseline for original statement to get SQL_HANDLE
SQL>
SQL> !cat create_baseline.sql
var ret number
exec :ret := dbms_spm.load_plans_from_cursor_cache(-
    sql_id=>'&sql_id', -
    plan_hash_value=>&plan_hash_value,-
    fixed=>'&fixed');




SQL> @create_baseline
Enter value for sql_id: 9df852xw86wxt
Enter value for plan_hash_value: 3498336203
Enter value for fixed: NO

PL/SQL procedure successfully completed.

SQL> -- now add the other plan as a fixed Baseline
SQL>
SQL> !cat create_baseline2.sql
var ret number
exec :ret := dbms_spm.load_plans_from_cursor_cache(-
    sql_id=>'&sql_id', -
    plan_hash_value=>&plan_hash_value,-
    sql_handle=>'&sql_handle',-
    fixed=>'&fixed');


SQL> @create_baseline2
Enter value for sql_id: fbnx1bws6n4xu
Enter value for plan_hash_value: 2709260180
Enter value for sql_handle: SYS_SQL_19fcc3effcce06c0
Enter value for fixed: YES

PL/SQL procedure successfully completed.

SQL> @baselines
Enter value for sql_text: 
Enter value for name: 
Enter value for plan_name: 

SQL_HANDLE                     PLAN_NAME                      SQL_TEXT                                           ENABLED ACC FIX LAST_EXECUTED
------------------------------ ------------------------------ -------------------------------------------------- ------- --- --- ----------------
SYS_SQL_19fcc3effcce06c0       SYS_SQL_PLAN_fcce06c08b1420d2  select avg(pk_col) from kso.little_skew where col1 YES     YES NO
SYS_SQL_19fcc3effcce06c0       SYS_SQL_PLAN_fcce06c02fdfd157  select avg(pk_col) from kso.little_skew where col1 YES     YES YES

SQL> select avg(pk_col) from kso.little_skew where col1 = 1;

AVG(PK_COL)
-----------
 310999.357

SQL> /        

AVG(PK_COL)
-----------
 310999.357

SQL> -- check to see if it's using the fixed Baseline
SQL> @find_sql
Enter value for sql_text: %little%
Enter value for sql_id: 

SQL_ID         CHILD  PLAN_HASH      EXECS     AVG_ETIME      AVG_LIO SQL_TEXT
------------- ------ ---------- ---------- ------------- ------------ ------------------------------------------------------------
9df852xw86wxt      0 3498336203          2           .19        3,279 select avg(pk_col) from kso.little_skew where col1 = 1
fbnx1bws6n4xu      0 2709260180          1           .86        5,278 select /*+ index (a little_skew_col1) */ avg(pk_col) from ks
                                                                      o.little_skew a where col1 = 1


SQL> 
SQL> @dplan
Enter value for sql_id: 9df852xw86wxt
Enter value for child_no: 0

PLAN_TABLE_OUTPUT
------------------------------------------------------------------------------------------------------------------------------------------------------
SQL_ID  9df852xw86wxt, child number 0
-------------------------------------
select avg(pk_col) from kso.little_skew where col1 = 1

Plan hash value: 3498336203

----------------------------------------------------------------------------------
| Id  | Operation          | Name        | Rows  | Bytes | Cost (%CPU)| Time     |
----------------------------------------------------------------------------------
|   0 | SELECT STATEMENT   |             |       |       |   907 (100)|          |
|   1 |  SORT AGGREGATE    |             |     1 |     9 |            |          |
|*  2 |   TABLE ACCESS FULL| LITTLE_SKEW |   620K|  5449K|   907   (2)| 00:00:11 |
----------------------------------------------------------------------------------

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

   2 - filter("COL1"=1)


19 rows selected.

SQL> -- no it's not using the Baseline, why not?

So we created a Fixed Baseline on a statement that used a hint to force an index based access path, attached it to another statement with no hints, and then re-ran the un-hinted statement. It did not pick up the Fixed Baseline. The next step was to have a look at a 10053 trace file. Here are some excerpts from the 10053 trace file.


...

SPM: statement found in SMB

...

******************************************
----- Current SQL Statement for this session (sql_id=9df852xw86wxt) -----
select avg(pk_col) from kso.little_skew where col1 = 1
*******************************************

...

SPM: cost-based plan found in the plan baseline, planId = 2333352146
SPM: fixed planId's of plan baseline are: 803197271
SPM: using qksan to reproduce, cost and select accepted plan, sig = 1872586980585244352
SPM: reproduce plan round 1, using session OFE=11010007
SPM: using qksan to reproduce accepted plan, planId = 803197271
Registered qb: SEL$1 0xf6d872ec (PARSER)
---------------------
QUERY BLOCK SIGNATURE
---------------------
  signature (): qb_name=SEL$1 nbfros=1 flg=0
    fro(0): flg=4 objn=90376 hint_alias="LITTLE_SKEW"@"SEL$1"

DOP: Automatic degree of parallelism is disabled: Parameter.
PM: Considering predicate move-around in query block SEL$1 (#0)
**************************
Predicate Move-Around (PM)
**************************
OPTIMIZER INFORMATION

******************************************
----- Current SQL Statement for this session (sql_id=7039h2744jjrv) -----
/* SQL Analyze(110,0) */ select avg(pk_col) from kso.little_skew where col1 = 1
*******************************************

...

SPM: planId in plan baseline = 803197271, planId of reproduced plan = 2333352146
------- START SPM Plan Dump -------
SPM: failed to reproduce the plan using the following info:
  parse_schema name        : SYS
  plan_baseline signature  : 1872586980585244352
  plan_baseline plan_id    : 803197271
  plan_baseline hintset    :
    hint num  1 len 27 text: IGNORE_OPTIM_EMBEDDED_HINTS
    hint num  2 len 37 text: OPTIMIZER_FEATURES_ENABLE('11.1.0.7')
    hint num  3 len 22 text: DB_VERSION('11.1.0.7')
    hint num  4 len  8 text: ALL_ROWS
    hint num  5 len 22 text: OUTLINE_LEAF(@"SEL$1")
    hint num  6 len 57 text: INDEX_RS_ASC(@"SEL$1" "A"@"SEL$1" ("LITTLE_SKEW"."COL1"))
SPM: generated non-matching plan:
----- Explain Plan Dump -----
----- Plan Table -----

============
Plan Table
============
-----------------------------------------+-----------------------------------+
| Id  | Operation           | Name       | Rows  | Bytes | Cost  | Time      |
-----------------------------------------+-----------------------------------+
| 0   | SELECT STATEMENT    |            |       |       |   907 |           |
| 1   |  SORT AGGREGATE     |            |     1 |     9 |       |           |
| 2   |   TABLE ACCESS FULL | LITTLE_SKEW|  605K | 5449K |   907 |  00:00:11 |
-----------------------------------------+-----------------------------------+
Predicate Information:
----------------------
2 - filter("COL1"=1)

Content of other_xml column
===========================
  db_version     : 11.1.0.7
  parse_schema   : SYS
  plan_hash      : 3498336203
  plan_hash_2    : 2333352146
  Outline Data:
  /*+
    BEGIN_OUTLINE_DATA
      IGNORE_OPTIM_EMBEDDED_HINTS
      OPTIMIZER_FEATURES_ENABLE('11.1.0.7')
      DB_VERSION('11.1.0.7')
      ALL_ROWS
      OUTLINE_LEAF(@"SEL$1")
      FULL(@"SEL$1" "LITTLE_SKEW"@"SEL$1")
    END_OUTLINE_DATA
  */

------- END SPM Plan Dump -------


So it appears that the Baseline is found in the SMB (SQL Management Base). It then appears to try to reproduce the plan in a separate session using the hints. It then announces that it came up with a different plan and spits out the plan data that it came up with. So it appears that the plan_hash_value is just used for comparison to see if it came up with the same plan as the one that was in place when the Baseline was generated. If not, then it falls back to the regular (no Baseline) behavior. Not at all what I had hoped for!

It may be that 11gR1 is an intermediate step and that a future version (11gR2 maybe, I hope) will actually store the plan details instead of just the plan hash value. But as I said in the intro, this is complete speculation on my part.

Hidden SQL – why can’t I find my SQL Text?

I recently ran into an interesting issue that drove me crazy for a couple of days! A very frequently executed statement on a database was generating some waits on “SQL*Net more data from client”. ASH shows the statement, as does the V$SESSION view, but the statement never shows up in the V$SQL view nor in the AWR tables. Here’s a brief run down of how the investigation went.

The reason for looking at this in the first place was that the application was timing out for brief periods of time. So a quick look at an AWR report for the time period showed a significant amount of time being spent waiting on the “SQL*Net more data from client” event. This event was taking a much larger slice of the pie than we saw during periods of “normal” activity. Here’s a little excerpt from one of the AWR reports:

Top 5 Timed Foreground Events
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
                                                           Avg
                                                          wait   % DB
Event                                 Waits     Time(s)   (ms)   time Wait Class
------------------------------ ------------ ----------- ------ ------ ----------
DB CPU                                            2,045          57.7
SQL*Net more data from client       165,760         868      5   24.5 Network
db file sequential read              58,083         449      8   12.7 User I/O
log file sync                        33,656          85      3    2.4 Commit
direct path read                     22,026          42      2    1.2 User I/O


...

                                                    % of Waits
                                 -----------------------------------------------
                           Total
Event                      Waits  <1ms  <2ms  <4ms  <8ms <16ms <32ms  <=1s   >1s
-------------------------- ----- ----- ----- ----- ----- ----- ----- ----- -----
SQL*Net break/reset to cli  833   95.1    .6    .2          .1   3.6    .4
SQL*Net message to client  7537K 100.0    .0
SQL*Net more data from cli  165K  87.5    .4    .1    .0    .0   7.1   4.8
SQL*Net more data to clien  410K 100.0    .0

Obviously this is not good. This is on an 11g system so the AWR report provides a nice little histogram section on the wait events. The histogram indicates that most of these events are under 1ms, but a significant percentage are in the 16ms – 1sec range. So the question was, what could be causing those waits.

No problem, just check the Active Session History, find the sql_id for the statement(s) waiting on this event, and then look in V$SQL for the text. But not so fast bucko!

SQL> !cat find_sql_waiting_on_event.sql
select event, sql_id, count(*),
avg(time_waited) avg_time_waited
from v$active_session_history
where event like nvl('&event','%more data from%')
group by event, sql_id
order by event, 3
/

SQL> @find_sql_waiting_on_event
Enter value for event: 

EVENT                          SQL_ID          COUNT(*)
------------------------------ ------------- ----------
SQL*Net more data from client  dkc2kbj7kdsu7         21
SQL*Net more data from client                        62
SQL*Net more data from client  40du2847gh6sq        156
SQL*Net more data from client  7vtb7h3kpfat0       2965


SQL> -- Ah there's the culpret, 7vtb7h3kpfat0
SQL>
SQL> @find_sql
Enter value for sql_text:
Enter value for sql_id: 7vtb7h3kpfat0
Enter value for plan_hash_value:

no rows selected

SQL> -- hmm, must have aged out of the shared pool (seems unlikely since ASH has it so many times)
SQL> -- but maybe it's in the AWR tables
SQL>
SQL> @find_sql_awr
Enter value for sql_text:
Enter value for sql_id: 7vtb7h3kpfat0

no rows selected

SQL> -- nope, not there either

So I tried a couple of things to see if I could prove to myself that it was never in V$SQL (and thus never in the AWR tables). First I tried coloring the statement with the dbms_workload_repository.add_colored_sql procedure. (See Dion Cho’s post on this feature for more info). No luck! Then I tried using Tanel Poder’s sample.sql script (more info on that here) to run a bunch of queries against the V$SQLAREA view to see if the statement ever showed up. It did not! I then traced (10046) a bunch of the sessions that were executing the statement, hoping that the trace files would have the statement text. They did not, nor was the SQL_ID even contained in any of the trace files!

Turns out it is never in the shared pool and it is never in the AWR tables. But it is captured by ASH and it shows up in the SQL_ID column in V$SESSION. Here’s a little more output from the system:

SQL> select username, sid, serial#, status, sql_id, event, seconds_in_wait
  2  from v$session
  3  where username like nvl('&username',username)
  4  and sid like nvl('&sid',sid)
  5  and sql_id='7vtb7h3kpfat0'
  6* order by username, sid, serial#;

Enter value for username:
Enter value for sid:
 
USERNAME                     SID    SERIAL# STATUS   SQL_ID        EVENT                          SECONDS_IN_WAIT
------------------------- ------ ---------- -------- ------------- ------------------------------ ---------------
XX_OWNER                    4661       4929 INACTIVE 7vtb7h3kpfat0 SQL*Net message from client                823
XX_OWNER                    4676       3835 INACTIVE 7vtb7h3kpfat0 SQL*Net message from client                  0
XX_OWNER                    4682       9170 INACTIVE 7vtb7h3kpfat0 SQL*Net message from client                 16
XX_OWNER                    4699      11522 INACTIVE 7vtb7h3kpfat0 SQL*Net message from client                537
XX_OWNER                    4712       9592 INACTIVE 7vtb7h3kpfat0 SQL*Net message from client                 93
XX_OWNER                    4717       6659 INACTIVE 7vtb7h3kpfat0 SQL*Net message from client                814
XX_OWNER                    4727      25467 INACTIVE 7vtb7h3kpfat0 SQL*Net message from client                155
XX_OWNER                    4739       8796 INACTIVE 7vtb7h3kpfat0 SQL*Net message from client                 17
XX_OWNER                    4755       7327 INACTIVE 7vtb7h3kpfat0 SQL*Net message from client                  9
XX_OWNER                    4800       4002 INACTIVE 7vtb7h3kpfat0 SQL*Net message from client                 11
XX_OWNER                    4826      15699 INACTIVE 7vtb7h3kpfat0 SQL*Net message from client                153
XX_OWNER                    4838       6283 INACTIVE 7vtb7h3kpfat0 SQL*Net message from client                 68
XX_OWNER                    4849      11468 INACTIVE 7vtb7h3kpfat0 SQL*Net message from client               1052
XX_OWNER                    5089       8610 INACTIVE 7vtb7h3kpfat0 SQL*Net message from client                  1
XX_OWNER                    5091       7709 INACTIVE 7vtb7h3kpfat0 SQL*Net message from client                 31
XX_OWNER                    5168       4728 INACTIVE 7vtb7h3kpfat0 SQL*Net message from client                585
XX_OWNER                    5185       8298 INACTIVE 7vtb7h3kpfat0 SQL*Net message from client                157
XX_OWNER                    5186       6969 INACTIVE 7vtb7h3kpfat0 SQL*Net message from client               1197
XX_OWNER                    5210      10830 INACTIVE 7vtb7h3kpfat0 SQL*Net message from client                  0
XX_OWNER                    5232       6509 INACTIVE 7vtb7h3kpfat0 SQL*Net message from client                  1
XX_OWNER                    5251      12231 INACTIVE 7vtb7h3kpfat0 SQL*Net message from client                155
XX_OWNER                    5400       5217 INACTIVE 7vtb7h3kpfat0 SQL*Net message from client                697
XX_OWNER                    5423      12903 INACTIVE 7vtb7h3kpfat0 SQL*Net message from client                  5
XX_OWNER                    5434      14154 INACTIVE 7vtb7h3kpfat0 SQL*Net message from client                191
XX_OWNER                    5441      33222 INACTIVE 7vtb7h3kpfat0 SQL*Net message from client                  3
XX_OWNER                    5442       5669 INACTIVE 7vtb7h3kpfat0 SQL*Net message from client                217

26 rows selected.

SQL> -- so there are a lot of sessions that execute our statement and then wait
SQL> -- (sometimes for a long time) before the user requests another action
SQL>
SQL> -- Using Tanel's sample.sql script - does about 1000 queries against V$SQLAREA in a sec or so
SQL>
SQL> @sample sql_text v$sqlarea "sql_id = '7vtb7h3kpfat0'" 1000

no rows selected

SQL> -- doesn't look like we'll ever catch it in the shared pool

Grasping at straws, I started looking for any views that had a sql_id and/or sql_text field, and I found one that I hadn’t thought to look in – V$OPEN_CURSOR. Ah, that’s probably a good place to look since surely a cursor must be created for this statement. Sure enough, this turned out to provide the necessary clue.

SQL> select distinct * from v$open_cursor
  2  where rownum < 10
  3* and sql_id like '%fat%';

SADDR               SID USER_NAME                      ADDRESS          HASH_VALUE SQL_ID        SQL_TEXT                                  LAST_SQL_
---------------- ------ ------------------------------ ---------------- ---------- ------------- ----------------------------------------- ---------
SQL_EXEC_ID
-----------
0000000210ED3980   4750 XX_OWNER                       000000021AFEB748 3847695136 7vtb7h3kpfat0 table_4_9_fbd5_0_0_0

00000002111EC2E8   5043 SIGNON                         0000000219E02E80 1527693606 6pfatm1dhxh96 SELECT  u.app_user_id, u.username, u.pass
                                                                                                 word, u.first_name,

000000021163BDA8   5451 XX_OWNER                       000000021AFEB748 3847695136 7vtb7h3kpfat0 table_4_9_fbd5_0_0_0

00000002114067E0   5242 XX_OWNER                       000000021AFEB748 3847695136 7vtb7h3kpfat0 table_4_9_fbd5_0_0_0

00000002114372F0   5260 SIGNON                         0000000219E02E80 1527693606 6pfatm1dhxh96 SELECT  u.app_user_id, u.username, u.pass
                                                                                                 word, u.first_name,

0000000210F06FD8   4769 XX_OWNER                       000000021AFEB748 3847695136 7vtb7h3kpfat0 table_4_9_fbd5_0_0_0

0000000211439E38   5261 SIGNON                         0000000219E02E80 1527693606 6pfatm1dhxh96 SELECT  u.app_user_id, u.username, u.pass
                                                                                                 word, u.first_name,

00000002111E97A0   5042 SIGNON                         0000000219E02E80 1527693606 6pfatm1dhxh96 SELECT  u.app_user_id, u.username, u.pass
                                                                                                 word, u.first_name,

000000021161E190   5440 XX_OWNER                       000000021AFEB748 3847695136 7vtb7h3kpfat0 table_4_9_fbd5_0_0_0


9 rows selected.

So the SQL_ID was present in the V$OPEN_CURSOR view and there was a value in the SQL_TEXT field. Unfortunately, it didn't provide the text of the original statement, but at least I now had something to work with. A quick google for table_4_9_fbd5_0_0_0 (which is what was in the SQL_TEXT field) turned up nothing, of course. But a little digging turned up this post on Ask Tom. You'll have to read down a ways in that post to find that the real culpret was LOBs. Also, see this post on the Oracle-l list (which is what I originally found that pointed me to the Ask Tom article).

So it appears that the issue is that LOBs are being accessed, which causes Oracle to generate a new SQL_ID for the LOB access part of the execution. Apparently, these types of statements do not get exposed via the V$SQL and V$SQLAREA views and thus do not get captured by AWR. There are other types of statements that exhibit this behavior as well, by the way. The Tom Kyte post talks about nested tables for example. So back to the question, what statement generated the SQL_ID with the missing sql_text in the first place? We'll the first clue came from the Tom Kyte post. Apparently the middle bit of the text in the V$OPEN_CURSOR view is a hex representation of the object_id of the object that is being accessed (in our case, "fbd5"). So if we convert it to decimal we can find the object that is contains the LOB, like so:

SQL> select owner, object_name, object_type
  2  from dba_objects
  3  where object_id = (select to_number('&hex_value','XXXXXX') from dual);
Enter value for hex_value: fbd5

OWNER                          OBJECT_NAME                    OBJECT_TYPE
------------------------------ ------------------------------ -------------------
XX_OWNER                       XXX_MY_TABLE                   TABLE

So now I know that I'm looking for a statement that is accessing XXX_MY_TABLE (note: names have been changed to protect the innocent). But how to find the statement, that's the question that was never answered in the Tom Kyte post. It was at about this point, while I was filling my coffee cup, that I had one of those ah-ha moments (usually I have them when I'm doing something else - not even actively thinking about the problem). Anyway, I got to thinking about the PREV_SQL_ID in the V$SESSION view. If a statement that accesses a LOB, immediately generates a new SQL_ID for the LOB access part of the execution, perhaps the original statement's SQL_ID would be in the PREV_SQL_ID field. And that's exactly what I found.


SQL> select username, sid, serial#, status, sql_id, prev_sql_id, event, seconds_in_wait
  2  from v$session
  3  where username like nvl('&username',username)
  4  and sid like nvl('&sid',sid)
  5  and sql_id='7vtb7h3kpfat0'
  6* order by username, sid, serial#;

Enter value for username:
Enter value for sid:


USERNAME                     SID    SERIAL# STATUS   SQL_ID        PREV_SQL_ID   EVENT                          SECONDS_IN_WAIT
------------------------- ------ ---------- -------- ------------- ------------- ------------------------------ ---------------
XX_OWNER                    4665       8707 INACTIVE 7vtb7h3kpfat0 78jdubkb65p2w SQL*Net message from client               1235
XX_OWNER                    4745       9383 INACTIVE 7vtb7h3kpfat0 78jdubkb65p2w SQL*Net message from client                  1
XX_OWNER                    4792      23304 INACTIVE 7vtb7h3kpfat0 78jdubkb65p2w SQL*Net message from client               1235
XX_OWNER                    4816      11098 INACTIVE 7vtb7h3kpfat0 78jdubkb65p2w SQL*Net message from client                  0
XX_OWNER                    4844       3050 INACTIVE 7vtb7h3kpfat0 78jdubkb65p2w SQL*Net message from client                773
XX_OWNER                    4907       8184 INACTIVE 7vtb7h3kpfat0 78jdubkb65p2w SQL*Net message from client                232
XX_OWNER                    4959      35967 INACTIVE 7vtb7h3kpfat0 78jdubkb65p2w SQL*Net message from client                633
XX_OWNER                    5154      33701 INACTIVE 7vtb7h3kpfat0 78jdubkb65p2w SQL*Net message from client                 25
XX_OWNER                    5230      12792 INACTIVE 7vtb7h3kpfat0 78jdubkb65p2w SQL*Net message from client                510
XX_OWNER                    5248      49715 INACTIVE 7vtb7h3kpfat0 78jdubkb65p2w SQL*Net message from client                456
XX_OWNER                    5249      32300 INACTIVE 7vtb7h3kpfat0 78jdubkb65p2w SQL*Net message from client                147
XX_OWNER                    5282      21331 INACTIVE 7vtb7h3kpfat0 78jdubkb65p2w SQL*Net message from client                182
XX_OWNER                    5285        386 INACTIVE 7vtb7h3kpfat0 78jdubkb65p2w SQL*Net message from client                185
XX_OWNER                    5295        792 INACTIVE 7vtb7h3kpfat0 78jdubkb65p2w SQL*Net message from client                 40
XX_OWNER                    5416      49780 INACTIVE 7vtb7h3kpfat0 78jdubkb65p2w SQL*Net message from client                  7
XX_OWNER                    5419      22645 INACTIVE 7vtb7h3kpfat0 78jdubkb65p2w SQL*Net message from client                890
XX_OWNER                    5442       6200 INACTIVE 7vtb7h3kpfat0 78jdubkb65p2w SQL*Net message from client               1326

17 rows selected.

SQL> @find_sql_long
Enter value for sql_id: 78jdubkb65p2w

SQL_TEXT
----------------------------------------------------------------------
SELECT  XYZ_COLUMN, BLAH ... FROM XXX_MY_TABLE ...


SQL> @find_sql
Enter value for sql_text:
Enter value for sql_id: 78jdubkb65p2w

SQL_ID         CHILD  PLAN_HASH      EXECS     AVG_ETIME      AVG_LIO SQL_TEXT
------------- ------ ---------- ---------- ------------- ------------ -----------------------------------------
78jdubkb65p2w      0  147781538  9,534,632         .0006           11 SELECT  XYZ_COLUMN, BLAH
78jdubkb65p2w      1  147781538        191         .0005           11

One last comment (and then I'll shut up):

I was surprised to find that the statement was short - only a few lines long. I was expecting a really long string that would not fit in a single SQL*Net packet. After all, we are waiting on the "SQL*Net more data FROM client" event, right? Which is supposed to be the time waited for an additional packet from the client when Oracle knows that more is coming. Clearly this was not the case. Rather it is waiting because Oracle is sending data back to the client that takes more than one packet (i.e. the LOB). You would expect that time would be logged under the "SQL*Net more data TO client" event in this case. However, it appears that time is logged to that event only until the packet is turned over to the network. It appears that Oracle then starts logging time to the "SQL*Net more data FROM client" event while it waits for the next response from the client. Therefore, the actual network transfer time is clocked to the wrong event. You can understand why the developers made this choice, because Oracle has no way of knowing how long it actually takes the packet to get to the client. It only knows how long the round trip takes. So maybe they should have named the event slightly differently, like "SQL*Net more data from client including the entire round trip network time" or something. Anyway, Tanel Poder has a post that briefly mentions this quirk of the SQL*Net events.

Note: this is somewhat speculative on my part as I have not tried to prove exactly where the "TO" event stops and the "FROM" event begins. But I am pretty sure Tanel is correct on this point.

So there you have it. Just a little story about wandering through the weeds on the way to enlightenment.

=============================

Note: This part was added after Dion Cho commented that he wasn't able to re-produce the behavior, so I gave it shot (I got close). Here's the output:

> sqlplus / as sysdba

SQL*Plus: Release 11.1.0.7.0 - Production on Mon Apr 20 14:59:25 2009

Copyright (c) 1982, 2008, Oracle.  All rights reserved.


Connected to:
Oracle Database 11g Enterprise Edition Release 11.1.0.7.0 - Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options

SQL> -- session (SID 124) connected as KSO issues "select xml_clob from test_lob"

...


SQL> -- what's going on?
SQL> @sessions
Enter value for username: 
Enter value for sid: 

USERNAME                   SID    SERIAL# STATUS   SQL_ID        EVENT                          SECONDS_IN_WAIT
------------------------- ---- ---------- -------- ------------- ------------------------------ ---------------
KSO                        124       2402 ACTIVE   cu98u9ukjqj19 SQL*Net message from client                  0
SYS                        128       3580 ACTIVE   bsbmyw5thg8qf SQL*Net message to client                    0

SQL> -- KSO is running cu98u9ukjqj19, what's that doing?
SQL> @find_sql
Enter value for sql_text: 
Enter value for sql_id: cu98u9ukjqj19

no rows selected

SQL> -- so that's probably the LOB access, let's check 
SQL> select * from v$open_cursor where sql_id like 'cu98u9ukjqj19';

SADDR     SID USER_NAME               ADDRESS  HASH_VALUE SQL_ID        SQL_TEXT                              LAST_SQL_ SQL_EXEC_ID
-------- ---- ----------------------- -------- ---------- ------------- ------------------------------------- --------- -----------
DB1A69C8  124 KSO                     E0BD4C0C 2770027561 cu98u9ukjqj19 table_4_9_19a1d_0_0_0



SQL> -- yep, LOB access, let' see if we can find the original statement
SQL> @sessionsp
Enter value for username: 
Enter value for sid: 

USERNAME                   SID    SERIAL# STATUS   SQL_ID        PREV_SQL_ID   EVENT                          SECONDS_IN_WAIT
------------------------- ---- ---------- -------- ------------- ------------- ------------------------------ ---------------
KSO                        124       2402 ACTIVE   cu98u9ukjqj19 9babjv8yq8ru3 direct path read                             0
SYS                        128       3580 ACTIVE   grdgy5dcmqd0f 9babjv8yq8ru3 SQL*Net message to client                    0

SQL> -- says prev statement is 9babjv8yq8ru3
SQL> @find_sql
Enter value for sql_text: 
Enter value for sql_id: 9babjv8yq8ru3

SQL_ID         CHILD  PLAN_HASH      EXECS     AVG_ETIME      AVG_LIO SQL_TEXT
------------- ------ ---------- ---------- ------------- ------------ ------------------------------------------------------------
9babjv8yq8ru3      1          0         39           .01           54 BEGIN DBMS_OUTPUT.GET_LINES(:LINES, :NUMLINES); END;

SQL> -- oops, SQL*Plusism - need to turn off serveroutput

/*
-- go to other session here and set serveroutput off and re-run select statement
*/

SQL> -- wait a little while until the statement finishes 
SQL> @sessionsp
Enter value for username: 
Enter value for sid: 

USERNAME                   SID    SERIAL# STATUS   SQL_ID        PREV_SQL_ID   EVENT                          SECONDS_IN_WAIT
------------------------- ---- ---------- -------- ------------- ------------- ------------------------------ ---------------
KSO                        124       2402 INACTIVE               djqbj30qjyngw SQL*Net message from client                 74
SYS                        128       3580 ACTIVE   grdgy5dcmqd0f 9babjv8yq8ru3 SQL*Net message to client                    0

SQL> -- note that the SQL_ID field has been wiped after the statement completes - need to look a little closer at this behavior
SQL> -- the java application I was looking at in production did not cause this behavior - i.e. the SQL_ID field would not be cleared
SQL> -- so finding the SQL_ID for the LOB access and the PREV_SQL_ID for the original statement didn't happen in my test case 
SQL> -- although the PREV_SQL_ID field does contain the value for the original statement
 
SQL> @find_sql
Enter value for sql_text: 
Enter value for sql_id: djqbj30qjyngw

SQL_ID         CHILD  PLAN_HASH      EXECS     AVG_ETIME      AVG_LIO SQL_TEXT
------------- ------ ---------- ---------- ------------- ------------ ------------------------------------------------------------
djqbj30qjyngw      0  825212230          2          2.61       53,065 select xml_clob from test_lob


Do SQL Plan Baselines Use Hints?

I posted this weekend on SQL Profiles and there were a couple of follow up comments that got me wondering about the internal mechanism used by Baselines and since this got a little wordy, I decided to make it a new post as opposed to just a comment. The documentation appears to indicate that Baselines actually store a plan, as opposed to the earlier mechanism used by both Outlines and SQL Profiles, which are hint based. But the DBA_SQL_PLAN_BASELINES view exposes a column called OTHER_XML which contains, you guessed it, hints. (by the way, this column also exists in the V$SQL_PLAN view, where it exposes hints for every plan in the shared pool) So anyway, the question was posed, “Do SQL Plan Baselines use hints?”. The answer is … I don’t think so. Here’s why:

  1. The DBA_SQL_PLAN_BASELINES view is based on SQLOBJ$, SQLOBJ$DATA, and SQLOBJ$AUXDATA. These tables contain data for both SQL Profiles and Baselines (but not for Outlines). The SQLOBJ$ table has a column (PLAN_ID) which is populated with a plan hash value (but not the one exposed in V$SQL – more on that later). And now the interesting bit, the entries for the Baselines have a value in the PLAN_ID column while the entries for the SQL Profiles don’t. Hmmmm…
  2. 10053 trace files have a section labeled “Final query after transformations:”. For statements using both Outlines and SQL Profiles, the “Final Query” includes hint text. For both fixed and non-fixed Baselines, the “Final Query” does not include hints.

So here’s some excerpts from three 10053 trace files. They were all created on the same 11.1.0.7 database. The first file was created for a statement using an Outline. The second was created for a statement using a SQL Profile. The third was created for a statement using a Baseline.

===================================================================================
10053 level 1 for statement using an Outline
===================================================================================

...

---------------------
QUERY BLOCK SIGNATURE
---------------------
  signature (): qb_name=SEL$1 nbfros=1 flg=0
    fro(0): flg=4 objn=79200 hint_alias="SKEW"@"SEL$1"

SPM: statement not found in SMB

...


******************************************
----- Current SQL Statement for this session (sql_id=0r09xac72gvj1) -----
select /* test1 */ avg(pk_col) from kso.skew where col1 > 0
*******************************************

...

Final query after transformations:******* UNPARSED QUERY IS *******
SELECT /*+ FULL ("SKEW") */ AVG("SKEW"."PK_COL") "AVG(PK_COL)" FROM "KSO"."SKEW" "SKEW" WHERE "SKEW"."COL1">0

...

Starting SQL statement dump

user_id=0 user_name=SYS module=sqlplus@homer (TNS V1-V3) action=
sql_id=0r09xac72gvj1 plan_hash_value=568322376 problem_type=3
----- Current SQL Statement for this session (sql_id=0r09xac72gvj1) -----
select /* test1 */ avg(pk_col) from kso.skew where col1 > 0
sql_text_length=60
sql=select /* test1 */ avg(pk_col) from kso.skew where col1 > 0
----- Explain Plan Dump -----
----- Plan Table -----

============
Plan Table
============
--------------------------------------+-----------------------------------+
| Id  | Operation           | Name    | Rows  | Bytes | Cost  | Time      |
--------------------------------------+-----------------------------------+
| 0   | SELECT STATEMENT    |         |       |       |   43K |           |
| 1   |  SORT AGGREGATE     |         |     1 |    11 |       |           |
| 2   |   TABLE ACCESS FULL | SKEW    |   31M |  336M |   43K |  00:09:54 |
--------------------------------------+-----------------------------------+
Predicate Information:
----------------------
2 - filter("COL1">0)

Content of other_xml column
===========================
  db_version     : 11.1.0.7
  parse_schema   : SYS
  plan_hash      : 568322376
  plan_hash_2    : 1429740808
  outline        : KSOTEST1
  Outline Data:
  /*+
    BEGIN_OUTLINE_DATA
      IGNORE_OPTIM_EMBEDDED_HINTS
      OPTIMIZER_FEATURES_ENABLE('11.1.0.7')
      DB_VERSION('11.1.0.7')
      ALL_ROWS
      OUTLINE_LEAF(@"SEL$1")
      FULL(@"SEL$1" "SKEW"@"SEL$1")
    END_OUTLINE_DATA
  */

Optimizer state dump:
Compilation Environment Dump
optimizer_mode_hinted               = true
optimizer_features_hinted           = 11.1.0.7

...

===================================================================================
10053 level 1 for statement using a manually generated SQL Profile
===================================================================================

...

---------------------
QUERY BLOCK SIGNATURE
---------------------
  signature (): qb_name=SEL$1 nbfros=1 flg=0
    fro(0): flg=4 objn=79200 hint_alias="SKEW"@"SEL$1"

SPM: statement found in SMB
SPM: current statement has no SQL plan baseline, sig = 4814772129047009103

...

******************************************
----- Current SQL Statement for this session (sql_id=399m90n8jzpu6) -----
select avg(pk_col) from kso.skew
*******************************************

...

Final query after transformations:******* UNPARSED QUERY IS *******
SELECT /*+ INDEX_FFS ("SKEW" "SYS_C0015494") */ AVG("SKEW"."PK_COL") "AVG(PK_COL)" FROM "KSO"."SKEW" "SKEW"

...

SPM: statement in SMB but no plan baseline, sig = 4814772129047009103
Starting SQL statement dump

user_id=0 user_name=SYS module=sqlplus@homer (TNS V1-V3) action=
sql_id=399m90n8jzpu6 plan_hash_value=-2082116200 problem_type=3
----- Current SQL Statement for this session (sql_id=399m90n8jzpu6) -----
select avg(pk_col) from kso.skew
sql_text_length=33
sql=select avg(pk_col) from kso.skew
----- Explain Plan Dump -----
----- Plan Table -----

============
Plan Table
============
---------------------------------------------+-----------------------------------+
| Id  | Operation              | Name        | Rows  | Bytes | Cost  | Time      |
---------------------------------------------+-----------------------------------+
| 0   | SELECT STATEMENT       |             |       |       |   19K |           |
| 1   |  SORT AGGREGATE        |             |     1 |     6 |       |           |
| 2   |   INDEX FAST FULL SCAN | SYS_C0015494|   31M |  183M |   19K |  00:04:58 |
---------------------------------------------+-----------------------------------+
Predicate Information:
----------------------

Content of other_xml column
===========================
  db_version     : 11.1.0.7
  parse_schema   : SYS
  plan_hash      : 2212851096
  plan_hash_2    : 4073867208
  sql_profile    : PROFILE_399m90n8jzpu6
  Outline Data:
  /*+
    BEGIN_OUTLINE_DATA
      IGNORE_OPTIM_EMBEDDED_HINTS
      OPTIMIZER_FEATURES_ENABLE('11.1.0.7')
      DB_VERSION('11.1.0.7')
      ALL_ROWS
      OUTLINE_LEAF(@"SEL$1")
      INDEX_FFS(@"SEL$1" "SKEW"@"SEL$1" ("SKEW"."PK_COL"))
    END_OUTLINE_DATA
  */

Optimizer state dump:
Compilation Environment Dump
optimizer_mode_hinted               = true
optimizer_features_hinted           = 11.1.0.7

...

===================================================================================
10053 level 1 for statement using a Baseline
===================================================================================

...

---------------------
QUERY BLOCK SIGNATURE
---------------------
  signature (): qb_name=SEL$1 nbfros=1 flg=0
    fro(0): flg=4 objn=79200 hint_alias="SKEW"@"SEL$1"

SPM: statement found in SMB
DOP: Automatic degree of parallelism is disabled: Parameter.
PM: Considering predicate move-around in query block SEL$1 (#0)
**************************
Predicate Move-Around (PM)
**************************
OPTIMIZER INFORMATION

******************************************
----- Current SQL Statement for this session (sql_id=0qa98gcnnza7h) -----
select avg(pk_col) from kso.skew
where col1 > 0
*******************************************

...

Final query after transformations:******* UNPARSED QUERY IS *******
SELECT AVG("SKEW"."PK_COL") "AVG(PK_COL)" FROM "KSO"."SKEW" "SKEW" WHERE "SKEW"."COL1">0

...

SPM: cost-based plan found in the plan baseline, planId = 1429740808
SPM: cost-based plan was successfully matched, planId = 1429740808
Starting SQL statement dump

user_id=0 user_name=SYS module=sqlplus@homer (TNS V1-V3) action=
sql_id=0qa98gcnnza7h plan_hash_value=568322376 problem_type=3
----- Current SQL Statement for this session (sql_id=0qa98gcnnza7h) -----
select avg(pk_col) from kso.skew
where col1 > 0
sql_text_length=48
sql=select avg(pk_col) from kso.skew
where col1 > 0
----- Explain Plan Dump -----
----- Plan Table -----

============
Plan Table
============
--------------------------------------+-----------------------------------+
| Id  | Operation           | Name    | Rows  | Bytes | Cost  | Time      |
--------------------------------------+-----------------------------------+
| 0   | SELECT STATEMENT    |         |       |       |   43K |           |
| 1   |  SORT AGGREGATE     |         |     1 |    11 |       |           |
| 2   |   TABLE ACCESS FULL | SKEW    |   31M |  336M |   43K |  00:09:54 |
--------------------------------------+-----------------------------------+
Predicate Information:
----------------------
2 - filter("COL1">0)

Content of other_xml column
===========================
  db_version     : 11.1.0.7
  parse_schema   : SYS
  plan_hash      : 568322376
  plan_hash_2    : 1429740808
  Outline Data:
  /*+
    BEGIN_OUTLINE_DATA
      IGNORE_OPTIM_EMBEDDED_HINTS
      OPTIMIZER_FEATURES_ENABLE('11.1.0.7')
      DB_VERSION('11.1.0.7')
      ALL_ROWS
      OUTLINE_LEAF(@"SEL$1")
      FULL(@"SEL$1" "SKEW"@"SEL$1")
    END_OUTLINE_DATA
  */

Optimizer state dump:
Compilation Environment Dump
optimizer_mode_hinted               = false
optimizer_features_hinted           = 0.0.0

...

A couple of final thoughts:

These are very simple examples, so they may not be representative of more complicated statements. I’ve had a quick look at some more realistic examples though, and the basic info I’ve presented seems to hold for them as well. It is clear however, that a ton of work is still going on when the statement is parsed. I’m assuming that is due to the optimizer’s attempts to see if a potentially better plan might exist, even with a fixed Baseline.

It appears that every statement is checked early in the parsing process to see if it is stored in the SMB (SQL Management Base) which is where Baselines are stored (and apparently where SQL Profiles are stored as well).

The 10053 trace shows a couple of plan hash values (PLAN_HASH and PLAN_HASH2). The one labeled PLAN_HASH is the one found in the V$SQL view, the one labeled PLAN_HASH2 is the one found in the SQLOBJ$ table. I’m not sure how to relate these two yet.

I’m hopeful that fixed Baselines will provide the ability to absolutely lock a Plan for a statement, as opposed to the hint based approaches. Not that those haven’t worked pretty well, but actually storing a plan instead of hints that try to limit the optimizers choices, if indeed that’s what’s actually happening, seems a much better approach.

That’s all for now. I’ve been working with Baselines in a production 11.1.0.7 database for a few weeks now and have been wanting to do a post on my observations but keep getting distracted. Hopefully in the next few days I will get a chance to do that.

Please let me know if you can shed any further light on Baselines. I’d be very interested to hear about any experiences with them.

SQL Profiles

Well I was wrong! SQL Profiles are better than Outlines. For a while now I have been saying that I didn’t like SQL Profiles because they were less stable than Outlines. Turns out that the OPT_ESTIMATE hint used by SQL Profiles which are created by the SQL Tuning Advisor is what I really didn’t like. I just didn’t know it.

Let me back up for a minute. I posted about Oracle’s SQL Tuning Advisor a while back. It’s a feature that was added to Oracle in version 10g. It basically looks a SQL statement and tries to come up with a better execution plan than the one the optimizer has picked. Since it is allowed as much time as it wants to do it’s analysis, the advisor can sometimes find better approaches. That’s because it can actually validate the optimizer’s original estimates by running various steps in a given plan and comparing the actual results to the estimates. When it’s all done, if it has found a better plan, it offers to implement that new plan via a SQL Profile. Those offered Profiles often have a lightly documented hint (OPT_ESTIMATE) that allows it to scale the optimizer estimates for various operations – essentially it’s a fudge factor. The problem with this hint is that, far from locking a plan in place, it is locking an empirically derived fudge factor in place. This still leaves the optimizer with a lot of flexibility when it comes to choosing a plan. It also sets up a commonly occurring situation where the fudge factors stop making sense as the statistics change. Thus the observation that SQL Profiles tend to sour over time.

I have to give credit to Randolf Geist for making me take a second look at SQL Profiles. He commented on my Outlines post last week and recommended I give his post on SQL Profiles a look. I did and it really got me thinking. One of the things I liked the best about the post was that he created a couple of scripts to pull the existing hints from a statement in the shared pool or the AWR tables , and create a SQL Profile from those hints using the DBMS_SQLTUNE.IMPORT_SQL_PROFILE procedure. This makes perfect sense because the hints are stored with every plan (that’s what DBMS_XPLAN uses to spit them out if you ask for them). Unfortunately this procedure is only lightly documented. Also he had a nice script for pulling the hints from V$SQL_PLAN table which I have made use of as well.

So as always I have created a few scripts (borrowing from Randolf mostly).

create_sql_profile.sql – uses cursor from the shared pool
create_sql_profile_awr.sql – uses AWR tables
sql_profile_hints.sql – shows the hints in a SQL Profile for 10g

So here’s little example:
Note: unstable_plans.sql and awr_plan_stats.sql are discussed here: Unstable Plans (Plan Instability)

SQL> @unstable_plans
Enter value for min_stddev:
Enter value for min_etime:

SQL_ID        SUM(EXECS)   MIN_ETIME   MAX_ETIME   NORM_STDDEV
------------- ---------- ----------- ----------- -------------
0qa98gcnnza7h          4       42.08      208.80        2.8016

SSQL> @awr_plan_stats
Enter value for sql_id: 0qa98gcnnza7h

SQL_ID        PLAN_HASH_VALUE        EXECS          ETIME    AVG_ETIME        AVG_LIO
------------- --------------- ------------ -------------- ------------ --------------
0qa98gcnnza7h       568322376            3          126.2       42.079      124,329.7
0qa98gcnnza7h      3723858078            1          208.8      208.796   28,901,466.0

SQL> @create_sql_profile_awr
Enter value for sql_id: 0qa98gcnnza7h
Enter value for plan_hash_value: 568322376
Enter value for category:
Enter value for force_matching:

PL/SQL procedure successfully completed.

SQL> @sql_profiles
Enter value for sql_text:
Enter value for name: PROFIL%

NAME                           CATEGORY        STATUS   SQL_TEXT                                                               FOR
------------------------------ --------------- -------- ---------------------------------------------------------------------- ---
PROFILE_0qa98gcnnza7h          DEFAULT         ENABLED  select avg(pk_col) from kso.skew                                       NO

SQL> set echo on
SQL> @sql_profile_hints
SQL> set lines 155
SQL> col hint for a150
SQL> select attr_val hint
  2  from dba_sql_profiles p, sqlprof$attr h
  3  where p.signature = h.signature
  4  and name like ('&profile_name')
  5  order by attr#
  6  /
Enter value for profile_name: PROFILE_0qa98gcnnza7h

HINT
------------------------------------------------------------------------------------------------------------------------------------------------------
IGNORE_OPTIM_EMBEDDED_HINTS
OPTIMIZER_FEATURES_ENABLE('10.2.0.3')
ALL_ROWS
OUTLINE_LEAF(@"SEL$1")
FULL(@"SEL$1" "SKEW"@"SEL$1")

SQL> @sql_hints_awr
SQL> select
  2  extractvalue(value(d), '/hint') as outline_hints
  3  from
  4  xmltable('/*/outline_data/hint'
  5  passing (
  6  select
  7  xmltype(other_xml) as xmlval
  8  from
  9  dba_hist_sql_plan
 10  where
 11  sql_id = '&sql_id'
 12  and plan_hash_value = &plan_hash_value
 13  and other_xml is not null
 14  )
 15  ) d;
Enter value for sql_id: 0qa98gcnnza7h
Enter value for plan_hash_value: 568322376

OUTLINE_HINTS
-----------------------------------------------------------------------------------------------------------------------------------------------------------
IGNORE_OPTIM_EMBEDDED_HINTS
OPTIMIZER_FEATURES_ENABLE('10.2.0.3')
ALL_ROWS
OUTLINE_LEAF(@"SEL$1")
FULL(@"SEL$1" "SKEW"@"SEL$1")

A couple of additional points:

  • Outlines and SQL Profiles both take the same approach to controlling execution plans. They both attempt to force the optimizer down a certain path by applying hints behind the scenes. This is in my opinion an almost impossible task. The more complex the statement, the more difficult the task becomes. The newest kid on the block in this area (in 11g) is called a baseline and while it doesn’t abandon the hinting approach altogether, it does at least store the plan_hash_value – so it can tell if it regenerated the correct plan or not.
  • It does not appear that Outlines are being actively pursued by Oracle development anymore. So while they still work in 11g, they are becoming a little less reliable (and they were a bit quirky to begin with).
  • SQL Profiles have the ability to replace literals with bind variables similar to the cursor_sharing parameter. This means you can have a SQL Profile that will match multiple statements which use literals without having to set cursor_sharing for the whole instance.
  • Outlines take precedence over SQL Profiles. You can create both on the same statement and if you do, the outline will be used and the SQL Profile will be ignored. This is true in 11g as well, by the way.
  • Outlines don’t appear to use the OPT_ESTIMATE hint. So I believe it is still a valid approach to accept a SQL Profile as offered by the SQL Tuning Advisor and then create an Outline on top of it. It seems to work pretty well most of the time. (be sure and check the hints and the plan that gets produced)
  • Manually created SQL Profiles also don’t appear to use the OPT_ESTIMATE hint. So I believe it is also a valid approach to accept a SQL Profile as offered by the SQL Tuning Advisor and then create a SQL Profile on top of it. Note that you’ll have to use a different category, then drop the original, then enable the new SQL Profile. Which means this approach is a bit more work than just creating an Outline in the DEFAULT category.

Have a look at the difference between SQL Tuning Set generated hints and those created by a manual SQL Profile or an Outline (note that I have tried to change the object names to protect the innocent and in so doing may have made it slightly more difficult to follow) :

SQL>
SQL> select * from table(dbms_xplan.display_cursor('&sql_id','&child_no',''));
Enter value for sql_id: fknfhx8wth51q
Enter value for child_no: 1

PLAN_TABLE_OUTPUT
------------------------------------------------------------------------------------------------------------------------------------------------------
SQL_ID  fknfhx8wth51q, child number 1
-------------------------------------
SELECT /* test4 */ col1, col2, col3 ...


Plan hash value: 3163842146

----------------------------------------------------------------------------------------------------------
| Id  | Operation                     | Name                     | Rows  | Bytes | Cost (%CPU)| Time     |
----------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT              |                          |       |       |  1778 (100)|          |
|   1 |  NESTED LOOPS                 |                          |  1039 | 96627 |  1778   (1)| 00:00:33 |
|   2 |   NESTED LOOPS                |                          |   916 | 57708 |  1778   (1)| 00:00:33 |
|*  3 |    TABLE ACCESS BY INDEX ROWID| TABLE_XXXX_LOOKUP        |   446 | 17840 |   891   (1)| 00:00:17 |
|*  4 |     INDEX RANGE SCAN          | INDEX_XXXX_IS_CPCI       | 12028 |       |    18   (0)| 00:00:01 |
|   5 |    TABLE ACCESS BY INDEX ROWID| TABLE_XXXX_IDENT         |     2 |    46 |     2   (0)| 00:00:01 |
|*  6 |     INDEX RANGE SCAN          | INDEX_XXXXIP_17_FK       |     2 |       |     1   (0)| 00:00:01 |
|*  7 |   INDEX UNIQUE SCAN           | PK_TABLE_XXXX_ASSIGNMENT |     1 |    30 |     0   (0)|          |
----------------------------------------------------------------------------------------------------------

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

   3 - filter(( 
...
   4 - access("L"."COL1"=:N1)
   6 - access("L"."COL2"="I"."COL1")

Note
-----
   - SQL profile SYS_SQLPROF_012061f471d50001 used for this statement


85 rows selected.

SQL> @sql_profile_hints
Enter value for name: SYS_SQLPROF_012061f471d50001

HINT
------------------------------------------------------------------------------------------------------------------------------------------------------
OPT_ESTIMATE(@"SEL$1", TABLE, "L"@"SEL$1", SCALE_ROWS=0.0536172171)
OPT_ESTIMATE(@"SEL$1", INDEX_SKIP_SCAN, "A"@"SEL$1", PK_TABLE_XXXX_ASSIGNMENT, SCALE_ROWS=4)
COLUMN_STATS("APP_OWNER"."TABLE_XXXX_ASSIGNMENT", "COL1", scale, length=6 distinct=1234 nulls=0 min=1000000014 max=1026369632)
COLUMN_STATS("APP_OWNER"."TABLE_XXXX_ASSIGNMENT", "COL2", scale, length=12 distinct=2 nulls=0)
COLUMN_STATS("APP_OWNER"."TABLE_XXXX_ASSIGNMENT", "COL3", scale, length=12 distinct=2 nulls=0)
TABLE_STATS("APP_OWNER"."TABLE_XXXX_ASSIGNMENT", scale, blocks=5 rows=2400)
OPTIMIZER_FEATURES_ENABLE(default)

7 rows selected.

SQL> -- no direct hints - only stats and scaling on the profile created by the SQL Tuning Advisor
SQL> -- (i.e. the dreaded OPT_ESTIMATE hints and no directive type hints like INDEX or USE_NL)
SQL>
SQL> -- now let's try an outline on top of it
SQL> @create_outline

Session altered.

Enter value for sql_id: fknfhx8wth51q
Enter value for child_number: 1
Enter value for outline_name: KSOTEST1
Outline KSOTEST1 created.

PL/SQL procedure successfully completed.

SQL> @outline_hints
Enter value for name: KSOTEST1

HINT
------------------------------------------------------------------------------------------------------------------------------------------------------
USE_NL(@"SEL$1" "A"@"SEL$1")
USE_NL(@"SEL$1" "I"@"SEL$1")
LEADING(@"SEL$1" "L"@"SEL$1" "I"@"SEL$1" "A"@"SEL$1")
INDEX(@"SEL$1" "A"@"SEL$1" ("TABLE_XXXX_ASSIGNMENT"."COL1" "TABLE_XXXX_ASSIGNMENT"."COL2" "TABLE_XXXX_ASSIGNMENT"."COL3"))
INDEX_RS_ASC(@"SEL$1" "I"@"SEL$1" ("TABLE_XXXX_IDENT"."COL1"))
INDEX_RS_ASC(@"SEL$1" "L"@"SEL$1" ("TABLE_XXXX_LOOKUP"."COL1" "TABLE_XXXX_LOOKUP"."COL2"))
OUTLINE_LEAF(@"SEL$1")
ALL_ROWS
DB_VERSION('11.1.0.7')
OPTIMIZER_FEATURES_ENABLE('11.1.0.7')
IGNORE_OPTIM_EMBEDDED_HINTS

11 rows selected.

SQL> -- no OPT_ESTIMATE hints on the outline
SQL> -- directive type hints - INDEX, USE_NL, etc...
SQL> 
SQL> -- now let's try creating a manual profile
SQL> @create_sql_profile.sql
Enter value for sql_id: fknfhx8wth51q
Enter value for child_no: 1
Enter value for category: TEST
Enter value for force_matching:

PL/SQL procedure successfully completed.

SQL> @sql_profile_hints
Enter value for name: PROFILE_fknfhx8wth51q

HINT
------------------------------------------------------------------------------------------------------------------------------------------------------
IGNORE_OPTIM_EMBEDDED_HINTS
OPTIMIZER_FEATURES_ENABLE('11.1.0.7')
DB_VERSION('11.1.0.7')
ALL_ROWS
OUTLINE_LEAF(@"SEL$1")
INDEX_RS_ASC(@"SEL$1" "L"@"SEL$1" ("TABLE_XXXX_LOOKUP"."COL1" "TABLE_XXXX_LOOKUP"."COL2"))
INDEX_RS_ASC(@"SEL$1" "I"@"SEL$1" ("TABLE_XXXX_IDENT"."COL1"))
INDEX(@"SEL$1" "A"@"SEL$1" ("TABLE_XXXX_ASSIGNMENT"."COL1" "TABLE_XXXX_ASSIGNMENT"."COL2" "TABLE_XXXX_ASSIGNMENT"."COL3"))
LEADING(@"SEL$1" "L"@"SEL$1" "I"@"SEL$1" "A"@"SEL$1")
USE_NL(@"SEL$1" "I"@"SEL$1")
USE_NL(@"SEL$1" "A"@"SEL$1")

11 rows selected.

SQL> -- no OPT_ESTIMATE with the SQL Profile we created manually !
SQL> -- again it's directive - USE_NL, INDEX, LEADING, etc...
SQL>

So I apologize to all you SQL Profiles out there who have been lumped together by my prejudiced view, just because of the acts of a few of your brethren (i.e. the ones created by the SQL Tuning Advisor). SQL Profiles do indeed have all the capabilities of Outlines and probably are a better choice in most cases than Outlines.

Thanks again to Randolf Geist for his comments and his ideas on creating manual SQL Profiles.