Skip to Main Content

Breadcrumb

Question and Answer

Tom Kyte

Thanks for the question, Amiel.

Asked: May 07, 2006 - 2:23 pm UTC

Answered by: Tom Kyte - Last updated: September 04, 2013 - 5:52 pm UTC

Category: Developer - Version: 9.2.6

Viewed 10K+ times! This question is

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>

and you rated our response

  (37 ratings)

Is this answer out of date? If it is, please let us know via a Review

Reviews

very good explaination

May 08, 2006 - 9:14 am UTC

Reviewer: Jagjeet Singh from India


Try Jonathan Lewis' latest book, too

May 08, 2006 - 9:39 am UTC

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 08, 2006 - 9:41 am UTC

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 09, 2006 - 11:22 am UTC

Reviewer: Amiel D.

Think you. It was just the explanation I needed.
Amiel


what is rounded cardinality in 10053 trace file?

May 22, 2006 - 4:02 pm UTC

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.

Tom Kyte

Followup  

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.

May 22, 2006 - 5:13 pm UTC

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!



Tom Kyte

Followup  

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.

May 22, 2006 - 6:48 pm UTC

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?

Tom Kyte

Followup  

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>





 

May 23, 2006 - 9:14 am UTC

Reviewer: A reader

Great explanation! Thanks a lot Tom.

How are ROUNDED CDN and CMPTD CDN calculated?

June 18, 2006 - 11:59 am UTC

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.



Tom Kyte

Followup  

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?

June 18, 2006 - 12:41 pm UTC

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 - 8:41 pm UTC

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 - 10:36 am UTC

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 01, 2006 - 3:48 am UTC

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: #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
~


Tom Kyte

Followup  

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

February 02, 2007 - 7:10 pm UTC

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 - 10:33 am UTC

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.
Tom Kyte

Followup  

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'

October 16, 2007 - 2:44 am UTC

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 05, 2009 - 2:42 pm UTC

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';
Tom Kyte

Followup  

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

February 05, 2009 - 3:14 pm UTC

Reviewer: A reader

Thank you. That worked. Hard parse was the key. The query I was running was cached.

10053 and hard parse

February 06, 2009 - 4:26 am UTC

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 ?
Tom Kyte

Followup  

February 06, 2009 - 3:32 pm UTC

it is not the same

Index access path not considered...

April 20, 2010 - 7:34 am UTC

Reviewer: Ye from Shanghai, China

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

Tom Kyte

Followup  

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.

April 20, 2010 - 10:34 am UTC

Reviewer: A reader

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

Tom Kyte

Followup  

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

April 21, 2010 - 3:50 am UTC

Reviewer: Ye from Shanghai, China

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

Tom Kyte

Followup  

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

October 11, 2011 - 12:05 pm UTC

Reviewer: Lasse Jenssen from Norway

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>
Tom Kyte

Followup  

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

October 11, 2011 - 1:00 pm UTC

Reviewer: Jonathan Taylor from Huddersfield, UK

Apart from the VARCHAR2/DATE difference - the date is also different between the 2 versions (2010/2011).


Tom Kyte

Followup  

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

October 12, 2011 - 5:45 am UTC

Reviewer: Lasse Jenssen from Norway

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>
Tom Kyte

Followup  

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

October 12, 2011 - 8:31 am UTC

Reviewer: Lasse Jenssen from Norway

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?


Tom Kyte

Followup  

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

October 13, 2011 - 1:39 pm UTC

Reviewer: Lasse Jenssen from Norway

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).
Tom Kyte

Followup  

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

November 04, 2011 - 4:09 pm UTC

Reviewer: Lasse Jenssen from Norway

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>
Tom Kyte

Followup  

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

November 08, 2011 - 1:42 am UTC

Reviewer: Lasse Jenssen from Norway

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

November 08, 2011 - 3:43 am UTC

Reviewer: Lasse Jenssen from Norway

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>
Tom Kyte

Followup  

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

December 22, 2011 - 1:51 pm UTC

Reviewer: Michael from USA

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
***************************************

Tom Kyte

Followup  

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

December 22, 2011 - 2:49 pm UTC

Reviewer: Michael from USA

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")




Tom Kyte

Followup  

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

January 13, 2012 - 11:50 am UTC

Reviewer: Sergei Romanenko from USA

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

Tom Kyte

Followup  

January 17, 2012 - 9:41 am UTC

no problem doing that.

Optimzer choosing higher cost?

September 20, 2012 - 8:06 am UTC

Reviewer: Lasse Jenssen from Norway

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>
Tom Kyte

Followup  

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

September 23, 2012 - 11:00 pm UTC

Reviewer: A reader

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

April 25, 2013 - 12:19 pm UTC

Reviewer: LUIS from SPAIN

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
Tom Kyte

Followup  

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

August 28, 2013 - 10:34 pm UTC

Reviewer: pranav

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.



Tom Kyte

Followup  

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.

More to Explore

Analytics

Analytic SQL got you confused? Check out Connor McDonald's complete video course.