Ever wonder what the Oracle Database Cost Based Optimizer (CBO) was doing behind the scenes or how it comes up with an execution plan? While other tools or settings show us WHAT the CBO comes up with, the 10053 trace event setting tells us HOW the CBO came to its decision (the final execution plan).
When it comes to performance
tuning, we can spend time on one or both ends of the problem. On the "before
there is a problem" end, we (anyone who writes SQL) have the opportunity
to write good or efficient SQL. The end result is a statement which is optimal,
or nearly so, and for the most part, we've done our due diligence in terms of
avoiding introducing a problem child SQL statement into the fray.
On the other end is where we
get to practice our "Oracle CSI" skills and choose a tool which helps
us solve the "why is this statement so bad?" issue. Common to both
ends is the Cost Based Optimizer. The execution plan generated by the CBO is
used to confirm several aspects of our statement of interest. Access method(s),
or how Oracle intends on going about the task of getting rows is one key
element within a plan. For example, if you were expecting an index to be used
but the access method against that table reflects a full table scan, you know
have some work to do regarding the index and perhaps some initialization
parameters.
Another key area has to do
with join methods. Aside from hints, we don't generally change what Oracle (the
CBO) does. There's nothing we're coding that has much to do with which join
method (typical methods being nested loop, hash, and merge sort) will be used.
What influences the join method is the size of rowsets, and the CBO gets that
from statistics. Looked at another way, Oracle naturally considers indexes once
we put them in place. Oracle internally comes up with join methods and what we
code indirectly influences how the two result sets are joined.
So, behind the scenes, what
is the CBO doing when it comes to how it comes up with an execution plan? This
is where the 10053 trace event comes into play. Other tools or settings show us
WHAT the CBO comes up with; the 10053 setting tells us HOW the CBO came to its
decision (the final execution plan).
For a relatively simple
query, you might be amazed at all the work Oracle, via the CBO, goes through.
Let's run a 10053 trace event and examine the contents of the trace file.
There are a couple of ways
to start this trace event. A simple alter session command turns it on (and
off).
ALTER SESSION SET EVENTS='10053 trace name context forever, level 1';
...your statement here...
ALTER SESSION SET EVENTS '10053 trace name context off';
Another method involves
using ORADEBUG, which overall, has the advantage of outputting the name of the
trace file, but has the disadvantage of having to connect as SYS. Using the
ALTER SESSION option is more flexible as pretty much any user can do this.
conn / as sysdba
oradebug setmypid
oradebug unlimit
oradebug event 10053 trace name context forever, level 1
...your statement here...
oradebug event 10053 trace name context off
oradebug tracefile_name
Yet another method includes
DBMS_SYSTEM and its SET_EV subprogram. This built-in doesn't have the best documentation
in the world (or public support for that matter).
You have a choice of two
levels with the 10053 trace event. Level 1 is more comprehensive than level 2.
What is collected in the trace file includes:
1. Parameters used by the
optimizer (level 1 only)
2. Index statistics (level 1
only)
3. Column statistics
4. Single Access Paths
5. Join Costs
6. Table Joins Considered
7. Join Methods Considered
(NL/MS/HA)
Unlike "normal"
tracing using SQL_TRACE, the trace file generated here is already formatted.
Having the PLAN_TABLE in your schema (assuming this is done via ALTER SESSION
by someone other than SYS) is needed as that is where, as always, the execution
plan output is stored and 10053 tracing includes the output of the execution
plan for your statement.
Let's take a fairly simple
statement (as seen in various places throughout Oracle's documentation) and
examine its 10053 output.
SELECT ch.channel_class,
c.cust_city,
t.calendar_quarter_desc,
SUM(s.amount_sold) sales_amount
FROM sh.sales s,
sh.times t,
sh.customers c,
sh.channels ch
WHERE s.time_id = t.time_id
AND s.cust_id = c.cust_id
AND s.channel_id = ch.channel_id
AND c.cust_state_province = 'CA'
AND ch.channel_desc in ('Internet','Catalog')
AND t.calendar_quarter_desc IN ('1999-01','1999-02')
GROUP BY ch.channel_class, c.cust_city, t.calendar_quarter_desc
ORDER by 1,2,3,4;
Using Oracle 11g, the
output file can be found in the trace folder under this path (ORACLE_BASE for
me is c:\apporacle):
$ORACLE_BASE\diag\rdbms\ora11g\ora11g\trace
This location corresponds to
your background_dump_dest parameter. The trace file
(for the above statement) has nearly 6,000 lines in it, and much of the output
is similar blocks. You can clearly see how the optimizer tries different join
orders, giving way to the idea that the order in which you list tables in the
FROM clause is not necessarily the join order seen within the execution plan.
For this example, the CBO
tries 21 permutations. Note that these are permutations, where order is
important, not combinations, where order is not important.
Join order[1]: CHANNELS[CH]#0 TIMES[T]#1 CUSTOMERS[C]#2 SALES[S]#3
***********************
Best so far: Table#: 0 cost: 3.0015 card: 2.0000 bytes: 42
Table#: 1 cost: 37.2306 card: 362.0000 bytes: 13394
Table#: 2 cost: 146316.6073 card: 1233849.4565 bytes: 77732487
Table#: 3 cost: 152643.9004 card: 27500.9348 bytes: 2310084
***********************
Join order[2]: CHANNELS[CH]#0 TIMES[T]#1 SALES[S]#3 CUSTOMERS[C]#2
***********************
Best so far: Table#: 0 cost: 3.0015 card: 2.0000 bytes: 42
Table#: 1 cost: 37.2306 card: 362.0000 bytes: 13394
Table#: 3 cost: 536.1840 card: 56955.6791 bytes: 3303448
Table#: 2 cost: 946.4226 card: 27500.9348 bytes: 2310084
***********************
Join order[3]: CHANNELS[CH]#0 CUSTOMERS[C]#2 TIMES[T]#1 SALES[S]#3
Join order aborted: cost > best plan cost (--shown here once)
***********************
Join order[4]: CHANNELS[CH]#0 CUSTOMERS[C]#2 SALES[S]#3 TIMES[T]#1
Join order[5]: CHANNELS[CH]#0 SALES[S]#3 TIMES[T]#1 CUSTOMERS[C]#2
***********************
Best so far: Table#: 0 cost: 3.0015 card: 2.0000 bytes: 42
Table#: 3 cost: 501.9521 card: 459421.5000 bytes: 19295724
Table#: 1 cost: 522.8420 card: 56955.6791 bytes: 3303448
Table#: 2 cost: 933.0806 card: 27500.9348 bytes: 2310084
***********************
Join order[6]: CHANNELS[CH]#0 SALES[S]#3 CUSTOMERS[C]#2 TIMES[T]#1
Join order[7]: TIMES[T]#1 CHANNELS[CH]#0 CUSTOMERS[C]#2 SALES[S]#3
Join order[8]: TIMES[T]#1 CHANNELS[CH]#0 SALES[S]#3 CUSTOMERS[C]#2
Join order[9]: TIMES[T]#1 CUSTOMERS[C]#2 CHANNELS[CH]#0 SALES[S]#3
Join order[10]: TIMES[T]#1 SALES[S]#3 CHANNELS[CH]#0 CUSTOMERS[C]#2
***********************
Best so far: Table#: 1 cost: 18.1146 card: 181.0000 bytes: 2896
Table#: 3 cost: 517.0666 card: 113911.3582 bytes: 4214707
Table#: 0 cost: 521.1319 card: 56955.6791 bytes: 3303448
Table#: 2 cost: 931.3705 card: 27500.9348 bytes: 2310084
***********************
Join order[11]: TIMES[T]#1 SALES[S]#3 CUSTOMERS[C]#2 CHANNELS[CH]#0
***********************
Best so far: Table#: 1 cost: 18.1146 card: 181.0000 bytes: 2896
Table#: 3 cost: 517.0666 card: 113911.3582 bytes: 4214707
Table#: 2 cost: 923.7783 card: 55001.8696 bytes: 3465126
Table#: 0 cost: 931.3608 card: 27500.9348 bytes: 2310084
***********************
Join order[12]: CUSTOMERS[C]#2 CHANNELS[CH]#0 TIMES[T]#1 SALES[S]#3
Join order[13]: CUSTOMERS[C]#2 TIMES[T]#1 CHANNELS[CH]#0 SALES[S]#3
Join order[14]: CUSTOMERS[C]#2 SALES[S]#3 CHANNELS[CH]#0 TIMES[T]#1
Join order[15]: CUSTOMERS[C]#2 SALES[S]#3 TIMES[T]#1 CHANNELS[CH]#0
Join order[16]: SALES[S]#3 CHANNELS[CH]#0 TIMES[T]#1 CUSTOMERS[C]#2
Join order[17]: SALES[S]#3 CHANNELS[CH]#0 CUSTOMERS[C]#2 TIMES[T]#1
Join order[18]: SALES[S]#3 TIMES[T]#1 CHANNELS[CH]#0 CUSTOMERS[C]#2
Join order[19]: SALES[S]#3 TIMES[T]#1 CUSTOMERS[C]#2 CHANNELS[CH]#0
Join order[20]: SALES[S]#3 CUSTOMERS[C]#2 CHANNELS[CH]#0 TIMES[T]#1
Join order[21]: SALES[S]#3 CUSTOMERS[C]#2 TIMES[T]#1 CHANNELS[CH]#0
The best (lowest cost)
permutation is join order #11, which starts with TIMES, joins to SALES, then
joined to CUSTOMERS, and finally joined to CHANNELS. What does the execution
plan look like?
PLAN_TABLE_OUTPUT
--------------------------------------------------------------
| Id | Operation | Name | Rows |
--------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1237 |
| 1 | SORT ORDER BY | | 1237 |
| 2 | HASH GROUP BY | | 1237 |
|* 3 | HASH JOIN | | 27501 |
|* 4 | TABLE ACCESS FULL | CHANNELS | 2 |
|* 5 | HASH JOIN | | 55002 |
|* 6 | TABLE ACCESS FULL | CUSTOMERS | 3408 |
|* 7 | HASH JOIN | | 113K|
| 8 | PART JOIN FILTER CREATE | :BF0000 | 181 |
|* 9 | TABLE ACCESS FULL | TIMES | 181 |
| 10 | PARTITION RANGE JOIN-FILTER| | 918K|
| 11 | TABLE ACCESS FULL | SALES | 918K|
Reading the lines (RSO, or
row source operations), we see exactly that progression:
TIMES-SALES-CUSTOMERS-CHANNELS.
Another line in the 10053
trace file shows that 21 permutations were tried and up to 2000 would have been
considered. Since four tables results in 24 permutations (4!=4*3*2*1), why were
three permutations skipped? In my example, table permutations 1230, 2031 and
2130 were not considered and there is nothing in the trace file to show why
these were omitted (there is no obvious message about 2-0-3-1 being pruned
because anything starting with 2-0 is guaranteed to be higher than what 2-0-1-3
had as a cost).
The trace file includes an
extensive listing of all default hidden and unhidden parameters that are in
place, plus a long list of bug fixes (enabled or not). Techniques such as join
eliminations, query transformations, common subexpression elimination,
self-join conversions, predicate move-around, and a slew of other approaches
are detailed in the file.
A side benefit of running a
trace is the output showing all of the statistics for a table and its
associated indexes. The "BASE STATISTICAL INFORMATION" (section title
in the file) for the customers table shows the following:
Table Stats::
Table: CUSTOMERS Alias: C
#Rows: 55500 #Blks: 1486 AvgRowLen: 181.00
Index Stats::
Index: CUSTOMERS_GENDER_BIX Col#: 4
LVLS: 1 #LB: 3 #DK: 2 LB/K: 1.00 DB/K: 2.00 CLUF: 5.00
Index: CUSTOMERS_MARITAL_BIX Col#: 6
LVLS: 1 #LB: 5 #DK: 11 LB/K: 1.00 DB/K: 1.00 CLUF: 18.00
Index: CUSTOMERS_PK Col#: 1
LVLS: 1 #LB: 115 #DK: 55500 LB/K: 1.00 DB/K: 1.00 CLUF: 54405.00
Index: CUSTOMERS_YOB_BIX Col#: 5
LVLS: 1 #LB: 19 #DK: 75 LB/K: 1.00 DB/K: 1.00 CLUF: 75.00
The output here can be
correlated against DBA_TABLES and DBA_INDEXES if need be (DB/K, for example,
corresponds to average data blocks per key).
Yet another benefit of
running this trace event is that you can see what Oracle comes up with for a
stored outline.
Outline Data:
/*+
BEGIN_OUTLINE_DATA
IGNORE_OPTIM_EMBEDDED_HINTS
OPTIMIZER_FEATURES_ENABLE('11.2.0.1')
DB_VERSION('11.2.0.1')
ALL_ROWS
OUTLINE_LEAF(@"SEL$1")
FULL(@"SEL$1" "T"@"SEL$1")
FULL(@"SEL$1" "S"@"SEL$1")
FULL(@"SEL$1" "C"@"SEL$1")
FULL(@"SEL$1" "CH"@"SEL$1")
LEADING(@"SEL$1" "T"@"SEL$1" "S"@"SEL$1" "C"@"SEL$1" "CH"@"SEL$1")
USE_HASH(@"SEL$1" "S"@"SEL$1")
USE_HASH(@"SEL$1" "C"@"SEL$1")
USE_HASH(@"SEL$1" "CH"@"SEL$1")
PX_JOIN_FILTER(@"SEL$1" "S"@"SEL$1")
SWAP_JOIN_INPUTS(@"SEL$1" "C"@"SEL$1")
SWAP_JOIN_INPUTS(@"SEL$1" "CH"@"SEL$1")
USE_HASH_AGGREGATION(@"SEL$1")
END_OUTLINE_DATA
*/
In a SQL*Plus session,
create a stored outline and query USER_OUTLINE_HINTS. You should expect to see
the same output.
CREATE OUTLINE star_query
FOR CATEGORY test_outlines ON
;
SELECT join_pos, hint
FROM user_outline_hints
WHERE name = 'STAR_QUERY';
JOIN_POS HINT
---------- ------------------------------------------------------------
0 USE_HASH_AGGREGATION(@"SEL$1")
0 SWAP_JOIN_INPUTS(@"SEL$1" "CH"@"SEL$1")
0 SWAP_JOIN_INPUTS(@"SEL$1" "C"@"SEL$1")
0 PX_JOIN_FILTER(@"SEL$1" "S"@"SEL$1")
0 USE_HASH(@"SEL$1" "CH"@"SEL$1")
0 USE_HASH(@"SEL$1" "C"@"SEL$1")
0 USE_HASH(@"SEL$1" "S"@"SEL$1")
0 LEADING(@"SEL$1" "T"@"SEL$1" "S"@"SEL$1" "C"@"SEL$1" "CH"@"SEL$1")
4 FULL(@"SEL$1" "CH"@"SEL$1")
3 FULL(@"SEL$1" "C"@"SEL$1")
2 FULL(@"SEL$1" "S"@"SEL$1")
1 FULL(@"SEL$1" "T"@"SEL$1")
0 OUTLINE_LEAF(@"SEL$1")
0 ALL_ROWS
0 DB_VERSION('11.2.0.1')
0 OPTIMIZER_FEATURES_ENABLE('11.2.0.1')
0 IGNORE_OPTIM_EMBEDDED_HINTS
In Closing
Exploring the dump file from
the 10053 trace event will give you a better understanding of what the
optimizer is doing while it is coming up with the best plan it can (based on
the number of permutations). The plan you see is probably the best possible
plan, given certain conditions. One is good statistics. Another, and not quite
as obvious, is what session or system parameters are set to. If you noticed the
name of the outline (STAR_QUERY), does the execution plan look like the results
of a star query? The answer is no (but Oracle can elect to use a
"normal" plan if the cost is best), but for certainty, we know that a
star query transformation was not considered because we did not see any
star-related lines in the outline. One line in the outline would have been
this:
OPT_PARAM('star_transformation_enabled' 'true')
Another tell-tale would have
been the use of bitmap indexes in the execution plan. The overall point of this
is that the CBO returned the best plan, given what it had to work with. It
still may not have been the best plan overall because not all of the
prerequisites to have a better plan were enabled.
Additional Resources
Oracle Wiki: HOW TO trace the CBO working out the execution path (event 10053
Oracle : Understanding Optimization
»
See All Articles by Columnist
Steve Callan