|
Amiel -- Thanks for the question regarding "10053", version 9.2.6
Submitted on 7-May-2006 14:23 Central time zone
Last updated 6-Feb-2009 15:32
You Asked
Dear tom,
A. your new book is illuminating.
B. could you please, post an 10053 trace file and explain in your
Word what is going on there?
C. try to hack it my self - didn't worked for me, too much numbers.
Regards,
Amiel
and we said...
Do you have access to my book "Effective Oracle by Design", in there I write (among lots
of other stuff):
<quote src=effective Oracle by Design CBO chapter>
Use the 10053 Event to Trace CBO Choices
Have you ever wondered why the CBO is making the choices it is making? It is not because
it is arbitrary or capricious, rather the opposite. It is a piece of predicable software
that comes to conclusions based on inputs. Given the same inputs, it will steadfastly
give the same outputs (well, until you upgrade, that is). It appears arbitrary and
capricious at times because what it does is among the most complex things Oracle itself
does. Cost-based query optimization is a hard thing to do-truly computer science. The
myriad of facts, parameters, and choices the CBO is faced with make it difficult for a
human to predict what will happen.
When I'm faced with a query plan I just cannot explain, I use the 10053 trace event. I
use this after I've tried all of the normal paths, such as using hints to get the query
plan I felt I should have gotten in the first place. Most of the time, the COST/CARD
output resulting from that exercise is sufficient to see where the plan went wrong and
what statistics I might be missing.
Note that this trace event is undocumented, unsupported, and works only in certain
circumstances. However, it is widely known outside Oracle Corporation. A simple Google
search for event 10053 will return more than 1,500 documents on the Web and hundreds of
hits on the newsgroups. There are even Oracle support notes on this topic available on
metalink.oracle.com, the Oracle support web site, if you search for 10053.
I do not make a regular practice of reading these trace files. In fact, I most often use
them in the filing of a Technical Assistance Request (TAR) with Oracle support. They
provide information to the support analysts that can be useful in diagnosing
optimizer-related issues. However, an example will show you what you might expect to see
in the trace file generated by this event. In order to generate the CBO trace file, we
need to set an event and then simply parse a query. One technique is as follows:
big_table@ORA920> ALTER SESSION SET EVENTS
2 '10053 trace name context forever, level 1';
Session altered.
big_table@ORA920> explain plan for
2 select * from big_table where object_id = 55;
Explained.
Now we are ready to inspect the trace file. You can use the same technique outlined in
the "TKPROF" section of Chapter 2 to get a trace filename for your session (see that
chapter for details if you do not know how to identify your session's trace file). Upon
exiting SQL*Plus and editing the trace file, you will see something like this:
/usr/oracle/ora920/OraHome1/admin/ora920/udump/ora920_ora_23183.trc
Oracle9i Enterprise Edition Release 9.2.0.1.0 - Production
With the Partitioning, OLAP and Oracle Data Mining options
JServer Release 9.2.0.1.0 - Production
ORACLE_HOME = /usr/oracle/ora920/OraHome1
System name: Linux
Node name: tkyte-pc-isdn.us.oracle.com
Release: 2.4.18-14
Version: #1 Wed Sep 4 13:35:50 EDT 2002
Machine: i686
Instance name: ora920
Redo thread mounted by this instance: 1
Oracle process number: 18
Unix process pid: 23183, image: oracle@tkyte-pc-isdn.us.oracle.com
This is just the standard trace file header. The interesting stuff comes next:
*** SESSION ID:(15.1158) 2003-01-26 16:54:53.834
QUERY
explain plan for select * from big_table where object_id = 55
***************************************
PARAMETERS USED BY THE OPTIMIZER
********************************
OPTIMIZER_FEATURES_ENABLE = 9.2.0
OPTIMIZER_MODE/GOAL = Choose
lots chopped out here
DB_FILE_MULTIBLOCK_READ_COUNT = 16
_NEW_SORT_COST_ESTIMATE = TRUE
_GS_ANTI_SEMI_JOIN_ALLOWED = TRUE
_CPU_TO_IO = 0
_PRED_MOVE_AROUND = TRUE
***************************************
There, you will find the parameters that affect the CBO. The parameters that start with _
are undocumented parameters. Most of the other parameters are discussed in the previous
sections. These are the parameters you have free access to modify as you see fit.
Caution: Never set _ parameters in a real system without the expressed guidance and
consent of support. This is not just me "stating the company line" here; this is for
real. Undocumented parameters have unanticipated side effects (they could be seriously
damaging to your data, your security, and many other things). Undocumented parameters
change in meaning from release to release. Every time you upgrade, you need to ask
support, "Do I still need this undocumented parameter?" I will not discuss the meaning,
range of values, or use of any of these undocumented parameters.
Next in the trace file you'll find the base statistical information used:
BASE STATISTICAL INFORMATION
***********************
Table stats Table: BIG_TABLE Alias: BIG_TABLE
TOTAL :: CDN: 1833857 NBLKS: 22188 AVG_ROW_LEN: 84
-- Index stats
INDEX NAME: OBJECT_ID_IDX COL#: 4
TOTAL :: LVLS: 2 #LB: 4202 #DK: 1833792 LB/K: 1 DB/K: 1 CLUF: 21921
INDEX NAME: OBJECT_TYPE_IDX COL#: 6
TOTAL :: LVLS: 2 #LB: 5065 #DK: 27 LB/K: 187 DB/K: 2414 CLUF: 65187
_OPTIMIZER_PERCENT_PARALLEL = 0
You'll see this for all of the referenced objects in the query. This in itself can help
you diagnose the problem right away. If you know that the cardinality of the table
BIG_TABLE is really 1 and the number of blocks is 1, right here you can see what the
problem is. The optimizer sees cardinality (CDN) of 1,833,857 rows and 22,188 blocks
(NBLKS). So, the statistics would be out of date if there were really just one row.
Here's a quick explanation of what the abbreviations mean:
CDN Cardinality, a count of rows
NBLKS Number of blocks
AVG_ROW_LEN The computed average row length
COL# Column numbers in the table the index is on (select * from user_tab_columns where
column_id = 4 and table_name = 'BIG_TABLE' would reveal the name of the column in this
case)
LVLS Number of levels in the B*Tree
#LB Number of leaf blocks
#DK Number of distinct keys
LB/K Number of leaf blocks per key value on average
DB/K Number of base table data blocks per key value; how many table accesses (logical
I/O's) would be made using an equality predicate on this index. Directly related to the
cluster factor below.
CLUF Clustering factor of this index; a measure of how sorted a base table is with
respect to this index.
Many times, a quick scan of this information can pinpoint the problem right away. A smack
to the forehead, followed by a quick analysis of the table, and you've fixed the problem.
If not, it starts to get more complex.
The next section shows the table-access cost, presenting the best access method for each
table. Again, if the information appears incorrect to you, that would point to bad
statistics or insufficient statistics (for example, no histograms, where histograms would
have played an important role). In this example, you would see the following:
***************************************
SINGLE TABLE ACCESS PATH
Column: OBJECT_ID Col#: 4 Table: BIG_TABLE Alias: BIG_TABLE
NDV: 1833792 NULLS: 0 DENS: 5.4534e-07
HEIGHT BALANCED HISTOGRAM: # BKT: 75 #VAL: 76
TABLE: BIG_TABLE ORIG CDN: 1833857 ROUNDED CDN: 1 CMPTD CDN: 1
Access path: tsc Resc: 2136 Resp: 2136
Access path: index (equal)
Index: OBJECT_ID_IDX
TABLE: BIG_TABLE
RSC_CPU: 0 RSC_IO: 4
IX_SEL: 0.0000e+00 TB_SEL: 5.4534e-07
BEST_CST: 4.00 PATH: 4 Degree: 1
***************************************
Here, you can see more basic information and the costs associated with the various access
paths into this table. This example shows two access paths:
Access Path: tsc A table scan, with a "serial" cost of 2136 (resc) and a parallel
cost of 2136 (resp) in this case.
Access Path: index (equal) An index access based on an equality predicate. Other
paths might be index unique, no sta/sto keys-unbounded range scan (start/stop keys),
index, and so on. This has a serial cost of 4 based on estimated I/O (RSC_IO).
As important as what you can see, is many times what you cannot see. For example,
missing Access Paths - indexes you thought should be considered but were not. There
absence may help you figure out "why" they were not being used. For example, I recently
received a question on AskTom:
We have 2 fact tables in our dataware house. One for transactions of type V, another for
transactions of type M. Each table is partitioned by day and there are 90 days online.
There are 145 Million rows of type V, 133 million of type M. They are stuctured in
exactly the same way (same partition key, same indexes, etc). The only real difference is
that the row size of the table of type V is larger (203 bytes) than the row size of the
table of type M (141 bytes). We have a query to look for transactions of type V for
customer X. Performance is good. We have an "identical" query to look for transactions of
type M for customer X. Performance is horrible. The difference between the two is the
query against V is using an INDEX RANGE SCAN. The query against M will only use an INDEX
FULL SCAN. What could be the reason?
Well, we went back and forth on this - tried hints, tried everything. Spent a while
scratching our heads. Finally - I asked them to email me the 10053 trace files. What I
discovered was the index was not only not being range scanned for the query against "M",
it wasn't even being considered. That was a great clue - there was something that was
precluding this index from being used in that fashion. I immediately asked for the
CREATE TABLE and CREATE INDEX statements - something I should have asked for in the
beginning, I was over analyzing the problem and didn't rule out "simple things" first.
When I got them - I discovered that the indexed column was a NUMBER(12) in the V table
and a VARCHAR2(12) in the M table. It was a simple datatype conversion that was
precluding the index from being used in a range scan! They were joining these V and M
tables to some other table by this column - when it was a NUMBER, the index could be
range scanned, when it was a VARCHAR2 - it could not. In the end - what was assumed to
be an "optimizer problem" turned out to be an implementation mistake - the column was
supposed to be a NUMBER, they implemented wrong. Fixing that issue solved the problem
immediately. I'm not sure if I looked at the CREATE TABLES that I would have caught it
right away myself - it was something they overlooked easily enough and it was their data!
The 10053 trace certainly helped here by showing that access path was not even
considered.
Now, continuing on in this trace file, you can also see the ORIG CDN, which is the
original cardinality of the base table, as well as the CMPTD CDN, the computed
cardinality-how many rows the optimizer expects to get back from this object (regardless
of the access method).
Now, unfortunately, the interesting output of this is the PATH, which is a nebulous 4 in
this case. The 4 just happens to mean index-range scan. We know that because the
least-cost access path is the index (equal), and that it is really an index-range scan
(it has to be). OBJECT_ID_IDX is a nonunique index, and the predicate was where object_id
= 55.
Basically, in this section you will be looking to see if the raw numbers even make sense,
given your knowledge of the real situation. If not, it probably points to bad statistics,
something you need to correct before assuming that something is wrong with the optimizer.
Or, as noted, you'll be looking for what isn't there - and then trying to figure out
"why" as I did.
The rest of this report, while interesting, is mostly useful only to Oracle support
analysts and the optimizer developers themselves. It can be interesting to look at, to
try and get a better understanding of the complexity of the software that is the
optimizer. Here, you will see a review of all of the possible plans, including their
costs and what they are doing. At the very bottom, you'll ultimately see the chosen plan
and its cost.
Now, the trace file in this example is fairly small, concise, and easy to understand. If
you take a nontrivial query, however, you'll see how complex this file can truly be. I
did a 150 table join and traced it. The resulting trace file itself was almost 80,000
lines of text, simply due to the massive permutations by which the query could be
processed after reordering the tables.
So, my recommendation with this 10053 trace event is that you use this only when you
believe the optimizer to be very wrong. You would generate the trace file and look at the
first few pages, eyeball the numbers and init.ora settings, and make sure that they are
realistic. If not, you would start there by correcting the problem-adjusting the
parameter you thought was already set, or fixing the statistics by updating out-of-date
ones or doing a more comprehensive gather, to include histograms, for example.
Lastly, if all else fails, you have the trace file you need to open a TAR with Oracle
support, to find out why a particular plan is being selected. At this point, it would be
best if you actually have two traces: one for the original query and another for a hinted
query that massively outperforms your existing one. This information will be more than
enough for the support technicians to discover the scientific reason for the performance
differences and probably to suggest a workaround to solve the problem.
</quote>
very good explaination
May 8, 2006 - 9am Central time zone
Reviewer: Jagjeet Singh from India
Try Jonathan Lewis' latest book, too
May 8, 2006 - 9am Central time zone
Reviewer: Doug Burns from Edinburgh, UK
There is a chapter (an appendix, if I remember correctly) dedicated to walking through a 10053
trace file. I wouldn't say it makes easy reading, but it's certainly detailed ;-)
Cost based from Jonathan Lewis
May 8, 2006 - 9am Central time zone
Reviewer: Bauer Wolfgang from Bavaria/Germany
Jonathan Lewis has also a own chapter about the 10053 trace file in his new book "Cost based".
May 9, 2006 - 11am Central time zone
Reviewer: Amiel D.
Think you. It was just the explanation I needed.
Amiel
what is rounded cardinality in 10053 trace file?
May 22, 2006 - 4pm Central time zone
Reviewer: A reader from NC USA
In your example, there is a rounded card like this:
**************************
TABLE: BIG_TABLE ORIG CDN: 1833857 ROUNDED CDN: 1 CMPTD CDN: 1
**************************
Why ROUNDED CDN is way off than ORIG CDN?
I also noticed this in some of the execution plan in our Oracle 10g environment. It seemed to me
Oracle autotrace is using the ROUNDED CDG when evaluating different execution plans, and sometimes
ROUNDED CDG is much much smaller than the original cardinality. Why is that?
Thanks.
Followup May 22, 2006 - 4pm Central time zone:
it is not way off, it is "perfect"
table (orig) cardinality is 1,833,857
rounded (estimated) cardinality is 1
which is precisely correct.
May 22, 2006 - 5pm Central time zone
Reviewer: A reader from NC USA
I am confused. So what does rounded cardinality mean in the trace file? Why sometimes it is
matching the original cardinality and sometimes is not. Could you explain what rounded cardinality
is or point me some resources I can read. I appreciate your help!
Followup May 23, 2006 - 6am Central time zone:
original cardinality is the original, before anything applied, cardinality. Estimate of rows
flowing INTO.
the other one is the guess of rows flowing out.
I had 1.8 million records
Of which I expected 1 row as output.
May 22, 2006 - 6pm Central time zone
Reviewer: A reader from NC, USA
I did a little research and found out that the rounded cardinality is original cardinality/distinct
values. Is that right?
I knew sqlplus autotrace is not the true execution plan. In oracle10g, the rounded cardinality in
10053 trace file matches the rows in the execution plan I saw in sqlplus autotrace traceonly. When
I use 'alter session set sql_trace=true' and tkprof, I saw another different execution plan and the
true number of rows returned. What I can not understand is how Oracle estimates the rows in
autotrace in one way and actually picks up another execution plan when executing the SQL? Am I
missing something here?
Followup May 23, 2006 - 7am Central time zone:
... What I can not understand is how Oracle estimates the
rows in autotrace in one way and actually picks up another execution plan when
executing the SQL? ...
I don't know what you meant by that comment.
Unless you are asking "why does autotrace sometimes not show me the actual plan used" - in which
case there are many reasons:
a) explain plan does not bind variable peek, a real query would.
b) explain plan sees all binds as varchar2's - in real life they are numbers, dates, varchar2's and
so on. Hence, implicit conversions may or may not be observed by explain plan that would be
observed in real life.
c) explain plan does a hard parse, uses the statistics/dynamic samples that are IN PLACE RIGHT NOW.
A query that was run for real "a little while ago" or "a little while from now" might see
different inputs
d) explain plan uses the current operational environment to come up with a plan. You might be
explaining in a FIRST_ROWS session, whereas the query was actually executed in a ALL_ROWS session
(or any one of the optimizer parameters could be different)
e) any combination of a, b, c, d...
As for the rounded - no, not even close. It is the "guessed at cardinality"
Consider a pair of scripts, test.sql and test2.sql:
---------------- test.sql --------------------
set echo on
drop table t;
create table t
as
select rownum id1, case when mod(rownum,100)<80 then 0 else mod(rownum,100) end id2
from all_objects;
exec dbms_stats.gather_table_stats( user, 'T', method_opt => 'for all columns size 254' );
select count(case when id1=0 then 1 end) id1_0,
count(case when id2=0 then 1 end) id2_0,
count(case when id1=42 then 1 end) id1_42,
count(case when id2=42 then 1 end) id2_42,
count(case when id1=99 then 1 end) id1_99,
count(case when id2=99 then 1 end) id2_99
from t
/
@test2 "id1=0"
@test2 "id2=0"
@test2 "id1=42"
@test2 "id2=42"
@test2 "id1=99"
@test2 "id2=99"
------------------------------------------
-------------- test2.sql -----------------
column trace new_val TRACE
select c.value || '/' || d.instance_name || '_ora_' || a.spid || '.trc' trace
from v$process a, v$session b, v$parameter c, v$instance d
where a.addr = b.paddr
and b.audsid = userenv('sessionid')
and c.name = 'user_dump_dest'
/
alter session set events '10053 trace name context forever, level 1';
set autotrace traceonly explain
select * from t where &1.;
set autotrace off
disconnect
connect /
!echo &TRACE
!grep 'Card: Original: ' &TRACE
------------------------------------------------------
When run - produces the following output - note how the autotrace estimate is the "rounded card"
- it is the GUESS, the estimated cardinality flowing out of the step
ops$tkyte@ORA10GR2> create table t
2 as
3 select rownum id1, case when mod(rownum,100)<80 then 0 else mod(rownum,100) end id2
4 from all_objects;
Table created.
ops$tkyte@ORA10GR2>
ops$tkyte@ORA10GR2> exec dbms_stats.gather_table_stats( user, 'T', method_opt => 'for all columns
size 254' );
PL/SQL procedure successfully completed.
ops$tkyte@ORA10GR2>
ops$tkyte@ORA10GR2> select count(case when id1=0 then 1 end) id1_0,
2 count(case when id2=0 then 1 end) id2_0,
3 count(case when id1=42 then 1 end) id1_42,
4 count(case when id2=42 then 1 end) id2_42,
5 count(case when id1=99 then 1 end) id1_99,
6 count(case when id2=99 then 1 end) id2_99
7 from t
8 /
ID1_0 ID2_0 ID1_42 ID2_42 ID1_99 ID2_99
---------- ---------- ---------- ---------- ---------- ----------
0 40079 1 0 1 500
ops$tkyte@ORA10GR2> @test2 "id1=0"
ops$tkyte@ORA10GR2> set echo off
TRACE
-------------------------------------------------------------------------------
/home/ora10gr2/admin/ora10gr2/udump/ora10gr2_ora_12273.trc
Session altered.
old 1: select * from t where &1.
new 1: select * from t where id1=0
Execution Plan
----------------------------------------------------------
Plan hash value: 1601196873
--------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
--------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | 6 | 24 (9)| 00:00:01 |
|* 1 | TABLE ACCESS FULL| T | 1 | 6 | 24 (9)| 00:00:01 |
--------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
1 - filter("ID1"=0)
Disconnected from Oracle Database 10g Enterprise Edition Release 10.2.0.1.0 - Production
With the Partitioning, OLAP and Data Mining options
Connected.
/home/ora10gr2/admin/ora10gr2/udump/ora10gr2_ora_12273.trc
Card: Original: 50087 Rounded: 1 Computed: 1.00 Non Adjusted: 1.00
Card: Original: 50087 Rounded: 1 Computed: 1.00 Non Adjusted: 1.00
ops$tkyte@ORA10GR2> @test2 "id2=0"
ops$tkyte@ORA10GR2> set echo off
TRACE
-------------------------------------------------------------------------------
/home/ora10gr2/admin/ora10gr2/udump/ora10gr2_ora_12277.trc
Session altered.
old 1: select * from t where &1.
new 1: select * from t where id2=0
Execution Plan
----------------------------------------------------------
Plan hash value: 1601196873
--------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
--------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 39812 | 233K| 24 (9)| 00:00:01 |
|* 1 | TABLE ACCESS FULL| T | 39812 | 233K| 24 (9)| 00:00:01 |
--------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
1 - filter("ID2"=0)
Disconnected from Oracle Database 10g Enterprise Edition Release 10.2.0.1.0 - Production
With the Partitioning, OLAP and Data Mining options
Connected.
/home/ora10gr2/admin/ora10gr2/udump/ora10gr2_ora_12277.trc
Card: Original: 50087 Rounded: 39812 Computed: 39811.60 Non Adjusted: 39811.60
Card: Original: 50087 Rounded: 39812 Computed: 39811.60 Non Adjusted: 39811.60
ops$tkyte@ORA10GR2> @test2 "id1=42"
ops$tkyte@ORA10GR2> set echo off
TRACE
-------------------------------------------------------------------------------
/home/ora10gr2/admin/ora10gr2/udump/ora10gr2_ora_12280.trc
Session altered.
old 1: select * from t where &1.
new 1: select * from t where id1=42
Execution Plan
----------------------------------------------------------
Plan hash value: 1601196873
--------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
--------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | 6 | 24 (9)| 00:00:01 |
|* 1 | TABLE ACCESS FULL| T | 1 | 6 | 24 (9)| 00:00:01 |
--------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
1 - filter("ID1"=42)
Disconnected from Oracle Database 10g Enterprise Edition Release 10.2.0.1.0 - Production
With the Partitioning, OLAP and Data Mining options
Connected.
/home/ora10gr2/admin/ora10gr2/udump/ora10gr2_ora_12280.trc
Card: Original: 50087 Rounded: 1 Computed: 1.00 Non Adjusted: 1.00
Card: Original: 50087 Rounded: 1 Computed: 1.00 Non Adjusted: 1.00
ops$tkyte@ORA10GR2> @test2 "id2=42"
ops$tkyte@ORA10GR2> set echo off
TRACE
-------------------------------------------------------------------------------
/home/ora10gr2/admin/ora10gr2/udump/ora10gr2_ora_12285.trc
Session altered.
old 1: select * from t where &1.
new 1: select * from t where id2=42
Execution Plan
----------------------------------------------------------
Plan hash value: 1601196873
--------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
--------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | 6 | 24 (9)| 00:00:01 |
|* 1 | TABLE ACCESS FULL| T | 1 | 6 | 24 (9)| 00:00:01 |
--------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
1 - filter("ID2"=42)
Disconnected from Oracle Database 10g Enterprise Edition Release 10.2.0.1.0 - Production
With the Partitioning, OLAP and Data Mining options
Connected.
/home/ora10gr2/admin/ora10gr2/udump/ora10gr2_ora_12285.trc
Card: Original: 50087 Rounded: 1 Computed: 0.49 Non Adjusted: 0.49
Card: Original: 50087 Rounded: 1 Computed: 0.49 Non Adjusted: 0.49
ops$tkyte@ORA10GR2> @test2 "id1=99"
ops$tkyte@ORA10GR2> set echo off
TRACE
-------------------------------------------------------------------------------
/home/ora10gr2/admin/ora10gr2/udump/ora10gr2_ora_12288.trc
Session altered.
old 1: select * from t where &1.
new 1: select * from t where id1=99
Execution Plan
----------------------------------------------------------
Plan hash value: 1601196873
--------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
--------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | 6 | 24 (9)| 00:00:01 |
|* 1 | TABLE ACCESS FULL| T | 1 | 6 | 24 (9)| 00:00:01 |
--------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
1 - filter("ID1"=99)
Disconnected from Oracle Database 10g Enterprise Edition Release 10.2.0.1.0 - Production
With the Partitioning, OLAP and Data Mining options
Connected.
/home/ora10gr2/admin/ora10gr2/udump/ora10gr2_ora_12288.trc
Card: Original: 50087 Rounded: 1 Computed: 1.00 Non Adjusted: 1.00
Card: Original: 50087 Rounded: 1 Computed: 1.00 Non Adjusted: 1.00
ops$tkyte@ORA10GR2> @test2 "id2=99"
ops$tkyte@ORA10GR2> set echo off
TRACE
-------------------------------------------------------------------------------
/home/ora10gr2/admin/ora10gr2/udump/ora10gr2_ora_12291.trc
Session altered.
old 1: select * from t where &1.
new 1: select * from t where id2=99
Execution Plan
----------------------------------------------------------
Plan hash value: 1601196873
--------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
--------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 583 | 3498 | 24 (9)| 00:00:01 |
|* 1 | TABLE ACCESS FULL| T | 583 | 3498 | 24 (9)| 00:00:01 |
--------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
1 - filter("ID2"=99)
Disconnected from Oracle Database 10g Enterprise Edition Release 10.2.0.1.0 - Production
With the Partitioning, OLAP and Data Mining options
Connected.
/home/ora10gr2/admin/ora10gr2/udump/ora10gr2_ora_12291.trc
Card: Original: 50087 Rounded: 583 Computed: 582.72 Non Adjusted: 582.72
Card: Original: 50087 Rounded: 583 Computed: 582.72 Non Adjusted: 582.72
ops$tkyte@ORA10GR2>
May 23, 2006 - 9am Central time zone
Reviewer: A reader
Great explanation! Thanks a lot Tom.
How are ROUNDED CDN and CMPTD CDN calculated?
June 18, 2006 - 11am Central time zone
Reviewer: Rahul from NJ
Hi Tom,
We had a performance issue with some of our most frequently SQL following a recent patch (to
9.2.0.6 on HP-UX). Queries that had sub-second response times were taking minutes to run.
The patch was attempted and rolled back (twice). Consistent behavior as described below both times.
I have a 10053 trace files for the query, captured before and after the patch was rolled back. With
the patch in place, the 10053 trace does not even show the "good" plan/join order as being in
contention. One thing that stood out in the comparison were the ROUNDED CDN and CMPTD CDN in the
SINGLE TABLE ACCESS PATH section:
With patch in place (slow performing):
TABLE: TACTOSR ORIG CDN: 15167213 ROUNDED CDN: 379180 CMPTD CDN: 379180
With patch rolled back (behaves good):
TABLE: TACTOSR ORIG CDN: 15159550 ROUNDED CDN: 1 CMPTD CDN: 0
Stats were gathered before generating either trace (by using identical calls to DBMS_STATS). I am
assuming that the difference in ROUNDED and CMPTD CDN are different due to some differences in the
statistics. How are these calculated? Is there something I should look for in the trace
files/stats?
After reading your answer above, I checked the datatypes of the columns involved in the joins. I
did find one difference - a varchar(2) column equated to a varchar(3) column. But the patch was
already gone, so I couldn't verify that.
Another thing was without the patch, the plans are identical with or without binds. With the patch
in place the plan without binds is good, the plan with binds (very different) is bad. We do have
the single bucket histograms generated by 'FOR ALL COLUMNS SIZE 1'.
Apologize for the lack of test case. Haven't been able to simulate this with a simple test case
yet.
Followup June 18, 2006 - 12pm Central time zone:
have you opened your tar with support on this.
Insufficient data to say how THESE cardinalities were computed as it really depends on the query
itself.
Re: How are ROUNDED CDN and CMPTD CDN calculated?
June 18, 2006 - 12pm Central time zone
Reviewer: Rahul from NJ
Thanks Tom, you respond faster than our internal support ;).
Yes, a TAR was opened. The suggestion from support (as relayed by the DBAs) was "Create
Histograms". Now this issue was only found in Production (none of the test systems with Production
size data - reportedly with same patches) had this issue. And I thought it a bad idea to introduce
histograms in a Prod system without a full system test. So the patch was rolled back.
Sorry, I also made a mistake above. It should have read:
With patch rolled back (behaves good):
TABLE: TACTOSR ORIG CDN: 15167213 ROUNDED CDN: 379180 CMPTD CDN: 379180
With patch in place (slow performing):
TABLE: TACTOSR ORIG CDN: 15159550 ROUNDED CDN: 1 CMPTD CDN: 0
The complete section is:
SINGLE TABLE ACCESS PATH
Column: PRIMARY_IR Col#: 8 Table: TACTOSR Alias: SYS_ALIAS_4
NDV: 2 NULLS: 0 DENS: 5.0000e-01
NO HISTOGRAM: # BKT: 1 #VAL: 2
TABLE: TACTOSR ORIG CDN: 15167213 ROUNDED CDN: 379180 CMPTD CDN: 379180
I am kicking myself for not figuring this out before rolling back the patch. But then, this was the
first time I waded throught the 10053 trace :). I now think checking the column stats for the
PRIMARY_IR would have helped.
Transitory values
June 19, 2006 - 8pm Central time zone
Reviewer: Gary from Sydney, Aus
"With patch rolled back (behaves good):
TABLE: TACTOSR ORIG CDN: 15167213 ROUNDED CDN: 379180"
Suggests it will return about 1 fifth of the table, and probably that there were five distinct
values in the column.
But the stats
"Column: PRIMARY_IR Table: TACTOSR NDV: 2 NULLS: 0"
indicates only two distinct values.
Perhaps the the predicate is matching one of the 'missing' three values which is above the high
value, or below the low value, that are currently recorded for the column.
Perhaps those missing values are transitory (eg In progress against Accepted/Declined) and/or so
few that they are being missed in an ESTIMATE
Re: Transitory values
June 20, 2006 - 10am Central time zone
Reviewer: Rahul from NJ
Thanks Gary.
Here are the column data. The column always has one of these 2 values.
select count(*), primary_ir
from tactosr
group by primary_ir
/
COUNT(*) PRIMARY_IR
-------------------------------------- ----------
6825288 0
8346837 1
I should have posted the query earlier. Here it is:
SELECT /*+ cardinality (pac 1000) */
am.ac_sys_nr,
am.inf_src_typ_cd,
am.svc_pvr_pyr_nr,
am.sls_pln_ver_typ_cd,
am.pend_trn_nr,
am.sls_grp_cd,
am.sales_vew_cd,
am.primary_ir,
am.scv_cps_rul_typ_cd,
am.int_comp_nr,
am.pend_sts_cd,
am.sls_pfl_ver_syc_ir,
'X' AA,--:b3
'X' BB,--:b3
'2' CC,
DECODE (am.pend_sts_cd, 'E', 'PE', 'I', 'PP', 'PO') DD,
'' EE,
'' FF
FROM tsrtosr ss,
tactosr am,
ptemp_acctdata pac
WHERE pac.trs_nr = :v2
AND pac.to_primary_ir = 'P'
AND am.ac_sys_nr = pac.ac_sys_nr
AND am.sls_pln_ver_typ_cd = :v1
AND am.primary_ir = '1'
AND ss.inf_src_typ_cd = am.inf_src_typ_cd
AND ss.sls_pln_ver_typ_cd = am.sls_pln_ver_typ_cd
AND ss.svc_pvr_pyr_nr = am.svc_pvr_pyr_nr
AND ss.object_typ_cd = 'SRS'
AND ( am.inf_src_typ_cd <> NVL (pac.frm_inf_src_typ_cd, '-1')
OR am.svc_pvr_pyr_nr <> NVL (pac.frm_svc_pvr_pyr_nr, '-1')
)
AND (am.ac_sys_nr,
am.svc_pvr_pyr_nr,
am.inf_src_typ_cd,
am.sls_pln_ver_typ_cd
) NOT IN (
SELECT gam.ac_sys_nr,
gam.svc_pvr_pyr_nr,
gam.inf_src_typ_cd,
gam.sls_pln_ver_typ_cd
FROM gtemp_actosr gam)
Suggests it will return about 1 fifth of the table
It is actually 1/40th, which suggests that it is the 0.25% rule for bind variables. What is funny
is that I don't have a bind variable equated to the PRIMARY_IR column at all in the above query.
Index not being used
August 1, 2006 - 3am Central time zone
Reviewer: atul from India
Hi,
Below is the 10053 trace, Could you please help us identifying why index is not being used.
***************************************
BASE STATISTICAL INFORMATION
***********************
Table stats Table: ORDER_LINE Alias: ORDER_LINE
TOTAL :: CDN: 13773190 NBLKS: 384934 AVG_ROW_LEN: 404
Column: ORDER_KEY Col#: 42 Table: ORDER_LINE Alias: ORDER_LINE
NDV: 1258261 NULLS: 0 DENS: 7.9475e-07 LO: 12 HI: 2877574
NO HISTOGRAM: KT: 1 #VAL: 2
-- Index stats
INDEX NAME: ORDER_LINE_F1 COL#: 91
TOTAL :: LVLS: 0 #LB: 0 #DK: 0 LB/K: 0 DB/K: 0 CLUF: 0
INDEX NAME: ORDER_LINE_F12 COL#: 1 50
TOTAL :: LVLS: 2 #LB: 18670 #DK: 13812080 LB/K: 1 DB/K: 1 CLUF: 723440
INDEX NAME: ORDER_LINE_F2 COL#: 30
TOTAL :: LVLS: 2 #LB: 14475 #DK: 406579 LB/K: 1 DB/K: 6 CLUF: 2444230
INDEX NAME: ORDER_LINE_F3 COL#: 29
TOTAL :: LVLS: 2 #LB: 15770 #DK: 863292 LB/K: 1 DB/K: 3 CLUF: 2750385
INDEX NAME: ORDER_LINE_F4 COL#: 82
TOTAL :: LVLS: 2 #LB: 8330 #DK: 196096 LB/K: 1 DB/K: 7 CLUF: 1530405
INDEX NAME: ORDER_LINE_F5 COL#: 26
TOTAL :: LVLS: 2 #LB: 10840 #DK: 218149 LB/K: 1 DB/K: 8 CLUF: 1854825
INDEX NAME: ORDER_LINE_F6 COL#: 25
TOTAL :: LVLS: 2 #LB: 8930 #DK: 71397 LB/K: 1 DB/K: 26 CLUF: 1866320
INDEX NAME: ORDER_LINE_F7 COL#: 67
TOTAL :: LVLS: 2 #LB: 5875 #DK: 1393 LB/K: 4 DB/K: 844 CLUF: 1175730
INDEX NAME: ORDER_LINE_F8 COL#: 66
TOTAL :: LVLS: 2 #LB: 5875 #DK: 1482 LB/K: 3 DB/K: 893 CLUF: 1323580
INDEX NAME: ORDER_LINE_F9 COL#: 98
TOTAL :: LVLS: 2 #LB: 14475 #DK: 112115 LB/K: 1 DB/K: 21 CLUF: 2382320
INDEX NAME: ORDER_LINE_SMID COL#: 94
TOTAL :: LVLS: 2 #LB: 13550 #DK: 3 LB/K: 4516 DB/K: 124581 CLUF: 373745
INDEX NAME: ORDER_LINE_SSID COL#: 92
TOTAL :: LVLS: 2 #LB: 14095 #DK: 2 LB/K: 7047 DB/K: 195312 CLUF: 390625
INDEX NAME: XBTORDLN_BKORD_PARTIAL_DATE COL#: 33
TOTAL :: LVLS: 0 #LB: 1 #DK: 8 LB/K: 1 DB/K: 1 CLUF: 8
INDEX NAME: XBTORDLN_BKORD_RELS_DATE COL#: 32
TOTAL :: LVLS: 1 #LB: 105 #DK: 10536 LB/K: 1 DB/K: 1 CLUF: 18516
INDEX NAME: XBTORDLN_BKORD_SHPCONFIRM_DATE COL#: 36
TOTAL :: LVLS: 1 #LB: 24 #DK: 3775 LB/K: 1 DB/K: 1 CLUF: 3794
TOTAL :: LVLS: 2 #LB: 14095 #DK: 2 LB/K: 7047 DB/K: 195312 CLUF: 390625
INDEX NAME: XBTORDLN_BKORD_PARTIAL_DATE COL#: 33
TOTAL :: LVLS: 0 #LB: 1 #DK: 8 LB/K: 1 DB/K: 1 CLUF: 8
INDEX NAME: XBTORDLN_BKORD_RELS_DATE COL#: 32
TOTAL :: LVLS: 1 #LB: 105 #DK: 10536 LB/K: 1 DB/K: 1 CLUF: 18516
INDEX NAME: XBTORDLN_BKORD_SHPCONFIRM_DATE COL#: 36
TOTAL :: LVLS: 1 #LB: 24 #DK: 3775 LB/K: 1 DB/K: 1 CLUF: 3794
INDEX NAME: XBTORDLN_BKORD_SHPPARTIAL_DATE COL#: 37
TOTAL :: LVLS: 0 #LB: 1 #DK: 47 LB/K: 1 DB/K: 1 CLUF: 45
INDEX NAME: XBTORDLN_CANELLED_DATE COL#: 39
TOTAL :: LVLS: 2 #LB: 1639 #DK: 113010 LB/K: 1 DB/K: 1 CLUF: 214614
INDEX NAME: XBTORDLN_CLOSED_DATE COL#: 38
TOTAL :: LVLS: 2 #LB: 9480 #DK: 3568 LB/K: 2 DB/K: 290 CLUF: 1036010
INDEX NAME: XBTORDLN_HLD_DATE COL#: 13
TOTAL :: LVLS: 2 #LB: 4489 #DK: 229430 LB/K: 1 DB/K: 2 CLUF: 572581
INDEX NAME: XBTORDLN_HLD_LAST_UPDATE_DATE COL#: 19
TOTAL :: LVLS: 2 #LB: 4524 #DK: 224983 LB/K: 1 DB/K: 2 CLUF: 560600
INDEX NAME: XBTORDLN_HLD_RELS_DATE COL#: 17
TOTAL :: LVLS: 2 #LB: 4534 #DK: 104180 LB/K: 1 DB/K: 5 CLUF: 573855
INDEX NAME: XBTORDLN_LINE_ID COL#: 2
TOTAL :: LVLS: 2 #LB: 18055 #DK: 5226362 LB/K: 1 DB/K: 1 CLUF: 7797325
INDEX NAME: XBTORDLN_ORDER_KEY COL#: 42
TOTAL :: LVLS: 2 #LB: 15810 #DK: 464521 LB/K: 1 DB/K: 5 CLUF: 2782445
INDEX NAME: XBTORDLN_REQUEST_DATE COL#: 114
TOTAL :: LVLS: 2 #LB: 3375 #DK: 179407 LB/K: 1 DB/K: 4 CLUF: 856144
INDEX NAME: XPKORDER_LINE COL#: 1
TOTAL :: LVLS: 2 #LB: 15260 #DK: 13672230 LB/K: 1 DB/K: 1 CLUF: 696610
***********************
Table stats Table: ORDER_HEADER Alias: ORDER_HEADER
TOTAL :: CDN: 2274490 NBLKS: 78689 AVG_ROW_LEN: 479
Column: ORDER_KEY Col#: 1 Table: ORDER_HEADER Alias: ORDER_HEADER
NDV: 2274490 NULLS: 0 DENS: 4.3966e-07 LO: 15 HI: 2877569
NO HISTOGRAM: KT: 1 #VAL: 2
Column: ORDER_KEY Col#: 1 Table: ORDER_HEADER Alias: ORDER_HEADER
NDV: 2274490 NULLS: 0 DENS: 4.3966e-07 LO: 15 HI: 2877569
NO HISTOGRAM: KT: 1 #VAL: 2
-- Index stats
INDEX NAME: ORDER_HEADER_F1 COL#: 50
TOTAL :: LVLS: 2 #LB: 2576 #DK: 778935 LB/K: 1 DB/K: 1 CLUF: 1446634
INDEX NAME: ORDER_HEADER_F2 COL#: 48
TOTAL :: LVLS: 2 #LB: 2729 #DK: 135158 LB/K: 1 DB/K: 4 CLUF: 565740
INDEX NAME: ORDER_HEADER_SMID COL#: 92
TOTAL :: LVLS: 2 #LB: 2200 #DK: 3 LB/K: 733 DB/K: 27274 CLUF: 81824
INDEX NAME: ORDER_HEADER_SSID COL#: 90
TOTAL :: LVLS: 2 #LB: 2209 #DK: 3 LB/K: 736 DB/K: 27536 CLUF: 82609
INDEX NAME: XBTORDHDR_BAF_ORAN_ID COL#: 101
TOTAL :: LVLS: 1 #LB: 57 #DK: 13364 LB/K: 1 DB/K: 1 CLUF: 25575
INDEX NAME: XBTORDHDR_CANCELLED_DATE COL#: 54
TOTAL :: LVLS: 1 #LB: 329 #DK: 210331 LB/K: 1 DB/K: 1 CLUF: 197980
INDEX NAME: XBTORDHDR_CLOSED_DATE COL#: 55
TOTAL :: LVLS: 2 #LB: 1843 #DK: 4847 LB/K: 1 DB/K: 74 CLUF: 361914
INDEX NAME: XBTORDHDR_ENTERED_DATE COL#: 49
TOTAL :: LVLS: 2 #LB: 2907 #DK: 911711 LB/K: 1 DB/K: 1 CLUF: 1113901
INDEX NAME: XBTORDHDR_HLD_DATE COL#: 16
TOTAL :: LVLS: 1 #LB: 21 #DK: 16161 LB/K: 1 DB/K: 1 CLUF: 14168
INDEX NAME: XBTORDHDR_HLD_RELS_DATE COL#: 22
TOTAL :: LVLS: 2 #LB: 1313 #DK: 604871 LB/K: 1 DB/K: 1 CLUF: 590878
INDEX NAME: XBTORDHDR_ORDER_ID COL#: 2
TOTAL :: LVLS: 2 #LB: 2759 #DK: 1144572 LB/K: 1 DB/K: 1 CLUF: 1422420
INDEX NAME: XBTORDHDR_ORD_NO COL#: 3
TOTAL :: LVLS: 2 #LB: 2705 #DK: 2287793 LB/K: 1 DB/K: 1 CLUF: 813751
INDEX NAME: XBTORDHDR_PO_NO COL#: 34
TOTAL :: LVLS: 2 #LB: 3328 #DK: 695393 LB/K: 1 DB/K: 2 CLUF: 1659465
INDEX NAME: XBTORDHDR_SALES_CONTRACT_NO COL#: 99
TOTAL :: LVLS: 1 #LB: 160 #DK: 4254 LB/K: 1 DB/K: 8 CLUF: 37052
INDEX NAME: XBTORDHDR_SALES_LIC_PROG_NAME COL#: 100
Table stats Table: STG_SERVICE_CONTRACT_LINE Alias: STG_SERVICE_CONTRACT_LINE
TOTAL :: CDN: 220488 NBLKS: 2619 AVG_ROW_LEN: 166
_OPTIMIZER_PERCENT_PARALLEL = 0
***************************************
SINGLE TABLE ACCESS PATH
TABLE: STG_SERVICE_CONTRACT_LINE ORIG CDN: 220488 ROUNDED CDN: 220488 CMPTD CDN: 220488
Access path: tsc Resc: 252 Resp: 252
BEST_CST: 252.00 PATH: 2 Degree: 1
***************************************
SINGLE TABLE ACCESS PATH
Column: SOURCE_SYS Col#: 90 Table: ORDER_HEADER Alias: ORDER_HEADER
NDV: 2 NULLS: 0 DENS: 5.0000e-01 LO: 1 HI: 5
NO HISTOGRAM: KT: 1 #VAL: 2
Column: SOURCE_MOD Col#: 92 Table: ORDER_HEADER Alias: ORDER_HEADER
NDV: 3 NULLS: 0 DENS: 3.3333e-01 LO: 1 HI: 3
NO HISTOGRAM: KT: 1 #VAL: 2
TABLE: ORDER_HEADER ORIG CDN: 2274490 ROUNDED CDN: 379082 CMPTD CDN: 379082
Access path: tsc Resc: 7568 Resp: 7568
Access path: index (equal)
Index: ORDER_HEADER_SMID
TABLE: ORDER_HEADER
RSC_CPU: 0 RSC_IO: 28011
IX_SEL: 0.0000e+00 TB_SEL: 3.3333e-01
Access path: index (equal)
Index: ORDER_HEADER_SSID
TABLE: ORDER_HEADER
RSC_CPU: 0 RSC_IO: 42412
IX_SEL: 0.0000e+00 TB_SEL: 5.0000e-01
Access path: and-equal
RSC_CPU 0 RSC_IO: 80055
Access path: index (equal)
Index: ORDER_HEADER_SMID
TABLE: ORDER_HEADER
RSC_CPU: 0 RSC_IO: 736
IX_SEL: 3.3333e-01 TB_SEL: 3.3333e-01
Access path: index (equal)
Index: ORDER_HEADER_SSID
TABLE: ORDER_HEADER
RSC_CPU: 0 RSC_IO: 1107
IX_SEL: 5.0000e-01 TB_SEL: 5.0000e-01
******** Bitmap access path rejected ********
Cost: 33964 Cost_io: 33964 Cost_cpu: 0 Selectivity: 0
Not believed to be index-only.
Access path: index (no sta/stp keys)
Index: XBTORDHDR_ORDER_ID
TABLE: ORDER_HEADER
RSC_CPU: 0 RSC_IO: 2761
IX_SEL: 1.0000e+00 TB_SEL: 1.0000e+00
Access path: index (no sta/stp keys)
Index: XBTORDHDR_ORD_NO
TABLE: ORDER_HEADER
RSC_CPU: 0 RSC_IO: 2707
IX_SEL: 1.0000e+00 TB_SEL: 1.0000e+00
Access path: index (no sta/stp keys)
Index: XPKORDER_HEADER
TABLE: ORDER_HEADER
RSC_CPU: 0 RSC_IO: 2506
IX_SEL: 1.0000e+00 TB_SEL: 1.0000e+00
******** Cost index join ********
Ix HA Join
Outer table:
resc: 920 cdn: 758163 rcz: 13 deg: 1 resp: 920
Inner table: <no name>
resc: 1384 cdn: 1137245 rcz: 13 deg: 1 resp: 1384
using join:8 distribution:2 #groups:1
Hash join one ptn Resc: 358 Deg: 1
hash_area: 1280 (max=1280) buildfrag: 1281 probefrag: 1736 ppasses: 2
Hash join Resc: 2662 Resp: 2662
Ix HA Join
Outer table:
resc: 920 cdn: 379082 rcz: 26 deg: 1 resp: 920
Inner table: <no name>
resc: 3451 cdn: 2274490 rcz: 17 deg: 1 resp: 3451
using join:8 distribution:2 #groups:1
Hash join one ptn Resc: 561 Deg: 1
hash_area: 1280 (max=1280) buildfrag: 1281 probefrag: 4026 ppasses: 2
Hash join Resc: 4932 Resp: 4932
Ix HA Join
Outer table:
resc: 920 cdn: 189541 rcz: 43 deg: 1 resp: 920
Inner table: <no name>
resc: 3384 cdn: 2274490 rcz: 17 deg: 1 resp: 3384
using join:8 distribution:2 #groups:1
Hash join one ptn Resc: 406 Deg: 1
hash_area: 1280 (max=1280) buildfrag: 1281 probefrag: 4026 ppasses: 2
Hash join Resc: 4710 Resp: 4710
Ix HA Join
Outer table:
resc: 920 cdn: 94771 rcz: 60 deg: 1 resp: 920
Inner table: <no name>
resc: 3132 cdn: 2274490 rcz: 16 deg: 1 resp: 3132
using join:8 distribution:2 #groups:1
Hash join one ptn Resc: 258 Deg: 1
hash_area: 1280 (max=1280) buildfrag: 1281 probefrag: 3888 ppasses: 2
Hash join Resc: 4310 Resp: 4310
******** Index join cost ********
Cost: 16616
BEST_CST: 7568.00 PATH: 2 Degree: 1
***************************************
SINGLE TABLE ACCESS PATH
SM Join
Outer table:
resc: 252 cdn: 220488 rcz: 40 deg: 1 resp: 252
Inner table: ORDER_LINE
resc: 37021 cdn: 1259876 rcz: 40 deg: 1 resp: 37021
using join:1 distribution:2 #groups:1
SORT resource Sort statistics
Sort width: 144 Area size: 7077888 Max Area size: 7077888 Degree: 1
Blocks to Sort: 728 Row size: 54 Rows: 220488
Initial runs: 2 Merge passes: 1 IO Cost / pass: 812
Total IO sort cost: 770
Total CPU sort cost: 0
Total Temp space used: 21283000
SORT resource Sort statistics
Sort width: 144 Area size: 7077888 Max Area size: 7077888 Degree: 1
Blocks to Sort: 4159 Row size: 54 Rows: 1259876
Initial runs: 10 Merge passes: 1 IO Cost / pass: 4565
Total IO sort cost: 4362
Total CPU sort cost: 0
Total Temp space used: 151798000
Merge join Cost: 42405 Resp: 42405
HA Join
Outer table:
resc: 252 cdn: 220488 rcz: 40 deg: 1 resp: 252
Inner table: ORDER_LINE
resc: 37021 cdn: 1259876 rcz: 40 deg: 1 resp: 37021
using join:8 distribution:2 #groups:1
Hash join one ptn Resc: 443 Deg: 1
hash_area: 1280 (max=1280) buildfrag: 1281 probefrag: 3999 ppasses: 2
Hash join Resc: 37716 Resp: 37716
Join result: cost: 37716 cdn: 223705 rcz: 80
Now joining: ORDER_HEADER[ORDER_HEADER]#1 *******
NL Join
Outer table: cost: 37716 cdn: 223705 rcz: 80 resp: 37716
Inner table: ORDER_HEADER
Access path: tsc Resc: 7568
Join: Resc: 1693037156 Resp: 1693037156
Access path: index (unique)
Index: XPKORDER_HEADER
TABLE: ORDER_HEADER
RSC_CPU: 0 RSC_IO: 2
IX_SEL: 4.3966e-07 TB_SEL: 4.3966e-07
Join: resc: 485126 resp: 485126
Access path: index (join stp)
Index: ORDER_HEADER_SMID
TABLE: ORDER_HEADER
RSC_CPU: 0 RSC_IO: 28010
IX_SEL: 0.0000e+00 TB_SEL: 3.3333e-01
Join: resc: 6266014766 resp: 6266014766
Access path: index (join stp)
Index: ORDER_HEADER_SSID
TABLE: ORDER_HEADER
RSC_CPU: 0 RSC_IO: 42411
IX_SEL: 0.0000e+00 TB_SEL: 5.0000e-01
Join: resc: 9487590471 resp: 9487590471
Access path: index (eq-unique)
Index: XPKORDER_HEADER
TABLE: ORDER_HEADER
RSC_CPU: 0 RSC_IO: 2
IX_SEL: 0.0000e+00 TB_SEL: 0.0000e+00
Join: resc: 485126 resp: 485126
Access path: and-equal
RSC_CPU 0 RSC_IO: 80053
Join: resc: 17908294081 resp: 17908294081
Access path: index (join stp)
Index: ORDER_HEADER_SMID
TABLE: ORDER_HEADER
RSC_CPU: 0 RSC_IO: 735
:$
STAT #1 id=2 cnt=0 pid=1 pos=1 obj=0 op='UNION-ALL '
STAT #1 id=3 cnt=0 pid=2 pos=1 obj=0 op='HASH JOIN '
STAT #1 id=4 cnt=178745 pid=3 pos=1 obj=307367 op='TABLE ACCESS FULL ORDER_HEADER '
STAT #1 id=5 cnt=0 pid=3 pos=2 obj=0 op='HASH JOIN '
STAT #1 id=6 cnt=227905 pid=5 pos=1 obj=935481 op='TABLE ACCESS FULL STG_SERVICE_CONTRACT_LINE '
STAT #1 id=7 cnt=0 pid=5 pos=2 obj=307369 op='TABLE ACCESS FULL ORDER_LINE '
STAT #1 id=8 cnt=0 pid=2 pos=2 obj=0 op='HASH JOIN '
STAT #1 id=9 cnt=0 pid=8 pos=1 obj=0 op='HASH JOIN '
STAT #1 id=10 cnt=0 pid=9 pos=1 obj=935480 op='TABLE ACCESS FULL STG_SVC_SALES_CREDITS '
STAT #1 id=11 cnt=0 pid=9 pos=2 obj=307367 op='TABLE ACCESS FULL ORDER_HEADER '
STAT #1 id=12 cnt=0 pid=8 pos=2 obj=307369 op='TABLE ACCESS FULL ORDER_LINE '
QUERY
alter session set events '10053 trace name context off'
=====================
PARSING IN CURSOR #1 len=56 dep=0 uid=59 oct=42 lid=59 tim=7090154518375 hv=3619980294
ad='51f7aae0'
alter session set events '10053 trace name context off'
END OF STMT
PARSE #1:c=0,e=1208,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=4,tim=7090154518359
EXEC #1:c=0,e=246,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=7090154518946
~
Followup February 5, 2009 - 4pm Central time zone:
umm, no, but thanks for the really big bit of trace file (without any sort of explaination of what
we are looking at at all)
Great Article
February 2, 2007 - 7pm Central time zone
Reviewer: Tommy Petersen from Phillipsburg, NJ USA
Rarely have I found an article that could resolve my problems so fast.
Thank you for the clear explanation of how to read the SQL Trace report, and the explanation of why Explain Plan and the actual execution uses different paths helped me along too.
I have been working for 2 weeks on a single table query that does a tablescan although the where clause uses the primary key column.
It turns out the program uses a numeric column instead of a character column, but I don't have access to the code (vendor supplied) so I did not know that. After reading this article I was able to replicate the bad behavior of the application and make suggestions to how we resolve it.
Thank you very much.
IX_SEL and 'LIKE :bind'
October 15, 2007 - 10am Central time zone
Reviewer: Alex from Russia
Could you further clarify the meaning of IX_SEL parameter, and how it calculated when using 'LIKE :bind' on indexed column?
Please consider a script (10.1.0.5):
DROP TABLE test_tbl;
CREATE TABLE test_tbl (pk NUMBER, str VARCHAR2(10));
CREATE INDEX test_idx ON test_tbl(str);
BEGIN
dbms_stats.set_table_stats(
ownname => null,
tabname => 'TEST_TBL',
numrows => 174000,
numblks => 3000,
avgrlen => 120);
dbms_stats.set_column_stats(
ownname => null,
tabname => 'TEST_TBL',
colname => 'STR',
distcnt => 153000,
nullcnt => 130,
avgclen => 8);
dbms_stats.set_index_stats(
ownname => null,
indname => 'TEST_IDX',
numrows => 174000,
numlblks => 450,
numdist => 153000,
avglblk => 1,
avgdblk => 1,
clstfct => 84600,
indlevel => 1);
END;
/
ALTER SESSION SET EVENTS '10053 trace name context forever, level 1';
EXPLAIN PLAN FOR SELECT * FROM test_tbl t WHERE t.str LIKE :f1;
ALTER SESSION SET EVENTS '10053 trace name context OFF';
Trace file:
***************************************
BASE STATISTICAL INFORMATION
***********************
Table stats Table: TEST_TBL Alias: T
TOTAL :: CDN: 174000 NBLKS: 3000 AVG_ROW_LEN: 120
Index stats
Index: TEST_IDX COL#: 2
TOTAL :: LVLS: 1 #LB: 450 #DK: 153000 LB/K: 1 DB/K: 1 CLUF: 84600
_OPTIMIZER_PERCENT_PARALLEL = 0
***************************************
SINGLE TABLE ACCESS PATH
COLUMN: STR(VARCHAR2) Col#: 2 Table: TEST_TBL Alias: T
Size: 8 NDV: 153000 Nulls: 130 Density: 6.5359e-006 Min: 0 Max: 0
TABLE: TEST_TBL Alias: T
Original Card: 174000 Rounded: 8694 Computed: 8693.50 Non Adjusted: 8693.50
Access Path: table-scan Resc: 587 Resp: 587
Access Path: index (scan)
Index: TEST_IDX
rsc_cpu: 6041194 rsc_io: 767
ix_sel: 8.9933e-003 ix_sel_with_filters: 8.9933e-003
BEST_CST: 569.62 PATH: 4 Degree: 1
As you see, IX_SEL = 0.0089933, so we have a problem because of extremely low cost for index access path (1 + 0.0089933 * 450 + 0.0089933 * 84600 = 766).
But there are no column histograms, and no bind_peeking happened. Shouldn't IX_SEL be equal to 0.05 for such a case? And HOW the value of 0.0089933 was calculated in fact?
Thank you.
Followup October 15, 2007 - 12pm Central time zone:
well, it is not clear to me why "we have a problem".
Re: IX_SEL and 'LIKE :bind'
October 16, 2007 - 2am Central time zone
Reviewer: Alex from Russia
Well, the problem is that we expect IX_SEL will be 8694/174000=0.05 but in fact IX_SEL = 0.0089933.
Please clarify how Oracle calculates the value of IX_SEL when we use 'LIKE :bind' on indexed column without histograms.
It will be very useful information for those who try to tune similar queries.
Thank you for quick response.
trace file not showing up
February 5, 2009 - 2pm Central time zone
Reviewer: A reader from Concord, CA USA
Database version: Oracle Database 10g Enterprise Edition Release 10.2.0.3.0 - 64bit Production
Windows 2003
The trace files just don't show up when I do a 10053 trace, but work fine when I do a 10046 trace.
Is there anything that I need to set? I've done this in other databases, and the trace files were
created. I don't know if support can help, because I don't think Oracle supports 10053 trace.
The syntax I'm using is:
ALTER SESSION SET EVENTS '10053 TRACE NAME CONTEXT FOREVER, LEVEL 1';
Followup February 5, 2009 - 2pm Central time zone:
on the server, log into sqlplus
run this script (fix the trace name if that doesn't match your format please):
column trace new_val TRACE
select c.value || '\' || d.instance_name || '_ora_' || a.spid || '.trc' trace
from v$process a, v$session b, v$parameter c, v$instance d
where a.addr = b.paddr
and b.audsid = userenv('sessionid')
and c.name = 'user_dump_dest'
/
alter session set events '10053 trace name context forever, level 1';
select /*+ first_rows */ * from dual;
host dir &TRACE
and cut and paste the results. A 10053 trace will be created
o upon a HARD parse
o of a cost based query
Working now
February 5, 2009 - 3pm Central time zone
Reviewer: A reader
Thank you. That worked. Hard parse was the key. The query I was running was cached.
10053 and hard parse
February 6, 2009 - 4am Central time zone
Reviewer: Narendra from UK
Hello Tom,
You said
A 10053 trace will be created
o upon a HARD parse
o of a cost based query
But won't the command to start the trace 'alter session' cause the query to hard parse ? I remember reading about the so-called magic that happens due to bind-peeking, with 10046 trace. Isn't the behaviour same for 10053 trace ?
Followup February 6, 2009 - 3pm Central time zone:
it is not the same
|
|
|
|
|
|