very good explaination
Jagjeet Singh, May 08, 2006 - 9:14 am UTC
Try Jonathan Lewis' latest book, too
Doug Burns, May 08, 2006 - 9:39 am UTC
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
Bauer Wolfgang, May 08, 2006 - 9:41 am UTC
Jonathan Lewis has also a own chapter about the 10053 trace file in his new book "Cost based".
Amiel D., May 09, 2006 - 11:22 am UTC
Think you. It was just the explanation I needed.
Amiel
what is rounded cardinality in 10053 trace file?
A reader, May 22, 2006 - 4:02 pm UTC
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.
May 22, 2006 - 4:13 pm UTC
it is not way off, it is "perfect"
table (orig) cardinality is 1,833,857
rounded (estimated) cardinality is 1
which is precisely correct.
A reader, May 22, 2006 - 5:13 pm UTC
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!
May 23, 2006 - 6:50 am UTC
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.
A reader, May 22, 2006 - 6:48 pm UTC
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?
May 23, 2006 - 7:19 am UTC
... 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 - <b>note how the autotrace estimate is the "rounded card" - it is the GUESS, the estimated cardinality flowing out of the step</b>
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>
A reader, May 23, 2006 - 9:14 am UTC
Great explanation! Thanks a lot Tom.
How are ROUNDED CDN and CMPTD CDN calculated?
Rahul, June 18, 2006 - 11:59 am UTC
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.
June 18, 2006 - 12:21 pm UTC
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?
Rahul, June 18, 2006 - 12:41 pm UTC
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
Gary, June 19, 2006 - 8:41 pm UTC
"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
Rahul, June 20, 2006 - 10:36 am UTC
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
atul, August 01, 2006 - 3:48 am UTC
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: #BKT: 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: #BKT: 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: #BKT: 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: #BKT: 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: #BKT: 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
~
February 05, 2009 - 4:09 pm UTC
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
Tommy Petersen, February 02, 2007 - 7:10 pm UTC
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'
Alex, October 15, 2007 - 10:33 am UTC
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.
October 15, 2007 - 12:33 pm UTC
well, it is not clear to me why "we have a problem".
Re: IX_SEL and 'LIKE :bind'
Alex, October 16, 2007 - 2:44 am UTC
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
A reader, February 05, 2009 - 2:42 pm UTC
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';
February 05, 2009 - 2:55 pm UTC
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
A reader, February 05, 2009 - 3:14 pm UTC
Thank you. That worked. Hard parse was the key. The query I was running was cached.
10053 and hard parse
Narendra, February 06, 2009 - 4:26 am UTC
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 ?
February 06, 2009 - 3:32 pm UTC
it is not the same
Index access path not considered...
Ye, April 20, 2010 - 7:34 am UTC
Hi Tom
Great article. I was trying to figure out why index access path is not considered in a particular case. I read through your example where two tables vary by one column (with different data types). But in my case, the two tables are same (i actually used create table as ...)
Here is my issue
I have one table big_table which is essentially created off dba_objects, and then I added a column id (number) and populated the id column and created an index
CREATE TABLE BIG_TABLE
(
OWNER VARCHAR2(30 BYTE) NOT NULL,
OBJECT_NAME VARCHAR2(30 BYTE) NOT NULL,
SUBOBJECT_NAME VARCHAR2(30 BYTE),
OBJECT_ID NUMBER NOT NULL,
DATA_OBJECT_ID NUMBER,
OBJECT_TYPE VARCHAR2(19 BYTE),
CREATED DATE NOT NULL,
LAST_DDL_TIME DATE NOT NULL,
TIMESTAMP VARCHAR2(19 BYTE),
STATUS VARCHAR2(7 BYTE),
TEMPORARY VARCHAR2(1 BYTE),
GENERATED VARCHAR2(1 BYTE),
SECONDARY VARCHAR2(1 BYTE),
ID NUMBER
)
CREATE INDEX IDX_BIG_R1 ON BIG_TABLE
(ID)
i have done the stats gathering and when I do
select * from big_table where id between 1 and 2;
----------------------------------------------------------
Plan hash value: 3993303771
-------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
-------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | 87 | 42 (0)| 00:00:01 |
|* 1 | TABLE ACCESS FULL| BIG_TABLE | 1 | 87 | 42 (0)| 00:00:01 |
-------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
1 - filter("ID"<=2 AND "ID">=1)
I later created a BIG_TABLE2 using
create table big_table2 as select * from big_table;
create index idx_big2_r1 on big_table2(id);
----------------------------------------------------------
Plan hash value: 4214139963
--------------------------------------------------------------------------------
-----------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)|
Time |
--------------------------------------------------------------------------------
-----------
| 0 | SELECT STATEMENT | | 2 | 174 | 1 (0)|
00:00:01 |
| 1 | TABLE ACCESS BY INDEX ROWID| BIG_TABLE2 | 2 | 174 | 1 (0)|
00:00:01 |
|* 2 | INDEX RANGE SCAN | IDX_BIG2_R1 | 2 | | 1 (0)|
00:00:01 |
--------------------------------------------------------------------------------
-----------
Predicate Information (identified by operation id):
---------------------------------------------------
2 - access("ID">=1 AND "ID"<=2)
and this is using index. the 10053 trace shows that for big_table, index is not even considered in the access path:
***************************************
BASE STATISTICAL INFORMATION
***********************
Table Stats::
Table: BIG_TABLE Alias: BIG_TABLE
#Rows: 13413 #Blks: 186 AvgRowLen: 87.00
Index Stats::
Index: IDX_BIG_R1 Col#: 14
LVLS: 1 #LB: 29 #DK: 13413 LB/K: 1.00 DB/K: 1.00 CLUF: 13411.00
Index: IDX_BIG_R2 Col#: 2
LVLS: 1 #LB: 55 #DK: 3531 LB/K: 1.00 DB/K: 3.00 CLUF: 10693.00
***************************************
SINGLE TABLE ACCESS PATH
Column (#14): ID(NUMBER)
AvgLen: 5.00 NDV: 13413 Nulls: 0 Density: 7.4555e-005 Min: 1 Max: 13413
Table: BIG_TABLE Alias: BIG_TABLE
Card: Original: 13413 Rounded: 2 Computed: 2.00 Non Adjusted: 2.00
Access Path: TableScan
Cost: 42.41 Resp: 42.41 Degree: 0
Cost_io: 42.00 Cost_cpu: 7494668
Resp_io: 42.00 Resp_cpu: 7494668
Best:: AccessPath: TableScan
Cost: 42.41 Degree: 1 Resp: 42.41 Card: 2.00 Bytes: 0
while for BIG_TABLE2, the index is considered
***************************************
BASE STATISTICAL INFORMATION
***********************
Table Stats::
Table: BIG_TABLE2 Alias: BIG_TABLE2
#Rows: 13413 #Blks: 188 AvgRowLen: 87.00
Index Stats::
Index: IDX_BIG2_R1 Col#: 14
LVLS: 1 #LB: 29 #DK: 13413 LB/K: 1.00 DB/K: 1.00 CLUF: 176.00
***************************************
SINGLE TABLE ACCESS PATH
Column (#14): ID(NUMBER)
AvgLen: 5.00 NDV: 13413 Nulls: 0 Density: 7.4555e-005 Min: 1 Max: 13413
Table: BIG_TABLE2 Alias: BIG_TABLE2
Card: Original: 13413 Rounded: 2 Computed: 2.00 Non Adjusted: 2.00
Access Path: TableScan
Cost: 43.41 Resp: 43.41 Degree: 0
Cost_io: 43.00 Cost_cpu: 7508911
Resp_io: 43.00 Resp_cpu: 7508911
Access Path: index (RangeScan)
Index: IDX_BIG2_R1
resc_io: 3.00 resc_cpu: 23194
ix_sel: 1.4911e-004 ix_sel_with_filters: 1.4911e-004
Cost: 3.00 Resp: 3.00 Degree: 1
Best:: AccessPath: IndexRange Index: IDX_BIG2_R1
Cost: 3.00 Degree: 1 Resp: 3.00 Card: 2.00 Bytes: 0
I am on 10.2.0.1.0... Could you shed some light on this?
Thanks a lot
April 20, 2010 - 8:52 am UTC
show all of the work, from start to finish please. the create, the load, the gather (most important), the query running and the TKPROF or dbms_xplan.display_cursor output, not explain plan.
something like this:
ops$tkyte%ORA10GR2> drop table big_table;
Table dropped.
ops$tkyte%ORA10GR2>
ops$tkyte%ORA10GR2> CREATE TABLE BIG_TABLE
2 as
3 select * from dba_objects;
Table created.
ops$tkyte%ORA10GR2>
ops$tkyte%ORA10GR2> alter table big_table add id number;
Table altered.
ops$tkyte%ORA10GR2>
ops$tkyte%ORA10GR2> update big_table set id = rownum;
50551 rows updated.
ops$tkyte%ORA10GR2>
ops$tkyte%ORA10GR2> create index idx_big_r1 on big_table(id);
Index created.
ops$tkyte%ORA10GR2>
ops$tkyte%ORA10GR2> exec dbms_stats.gather_table_stats( user, 'BIG_TABLE' );
PL/SQL procedure successfully completed.
ops$tkyte%ORA10GR2>
ops$tkyte%ORA10GR2> set serveroutput off
ops$tkyte%ORA10GR2> select * from big_table where id between 1 and 2;
OWNER OBJECT_NAME SUBOBJECT_NAME OBJECT_ID DATA_OBJECT_ID OBJECT_TYPE CREATED LAST_DDL_ TIMESTAMP STATUS T G S ID
------------------------------ ------------------------------ ------------------------------ ---------- -------------- ------------------- --------- --------- ------------------- ------- - - - ----------
SYS ICOL$ 20 2 TABLE 30-JUN-05 30-JUN-05 2005-06-30:19:10:16 VALID N N N 1
SYS I_USER1 44 44 INDEX 30-JUN-05 30-JUN-05 2005-06-30:19:10:16 VALID N N N 2
ops$tkyte%ORA10GR2> select * from table(dbms_xplan.display_cursor);
PLAN_TABLE_OUTPUT
------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
SQL_ID 72142pmwrbdzd, child number 0
-------------------------------------
select * from big_table where id between 1 and 2
Plan hash value: 4016321129
------------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | | | 3 (100)| |
| 1 | TABLE ACCESS BY INDEX ROWID| BIG_TABLE | 1 | 98 | 3 (0)| 00:00:01 |
|* 2 | INDEX RANGE SCAN | IDX_BIG_R1 | 1 | | 2 (0)| 00:00:01 |
------------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
2 - access("ID">=1 AND "ID"<=2)
19 rows selected.
so we can reproduce your steps.
A reader, April 20, 2010 - 10:34 am UTC
Look like problem with clustering factor
Table Stats::
Table: BIG_TABLE Alias: BIG_TABLE
#Rows: 13413 lks: 186 AvgRowLen: 87.00
Index Stats::
Index: IDX_BIG_R1 Col#: 14
LVLS: 1 #LB: 29 #DK: 13413 LB/K: 1.00 DB/K: 1.00 CLUF: 13411.00
Index: IDX_BIG_R2 Col#: 2
LVLS: 1 #LB: 55 #DK: 3531 LB/K: 1.00 DB/K: 3.00 CLUF: 10693.00
Table Stats:: Table: BIG_TABLE2 Alias: BIG_TABLE2 #Rows: 13413 lks: 188 AvgRowLen: 87.00
Index Stats:: Index: IDX_BIG2_R1 Col#: 14 LVLS: 1 #LB: 29 #DK: 13413 LB/K: 1.00 DB/K: 1.00 CLUF: 176.00
April 20, 2010 - 10:52 am UTC
his point is - it was not considered, the clustering factor didn't come into play.
I suspect something else - and a full test case will help us determine that.
the clustering factors are near enough to each other to be both ok for a 1/2 row range scan. that wasn't it.
Mystery solved
Ye, April 21, 2010 - 3:50 am UTC
Hi Tom
Thanks for the quick response. The case was presented to me by a colleague and he did not remember how the original table BIG_TABLE and its index was created. We tried to reproduce the issue by creating a similiar table BIG_TABLE2 and its corresponding index (we even tried to randomize the ID value so the clustering factor becomes similar) and tried almost all means to make two tables same, and finally we found out the issue was that index IDX_BIG_R1 created on BIG_TABLE(ID) was a reverse index, that is why BETWEEN or <, > comparions do not use the index (while an EQ condition will use the index on BIG_TABLE). Took us quite some time since the scripts we reverse engineered from BIG_TABLE does not show the index was a reverse one.
Thanks
April 21, 2010 - 8:52 am UTC
:)
this is how I find 99.99999% of my issues myself.
I construct a concise test case to reproduce the issue. Works almost every time. And when you do - you get one of those "ah-hah" moments - when you discover the "rather obvious" cause yourself !
thanks for taking the time and thanks for following up!
IX_SEL varying when using bind
Lasse Jenssen, October 11, 2011 - 12:05 pm UTC
Hi Tom
I'm having a query which I trace (10053) executed both from Java and PL/SQL.
The table is range partitioned with the following main columns:
- PAYORADATE date (table is RANGE partition on this column)
- ACCOUNTNR varchar2(11)
There is several indexes on the table including these LOCAL indexes:
- BANK_LOCAL_IDX1 (ACCOUNTNR, -another column not queried- )
- BANK_LOCAL_IDX2 (PAYORADATE)
The query looks something like this:
<code>
variable c_code number
variable c_accountnr varchar2
variable c_date varchar2
exec :c_code:=9000;
exec :c_accountnr:='12345678901';
exec :c_date:='01.10.2011'; '
-- NLS_DATE_FORMAT = 'DD.MM.YYYY HH24:MI:SS'
select /* PL02 */ *
from BANK
where code= :c_code
and accountnr = :c_accountnr
and payoradate >= :c_date;
My java code would be:
...
PreparedStatement stmt = conn.prepareStatement(
"select /* JA02 */ *\n" +
"from BANK \n" +
"where code= ? \n" +
" and accountnr = ? \n" +
" and payoradate >= ? ");
stmt.setInt(1,9000);
stmt.setString(2, "12345678901");
stmt.setDate(3, Date.valueOf("2010-10-01"));
ResultSet r = stmt.executeQuery();
...
When I run from java (our application or my test program) the optimizer chooses to use the index BANK_LOCAL_IDX2. This is definitively not optimal. Then the query read a lot of buffers and then filtering on ACCOUNTNR and CODE. My PLSQL code chooses the index BANK_LOCAL_IDX1, and runs in a fraction of a second.
In my 10053 trace-files I find a difference in the following:
(Note! Everything else looks to be the same. The query is the same. The parameters are the same. It's the same database and the same data.)
Java trace:
-----------
Access path: index (scan)
Index: BANK_LOCAL_IDX2
TABLE: BANK
RSC_CPU: 0 RSC_IO: 263
IX_SEL: 2.3506e-06 TB_SEL: 2.3506e-06
PLSQL trace:
Access path: index (scan)
Index: BANK_LOCAL_IDX2
TABLE: BANK
RSC_CPU: 0 RSC_IO: 995124
IX_SEL: 9.0000e-03 TB_SEL: 9.0000e-03
How can the IX_SEL be different in these two cases?
The only difference in query being run from java or pl/sql.
Well ... another difference of course is that java maps the date value to a date datatype, and plsql does not. Is this whats causing this difference?</code>
October 11, 2011 - 12:47 pm UTC
can you verify the bind types being used - java can be funny that way. A simple sql_trace with binds would show the bind types being used.
Different dates
Jonathan Taylor, October 11, 2011 - 1:00 pm UTC
Apart from the VARCHAR2/DATE difference - the date is also different between the 2 versions (2010/2011).
October 11, 2011 - 2:00 pm UTC
good eye, great eye.
Yes, that would be the answer right there.
You get a 10053 trace only during a hard parse, so therefore it was hard parsed and bind peeking kicked in and there must be histograms - giving us the different metrics.
thanks - that was it.
RE: IX_SEL varying when using bind
Lasse Jenssen, October 12, 2011 - 5:45 am UTC
Hi again.
Nicely observed, BUT this was not the reason for my observations (This was a copy error from me). I checked my bind values and ran the test again (with new dummy comments to trigger hard parsing), and I see the same difference in IX_SEL values for BANK_LOCAL_IDX2.
I did a 10046 trace on both the PL/SQL and Java run and see the following in the BIND area:
PLSQL
-----------
PARSE #4:c=0,e=2742,p=0,cr=1,cu=0,mis=1,r=0,dep=0,og=0,tim=64071679263140
BINDS #4:
bind 0: dty=1 mxl=32(08) mal=00 scl=00 pre=00 oacflg=01 oacfl2=10 size=128 offset=0
bfp=1102fcae8 bln=32 avl=04 flg=05
value="9000"
bind 1: dty=1 mxl=32(22) mal=00 scl=00 pre=00 oacflg=01 oacfl2=10 size=0 offset=32
bfp=1102fcb08 bln=32 avl=11 flg=01
value="12345678901"
bind 2: dty=1 mxl=32(20) mal=00 scl=00 pre=00 oacflg=01 oacfl2=10 size=0 offset=64
bfp=1102fcb28 bln=32 avl=10 flg=01
value="01.10.2010"
JAVA:
---------
PARSE #2:c=10000,e=3108,p=0,cr=1,cu=0,mis=1,r=0,dep=0,og=0,tim=64071773507853
BINDS #2:
bind 0: dty=2 mxl=22(22) mal=00 scl=00 pre=00 oacflg=03 oacfl2=0 size=88 offset=0
bfp=1102f3a88 bln=22 avl=03 flg=05
value=9000
bind 1: dty=1 mxl=32(11) mal=00 scl=00 pre=00 oacflg=03 oacfl2=10 size=0 offset=24
bfp=1102f3aa0 bln=32 avl=11 flg=01
value="1234568901"
bind 2: dty=12 mxl=07(49) mal=00 scl=00 pre=00 oacflg=03 oacfl2=0 size=0 offset=56
bfp=1102f3ac0 bln=07 avl=07 flg=01
value="10/1/2010 0:0:0"
Hmmmm ... how should I interpret the different format on the date value? Both should be the same date.
Aha!!!! Your one comment solved it all - I think! Histograms!
There are histograms on these tables, AND from the beginning off 2010 the operation department started to copy statistics on new range partitions (from a STAT export from somewhere around the same time). If the optimizer interprets the dates differently "10.01.2010" and "01.10.2010" the stats could will definitly be different. "10.01.2010" could have lot's of "hits". If the statistics on partition containing data after "01.10.2010" is from copy of partition from late 2009 or early 2010 it could "guess" NO DATA at all. Must be it!?</code>
October 12, 2011 - 7:13 am UTC
Look at the bind types
dty is datatype,
plsql is binding a 1,1,,1 - string, string and string. (should have been NUMBER, string, DATE by the way.....)
java is binding 2, 1, 12 - NUMBER, string, DATE
so you are comparing apples and toaster ovens here in some respects. Be best to compare apples to apples.
RE: IX_SEL varying when using bind
Lasse Jenssen, October 12, 2011 - 8:31 am UTC
Yes you are perfectly right, that would be like comparing apples to toaster ovens.
1. Will binds in PL/SQL always be strings, or is this just because I use this syntax:
variable :c_code number
...
exec :c_code := 9000;
...
select * from BANK where code = :c_code and ...;
(Well this select does probably not run in the PLSQL engine, is this the reason for the bind datatype as string?)
2. If I change the java-code from "PAYORADATE >= ?" to "PAYORADATE >= to_date(?,'DD.MM.YYYY')" the bind datatype remains a date, but the execution plan totally changes. It stops to use the index on PAYORADATE, and instead use the index BANK_LOCAL_IDX1 (on ACCOUNTNR, -and other not referenced col-). How can the to_date make this difference?
October 12, 2011 - 10:21 am UTC
1) you didn't use plsql, that is why.
declare
c_code number := 9000;
c_accountnr varchar2(20) := '12345678901';
c_date date := to_date( '01.10.2011', 'dd.mm.yyyy' );
begin
for x in (
select /* PL02 */ *
from BANK
where code= c_code
and accountnr = c_accountnr
and payoradate >= c_date ) loop null; end loop;
end;
/
would do it.
2) it knows how to convert the bind at parse time and would peek at the bound value and use it.
RE: IX_SEL varying when using bind
Lasse Jenssen, October 13, 2011 - 1:39 pm UTC
Thanks again ...
But when it peeks it hits the same values as before (My test uses the same values), and then I would expect the same plan).
October 14, 2011 - 11:04 pm UTC
you had different data types.
If you force a hard parse from java and from plsql using exactly the same bind types - what do you see.
10053 trace rounded cdn
Lasse Jenssen, November 04, 2011 - 4:09 pm UTC
Hi Tom
I'm having a table ACTIVEUSER with an column USERNAME varchar2(100). The colum can have NULL values, but there is none. The column does have only distinct values (but indexes is not unique).
The colum is found in two indexes:
<code>
create index idx1 on ACTIVEUSER(USERNAME);
create index idx2 on ACTIVEUSER(lower(USERNAME));
The table is having about 1 mil rows.
There is NO histograms, and no sql_baselines (Oracle 10.2.0.1). When I parse the following query i get a hash join with two table scans:
select au.a_col from userassessmentrun uar, activeuser au where au.id = uar.id and au.username = :b1;
If i run the following instead, i get an index range scan and a nested loop (as expected):
select /*+ gather_plan_statistics */ userassessmentrunid from userassessmentrun uar, activeuser au where au.userid = uar.userid and lower(au.username) = lower(:b1);
When i do a 10053 trace I see the following differences.
Without function:
SINGLE TABLE ACCESS PATH
Column (#7): USERNAME(VARCHAR2)
AvgLen: 43.00 NDV: 949914 Nulls: 0 Density: 0.016667
Table: ACTIVEUSER Alias: AU
Card: Original: 949914 Rounded: 15832 Computed: 15831.90 Non Adjusted: 15831.90
Access Path: TableScan
Cost: 2511.33 Resp: 2511.33 Degree: 0
Cost_io: 2491.00 Cost_cpu: 386288149
Resp_io: 2491.00 Resp_cpu: 386288149
Access Path: index (AllEqRange)
Index: AUSER_USERNAME_IDX
resc_io: 15793.00 resc_cpu: 121099502
ix_sel: 0.016667 ix_sel_with_filters: 0.016667
Cost: 15799.37 Resp: 15799.37 Degree: 1
******** Begin index join costing ********
****** trying bitmap/domain indexes ******
Access Path: index (AllEqRange)
Index: AUSER_USERNAME_IDX
resc_io: 163.00 resc_cpu: 4299195
ix_sel: 0.016667 ix_sel_with_filters: 0.016667
Cost: 163.23 Resp: 163.23 Degree: 0
Access Path: index (FullScan)
Index: ATIVEUSER_PK
resc_io: 4285.00 resc_cpu: 220498170
ix_sel: 1 ix_sel_with_filters: 1
Cost: 4296.60 Resp: 4296.60 Degree: 0
******** Cost index join ********
Index join: Considering index join to index AUSER_USERNAME_IDX
Index join: Joining index ATIVEUSER_PK
Ix HA Join
Outer table:
resc: 163.34 card 15831.90 bytes: 53 deg: 1 resp: 163.34
Inner table: <no name>
resc: 5370.76 card: 949914.00 bytes: 16 deg: 1 resp: 5370.76
using dmeth: 2 #groups: 1
Cost per ptn: 5.62 #ptns: 1
hash_area: 256 (max=192000) Hash join: Resc: 5539.72 Resp: 5539.72 [multiMatchCost=0.00]
******** Index join cost ********
Cost: 5539.72
******** End index join costing ********
Best:: AccessPath: TableScan
Cost: 2511.33 Degree: 1 Resp: 2511.33 Card: 15831.90 Bytes: 0
With function:
SINGLE TABLE ACCESS PATH
Column (#14): SYS_NC00014$(VARCHAR2)
AvgLen: 43.00 NDV: 948554 Nulls: 0 Density: 1.0542e-06
Table: ACTIVEUSER Alias: AU
Card: Original: 949914 Rounded: 1 Computed: 1.00 Non Adjusted: 1.00
Access Path: TableScan
Cost: 2521.26 Resp: 2521.26 Degree: 0
Cost_io: 2491.00 Cost_cpu: 575004469
Resp_io: 2491.00 Resp_cpu: 575004469
Access Path: index (AllEqRange)
Index: IDX_USERNAME_LOWER
resc_io: 5.00 resc_cpu: 36707
ix_sel: 1.0542e-06 ix_sel_with_filters: 1.0542e-06
Cost: 5.00 Resp: 5.00 Degree: 1
******** Begin index join costing ********
****** trying bitmap/domain indexes ******
Access Path: index (AllEqRange)
Index: IDX_USERNAME_LOWER
resc_io: 3.00 resc_cpu: 21764
ix_sel: 1.0542e-06 ix_sel_with_filters: 1.0542e-06
Cost: 3.00 Resp: 3.00 Degree: 0
Access Path: index (FullScan)
Index: ATIVEUSER_PK
resc_io: 4285.00 resc_cpu: 220498170
ix_sel: 1 ix_sel_with_filters: 1
Cost: 4296.60 Resp: 4296.60 Degree: 0
Access Path: index (FullScan)
Index: AUSER_USERNAME_IDX
resc_io: 9633.00 resc_cpu: 256894032
ix_sel: 1 ix_sel_with_filters: 1
Cost: 9646.52 Resp: 9646.52 Degree: 0
******** Cost index join ********
Index join: Considering index join to index ATIVEUSER_PK
Index join: Joining index AUSER_USERNAME_IDX
Ix HA Join
Outer table:
resc: 5370.76 card 949914.00 bytes: 16 deg: 1 resp: 5370.76
Inner table: <no name>
resc: 12058.15 card: 949914.00 bytes: 53 deg: 1 resp: 12058.15
using dmeth: 2 #groups: 1
Cost per ptn: 4196.33 #ptns: 1
hash_area: 256 (max=192000) Hash join: Resc: 21625.23 Resp: 21625.23 [multiMatchCost=0.00]
******** Index join cost ********
Cost: 21625.23
******** End index join costing ********
Best:: AccessPath: IndexRange Index: IDX_USERNAME_LOWER
Cost: 5.00 Degree: 1 Resp: 5.00 Card: 1.00 Bytes: 0
I don't understand where the differences in rounded cardinality could come from?
The index statistics are very alike:
INDEX_NAME LEAF_BLOCKS DISTINCT_KEYS CLUSTERING_FACTOR NUM_ROWS
------------------------------ ----------- ------------- ----------------- ----------
IDX_USERNAME_LOWER 11084 948554 971633 975560
AUSER_USERNAME_IDX 9631 941466 937745 941466
Could this be a bug, or am I missing something here?</code>
November 07, 2011 - 11:34 am UTC
the index selectivity of the 'plain' index is rather high:
ix_sel: 0.016667
that is the cause of the 'bad' estimated cardinality of 15-16k (multiply 1,000,000 by 0.16666 and you get 16,666 - that is where the estimate came from).
The selectivity of the function based index is very low - hence the small (correct) estimated cardinality.
If there a chance that the index stats are not representative of the data right now on that first index?
it would be useful to see a bit more of the 10053 trace - the table and index stats sections.
RE: 10053 rounded cdn
Lasse Jenssen, November 08, 2011 - 1:42 am UTC
Thx,
Here is table and index section:
<code>
***************************************
BASE STATISTICAL INFORMATION
***********************
Table Stats::
Table: ACTIVEUSER Alias: AU
#Rows: 949914 #Blks: 11381 AvgRowLen: 122.00
Column (#1): USERID(NUMBER)
AvgLen: 6.00 NDV: 949914 Nulls: 0 Density: 1.0527e-06 Min: 672632 Max: 7354410
Index Stats::
Index: ATIVEUSER_PK Col#: 1
LVLS: 2 #LB: 4283 #DK: 949914 LB/K: 1.00 DB/K: 1.00 CLUF: 796757.00
Index: AUSER_USERNAME_IDX Col#: 7
LVLS: 2 #LB: 9631 #DK: 941466 LB/K: 1.00 DB/K: 1.00 CLUF: 937745.00
Index: EMAIL_VERIFICATION Col#: 12
LVLS: 0 #LB: 0 #DK: 0 LB/K: 0.00 DB/K: 0.00 CLUF: 0.00
Index: IDX_USERNAME_LOWER Col#: 14
LVLS: 2 #LB: 11084 #DK: 948554 LB/K: 1.00 DB/K: 1.00 CLUF: 971633.00
***********************
Table Stats::
Table: USERASSESSMENTRUN Alias: UAR
#Rows: 883604 #Blks: 6176 AvgRowLen: 36.00
Column (#2): USERID(NUMBER)
AvgLen: 6.00 NDV: 883604 Nulls: 403 Density: 1.1250e-06 Min: 692492 Max: 7335693
Histogram: HtBal #Bkts: 254 UncompBkts: 254 EndPtVals: 255
Index Stats::
Index: USERASSESSMENTRUN_PK Col#: 1
LVLS: 2 #LB: 4341 #DK: 883604 LB/K: 1.00 DB/K: 1.00 CLUF: 733976.00
Index: USERASSESSMENTRUN_UID_FK_IDX Col#: 2
LVLS: 2 #LB: 3220 #DK: 882998 LB/K: 1.00 DB/K: 1.00 CLUF: 731520.00
Index: USRASSESSRUN_ASSESSCNT_FK_IDX Col#: 3
LVLS: 2 #LB: 6386 #DK: 204 LB/K: 31.00 DB/K: 343.00 CLUF: 70165.00
***************************************
If I check the column statistics i find the density:
select num_distinct, density, num_nulls, num_buckets, sample_size from dba_tab_col_statistics where table_name='ACTIVEUSER' and column_name='USERNAME';
NUM_DISTINCT DENSITY NUM_NULLS NUM_BUCKETS SAMPLE_SIZE
------------ ---------- ---------- ----------- -----------
949914 ,016666667 0 1 8056
1 row selected.
The statistics are collected using (the lock is to protect the table from beeing overwritten by the default gather statistics job. For an unknow reason it keeps making histogram on this column. That also I find very strange on a column with distint values - allthough not defined unique):
exec DBMS_STATS.DELETE_TABLE_STATS(ownname=>'<owner>',tabname=>'ACTIVEUSER',CASCADE_COLUMNS=>TRUE, CASCADE_INDEXES=>TRUE, NO_INVALIDATE=>FALSE);
exec DBMS_STATS.GATHER_TABLE_STATS (OwnName => '<owner>', TabName => 'ACTIVEUSER', Method_Opt=>'FOR ALL COLUMNS SIZE 1', Cascade => TRUE, No_Invalidate => FALSE);
exec DBMS_STATS.LOCK_TABLE_STATS(OwnName => '<owner>', TabName => 'ACTIVEUSER');
How is the density value calculated in the statistics gathering? I see the sample_size is very low for the column statistics, but I can't really see how this would mess up the density? Or?
Appreciate your comments.</code>
RE: 10053 rounded cdn
Lasse Jenssen, November 08, 2011 - 3:43 am UTC
A small addition to the above:
The USERNAME column datatype is varchar2(100).
When i look at the values i see that over 850000 (about 80%) has a length of 42 character. When I look at these the value is often something like "adf_student_XXXXXXXX".
I've read that calculating the density on character columns, oracle uses the 15 first character generating a desimal value. If i take the 15 first character of string being 42 character, and counting distinct values i get:
<code>
select count(distinct substr(username,1,15)) from activeuser where length(username)=42;
COUNT(DISTINCTSUBSTR(USERNAME,1,15))
------------------------------------
11
1 row selected.
Calculating density: 1/11=0,091
Now we're starting to get preatty close to the oracle calculated value of 0,016667. Do you think this could be a reasonable explaination?
And is so: What can we do about it?
Appreciate your comment.</code>
November 08, 2011 - 7:37 am UTC
you could, for this one case, use dbms_stats to set the density. Strings with an almost constant leading bit are killer when it comes to cardinality estimates.
Clarification on BEST Access Patth in 10053
Michael, December 22, 2011 - 1:51 pm UTC
Are you aware of any reason (other than a bug) that can produce the following 10053?
Looks like Best Path is the path with maximum (not minimum) cost.
***************************************
SINGLE TABLE ACCESS PATH
-----------------------------------------
BEGIN Single Table Cardinality Estimation
-----------------------------------------
Column (#2): ASE_CCS_UID(NUMBER) NO STATISTICS (using defaults)
AvgLen: 13.00 NDV: 178094 Nulls: 0 Density: 5.6150e-06
Column (#4): ASE_SGS_UID(NUMBER) NO STATISTICS (using defaults)
AvgLen: 13.00 NDV: 178094 Nulls: 0 Density: 5.6150e-06
Column (#5): ASE_IS_ACTIVE(NUMBER)
AvgLen: 3.00 NDV: 2 Nulls: 0 Density: 0.0017993 Min: 0 Max: 1
Histogram: Freq #Bkts: 2 UncompBkts: 4724 EndPtVals: 2
Table: SB_AGENT_SCHEDULE_ENTRY Alias: THIS_
Card: Original: 5699014 Rounded: 285 Computed: 284.95 Non Adjusted: 284.95
-----------------------------------------
END Single Table Cardinality Estimation
-----------------------------------------
Access Path: TableScan
Cost: 8678.53 Resp: 8678.53 Degree: 0
Cost_io: 8399.00 Cost_cpu: 2395052452
Resp_io: 8399.00 Resp_cpu: 2395052452
kkofmx: index filter:"THIS_"."ASE_IS_ACTIVE"=TO_NUMBER(:B1) AND "AGENT1_"."A_MSG_REQ_GUID" IS NULL AND "THIS_"."ASE_A_UID"="AGENT1_"."A_UID"
kkofmx: index filter:"THIS_"."ASE_CCS_UID"=TO_NUMBER(:B1) AND "THIS_"."ASE_SGS_UID"=TO_NUMBER(:B2) AND "THIS_"."ASE_IS_ACTIVE"=TO_NUMBER(:B3) AND "AGENT1_"."A_MSG_REQ_GUID" IS NULL AND "THIS_"."ASE_A_UID"="AGENT1_"."A_UID"
Access Path: index (skip-scan)
SS sel: 0.5 ANDV (#skips): 19356
SS io: 1935.55 vs. table scan io: 8399.00
Skip Scan chosen
Access Path: index (SkipScan)
Index: IX_ASE_A_UID
resc_io: 2511233.50 resc_cpu: 19588485753
ix_sel: 0.5 ix_sel_with_filters: 0.5
Cost: 251351.97 Resp: 251351.97 Degree: 1
Access Path: index (FullScan)
Index: IX_ASE_A_UID_CCS_UID
resc_io: 47008.00 resc_cpu: 1429460564
ix_sel: 1 ix_sel_with_filters: 0.0041982
Cost: 4726.99 Resp: 4726.99 Degree: 1
Access Path: index (AllEqGuess)
Index: IX_ASE_CCS_UID
resc_io: 2291.00 resc_cpu: 29571532
ix_sel: 0.0040461 ix_sel_with_filters: 0.0040461
Cost: 229.45 Resp: 229.45 Degree: 1
Best:: AccessPath: IndexRange Index: IX_ASE_A_UID
Cost: 251351.97 Degree: 1 Resp: 251351.97 Card: 284.95 Bytes: 0
***************************************
December 22, 2011 - 2:18 pm UTC
do you have the original query - does it have any hints. what is your version.
Clarification on BEST Access Patth in 10053
Michael, December 22, 2011 - 2:49 pm UTC
original query:
SELECT this_.ASE_A_UID as y0_
FROM SB_AGENT_SCHEDULE_ENTRY this_
INNER JOIN SB_AGENT agent1_ ON this_.ASE_A_UID = agent1_.A_UID
WHERE this_.ASE_CCS_UID = :1
AND this_.ASE_SGS_UID = :2
AND this_.ASE_IS_ACTIVE = :3
AND agent1_.A_MSG_REQ_GUID is null
Version is 10.2.0.4.4
No hints, but the following parameters were changed:
*************************************
PARAMETERS WITH ALTERED VALUES
******************************
_pga_max_size = 1048560 KB
optimizer_mode = first_rows
sqlstat_enabled = true
_b_tree_bitmap_plans = false
optimizer_index_cost_adj = 10
optimizer_index_caching = 90
_optim_peek_user_binds = false
optimizer_dynamic_sampling = 0
statistics_level = all
*********************************
the explain plan produced is :
---------------------------------------------------------------+------------------------------+
| Id | Operation | Name |Rows |Bytes|Cost | Time |
---------------------------------------------------------------+------------------------------+
| 0 | SELECT STATEMENT | | | | 62K | |
| 1 | NESTED LOOPS | | 4056| 606K| 62K | 00:13:39 |
| 2 | TABLE ACCESS FULL | SB_AGENT | 113K| 13M| 16K | 00:03:21 |
| 3 | TABLE ACCESS BY INDEX ROWID | SB_AGENT_SCHEDULE_ENTRY| 1| 37| 1 | 00:00:01 |
| 4 | INDEX RANGE SCAN | IX_ASE_A_UID_CCS_UID | 3| | 1 | 00:00:01 |
---------------------------------------------------------------+------------------------------+
Predicate Information:
----------------------
2 - filter("AGENT1_"."A_MSG_REQ_GUID" IS NULL)
3 - filter(("THIS_"."ASE_SGS_UID"=TO_NUMBER(:2) AND "THIS_"."ASE_IS_ACTIVE"=TO_NUMBER(:3)))
4 - access("THIS_"."ASE_A_UID"="AGENT1_"."A_UID" AND "THIS_"."ASE_CCS_UID"=TO_NUMBER(:1))
Changing optimizer_mode to first_rows_10 or _100 or _1000 fixes the problem.
I'm trying to find legitimate reason for such 10053, not to fix the query performance - it was fixed by a hint. The correct plan is :
---------------------------------------------------------------+-------------------------------+
| Id | Operation | Name |Rows |Bytes| Cost | Time |
---------------------------------------------------------------+-------------------------------+
| 0 | SELECT STATEMENT | | | | 2 | |
| 1 | NESTED LOOPS | | 11| 1683| 2 | 00:00:01 |
| 2 | TABLE ACCESS BY INDEX ROWID | SB_AGENT_SCHEDULE_ENTRY| 285| 10K| 1 | 00:00:01 |
| 3 | INDEX RANGE SCAN | IX_ASE_CCS_UID | 22K| | 1 | 00:00:01 |
| 4 | TABLE ACCESS BY INDEX ROWID | SB_AGENT | 11| 1276| 1 | 00:00:01 |
| 5 | INDEX UNIQUE SCAN | SYS_C0011186 | 1| | 1 | 00:00:01 |
---------------------------------------------------------------+-------------------------------+
Predicate Information:
----------------------
2 - filter(("THIS_"."ASE_SGS_UID"=TO_NUMBER(:2) AND "THIS_"."ASE_IS_ACTIVE"=TO_NUMBER(:3)))
3 - access("THIS_"."ASE_CCS_UID"=TO_NUMBER(:1))
4 - filter("AGENT1_"."A_MSG_REQ_GUID" IS NULL)
5 - access("THIS_"."ASE_A_UID"="AGENT1_"."A_UID")
December 22, 2011 - 3:02 pm UTC
... optimizer_mode = first_rows
...
there you go, that is it.
Not a bug, but what you requested. You got the plan that gets the first row as fast as possible - even though it might take days to get the last row.
first_rows, a setting to not use probably anymore, is sort of a rule based-cost based optimization. first_rows(n) is a true cost based optimization.
http://docs.oracle.com/cd/E11882_01/server.112/e25513/initparams168.htm#REFRN10145 Values:
first_rows_n
The optimizer uses a cost-based approach and optimizes with a goal of best response time to return the first n rows (where n = 1, 10, 100, 1000).
first_rows
The optimizer uses a mix of costs
and heuristics to find a best plan for fast delivery of the first few rows.
all_rows
The optimizer uses a cost-based approach for all SQL statements in the session and optimizes with a goal of best throughput (minimum resource use to complete the entire statement).
the rule (heuristic) used is typically "an index is best, use them". It is not the case often however that this is best.
I'll reserve my comments on the other settings - suffice to say, I would probably be asking to comment them all out.
10053 trace viewer
Sergei Romanenko, January 13, 2012 - 11:50 am UTC
Tom, I wanted to let you and the readers know that there is a freeware 10053 trace file viewer. The viewer uses a navigation section, similar to the Contents section in PDF reader, for example. It allows jumping to the most important parts of 10053 trace. It also uses highlighter to improve readability of the trace and optionally formats the final query after transformations. The link to download: www.lab128.com/free_downloads.html
If you think this comment is not related to the discussion or inappropriate, then please ignore this posting.
Regards,
Sergei
January 17, 2012 - 9:41 am UTC
no problem doing that.
Optimzer choosing higher cost?
Lasse Jenssen, September 20, 2012 - 8:06 am UTC
I'm on 11g using ALL_ROWS, and see the same as described in previous posts: the CBO choosing access path with way higher cost.
<code>select * from ej1 where not exists
(select 'x' from br1 where br1.institution_code = ej1.institution_code and br1.branch= ej1.branch)
Trace file:
SINGLE TABLE ACCESS PATH
Single Table Cardinality Estimation for EJ1[EJ1]
Column (#12):
NewDensity:0.001583, OldDensity:0.000158 BktCnt:3158, PopBktCnt:3158, PopValCnt:3, NDV:3
Column (#12): INSTITUTION_CODE(
AvgLen: 4 NDV: 3 Nulls: 0 Density: 0.001583 Min: 3625 Max: 9021
Histogram: Freq #Bkts: 3 UncompBkts: 3158 EndPtVals: 3
Column (#13):
NewDensity:0.000317, OldDensity:0.000158 BktCnt:3158, PopBktCnt:3158, PopValCnt:194, NDV:194
Column (#13): BRANCH(
AvgLen: 5 NDV: 194 Nulls: 0 Density: 0.000317
Histogram: Freq #Bkts: 194 UncompBkts: 3158 EndPtVals: 194
...
Table: EJ1 Alias: EJ1
Card: Original: 3158.000000 Rounded: 3158 Computed: 3158.00 Non Adjusted: 3158.00
Access Path: TableScan
Cost: 64534.01 Resp: 64534.01 Degree: 0
Cost_io: 64440.00 Cost_cpu: 1695796833
Resp_io: 64440.00 Resp_cpu: 1695796833
****** trying bitmap/domain indexes ******
Access Path: index (FullScan)
Index: EJ1_IDX02
resc_io: 14.00 resc_cpu: 731500
ix_sel: 1.000000 ix_sel_with_filters: 1.000000
Cost: 14.04 Resp: 14.04 Degree: 0
Access Path: index (FullScan)
Index: EJ1_PK
resc_io: 15.00 resc_cpu: 738422
ix_sel: 1.000000 ix_sel_with_filters: 1.000000
Cost: 15.04 Resp: 15.04 Degree: 0
****** finished trying bitmap/domain indexes ******
Best:: AccessPath: TableScan
Cost: 64534.01 Degree: 1 Resp: 64534.01 Card: 3158.00 Bytes: 0
I thought the CBO always would choose the lowest cost here? An autotrace shows that:
- without INDEX hint: cost 64534, consitent gets: 240000
- with hint: cost: 1854, consitent gets: 2823
</code>
September 26, 2012 - 11:10 am UTC
without a reproducible test case, I cannot really comment on a tiny snippet of a trace file taken out of context.
I don't see the 1854 cost in the trace file at all there.
nl join vs hash join
A reader, September 23, 2012 - 11:00 pm UTC
Dear Tom,
I did a 10053 events ,I niticed the cost of NL JOIN is LESS THAN the HASH JOIN,but Oracle choose the HASH JOIN plan.
The database is 11gr2 EE.
Could you kindly tell me the reason?
Sorry just pasted part or the 10053 trace file:
NL Join
Outer table: Card: 1.00 Cost: 3.00 Resp: 3.00 Degree: 1 Bytes: 3
Access path analysis for T1
Inner table: T1 Alias: T1
Access Path: TableScan
NL Join: Cost: 293.92 Resp: 293.92 Degree: 1
Cost_io: 292.00 Cost_cpu: 38753901
Resp_io: 292.00 Resp_cpu: 38753901
Best NL cost: 293.92
resc: 293.92 resc_io: 292.00 resc_cpu: 38753901
resp: 293.92 resp_io: 292.00 resc_cpu: 38753901
...
Outer table: T2 Alias: T2
resc: 3.00 card 1.00 bytes: 3 deg: 1 resp: 3.00
Inner table: T1 Alias: T1
resc: 290.92 card: 72520.00 bytes: 97 deg: 1 resp: 290.92
using dmeth: 2 #groups: 1
Cost per ptn: 0.86 #ptns: 1
hash_area: 127 (max=25395) buildfrag: 1 probefrag: 965 ppasses: 1
Hash join: Resc: 294.78 Resp: 294.78 [multiMatchCost=0.00]
HA Join
HA cost: 294.78
resc: 294.78 resc_io: 292.00 resc_cpu: 56107958
resp: 294.78 resp_io: 292.00 resp_cpu: 56107958
Best:: JoinMethod: Hash
Cost: 294.78 Degree: 1 Resp: 294.78 Card: 1.00 Bytes: 100
***********************
Best so far: Table#: 0 cost: 3.0014 card: 1.0000 bytes: 3
Table#: 1 cost: 294.7771 card: 1.0000 bytes: 100
Regards
Alan
10053 - strange behaviour
LUIS, April 25, 2013 - 12:19 pm UTC
Hi tom,
I am having some trouble understanding what CBO is exactly doing.
Oracle 10.2.0.4 release.
I am doing a select to a table (not mixing with other tables)
and quite surpised or not quite understanding what CBO truly does :
Access Path: TableScan
Cost: 4146.98 Resp: 4146.98 Degree: 0
Cost_io: 4122.67 Cost_cpu: 244645032
Resp_io: 4122.67 Resp_cpu: 244645032
****** trying bitmap/domain indexes ******
Access Path: index (FullScan)
Index: IDX_XXXXX
resc_io: 103.00 resc_cpu: 7442108
ix_sel: 1 ix_sel_with_filters: 1
Cost: 103.74 Resp: 103.74 Degree: 0
Access Path: index (FullScan)
Index: PK_YYYYY
resc_io: 123.00 resc_cpu: 7584537
ix_sel: 1 ix_sel_with_filters: 1
Cost: 123.75 Resp: 123.75 Degree: 0
****** finished trying bitmap/domain indexes ******
Best:: AccessPath: TableScan
Cost: 4146.98 Degree: 1 Resp: 4146.98 Card: 29149.83 Bytes: 0
I thought CBO would decide to get the lower cost ( INDEX IDX_XXXXX )
At the start i thought ok i am hitting bug :
Bug 8795753 : FULL INDEX SCAN NOT CHOSEN EVEN THOUGH COST IS CHEAPER
So i decided to use INDEX HINT ON PK_YYYYY (example),
i viewed that PK_YYYYY changed to Cost: 20966.25 and tried again previous query without
index hint (just in case something had changed) and kept getting same cost for PK_YYYYY 123,75:
Access Path: index (FullScan)
Index: PK_YYYYY
resc_io: 20943.35 resc_cpu: 230472279
ix_sel: 1 ix_sel_with_filters: 1
Cost: 20966.25 Resp: 20966.25 Degree: 1
Best:: AccessPath: IndexRange Index: PK_YYYYY
Cost: 20966.25 Degree: 1 Resp: 20966.25 Card: 29149.83 Bytes: 0
My doubt is CBO should have decided getting best cost for Access Path or more
things should be taken into account (that the cost at that point) or i am hitting the bug (probably i am) ?.
But why is the cost of Access Path: index (FullScan) Index: PK_YYYYY being different from when i use
the hint from when i do ? ( maybe the bug is making error costs calculations on query without HINT ? )
Thanks
April 25, 2013 - 1:31 pm UTC
I cannot look at a snippet of a file and diagnose anything. give me a reproducible test case. (not the 10053 trace file, but rather the steps to reproduce it)
i don't know the query, i don't know the schema, there are more things we don't know here than we do know.
full test case, create table, populate table, queries to reproduce with..
10053 documentation
pranav, August 28, 2013 - 10:34 pm UTC
Tom,
I was just going through Wolfgang article on 10053. Disclaimer says "Oracle does not provide any documentation on the output of the 10053 event. This presentation is built on my interpretation of the results of many traces; with some jump-start help from ev10053.txt
There is no guarantee that the interpretation is accurate
and there are certainly gaps in my knowledge and
understanding of the trace. "
Why ORACLE wouldn't provide these granule details? Obviously for the DBA's or performance analysts who are trying to fix the issues, they could have come to more meaningful conclusions if ORACLE should have provided the details like how it calculates the costs for table scan/index scan(density/computed/rounded) etc. I mean, if CBO is doing some calculations wouldn't it be good to document those some where? Forget about people like me :-) This could even have saved some time for the experts(like you/Jonathan/Wolfgang etc) to do analysis and come up with these numbers.
September 04, 2013 - 5:52 pm UTC
because 10053 is a diagnostic trace we developed for our developers, the guys that write the optimizer, diagnose an issue. If you have a problem, support would ask you to turn this on - and give us the output.
the information you are asking for:
... like how it calculates the costs for table scan/index scan(density/computed/rounded) etc. ....
change from release to release, patch to patch, system to system, platform to platform, parameter setting to parameter setting. It is part of the "black box" of the database (not everything is documented).
This is the way I look at it:
the thing you as a DBA/developer need to do is make sure the cardinality estimates in the plan are within a good order of magnitude of reality. If they are - you are getting the plan we intended. If the plan we intended is not the right plan - that is a bug (we work that via support).
If the cardinality is not within a good order of magnitude - your job is to try to rectify that first. representative statistics, sufficient statistics (histograms), sql profiles (statistics for a query itself), extended statistics, dynamic sampling and so on. If you cannot under any circumstances get the cardinality estimated to be within that order of magnitude - that is a bug (we work that via support)
I've used a 10053 trace file so infrequently - I can count it on one hand. It just isn't something I've found necessary to do my job. Jonathan, Wolfgang - they are just interested in it, they like to reverse engineer the contents. And it is something that keeps them continuously busy because we can and frequently do change the content and even the meaning of the data in the trace files - since we consider that our own internal debugging information to be used by our developers.