Skip to Main Content
  • Questions

  • why the cardinaltiy of explain plan does not matches with the tkprof row source operations

Breadcrumb

Question and Answer

Tom Kyte

Thanks for the question, Reene.

Asked: November 28, 2007 - 12:27 am UTC

Last updated: December 03, 2007 - 7:39 am UTC

Version: 9.2.0.7

Viewed 1000+ times

You Asked

Hi Tom,

I have been trying to ask this question since quite some time at this forum as well as the other forums but could not get an answer so far-

as i have asked few weeks back also -

what are the all possible reasons for the differnece in cardinalities shown in explain plan and tkprof row source operation.

if there is a difference in the cardinalities in explain plan and tkprof then how this impact the performance of a query.

how to fix this issue - in one of your forums you have mentioned the use of dynamic_sampling , I understood that.
another reason mentioned was -

poor stats - I use the following to collect stats , do i need to change it,am i doing it wrong , please correct,if possible. i do the same tbing for all the tables of a query..we have a process alos which gather stats on stale object using monitoring ON option.

begin
dbms_stats.gather_table_stats (
ownname => 'ONT',
tabname => 'ORDER_MASTER',
estimate_percent => dbms_stats.auto_sample_size,
method_opt => 'for all columns size auto',
cascade => true,
degree => 16
) ;
end ;
/

please throw some light,pointers on this subject.

thanks
Reene


and Tom said...

... what are the all possible reasons for the differnece in cardinalities shown in explain plan and tkprof row source operation. ....

there are a possibly INFINITE number of reasons.

Let me ask you - You have a set of data, it is called T.

In this set of data, you have two columns - X, Y

X has twelve values.
Y has twelve values also.


You gather every bit of statistics you can - that is on the table, each of the columns (you know the high and low values - in fact you have histograms so you KNOW for any of the twelve values of X how many rows will be returned precisely), you have information in every index.

Now, you have a lot of information - but it won't be enough to answer the question, how many rows does:

where x = ? and y = ?

return. Let's make this even easier - X is perfectly distributed (the number of rows returned by "x=anything" is 1/12th of the data. Y is the same - y=anything returns 1/12th of the data.


Now, tell me - how many rows from:

where x = ? and y = ?


Using high school statistics we can "guess" (assuming that X and Y are independent)

rows-returned-by(x) times rows-returned-by(y) = 1/12*1/12 = 1/144

now, is that right?

maybe
maybe not

what if x=y for every row? then, well, it is EITHER 1/12th of the rows or it is 0 rows.

Well, the optimizer will pick neither of those, it will pick 1/144th of the rows, consider:

ops$tkyte%ORA10GR2> create table t
  2  as
  3  select mod(rownum,12) x, mod(rownum,12) y
  4    from all_objects
  5  /

Table created.

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> select count(*), count(*)/12, count(*)/144 from t;

  COUNT(*) COUNT(*)/12 COUNT(*)/144
---------- ----------- ------------
     49850  4154.16667   346.180556

ops$tkyte%ORA10GR2>
ops$tkyte%ORA10GR2>
ops$tkyte%ORA10GR2> @at
ops$tkyte%ORA10GR2> column PLAN_TABLE_OUTPUT format a72 truncate
ops$tkyte%ORA10GR2> set autotrace traceonly explain
ops$tkyte%ORA10GR2> select * from t where x = 5;

Execution Plan
----------------------------------------------------------
Plan hash value: 1601196873

------------------------------------------------------------------------
| Id  | Operation         | Name | Rows  | Bytes | Cost (%CPU)| Time
------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |      |  4079 | 20395 |    30  (10)| 00:00:01
|*  1 |  TABLE ACCESS FULL| T    |  4079 | 20395 |    30  (10)| 00:00:01
------------------------------------------------------------------------

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

   1 - filter("X"=5)

ops$tkyte%ORA10GR2> select * from t where y = 6;

Execution Plan
----------------------------------------------------------
Plan hash value: 1601196873

------------------------------------------------------------------------
| Id  | Operation         | Name | Rows  | Bytes | Cost (%CPU)| Time
------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |      |  4305 | 21525 |    31  (13)| 00:00:01
|*  1 |  TABLE ACCESS FULL| T    |  4305 | 21525 |    31  (13)| 00:00:01
------------------------------------------------------------------------

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

   1 - filter("Y"=6)

ops$tkyte%ORA10GR2> select * from t where x = 5 and y = 6;

Execution Plan
----------------------------------------------------------
Plan hash value: 1601196873

------------------------------------------------------------------------
| Id  | Operation         | Name | Rows  | Bytes | Cost (%CPU)| Time
------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |      |   357 |  1785 |    31  (13)| 00:00:01
|*  1 |  TABLE ACCESS FULL| T    |   357 |  1785 |    31  (13)| 00:00:01
------------------------------------------------------------------------

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

   1 - filter("X"=5 AND "Y"=6)

ops$tkyte%ORA10GR2> @atoff
ops$tkyte%ORA10GR2> set autotrace off
ops$tkyte%ORA10GR2> select * from t where x = 5 and y = 6;

no rows selected



In this specific case, a possible solution is (as demonstrated here also)
http://asktom.oracle.com/pls/asktom/f?p=100:11:0::::P11_QUESTION_ID:40230704959128#69134369478883 



ops$tkyte%ORA10GR2>
ops$tkyte%ORA10GR2> @at
ops$tkyte%ORA10GR2> column PLAN_TABLE_OUTPUT format a72 truncate
ops$tkyte%ORA10GR2> set autotrace traceonly explain
ops$tkyte%ORA10GR2> select /*+ dynamic_sampling(t 3) */ * from t where x = 5 and y = 6;

Execution Plan
----------------------------------------------------------
Plan hash value: 1601196873

------------------------------------------------------------------------
| Id  | Operation         | Name | Rows  | Bytes | Cost (%CPU)| Time
------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |      |     1 |     5 |    31  (13)| 00:00:01
|*  1 |  TABLE ACCESS FULL| T    |     1 |     5 |    31  (13)| 00:00:01
------------------------------------------------------------------------

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

   1 - filter("X"=5 AND "Y"=6)

Note
-----
   - dynamic sampling used for this statement

ops$tkyte%ORA10GR2> @atoff
ops$tkyte%ORA10GR2> set autotrace off



but what if bind variables are used? what then?


the optimizer works with imperfect information - it does the best guess. When we see a large disparity in the computed cardinality - we can usually say "why" in that case.


but to list them all - not really possible. I would say that complex predicates involving many conditions over many tables would be a leading cause.

Rating

  (16 ratings)

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

Comments

David, November 28, 2007 - 5:47 pm UTC

Jonathan Lewis' book has a great section in the early chapters (I can't remember precisely and don't have it to hand at present) about exactly these types of scenarios.

He has some theories about what cardinalities should be returned by the CBO based on the data and then sets out to determine why they differ from his expectations. It also has some excellent info on the cardinalities assigned to bind variables.

I'd highly recommend it.

impact on performance

Reene, November 29, 2007 - 1:54 am UTC

Hi Tom,

ok . I understand this case now more clearly.

I have few more question - which I have observed during the tuning.

1. generally if there is a difference in the cardinalities (big difference) between thee explain plan and row source operation then does it mean that query will perform poor becase optimizer WILL choose an inefficient plan ? is it true ? I have observed it with few of my queries.but want to be sure about this conclusion.

2. other than dynamic sampling ,what could be the possible solution. how to co-relate the cardinality mismatch with poor stats -is there a easier way for developers to understand - that is run few queires and check this out.

3. off the shelf packeges such as oracle apps or pepole soft or siebel general have queries with 10 or even 15 tables in the where clause, that is what i am into and these queires have usually all kind of where conditions - so is there a starting point ,to resolve the such kind of (cardinality and so the performance) issues.

4. if I set the optimizer_index_caching to 90 (earlier it was 0 ) then I see the few the FULL table scans for a query changes into index range scan in the explain plan (which is expected change) ,but does this mean that in row source operation also this will happen ? I will keep observing too.

5. what is the best way to collect the stats for a schema with large tables and many indexes as well , there are some tables with 60 million rows .best way means -which could in general give the optimizer the best possible information .

Thanks so much.

Reene
Tom Kyte
November 29, 2007 - 8:48 am UTC

1) it is safe to say that if you have a suboptimal plan, the root cause is an inaccurate cardinality estimate.

it is not safe to say that if you have an inaccurate cardinality estimate, you will have a bad plan.

it is safe to say that if you have an inaccurate cardinality estimate, the odds of the wrong plan being chosen are high.

2) dynamic sampling "fixed" this particular problem. you have dynamic sampling, you have "gather better statistics" for other cases (histograms for example), you have SQL profiles (analyze A QUERY), you have virtual columns and statistics on them in 11g, you have function based indexes and statistics on them in 10g, you have stored outlines, you have the occasional good hint (all rows, first rows(n), materialize, cardinality...), system statistics (instead of optimizer init.ora paramters - avoid those)

and when you need a sledge hammer, you have a hint, that you must code review with each release to make sure it does more good than harm


3) sql profiles where designed for that - to analyze a QUERY.

4) don't know what you mean.

5) depends. you might gather once and never again, you might have to gather some on a recurring basis (to keep the plans from changing), you might use dbms_stats.set column stats to tell us about every changing high values (sequences, dates) instead of gathering, you might estimate with small percents, you might have histograms on some things (expensive to compute) and not most of the rest...

sidetracked by mention of dynamic sampling ...

nameless, November 29, 2007 - 10:54 am UTC

Question was:

what are the all possible reasons for the differnece in cardinalities shown in explain plan and tkprof row source operation.

The answer could've been one line:

http://tkyte.blogspot.com/2007/04/when-explanation-doesn-sound-quite.html





Tom Kyte
November 29, 2007 - 7:00 pm UTC

that is just a list of other reasons.

which didn't mention this reason.

and there are more.

my point was: there are a whole bunch of them, some I don't even know yet because I haven't hit them.


they were not asking why explain plans do not match row source operations as far as the plan goes, they were asking "why are the card= values in the explain plan so different sometimes from the row values in a row source operation"

The presumption is the plans were the same - just the estimated card= values were WAY off from reality.

that is what I addressed here.

one last question

Reene, November 30, 2007 - 9:27 am UTC

Hi
Tom , thanks for expalining this in detail.

I am trying to tune the query below, below I am pasting the part of tkprof for this query - including row source and execution plan.

I have 2 question.

1)there is a table in this query mtl_parameters which has 377 rows only.

APPS@GLTEST-70>select count(*) from inv.mtl_parameters ;

COUNT(*)
----------
377

but in the row source - it shown that rows= 60006.

60006 INDEX GOAL: ANALYZED (UNIQUE SCAN) OF 'MTL_PARAMETERS_U1' (UNIQUE)

how it is possible ? mtl_parameters_u1 is an unique index.

MTL_PARAMETERS_U1 ORGANIZATION_ID 1


2) second question is not really a question , but request to suggest to improve this query as it is taking 2.34 hrs..
what is wrong in this , how to improve it by looking at the row source and plan - any sugggestion will be a help as I am trying since 15 days :)


Misses in library cache during parse: 0
Optimizer goal: CHOOSE
Parsing user id: 65 (APPS)
********************************************************************************

select count(*)
from
(
SELECT
oha.order_number || '|' ||
oha.cust_po_number || '|' ||
hca.ACCOUNT_NUMBER || '|' ||
hp.party_name || '|' ||
ott.name || '|' ||
otl.name || '|' ||
ola.return_reason_code || '|' ||
ola.SOURCE_TYPE_CODE || '|' ||
oha.flow_status_code || '|' ||
ola.flow_STATUS_CODE || '|' ||
TRUNC(oha.creation_date) || '|' ||
som.created_by || '|' ||
TRUNC(oha.booked_date) || '|' ||
DECODE(hold.released_flag, 'Y', 'N', NULL, 'N', 'N', 'Y') || '|' ||
ola.line_number || '|' ||
org.organization_code || '|' ||
ola.ordered_item || '|' ||
msi.item_type || '|' ||
ola.ordered_quantity || '|' ||
ola.unit_selling_price || '|' ||
ola.ordered_quantity*ola.unit_selling_price || '|' ||
TRUNC(ola.schedule_ship_date) || '|' ||
TRUNC(ola.request_date) || '|' ||
TRUNC(ola.promise_date) || '|' ||
ola.ACTUAL_SHIPMENT_DATE || '|' ||
ola.SHIP_SET_ID || '|' ||
ola.LINE_SET_ID || '|' ||
flv.meaning || '|' ||
DECODE(ola.source_type_code, 'INTERNAL', 'N', 'EXTERNAL', 'Y') || '|' ||
DECODE(ola.attribute13, 1, 'Y', 3, 'Y', NULL, 'N') || '|' ||
NVL(DECODE(wl.meaning, 'Backordered', 'Y'), 'N') || '|' ||
decode(wdd.released_status, 'Y', 'Y', 'C', 'Y', 'I', 'Y', 'N')|| '|' ||
wl.meaning || '|' ||
wdd.oe_interfaced_flag
FROM
ont.oe_order_headers_all oha ,
apps.hz_cust_accounts hca ,
apps.hz_parties hp ,
apps.FND_LOOKUP_VALUES_VL flv ,
ont.oe_order_holds_all hold ,
ont.oe_order_lines_all ola ,
inv.mtl_system_items_b msi ,
inv.mtl_parameters org ,
wsh.wsh_delivery_details wdd ,
WSH.WSH_DELIVERY_ASSIGNMENTS WDA ,
apps.wsh_lookups wl ,
ont.oe_transaction_types_tl ott ,
apps.oe_transaction_types_tl otl ,
gems_pom.gems_pom_srom_hdr_ext som
WHERE
oha.org_id = 3171 AND
flv.LOOKUP_TYPE(+) = 'SHIP_METHOD' AND
ola.shipping_method_code = flv.lookup_code(+) AND
flv.VIEW_APPLICATION_ID(+) = 3 AND
oha.sold_to_org_id = hca.cust_account_id AND
hca.party_id = hp.party_id AND
ola.header_id=hold.header_id (+) and
ola.line_id = hold.line_id (+) AND
oha.header_id=ola.header_id and
ola.ORDERED_ITEM = msi.segment1 and
ola.SHIP_FROM_ORG_ID = msi.organization_id and
oha.order_type_id=ott.transaction_type_id and
ola.line_type_id = otl.transaction_type_id and
ott.name like 'GPO%' AND
ola.ship_from_org_id=org.organization_id AND
ola.line_id=wdd.source_line_id (+) and
wdd.DELIVERY_DETAIL_ID = WDA.DELIVERY_DETAIL_ID AND
wl.lookup_code = NVL(wdd.released_status,'X') AND
wl.lookup_code = NVL(wdd.released_status,'X') AND
wl.lookup_type='PICK_STATUS' and
som.order_number(+) = oha.order_number
and ola.flow_status_code = 'CLOSED'
and ola.ACTUAL_SHIPMENT_DATE >= (trunc(sysdate)-56)
)

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.50 0.48 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 2 1094.35 9031.99 5293104 26077292 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 1094.85 9032.48 5293104 26077292 0


Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 65 (APPS)

Rows Row Source Operation
------- ---------------------------------------------------
1 SORT AGGREGATE (cr=26077292 r=5293104 w=12524 time=442064246 us)
39154 HASH JOIN OUTER (cr=26077292 r=5293104 w=12524 time=442057388 us)
39154 HASH JOIN OUTER (cr=26048824 r=5263389 w=11253 time=427784853 us)
39154 HASH JOIN (cr=26048817 r=5262238 w=10106 time=427257982 us)
11 INDEX RANGE SCAN OBJ#(705891) (cr=4 r=2 w=0 time=30811 us)(object id 705891)
39154 HASH JOIN (cr=26048813 r=5262236 w=10106 time=427142688 us)
39154 HASH JOIN (cr=25930988 r=5146335 w=9331 time=370703141 us)
40200 HASH JOIN (cr=24999336 r=4213943 w=8556 time=106489614 us)
1151 TABLE ACCESS FULL OBJ#(7594171) (cr=94 r=51 w=0 time=147652 us)
60006 HASH JOIN (cr=24999242 r=4213892 w=8556 time=106285633 us)
60006 HASH JOIN (cr=24996859 r=4212993 w=7657 time=104868042 us)
406968 TABLE ACCESS FULL OBJ#(714940) (cr=15805 r=13825 w=0 time=4947393 us)
60006 NESTED LOOPS (cr=24981054 r=4198517 w=7006 time=99155274 us)
60006 HASH JOIN (cr=24981052 r=4198517 w=7006 time=98989772 us)
346523 HASH JOIN (cr=24457761 r=3681624 w=7006 time=1122646305 us)
346524 HASH JOIN OUTER (cr=24172971 r=3403293 w=3658 time=131339395 us)
346409 HASH JOIN (cr=24143234 r=3370095 w=0 time=7446275140 us)
4578 INDEX FULL SCAN OBJ#(7595476) (cr=14 r=1 w=0 time=7693 us)(object id 7595476)
346409 TABLE ACCESS FULL OBJ#(688843) (cr=24143220 r=3370094 w=0 time=7445755534 us)
1066019 TABLE ACCESS FULL OBJ#(7594103) (cr=29737 r=29540 w=0 time=9038520 us)
54769356 INDEX FULL SCAN OBJ#(331689) (cr=284790 r=274983 w=0 time=950310902 us)(object id 331689)
508653 TABLE ACCESS FULL OBJ#(688602) (cr=523291 r=516893 w=0 time=165096637 us)
60006 INDEX UNIQUE SCAN OBJ#(9847) (cr=2 r=0 w=0 time=83850 us)(object id 9847)
981900 INDEX FULL SCAN OBJ#(1939950) (cr=2383 r=0 w=0 time=378775 us)(object id 1939950)
13773135 TABLE ACCESS FULL OBJ#(688523) (cr=931652 r=931617 w=0 time=255314157 us)
13777346 TABLE ACCESS FULL OBJ#(688727) (cr=117825 r=115126 w=0 time=49127575 us)
612 INDEX RANGE SCAN OBJ#(705891) (cr=7 r=4 w=0 time=43670 us)(object id 705891)
1009039 TABLE ACCESS FULL OBJ#(3718019) (cr=28468 r=28444 w=0 time=13167248 us)


Rows Execution Plan
------- ---------------------------------------------------
0 SELECT STATEMENT GOAL: CHOOSE
1 SORT (AGGREGATE)
39154 HASH JOIN (OUTER)
39154 HASH JOIN (OUTER)
39154 HASH JOIN
11 INDEX GOAL: ANALYZED (RANGE SCAN) OF 'FND_LOOKUP_VALUES_U1' (UNIQUE)
39154 HASH JOIN
39154 HASH JOIN
40200 HASH JOIN
1151 TABLE ACCESS GOAL: ANALYZED (FULL) OF 'OE_TRANSACTION_TYPES_TL'
60006 HASH JOIN
60006 HASH JOIN
406968 TABLE ACCESS GOAL: ANALYZED (FULL) OF 'HZ_CUST_ACCOUNTS'
60006 NESTED LOOPS
60006 HASH JOIN
346523 HASH JOIN
346524 HASH JOIN (OUTER)
346409 HASH JOIN
4578 INDEX GOAL: ANALYZED (FULL SCAN) OF 'OE_TRANSACTION_TYPES_TL_U1' (UNIQUE)
346409 TABLE ACCESS GOAL: ANALYZED (FULL) OF 'OE_ORDER_LINES_ALL'
1066019 TABLE ACCESS GOAL: ANALYZED (FULL) OF 'OE_ORDER_HOLDS_ALL'
54769356 INDEX GOAL: ANALYZED (FULL SCAN) OF 'MTL_SYSTEM_ITEMS_B_N1' (NON-UNIQUE)
508653 TABLE ACCESS GOAL: ANALYZED (FULL) OF 'OE_ORDER_HEADERS_ALL'
60006 INDEX GOAL: ANALYZED (UNIQUE SCAN) OF 'MTL_PARAMETERS_U1' (UNIQUE)
981900 INDEX GOAL: ANALYZED (FULL SCAN) OF 'HZ_PARTIES_U1' (UNIQUE)
13773135 TABLE ACCESS GOAL: ANALYZED (FULL) OF 'WSH_DELIVERY_DETAILS'
13777346 TABLE ACCESS GOAL: ANALYZED (FULL) OF 'WSH_DELIVERY_ASSIGNMENTS'
612 INDEX GOAL: ANALYZED (RANGE SCAN) OF 'FND_LOOKUP_VALUES_U1' (UNIQUE)
1009039 TABLE ACCESS GOAL: ANALYZED (FULL) OF 'GEMS_POM_SROM_HDR_EXT'



Thanks

Tom Kyte
November 30, 2007 - 1:55 pm UTC

1) because there were 60006 rows in the driving table in that nested loop join - it did 60006 index range scans!

consider:

ops$tkyte%ORA10GR2> create table t1 as select * from all_users;

Table created.

ops$tkyte%ORA10GR2> create table t2 as select * from all_users;

Table created.

ops$tkyte%ORA10GR2> alter table t2 add constraint t2_pk primary key(user_id);

Table altered.

ops$tkyte%ORA10GR2> exec dbms_stats.gather_table_stats(user,'T1' );

PL/SQL procedure successfully completed.

ops$tkyte%ORA10GR2> exec dbms_stats.gather_table_stats(user,'T2' );

PL/SQL procedure successfully completed.

ops$tkyte%ORA10GR2>
ops$tkyte%ORA10GR2> @trace
ops$tkyte%ORA10GR2> alter session set events '10046 trace name context forever, level 12';

Session altered.

ops$tkyte%ORA10GR2> select /*+ first_rows */ *
  2    from t1, t2
  3   where t1.user_id = t2.user_id
  4     and t2.created < sysdate;

...
35 rows selected.


now, all_users had 35 rows - tkprof shows:


Rows     Row Source Operation
-------  ---------------------------------------------------
     35  NESTED LOOPS  (cr=45 pr=0 pw=0 time=105 us)
     35   TABLE ACCESS FULL T1 (cr=6 pr=0 pw=0 time=739 us)
     35   TABLE ACCESS BY INDEX ROWID T2 (cr=39 pr=0 pw=0 time=627 us)
     35    INDEX UNIQUE SCAN T2_PK (cr=4 pr=0 pw=0 time=247 us)(object id 149738)



35 rows retrieved via the index - one at a time. If we:

ops$tkyte%ORA10GR2> insert into t1 select * from t1;

35 rows created.

ops$tkyte%ORA10GR2> insert into t1 select * from t1;

70 rows created.

ops$tkyte%ORA10GR2> insert into t1 select * from t1;

140 rows created.

ops$tkyte%ORA10GR2> insert into t1 select * from t1;

280 rows created.

ops$tkyte%ORA10GR2> insert into t1 select * from t1;

560 rows created.

ops$tkyte%ORA10GR2> insert into t1 select * from t1;

1120 rows created.

ops$tkyte%ORA10GR2> commit;

Commit complete.

ops$tkyte%ORA10GR2> set autotrace traceonly
ops$tkyte%ORA10GR2> select /*+ first_rows LOOK */ *
  2    from t1, t2
  3   where t1.user_id = t2.user_id
  4     and t2.created < sysdate;

2240 rows selected.



Now, we did not touch T2 - it has only 35 rows, but:

Rows     Row Source Operation
-------  ---------------------------------------------------
   2240  NESTED LOOPS  (cr=2557 pr=0 pw=0 time=45039 us)
   2240   TABLE ACCESS FULL T1 (cr=166 pr=0 pw=0 time=6870 us)
   2240   TABLE ACCESS BY INDEX ROWID T2 (cr=2391 pr=0 pw=0 time=32612 us)
   2240    INDEX UNIQUE SCAN T2_PK (cr=151 pr=0 pw=0 time=12194 us)(object id 149744)


we read 2,240 rows out of it - we read and re-read rows over and over because they joined in a 1:M fashion...



2) it is a pretty small query - are your PGA settings set reasonably? if you trace it with waits, what does TKPROF show us?

Will post it shortly

Reene, December 01, 2007 - 12:53 am UTC

Hi Tom

PGA is

APPS@GLTEST-70>show parameter pga

NAME TYPE VALUE
------------------------------------ ----------- ------------------
pga_aggregate_target big integer 5368709120

so it is almost 5 GB.

I will take 10046 tkprof and then tell the waits.

Thanks


some resource ...

nameless, December 01, 2007 - 8:47 am UTC

Renee:

Just in case you're not aware of it ... a paper from Wolfgang Breitling which you may find an interesting read:

http://www.centrexcc.com/Tuning%20by%20Cardinality%20Feedback.pdf


db_file_multiblock_read_count=128

Reene, December 03, 2007 - 7:31 am UTC

Hi Tom

As there were many Full table scans in the tkprof of above query (and tables were very large) , I chaged the
db_file_multiblock_read_count=128 (it was 8) at the session level and ran this query again

there was huge imprvoement - now it runs in 49 minutes (earlier it was taking 150 minutes) ,
also when i changed the optimizer_index_cost_adj to 50 (it is set as 100 at the db level) then again there was improvement of 2 mins.

is it really the db_file_multiblock_read_count helping or something else here.

also should i try to change the optimizer_index_caching and optimizer_index_cost_adj -will that be of any help.

here is the latest o/p of tkprof

tkprof after setting db_file_multiblock_read_count = 128

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 2 487.44 2929.53 944938 49242791 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 487.44 2929.53 944938 49242791 0 1

Misses in library cache during parse: 0
Optimizer goal: CHOOSE
Parsing user id: 65 (APPS)

Rows Row Source Operation
------- ---------------------------------------------------
1 SORT AGGREGATE (cr=49242791 r=944938 w=0 time=2078653852 us)
44667 HASH JOIN OUTER (cr=49242791 r=944938 w=0 time=2078646583 us)
44667 NESTED LOOPS (cr=49214205 r=916376 w=0 time=2067884881 us)
44667 NESTED LOOPS (cr=49079887 r=915788 w=0 time=2062053677 us)
44667 NESTED LOOPS OUTER (cr=48990202 r=911990 w=0 time=2032898533 us)
44662 NESTED LOOPS (cr=48896223 r=910701 w=0 time=2022465560 us)
44662 NESTED LOOPS (cr=48806897 r=910091 w=0 time=2015902039 us)
504196 NESTED LOOPS (cr=47305232 r=898123 w=0 time=2251611231 us)
504196 NESTED LOOPS (cr=46801034 r=898123 w=0 time=2247582494 us)
504196 NESTED LOOPS OUTER (cr=46801032 r=898123 w=0 time=2245988657 us)
504196 NESTED LOOPS (cr=45890010 r=898119 w=0 time=2239981753 us)
4996145 NESTED LOOPS (cr=15515286 r=508626 w=0 time=292613691 us)
4996288 HASH JOIN (cr=526849 r=503001 w=0 time=174616803 us)
12661 MERGE JOIN CARTESIAN (cr=555 r=0 w=0 time=13739 us)
11 INDEX RANGE SCAN OBJ#(705891) (cr=4 r=0 w=0 time=109 us)(object id 705891)
12661 BUFFER SORT (cr=551 r=0 w=0 time=11047 us)
1151 TABLE ACCESS BY INDEX ROWID OBJ#(7594171) (cr=551 r=0 w=0 time=4319 us)
1151 INDEX RANGE SCAN OBJ#(7595477) (cr=8 r=0 w=0 time=1455 us)(object id 7595477)
512900 TABLE ACCESS FULL OBJ#(688602) (cr=526294 r=503001 w=0 time=163741321 us)
4996145 TABLE ACCESS BY INDEX ROWID OBJ#(714940) (cr=14988437 r=5625 w=0 time=109268616 us)
4996145 INDEX UNIQUE SCAN OBJ#(715003) (cr=9992292 r=800 w=0 time=38210555 us)(object id 715003)
504196 TABLE ACCESS BY INDEX ROWID OBJ#(688843) (cr=30374724 r=389493 w=0 time=2477426717 us)
9126865 INDEX RANGE SCAN OBJ#(688858) (cr=10044455 r=35885 w=0 time=221755123 us)(object id 688858)
455389 INDEX RANGE SCAN OBJ#(705891) (cr=911022 r=4 w=0 time=4482920 us)(object id 705891)
504196 INDEX UNIQUE SCAN OBJ#(9847) (cr=2 r=0 w=0 time=794536 us)(object id 9847)
504196 INDEX RANGE SCAN OBJ#(7595476) (cr=504198 r=0 w=0 time=3120506 us)(object id 7595476)
44662 TABLE ACCESS BY INDEX ROWID OBJ#(688523) (cr=1501665 r=11968 w=0 time=72900178 us)
491282 INDEX RANGE SCAN OBJ#(688572) (cr=1010935 r=2449 w=0 time=22343567 us)(object id 688572)
44662 INDEX UNIQUE SCAN OBJ#(1939950) (cr=89326 r=610 w=0 time=6443723 us)(object id 1939950)
2505 TABLE ACCESS BY INDEX ROWID OBJ#(7594103) (cr=93979 r=1289 w=0 time=10222440 us)
2505 INDEX RANGE SCAN OBJ#(7595413) (cr=91477 r=633 w=0 time=4988619 us)(object id 7595413)
44667 INDEX RANGE SCAN OBJ#(688773) (cr=89685 r=3798 w=0 time=29012757 us)(object id 688773)
44667 INDEX RANGE SCAN OBJ#(331689) (cr=134318 r=588 w=0 time=5676434 us)(object id 331689)
1013286 TABLE ACCESS FULL OBJ#(3718019) (cr=28586 r=28562 w=0 time=9581968 us)


Rows Execution Plan
------- ---------------------------------------------------
0 SELECT STATEMENT GOAL: CHOOSE
1 SORT (AGGREGATE)
44667 HASH JOIN (OUTER)
44667 NESTED LOOPS
44667 NESTED LOOPS
44667 NESTED LOOPS (OUTER)
44662 NESTED LOOPS
44662 NESTED LOOPS
504196 NESTED LOOPS
504196 NESTED LOOPS
504196 NESTED LOOPS (OUTER)
504196 NESTED LOOPS
4996145 NESTED LOOPS
4996288 HASH JOIN
12661 MERGE JOIN (CARTESIAN)
11 INDEX GOAL: ANALYZED (RANGE SCAN)
OF 'FND_LOOKUP_VALUES_U1' (UNIQUE)
12661 BUFFER (SORT)
1151 TABLE ACCESS GOAL: ANALYZED (BY INDEX ROWID) OF 'OE_TRANSACTION_TYPES_TL'
1151 INDEX GOAL: ANALYZED (RANGE SCAN) OF 'OE_TRANSACTION_TYPES_TL_U2' (NON-UNIQUE)
512900 TABLE ACCESS GOAL: ANALYZED (FULL) OF 'OE_ORDER_HEADERS_ALL'
4996145 TABLE ACCESS GOAL: ANALYZED (BY INDEX ROWID) OF 'HZ_CUST_ACCOUNTS'
4996145 INDEX GOAL: ANALYZED (UNIQUE SCAN) OF 'HZ_CUST_ACCOUNTS_U1' (UNIQUE)
504196 TABLE ACCESS GOAL: ANALYZED (BY INDEX ROWID) OF 'OE_ORDER_LINES_ALL'
9126865 INDEX GOAL: ANALYZED (RANGE SCAN) OF 'OE_ORDER_LINES_N1' (NON-UNIQUE)
455389 INDEX GOAL: ANALYZED (RANGE SCAN) OF 'FND_LOOKUP_VALUES_U1' (UNIQUE)
504196 INDEX GOAL: ANALYZED (UNIQUE SCAN) OF 'MTL_PARAMETERS_U1' (UNIQUE)
504196 INDEX GOAL: ANALYZED (RANGE SCAN) OF 'OE_TRANSACTION_TYPES_TL_U1' (UNIQUE)
44662 TABLE ACCESS GOAL: ANALYZED (BY INDEX ROWID) OF 'WSH_DELIVERY_DETAILS'
491282 INDEX GOAL: ANALYZED (RANGE SCAN) OF
'WSH_DELIVERY_DETAILS_N3' (NON-UNIQUE)
44662 INDEX GOAL: ANALYZED (UNIQUE SCAN) OF
'HZ_PARTIES_U1' (UNIQUE)
2505 TABLE ACCESS GOAL: ANALYZED (BY INDEX ROWID) OF
'OE_ORDER_HOLDS_ALL'
2505 INDEX GOAL: ANALYZED (RANGE SCAN) OF
'OE_ORDER_HOLDS_ALL_N2' (NON-UNIQUE)
44667 INDEX GOAL: ANALYZED (RANGE SCAN) OF
'WSH_DELIVERY_ASSIGNMENTS_N3' (NON-UNIQUE)
44667 INDEX GOAL: ANALYZED (RANGE SCAN) OF
'MTL_SYSTEM_ITEMS_B_N1' (NON-UNIQUE)
1013286 TABLE ACCESS GOAL: ANALYZED (FULL) OF
'GEMS_POM_SROM_HDR_EXT'


Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 2 0.00 0.00
db file scattered read 12215 0.22 80.80
global cache cr request 266383 0.12 101.16
db file parallel read 962 0.31 34.11
latch free 184 0.01 0.07
db file sequential read 415626 0.50 2313.30
global cache s to x 5 0.00 0.00
SQL*Net message from client 2 23.10 23.10



********************************************************************************

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 2 0.00 0.00 0 0 0 0
Fetch 2 487.44 2929.53 944938 49242791 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 5 487.44 2929.53 944938 49242791 0 1


change in db file multiblock read count

Reene, December 03, 2007 - 7:42 am UTC

Hi Tom

I chnaged the db file multiblock read count to 128 at session level(it is set as 8 in my database).this has reduced the timing to 49 minutes from 150 minutes.

below is the latest output from tkprof.

tkprof after setting db_file_multiblock_read_count = 128

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 2 487.44 2929.53 944938 49242791 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 487.44 2929.53 944938 49242791 0 1

Misses in library cache during parse: 0
Optimizer goal: CHOOSE
Parsing user id: 65 (APPS)

Rows Row Source Operation
------- ---------------------------------------------------
1 SORT AGGREGATE (cr=49242791 r=944938 w=0 time=2078653852 us)
44667 HASH JOIN OUTER (cr=49242791 r=944938 w=0 time=2078646583 us)
44667 NESTED LOOPS (cr=49214205 r=916376 w=0 time=2067884881 us)
44667 NESTED LOOPS (cr=49079887 r=915788 w=0 time=2062053677 us)
44667 NESTED LOOPS OUTER (cr=48990202 r=911990 w=0 time=2032898533 us)
44662 NESTED LOOPS (cr=48896223 r=910701 w=0 time=2022465560 us)
44662 NESTED LOOPS (cr=48806897 r=910091 w=0 time=2015902039 us)
504196 NESTED LOOPS (cr=47305232 r=898123 w=0 time=2251611231 us)
504196 NESTED LOOPS (cr=46801034 r=898123 w=0 time=2247582494 us)
504196 NESTED LOOPS OUTER (cr=46801032 r=898123 w=0 time=2245988657 us)
504196 NESTED LOOPS (cr=45890010 r=898119 w=0 time=2239981753 us)
4996145 NESTED LOOPS (cr=15515286 r=508626 w=0 time=292613691 us)
4996288 HASH JOIN (cr=526849 r=503001 w=0 time=174616803 us)
12661 MERGE JOIN CARTESIAN (cr=555 r=0 w=0 time=13739 us)
11 INDEX RANGE SCAN OBJ#(705891) (cr=4 r=0 w=0 time=109 us)(object id 705891)
12661 BUFFER SORT (cr=551 r=0 w=0 time=11047 us)
1151 TABLE ACCESS BY INDEX ROWID OBJ#(7594171) (cr=551 r=0 w=0 time=4319 us)
1151 INDEX RANGE SCAN OBJ#(7595477) (cr=8 r=0 w=0 time=1455 us)(object id 7595477)
512900 TABLE ACCESS FULL OBJ#(688602) (cr=526294 r=503001 w=0 time=163741321 us)
4996145 TABLE ACCESS BY INDEX ROWID OBJ#(714940) (cr=14988437 r=5625 w=0 time=109268616 us)
4996145 INDEX UNIQUE SCAN OBJ#(715003) (cr=9992292 r=800 w=0 time=38210555 us)(object id 715003)
504196 TABLE ACCESS BY INDEX ROWID OBJ#(688843) (cr=30374724 r=389493 w=0 time=2477426717 us)
9126865 INDEX RANGE SCAN OBJ#(688858) (cr=10044455 r=35885 w=0 time=221755123 us)(object id 688858)
455389 INDEX RANGE SCAN OBJ#(705891) (cr=911022 r=4 w=0 time=4482920 us)(object id 705891)
504196 INDEX UNIQUE SCAN OBJ#(9847) (cr=2 r=0 w=0 time=794536 us)(object id 9847)
504196 INDEX RANGE SCAN OBJ#(7595476) (cr=504198 r=0 w=0 time=3120506 us)(object id 7595476)
44662 TABLE ACCESS BY INDEX ROWID OBJ#(688523) (cr=1501665 r=11968 w=0 time=72900178 us)
491282 INDEX RANGE SCAN OBJ#(688572) (cr=1010935 r=2449 w=0 time=22343567 us)(object id 688572)
44662 INDEX UNIQUE SCAN OBJ#(1939950) (cr=89326 r=610 w=0 time=6443723 us)(object id 1939950)
2505 TABLE ACCESS BY INDEX ROWID OBJ#(7594103) (cr=93979 r=1289 w=0 time=10222440 us)
2505 INDEX RANGE SCAN OBJ#(7595413) (cr=91477 r=633 w=0 time=4988619 us)(object id 7595413)
44667 INDEX RANGE SCAN OBJ#(688773) (cr=89685 r=3798 w=0 time=29012757 us)(object id 688773)
44667 INDEX RANGE SCAN OBJ#(331689) (cr=134318 r=588 w=0 time=5676434 us)(object id 331689)
1013286 TABLE ACCESS FULL OBJ#(3718019) (cr=28586 r=28562 w=0 time=9581968 us)


Rows Execution Plan
------- ---------------------------------------------------
0 SELECT STATEMENT GOAL: CHOOSE
1 SORT (AGGREGATE)
44667 HASH JOIN (OUTER)
44667 NESTED LOOPS
44667 NESTED LOOPS
44667 NESTED LOOPS (OUTER)
44662 NESTED LOOPS
44662 NESTED LOOPS
504196 NESTED LOOPS
504196 NESTED LOOPS
504196 NESTED LOOPS (OUTER)
504196 NESTED LOOPS
4996145 NESTED LOOPS
4996288 HASH JOIN
12661 MERGE JOIN (CARTESIAN)
11 INDEX GOAL: ANALYZED (RANGE SCAN)
OF 'FND_LOOKUP_VALUES_U1' (UNIQUE)
12661 BUFFER (SORT)
1151 TABLE ACCESS GOAL: ANALYZED (BY INDEX ROWID) OF 'OE_TRANSACTION_TYPES_TL'
1151 INDEX GOAL: ANALYZED (RANGE SCAN) OF 'OE_TRANSACTION_TYPES_TL_U2' (NON-UNIQUE)
512900 TABLE ACCESS GOAL: ANALYZED (FULL) OF 'OE_ORDER_HEADERS_ALL'
4996145 TABLE ACCESS GOAL: ANALYZED (BY INDEX ROWID) OF 'HZ_CUST_ACCOUNTS'
4996145 INDEX GOAL: ANALYZED (UNIQUE SCAN) OF 'HZ_CUST_ACCOUNTS_U1' (UNIQUE)
504196 TABLE ACCESS GOAL: ANALYZED (BY INDEX ROWID) OF 'OE_ORDER_LINES_ALL'
9126865 INDEX GOAL: ANALYZED (RANGE SCAN) OF 'OE_ORDER_LINES_N1' (NON-UNIQUE)
455389 INDEX GOAL: ANALYZED (RANGE SCAN) OF 'FND_LOOKUP_VALUES_U1' (UNIQUE)
504196 INDEX GOAL: ANALYZED (UNIQUE SCAN) OF 'MTL_PARAMETERS_U1' (UNIQUE)
504196 INDEX GOAL: ANALYZED (RANGE SCAN) OF 'OE_TRANSACTION_TYPES_TL_U1' (UNIQUE)
44662 TABLE ACCESS GOAL: ANALYZED (BY INDEX ROWID) OF 'WSH_DELIVERY_DETAILS'
491282 INDEX GOAL: ANALYZED (RANGE SCAN) OF
'WSH_DELIVERY_DETAILS_N3' (NON-UNIQUE)
44662 INDEX GOAL: ANALYZED (UNIQUE SCAN) OF
'HZ_PARTIES_U1' (UNIQUE)
2505 TABLE ACCESS GOAL: ANALYZED (BY INDEX ROWID) OF
'OE_ORDER_HOLDS_ALL'
2505 INDEX GOAL: ANALYZED (RANGE SCAN) OF
'OE_ORDER_HOLDS_ALL_N2' (NON-UNIQUE)
44667 INDEX GOAL: ANALYZED (RANGE SCAN) OF
'WSH_DELIVERY_ASSIGNMENTS_N3' (NON-UNIQUE)
44667 INDEX GOAL: ANALYZED (RANGE SCAN) OF
'MTL_SYSTEM_ITEMS_B_N1' (NON-UNIQUE)
1013286 TABLE ACCESS GOAL: ANALYZED (FULL) OF
'GEMS_POM_SROM_HDR_EXT'


Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 2 0.00 0.00
db file scattered read 12215 0.22 80.80
global cache cr request 266383 0.12 101.16
db file parallel read 962 0.31 34.11
latch free 184 0.01 0.07
db file sequential read 415626 0.50 2313.30
global cache s to x 5 0.00 0.00
SQL*Net message from client 2 23.10 23.10



********************************************************************************

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 2 0.00 0.00 0 0 0 0
Fetch 2 487.44 2929.53 944938 49242791 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 5 487.44 2929.53 944938 49242791 0 1


changed the db file multiblock read count

Reene, December 03, 2007 - 7:43 am UTC

Hi tom

I changed the the value of db file multiblock read count to 128 at the session level and then ran this sql again.

the run time has reduced to 49 minutes from 150 minutes.

here is the lates o/p from tkprof


tkprof after setting db_file_multiblock_read_count = 128

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 2 487.44 2929.53 944938 49242791 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 487.44 2929.53 944938 49242791 0 1

Misses in library cache during parse: 0
Optimizer goal: CHOOSE
Parsing user id: 65 (APPS)

Rows Row Source Operation
------- ---------------------------------------------------
1 SORT AGGREGATE (cr=49242791 r=944938 w=0 time=2078653852 us)
44667 HASH JOIN OUTER (cr=49242791 r=944938 w=0 time=2078646583 us)
44667 NESTED LOOPS (cr=49214205 r=916376 w=0 time=2067884881 us)
44667 NESTED LOOPS (cr=49079887 r=915788 w=0 time=2062053677 us)
44667 NESTED LOOPS OUTER (cr=48990202 r=911990 w=0 time=2032898533 us)
44662 NESTED LOOPS (cr=48896223 r=910701 w=0 time=2022465560 us)
44662 NESTED LOOPS (cr=48806897 r=910091 w=0 time=2015902039 us)
504196 NESTED LOOPS (cr=47305232 r=898123 w=0 time=2251611231 us)
504196 NESTED LOOPS (cr=46801034 r=898123 w=0 time=2247582494 us)
504196 NESTED LOOPS OUTER (cr=46801032 r=898123 w=0 time=2245988657 us)
504196 NESTED LOOPS (cr=45890010 r=898119 w=0 time=2239981753 us)
4996145 NESTED LOOPS (cr=15515286 r=508626 w=0 time=292613691 us)
4996288 HASH JOIN (cr=526849 r=503001 w=0 time=174616803 us)
12661 MERGE JOIN CARTESIAN (cr=555 r=0 w=0 time=13739 us)
11 INDEX RANGE SCAN OBJ#(705891) (cr=4 r=0 w=0 time=109 us)(object id 705891)
12661 BUFFER SORT (cr=551 r=0 w=0 time=11047 us)
1151 TABLE ACCESS BY INDEX ROWID OBJ#(7594171) (cr=551 r=0 w=0 time=4319 us)
1151 INDEX RANGE SCAN OBJ#(7595477) (cr=8 r=0 w=0 time=1455 us)(object id 7595477)
512900 TABLE ACCESS FULL OBJ#(688602) (cr=526294 r=503001 w=0 time=163741321 us)
4996145 TABLE ACCESS BY INDEX ROWID OBJ#(714940) (cr=14988437 r=5625 w=0 time=109268616 us)
4996145 INDEX UNIQUE SCAN OBJ#(715003) (cr=9992292 r=800 w=0 time=38210555 us)(object id 715003)
504196 TABLE ACCESS BY INDEX ROWID OBJ#(688843) (cr=30374724 r=389493 w=0 time=2477426717 us)
9126865 INDEX RANGE SCAN OBJ#(688858) (cr=10044455 r=35885 w=0 time=221755123 us)(object id 688858)
455389 INDEX RANGE SCAN OBJ#(705891) (cr=911022 r=4 w=0 time=4482920 us)(object id 705891)
504196 INDEX UNIQUE SCAN OBJ#(9847) (cr=2 r=0 w=0 time=794536 us)(object id 9847)
504196 INDEX RANGE SCAN OBJ#(7595476) (cr=504198 r=0 w=0 time=3120506 us)(object id 7595476)
44662 TABLE ACCESS BY INDEX ROWID OBJ#(688523) (cr=1501665 r=11968 w=0 time=72900178 us)
491282 INDEX RANGE SCAN OBJ#(688572) (cr=1010935 r=2449 w=0 time=22343567 us)(object id 688572)
44662 INDEX UNIQUE SCAN OBJ#(1939950) (cr=89326 r=610 w=0 time=6443723 us)(object id 1939950)
2505 TABLE ACCESS BY INDEX ROWID OBJ#(7594103) (cr=93979 r=1289 w=0 time=10222440 us)
2505 INDEX RANGE SCAN OBJ#(7595413) (cr=91477 r=633 w=0 time=4988619 us)(object id 7595413)
44667 INDEX RANGE SCAN OBJ#(688773) (cr=89685 r=3798 w=0 time=29012757 us)(object id 688773)
44667 INDEX RANGE SCAN OBJ#(331689) (cr=134318 r=588 w=0 time=5676434 us)(object id 331689)
1013286 TABLE ACCESS FULL OBJ#(3718019) (cr=28586 r=28562 w=0 time=9581968 us)


Rows Execution Plan
------- ---------------------------------------------------
0 SELECT STATEMENT GOAL: CHOOSE
1 SORT (AGGREGATE)
44667 HASH JOIN (OUTER)
44667 NESTED LOOPS
44667 NESTED LOOPS
44667 NESTED LOOPS (OUTER)
44662 NESTED LOOPS
44662 NESTED LOOPS
504196 NESTED LOOPS
504196 NESTED LOOPS
504196 NESTED LOOPS (OUTER)
504196 NESTED LOOPS
4996145 NESTED LOOPS
4996288 HASH JOIN
12661 MERGE JOIN (CARTESIAN)
11 INDEX GOAL: ANALYZED (RANGE SCAN)
OF 'FND_LOOKUP_VALUES_U1' (UNIQUE)
12661 BUFFER (SORT)
1151 TABLE ACCESS GOAL: ANALYZED (BY INDEX ROWID) OF 'OE_TRANSACTION_TYPES_TL'
1151 INDEX GOAL: ANALYZED (RANGE SCAN) OF 'OE_TRANSACTION_TYPES_TL_U2' (NON-UNIQUE)
512900 TABLE ACCESS GOAL: ANALYZED (FULL) OF 'OE_ORDER_HEADERS_ALL'
4996145 TABLE ACCESS GOAL: ANALYZED (BY INDEX ROWID) OF 'HZ_CUST_ACCOUNTS'
4996145 INDEX GOAL: ANALYZED (UNIQUE SCAN) OF 'HZ_CUST_ACCOUNTS_U1' (UNIQUE)
504196 TABLE ACCESS GOAL: ANALYZED (BY INDEX ROWID) OF 'OE_ORDER_LINES_ALL'
9126865 INDEX GOAL: ANALYZED (RANGE SCAN) OF 'OE_ORDER_LINES_N1' (NON-UNIQUE)
455389 INDEX GOAL: ANALYZED (RANGE SCAN) OF 'FND_LOOKUP_VALUES_U1' (UNIQUE)
504196 INDEX GOAL: ANALYZED (UNIQUE SCAN) OF 'MTL_PARAMETERS_U1' (UNIQUE)
504196 INDEX GOAL: ANALYZED (RANGE SCAN) OF 'OE_TRANSACTION_TYPES_TL_U1' (UNIQUE)
44662 TABLE ACCESS GOAL: ANALYZED (BY INDEX ROWID) OF 'WSH_DELIVERY_DETAILS'
491282 INDEX GOAL: ANALYZED (RANGE SCAN) OF
'WSH_DELIVERY_DETAILS_N3' (NON-UNIQUE)
44662 INDEX GOAL: ANALYZED (UNIQUE SCAN) OF
'HZ_PARTIES_U1' (UNIQUE)
2505 TABLE ACCESS GOAL: ANALYZED (BY INDEX ROWID) OF
'OE_ORDER_HOLDS_ALL'
2505 INDEX GOAL: ANALYZED (RANGE SCAN) OF
'OE_ORDER_HOLDS_ALL_N2' (NON-UNIQUE)
44667 INDEX GOAL: ANALYZED (RANGE SCAN) OF
'WSH_DELIVERY_ASSIGNMENTS_N3' (NON-UNIQUE)
44667 INDEX GOAL: ANALYZED (RANGE SCAN) OF
'MTL_SYSTEM_ITEMS_B_N1' (NON-UNIQUE)
1013286 TABLE ACCESS GOAL: ANALYZED (FULL) OF
'GEMS_POM_SROM_HDR_EXT'


Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 2 0.00 0.00
db file scattered read 12215 0.22 80.80
global cache cr request 266383 0.12 101.16
db file parallel read 962 0.31 34.11
latch free 184 0.01 0.07
db file sequential read 415626 0.50 2313.30
global cache s to x 5 0.00 0.00
SQL*Net message from client 2 23.10 23.10



********************************************************************************

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 2 0.00 0.00 0 0 0 0
Fetch 2 487.44 2929.53 944938 49242791 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 5 487.44 2929.53 944938 49242791 0 1


Change with dbfile multiblock read count

Reene, December 03, 2007 - 7:57 am UTC

Hi Tom.

For the above question - I changed the db file multiblock read count to 128 at the session level (actual value in db is set as 8) and there is hugge improvement- query takes 49 minutes from 150 minutes.

below is the latest o/p of tkprof

tkprof after setting db_file_multiblock_read_count = 128

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 2 487.44 2929.53 944938 49242791 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 487.44 2929.53 944938 49242791 0 1

Misses in library cache during parse: 0
Optimizer goal: CHOOSE
Parsing user id: 65 (APPS)

Rows Row Source Operation
------- ---------------------------------------------------
1 SORT AGGREGATE (cr=49242791 r=944938 w=0 time=2078653852 us)
44667 HASH JOIN OUTER (cr=49242791 r=944938 w=0 time=2078646583 us)
44667 NESTED LOOPS (cr=49214205 r=916376 w=0 time=2067884881 us)
44667 NESTED LOOPS (cr=49079887 r=915788 w=0 time=2062053677 us)
44667 NESTED LOOPS OUTER (cr=48990202 r=911990 w=0 time=2032898533 us)
44662 NESTED LOOPS (cr=48896223 r=910701 w=0 time=2022465560 us)
44662 NESTED LOOPS (cr=48806897 r=910091 w=0 time=2015902039 us)
504196 NESTED LOOPS (cr=47305232 r=898123 w=0 time=2251611231 us)
504196 NESTED LOOPS (cr=46801034 r=898123 w=0 time=2247582494 us)
504196 NESTED LOOPS OUTER (cr=46801032 r=898123 w=0 time=2245988657 us)
504196 NESTED LOOPS (cr=45890010 r=898119 w=0 time=2239981753 us)
4996145 NESTED LOOPS (cr=15515286 r=508626 w=0 time=292613691 us)
4996288 HASH JOIN (cr=526849 r=503001 w=0 time=174616803 us)
12661 MERGE JOIN CARTESIAN (cr=555 r=0 w=0 time=13739 us)
11 INDEX RANGE SCAN OBJ#(705891) (cr=4 r=0 w=0 time=109 us)(object id 705891)
12661 BUFFER SORT (cr=551 r=0 w=0 time=11047 us)
1151 TABLE ACCESS BY INDEX ROWID OBJ#(7594171) (cr=551 r=0 w=0 time=4319 us)
1151 INDEX RANGE SCAN OBJ#(7595477) (cr=8 r=0 w=0 time=1455 us)(object id 7595477)
512900 TABLE ACCESS FULL OBJ#(688602) (cr=526294 r=503001 w=0 time=163741321 us)
4996145 TABLE ACCESS BY INDEX ROWID OBJ#(714940) (cr=14988437 r=5625 w=0 time=109268616 us)
4996145 INDEX UNIQUE SCAN OBJ#(715003) (cr=9992292 r=800 w=0 time=38210555 us)(object id 715003)
504196 TABLE ACCESS BY INDEX ROWID OBJ#(688843) (cr=30374724 r=389493 w=0 time=2477426717 us)
9126865 INDEX RANGE SCAN OBJ#(688858) (cr=10044455 r=35885 w=0 time=221755123 us)(object id 688858)
455389 INDEX RANGE SCAN OBJ#(705891) (cr=911022 r=4 w=0 time=4482920 us)(object id 705891)
504196 INDEX UNIQUE SCAN OBJ#(9847) (cr=2 r=0 w=0 time=794536 us)(object id 9847)
504196 INDEX RANGE SCAN OBJ#(7595476) (cr=504198 r=0 w=0 time=3120506 us)(object id 7595476)
44662 TABLE ACCESS BY INDEX ROWID OBJ#(688523) (cr=1501665 r=11968 w=0 time=72900178 us)
491282 INDEX RANGE SCAN OBJ#(688572) (cr=1010935 r=2449 w=0 time=22343567 us)(object id 688572)
44662 INDEX UNIQUE SCAN OBJ#(1939950) (cr=89326 r=610 w=0 time=6443723 us)(object id 1939950)
2505 TABLE ACCESS BY INDEX ROWID OBJ#(7594103) (cr=93979 r=1289 w=0 time=10222440 us)
2505 INDEX RANGE SCAN OBJ#(7595413) (cr=91477 r=633 w=0 time=4988619 us)(object id 7595413)
44667 INDEX RANGE SCAN OBJ#(688773) (cr=89685 r=3798 w=0 time=29012757 us)(object id 688773)
44667 INDEX RANGE SCAN OBJ#(331689) (cr=134318 r=588 w=0 time=5676434 us)(object id 331689)
1013286 TABLE ACCESS FULL OBJ#(3718019) (cr=28586 r=28562 w=0 time=9581968 us)


Rows Execution Plan
------- ---------------------------------------------------
0 SELECT STATEMENT GOAL: CHOOSE
1 SORT (AGGREGATE)
44667 HASH JOIN (OUTER)
44667 NESTED LOOPS
44667 NESTED LOOPS
44667 NESTED LOOPS (OUTER)
44662 NESTED LOOPS
44662 NESTED LOOPS
504196 NESTED LOOPS
504196 NESTED LOOPS
504196 NESTED LOOPS (OUTER)
504196 NESTED LOOPS
4996145 NESTED LOOPS
4996288 HASH JOIN
12661 MERGE JOIN (CARTESIAN)
11 INDEX GOAL: ANALYZED (RANGE SCAN)
OF 'FND_LOOKUP_VALUES_U1' (UNIQUE)
12661 BUFFER (SORT)
1151 TABLE ACCESS GOAL: ANALYZED (BY INDEX ROWID) OF 'OE_TRANSACTION_TYPES_TL'
1151 INDEX GOAL: ANALYZED (RANGE SCAN) OF 'OE_TRANSACTION_TYPES_TL_U2' (NON-UNIQUE)
512900 TABLE ACCESS GOAL: ANALYZED (FULL) OF 'OE_ORDER_HEADERS_ALL'
4996145 TABLE ACCESS GOAL: ANALYZED (BY INDEX ROWID) OF 'HZ_CUST_ACCOUNTS'
4996145 INDEX GOAL: ANALYZED (UNIQUE SCAN) OF 'HZ_CUST_ACCOUNTS_U1' (UNIQUE)
504196 TABLE ACCESS GOAL: ANALYZED (BY INDEX ROWID) OF 'OE_ORDER_LINES_ALL'
9126865 INDEX GOAL: ANALYZED (RANGE SCAN) OF 'OE_ORDER_LINES_N1' (NON-UNIQUE)
455389 INDEX GOAL: ANALYZED (RANGE SCAN) OF 'FND_LOOKUP_VALUES_U1' (UNIQUE)
504196 INDEX GOAL: ANALYZED (UNIQUE SCAN) OF 'MTL_PARAMETERS_U1' (UNIQUE)
504196 INDEX GOAL: ANALYZED (RANGE SCAN) OF 'OE_TRANSACTION_TYPES_TL_U1' (UNIQUE)
44662 TABLE ACCESS GOAL: ANALYZED (BY INDEX ROWID) OF 'WSH_DELIVERY_DETAILS'
491282 INDEX GOAL: ANALYZED (RANGE SCAN) OF
'WSH_DELIVERY_DETAILS_N3' (NON-UNIQUE)
44662 INDEX GOAL: ANALYZED (UNIQUE SCAN) OF
'HZ_PARTIES_U1' (UNIQUE)
2505 TABLE ACCESS GOAL: ANALYZED (BY INDEX ROWID) OF
'OE_ORDER_HOLDS_ALL'
2505 INDEX GOAL: ANALYZED (RANGE SCAN) OF
'OE_ORDER_HOLDS_ALL_N2' (NON-UNIQUE)
44667 INDEX GOAL: ANALYZED (RANGE SCAN) OF
'WSH_DELIVERY_ASSIGNMENTS_N3' (NON-UNIQUE)
44667 INDEX GOAL: ANALYZED (RANGE SCAN) OF
'MTL_SYSTEM_ITEMS_B_N1' (NON-UNIQUE)
1013286 TABLE ACCESS GOAL: ANALYZED (FULL) OF
'GEMS_POM_SROM_HDR_EXT'


Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 2 0.00 0.00
db file scattered read 12215 0.22 80.80
global cache cr request 266383 0.12 101.16
db file parallel read 962 0.31 34.11
latch free 184 0.01 0.07
db file sequential read 415626 0.50 2313.30
global cache s to x 5 0.00 0.00
SQL*Net message from client 2 23.10 23.10



********************************************************************************

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 2 0.00 0.00 0 0 0 0
Fetch 2 487.44 2929.53 944938 49242791 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 5 487.44 2929.53 944938 49242791 0 1

the original query is

select count(*)
from
(
SELECT
oha.order_number || '|' ||
oha.cust_po_number || '|' ||
hca.ACCOUNT_NUMBER || '|' ||
hp.party_name || '|' ||
ott.name || '|' ||
otl.name || '|' ||
ola.return_reason_code || '|' ||
ola.SOURCE_TYPE_CODE || '|' ||
oha.flow_status_code || '|' ||
ola.flow_STATUS_CODE || '|' ||
TRUNC(oha.creation_date) || '|' ||
som.created_by || '|' ||
TRUNC(oha.booked_date) || '|' ||
DECODE(hold.released_flag, 'Y', 'N', NULL, 'N', 'N', 'Y') || '|' ||
ola.line_number || '|' ||
org.organization_code || '|' ||
ola.ordered_item || '|' ||
msi.item_type || '|' ||
ola.ordered_quantity || '|' ||
ola.unit_selling_price || '|' ||
ola.ordered_quantity*ola.unit_selling_price || '|' ||
TRUNC(ola.schedule_ship_date) || '|' ||
TRUNC(ola.request_date) || '|' ||
TRUNC(ola.promise_date) || '|' ||
ola.ACTUAL_SHIPMENT_DATE || '|' ||
ola.SHIP_SET_ID || '|' ||
ola.LINE_SET_ID || '|' ||
flv.meaning || '|' ||
DECODE(ola.source_type_code, 'INTERNAL', 'N', 'EXTERNAL', 'Y') || '|' ||
DECODE(ola.attribute13, 1, 'Y', 3, 'Y', NULL, 'N') || '|' ||
NVL(DECODE(wl.meaning, 'Backordered', 'Y'), 'N') || '|' ||
decode(wdd.released_status, 'Y', 'Y', 'C', 'Y', 'I', 'Y', 'N')|| '|' ||
wl.meaning || '|' ||
wdd.oe_interfaced_flag
FROM
ont.oe_order_headers_all oha ,
apps.hz_cust_accounts hca ,
apps.hz_parties hp ,
apps.FND_LOOKUP_VALUES_VL flv ,
ont.oe_order_holds_all hold ,
ont.oe_order_lines_all ola ,
inv.mtl_system_items_b msi ,
inv.mtl_parameters org ,
wsh.wsh_delivery_details wdd ,
WSH.WSH_DELIVERY_ASSIGNMENTS WDA ,
apps.wsh_lookups wl ,
ont.oe_transaction_types_tl ott ,
apps.oe_transaction_types_tl otl ,
gems_pom.gems_pom_srom_hdr_ext som
WHERE
oha.org_id = 3171 AND
flv.LOOKUP_TYPE(+) = 'SHIP_METHOD' AND
ola.shipping_method_code = flv.lookup_code(+) AND
flv.VIEW_APPLICATION_ID(+) = 3 AND
oha.sold_to_org_id = hca.cust_account_id AND
hca.party_id = hp.party_id AND
ola.header_id=hold.header_id (+) and
ola.line_id = hold.line_id (+) AND
oha.header_id=ola.header_id and
ola.ORDERED_ITEM = msi.segment1 and
ola.SHIP_FROM_ORG_ID = msi.organization_id and
oha.order_type_id=ott.transaction_type_id and
ola.line_type_id = otl.transaction_type_id and
ott.name like 'GPO%' AND
ola.ship_from_org_id=org.organization_id AND
ola.line_id=wdd.source_line_id (+) and
wdd.DELIVERY_DETAIL_ID = WDA.DELIVERY_DETAIL_ID AND
wl.lookup_code = NVL(wdd.released_status,'X') AND
wl.lookup_code = NVL(wdd.released_status,'X') AND
wl.lookup_type='PICK_STATUS' and
som.order_number(+) = oha.order_number
and ola.flow_status_code = 'CLOSED'
and ola.ACTUAL_SHIPMENT_DATE >= (trunc(sysdate)-56)
)


object id 688843

Reene, December 03, 2007 - 8:03 am UTC

Hi Tom this object id has lots of rows,i think due to a filter it shows less rows in the row source operation,otherwise this table has 5 million rows.

the oha table is the what you have pointed out.
338509 TABLE ACCESS FULL OBJ#(688843) (cr=24135343 r=3136408 w=0 time=6650644848 us)

this is basically a table with 5 m rows and in the query thetre is a filter org_id = 3171 and this comes out as 338509.

query I have posted above..

also I am not able to post anything in the review for this question.

Check Your Query

Venkat K, December 03, 2007 - 6:34 pm UTC

Hi Renee,

It looks like you are looking at a report that has to comb through massive amount of data - all the orders shipped in the last X number of days, the various holds, shipping details, etc and it looks like you are not using any filters to filter this vast data (except for the shipment date). So, the query taking as long as it is taking (a couple of hours) is not that big of a deal considering that you did not include any meaningful filters. If you are not passing any other parameters via the concurrent program, then the time seems reasonable - to me.

Either way, here are a few comments/suggestions based on your SQL. I did not try my suggestions(I have a 10g database) so take it with a grain of salt.

1. I see that you are joining Order Lines (OLA) to MTL_SYSTEM_ITEMS using SEGMENT1. First of all, this is not necessarily a reliable join since ORDERED_ITEM in ONT may/can be different from Item number (SEGMENT1) in Inventory. The better join would be to join OLA.INVENTORY_ITEM_ID to MSI.INVENTORY_ITEM_ID. I am hoping this would make use of the unique index on MTL_SYSTEM_ITEMS instead of the non-unique index that is currently being used. Not sure the unique index will help your overall performance.

2. The outer join on WSH_DELIVERY_DETAILS (WDD) seems to be redundant since you are not fetching records without deliveries (no outer join to WDA from WDD).

3. I am assuming that the filter at the end
and ola.ACTUAL_SHIPMENT_DATE >= (trunc(sysdate)-56)
is passed from concurrent manager based on user input.
If so, you might want to consider indexing ACTUAL_SHIPMENT_DATE. I realize creating an index might not be a favorable option but if this kind of reporting is used elsewhere in your organization, the index actually could be beneficial.

4. Finally, just schedule the report in concurrent manager and run it in batch for a certain number of days like 60 days (parameter value) and distribute the report to the users. Since the output is already delimited via pipes to be used in Excel(I presume), the end users can get rid of the data for days they are not interested in.


Regards,
Venkat

10046 outpuput

Reene, December 04, 2007 - 1:18 am UTC

Hi Tom

below the wait events stats for the above SQL.

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 2 0.00 0.00 0 0 0 0
Fetch 2 1042.59 8209.22 5045985 26070806 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 5 1042.59 8209.23 5045985 26070806 0 1

Misses in library cache during parse: 0
Misses in library cache during execute: 1

Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 3 0.00 0.00
SQL*Net message from client 3 0.00 0.00
SQL*Net more data from client 1 0.00 0.00
library cache lock 9 0.00 0.00
global cache cr request 1141939 0.08 345.37
db file sequential read 1157994 2.53 5919.90
db file scattered read 544248 0.64 1199.10
direct path write 835 0.08 0.42
direct path read 835 0.04 2.52
db file parallel read 992 0.48 5.17
latch free 23 0.01 0.03
global cache busy 53 0.98 42.20
log file sync 3 0.00 0.00
global cache s to x 4 0.00 0.00

please let me know if I should make another chnage.

Thanks

thanks!!

Reene, December 04, 2007 - 1:27 am UTC

Hi Tom,
thanks for your help and answering so many questiones.
Now I fee that i am better equipped to solve my problems.

As i mentioned in email , when I changed the following 3 parameters at the session level -
optimizer_index_cost_adj = 35 (it is 100 )
optimizer_index_caching = 65 (it is 0 otherwise in my db)
and
db_file_multiblock_read_count to 128 ( 8 is the value set in db)

then the run time of this query has come down to 36 minutes and the cpu time has also reduced to 1/3 .

thanks for help and explaining so many things.

new observation

Reene, December 04, 2007 - 1:33 am UTC

Hi Tom for the above SQL, when I took 10046 trace,

I observed one more thing , there is huge difference in explain plan and row sourc operation for the same SQL.

just want to post it , as I am not sure if it has some special signifcance, does 10046 has more accurate information than sql_trace=true ?

Misses in library cache during parse: 0
Optimizer goal: CHOOSE
Parsing user id: 65 (APPS)

Rows Row Source Operation
------- ---------------------------------------------------
1 SORT AGGREGATE (cr=26070806 r=5045985 w=16405 time=1776064069 us)
38085 HASH JOIN OUTER (cr=26070806 r=5045985 w=16405 time=1776057647 us)
38085 HASH JOIN OUTER (cr=26042338 r=5016270 w=15134 time=1763309392 us)
38085 HASH JOIN (cr=26042331 r=5014818 w=13685 time=1762665449 us)
11 INDEX RANGE SCAN OBJ#(705891) (cr=4 r=1 w=0 time=14148 us)(object id 705891)
38085 HASH JOIN (cr=26042327 r=5014817 w=13685 time=1762596181 us)
38085 HASH JOIN (cr=25917429 r=4896992 w=13685 time=1701992070 us)
39104 HASH JOIN (cr=24985795 r=3966156 w=13685 time=1457139819 us)
1151 TABLE ACCESS FULL OBJ#(7594171) (cr=94 r=0 w=0 time=4563 us)
58624 HASH JOIN (cr=24985701 r=3966156 w=13685 time=1457092349 us)
58624 HASH JOIN (cr=24983318 r=3962462 w=12369 time=1452948176 us)
406968 TABLE ACCESS FULL OBJ#(714940) (cr=15805 r=14386 w=0 time=7219977 us)
58624 NESTED LOOPS (cr=24967513 r=3947425 w=11718 time=1452847321 us)
58624 HASH JOIN (cr=24967511 r=3947425 w=11718 time=1452703811 us)
338617 HASH JOIN (cr=24444242 r=3447779 w=6944 time=1300174765 us)
338618 HASH JOIN OUTER (cr=24165096 r=3169069 w=3255 time=301829561 us)
338509 HASH JOIN (cr=24135357 r=3136409 w=0 time=6651149555 us)
4578 INDEX FULL SCAN OBJ#(7595476) (cr=14 r=1 w=0 time=14275 us)(object id 7595476)
338509 TABLE ACCESS FULL OBJ#(688843) (cr=24135343 r=3136408 w=0 time=6650644848 us)
1066020 TABLE ACCESS FULL OBJ#(7594103) (cr=29739 r=29405 w=0 time=11493856 us)
54769448 INDEX FULL SCAN OBJ#(331689) (cr=279146 r=275021 w=0 time=959480358 us)(object id 331689)
508654 TABLE ACCESS FULL OBJ#(688602) (cr=523269 r=494872 w=0 time=149020996 us)
58624 INDEX UNIQUE SCAN OBJ#(9847) (cr=2 r=0 w=0 time=74471 us)(object id 9847)
981901 INDEX FULL SCAN OBJ#(1939950) (cr=2383 r=2378 w=0 time=2979619 us)(object id 1939950)
13773143 TABLE ACCESS FULL OBJ#(688523) (cr=931634 r=930836 w=0 time=237689953 us)
13777354 TABLE ACCESS FULL OBJ#(688727) (cr=124898 r=117825 w=0 time=54211671 us)
612 INDEX RANGE SCAN OBJ#(705891) (cr=7 r=3 w=0 time=22325 us)(object id 705891)
1009040 TABLE ACCESS FULL OBJ#(3718019) (cr=28468 r=28444 w=0 time=11706833 us)


Rows Execution Plan
------- ---------------------------------------------------
0 SELECT STATEMENT GOAL: CHOOSE
1 SORT (AGGREGATE)
38085 HASH JOIN (OUTER)
38085 NESTED LOOPS
38085 NESTED LOOPS
11 NESTED LOOPS (OUTER)
38085 NESTED LOOPS
38085 NESTED LOOPS
39104 NESTED LOOPS
1151 NESTED LOOPS
58624 NESTED LOOPS (OUTER)
58624 NESTED LOOPS
406968 NESTED LOOPS
58624 HASH JOIN
58624 MERGE JOIN (CARTESIAN)
338617 INDEX GOAL: ANALYZED (RANGE SCAN) OF 'FND_LOOKUP_VALUES_U1' (UNIQUE)
338618 BUFFER (SORT)
338509 TABLE ACCESS GOAL: ANALYZED (BY INDEX ROWID) OF 'OE_TRANSACTION_TYPES_TL'
4578 INDEX GOAL: ANALYZED (RANGE SCAN) OF 'OE_TRANSACTION_TYPES_TL_U2'
(NON-UNIQUE)
338509 TABLE ACCESS GOAL: ANALYZED (FULL) OF 'OE_ORDER_HEADERS_ALL'
1066020 TABLE ACCESS GOAL: ANALYZED (BY INDEX ROWID) OF 'HZ_CUST_ACCOUNTS'
54769448 INDEX GOAL: ANALYZED (UNIQUE SCAN) OF 'HZ_CUST_ACCOUNTS_U1' (UNIQUE)
508654 TABLE ACCESS GOAL: ANALYZED (BY INDEX ROWID) OF 'OE_ORDER_LINES_ALL'
58624 INDEX GOAL: ANALYZED (RANGE SCAN) OF 'OE_ORDER_LINES_N1' (NON-UNIQUE)
981901 INDEX GOAL: ANALYZED (RANGE SCAN) OF 'FND_LOOKUP_VALUES_U1' (UNIQUE)
13773143 INDEX GOAL: ANALYZED (UNIQUE SCAN) OF 'MTL_PARAMETERS_U1' (UNIQUE)
13777354 INDEX GOAL: ANALYZED (RANGE SCAN) OF 'OE_TRANSACTION_TYPES_TL_U1' (UNIQUE)
612 TABLE ACCESS GOAL: ANALYZED (BY INDEX ROWID) OF 'WSH_DELIVERY_DETAILS'
1009040 INDEX GOAL: ANALYZED (RANGE SCAN) OF 'WSH_DELIVERY_DETAILS_N3' (NON-UNIQUE)
0 INDEX GOAL: ANALYZED (UNIQUE SCAN) OF 'HZ_PARTIES_U1' (UNIQUE)
0 TABLE ACCESS GOAL: ANALYZED (BY INDEX ROWID) OF 'OE_ORDER_HOLDS_ALL'
0 INDEX GOAL: ANALYZED (RANGE SCAN) OF 'OE_ORDER_HOLDS_ALL_N2' (NON-UNIQUE)
0 INDEX GOAL: ANALYZED (RANGE SCAN) OF 'WSH_DELIVERY_ASSIGNMENTS_N3' (NON-UNIQUE)
0 INDEX GOAL: ANALYZED (RANGE SCAN) OF 'MTL_SYSTEM_ITEMS_B_N1' (NON-UNIQUE)
0 TABLE ACCESS GOAL: ANALYZED (FULL) OF 'GEMS_POM_SROM_HDR_EXT'


Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 2 0.00 0.00
global cache cr request 1141939 0.08 345.37
db file sequential read 1157994 2.53 5919.90
db file scattered read 544248 0.64 1199.10
direct path write 835 0.08 0.42
direct path read 835 0.04 2.52
db file parallel read 992 0.48 5.17
latch free 23 0.01 0.03
global cache busy 53 0.98 42.20
log file sync 3 0.00 0.00
global cache s to x 4 0.00 0.00
SQL*Net message from client 2 0.00 0.00



********************************************************************************

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 2 0.00 0.00 0 0 0 0
Fetch 2 1042.59 8209.22 5045985 26070806 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 5 1042.59 8209.23 5045985 26070806 0 1

Thanks
Tom Kyte
December 03, 2007 - 7:39 am UTC

row source = WHAT HAPPENED FOR REAL, this should always be used

explain plan = what might happen, maybe

http://asktom.oracle.com/Misc/when-explanation-doesn-sound-quite.html


it is hard to say without the query, but looking at this bit:

338509 HASH JOIN (cr=24135357 r=3136409 w=0 time=6651149555 us)
4578 INDEX FULL SCAN OBJ#(7595476) (cr=14 r=1 w=0 time=14275
us)(object id 7595476)
338509 TABLE ACCESS FULL OBJ#(688843) (cr=24135343 r=3136408
w=0 time=6650644848 us)

that seems like a LOT of IO for so few rows - tell us about object 688843 - why so many physical IO's on that guy?

Thanks

Reene, December 04, 2007 - 3:33 am UTC

Hi Tom

when I changed the optimizer_index_caching=90
and optimizer_index_cost_adj=35
and db_file_multiblock_read_count=128
at the session level then this query has improved and it is taking 37 minutes as opposed to 150 miunutes of the earlier timing.

thanks for your help.

below is the latest o/p from tkprof

set timing on ;
alter session set db_file_multiblock_read_count = 128;
alter session set optimizer_index_cost_adj=35 ;
alter session set optimizer_index_caching=75;
alter session set statistics_level = all;
alter session set tracefile_identifier='pt49' ;
--alter session set sql_trace=true ;
alter session set events '10046 trace name context forever, level 12';

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 2 453.93 2214.02 951424 49242445 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 453.93 2214.02 951424 49242445 0 1

Misses in library cache during parse: 0
Optimizer goal: CHOOSE
Parsing user id: 65 (APPS)

Rows Row Source Operation
------- ---------------------------------------------------
1 SORT AGGREGATE (cr=49242445 r=951424 w=0 time=388501655 us)
44667 HASH JOIN OUTER (cr=49242445 r=951424 w=0 time=388494243 us)
44667 NESTED LOOPS (cr=49213859 r=922862 w=0 time=2202203427 us)
44667 NESTED LOOPS (cr=49079541 r=922372 w=0 time=2197845752 us)
44667 NESTED LOOPS OUTER (cr=48989856 r=918596 w=0 time=2174844626 us)
44662 NESTED LOOPS (cr=48897717 r=917361 w=0 time=2166325055 us)
44662 NESTED LOOPS (cr=48808391 r=916865 w=0 time=2161780258 us)
504196 NESTED LOOPS (cr=47306735 r=905888 w=0 time=2108263416 us)
504196 NESTED LOOPS (cr=46802537 r=905887 w=0 time=2104324160 us)
504196 NESTED LOOPS OUTER (cr=46802535 r=905887 w=0 time=2102763657 us)
504196 NESTED LOOPS (cr=45891513 r=905885 w=0 time=2096795107 us)
4996145 NESTED LOOPS (cr=15515295 r=519889 w=0 time=191066622 us)
4996288 HASH JOIN (cr=526858 r=518530 w=0 time=122860099 us)
12661 MERGE JOIN CARTESIAN (cr=555 r=57 w=0 time=289103 us)
11 INDEX RANGE SCAN OBJ#(705891) (cr=4 r=2 w=0 time=18222 us)(object id 705891)
12661 BUFFER SORT (cr=551 r=55 w=0 time=268146 us)
1151 TABLE ACCESS BY INDEX ROWID OBJ#(7594171) (cr=551 r=55 w=0 time=261124 us)
1151 INDEX RANGE SCAN OBJ#(7595477) (cr=8 r=8 w=0 time=14971 us)(object id 7595477)
512900 TABLE ACCESS FULL OBJ#(688602) (cr=526303 r=518473 w=0 time=112755335 us)
4996145 TABLE ACCESS BY INDEX ROWID OBJ#(714940) (cr=14988437 r=1359 w=0 time=59998827 us)
4996145 INDEX UNIQUE SCAN OBJ#(715003) (cr=9992292 r=114 w=0 time=28160559 us)(object id 715003)
504196 TABLE ACCESS BY INDEX ROWID OBJ#(688843) (cr=30376218 r=385996 w=0 time=1895573824 us)
9126865 INDEX RANGE SCAN OBJ#(688858) (cr=10046007 r=37921 w=0 time=165272333 us)(object id 688858)
455389 INDEX RANGE SCAN OBJ#(705891) (cr=911022 r=2 w=0 time=4477719 us)(object id 705891)
504196 INDEX UNIQUE SCAN OBJ#(9847) (cr=2 r=0 w=0 time=775043 us)(object id 9847)
504196 INDEX RANGE SCAN OBJ#(7595476) (cr=504198 r=1 w=0 time=3046061 us)(object id 7595476)
44662 TABLE ACCESS BY INDEX ROWID OBJ#(688523) (cr=1501656 r=10977 w=0 time=52302126 us)
491282 INDEX RANGE SCAN OBJ#(688572) (cr=1010935 r=1678 w=0 time=13737031 us)(object id 688572)
44662 INDEX UNIQUE SCAN OBJ#(1939950) (cr=89326 r=496 w=0 time=4429385 us)(object id 1939950)
2505 TABLE ACCESS BY INDEX ROWID OBJ#(7594103) (cr=92139 r=1235 w=0 time=8323999 us)
2505 INDEX RANGE SCAN OBJ#(7595413) (cr=89637 r=579 w=0 time=3700740 us)(object id 7595413)
44667 INDEX RANGE SCAN OBJ#(688773) (cr=89685 r=3776 w=0 time=22867682 us)(object id 688773)
44667 INDEX RANGE SCAN OBJ#(331689) (cr=134318 r=490 w=0 time=4211427 us)(object id 331689)
1013286 TABLE ACCESS FULL OBJ#(3718019) (cr=28586 r=28562 w=0 time=10467812 us)


Rows Execution Plan
------- ---------------------------------------------------
0 SELECT STATEMENT GOAL: CHOOSE
1 SORT (AGGREGATE)
44667 HASH JOIN (OUTER)
44667 NESTED LOOPS
44667 NESTED LOOPS
44667 NESTED LOOPS (OUTER)
44662 NESTED LOOPS
44662 NESTED LOOPS
504196 NESTED LOOPS
504196 NESTED LOOPS
504196 NESTED LOOPS (OUTER)
504196 NESTED LOOPS
4996145 NESTED LOOPS
4996288 HASH JOIN
12661 MERGE JOIN (CARTESIAN)
11 INDEX GOAL: ANALYZED (RANGE SCAN) OF 'FND_LOOKUP_VALUES_U1' (UNIQUE)
12661 BUFFER (SORT)
1151 TABLE ACCESS GOAL: ANALYZED (BY INDEX ROWID) OF 'OE_TRANSACTION_TYPES_TL'
1151 INDEX GOAL: ANALYZED (RANGE SCAN) OF 'OE_TRANSACTION_TYPES_TL_U2' (NON-UNIQUE)
512900 TABLE ACCESS GOAL: ANALYZED (FULL) OF 'OE_ORDER_HEADERS_ALL'
4996145 TABLE ACCESS GOAL: ANALYZED (BY INDEX ROWID) OF 'HZ_CUST_ACCOUNTS'
4996145 INDEX GOAL: ANALYZED (UNIQUE SCAN) OF 'HZ_CUST_ACCOUNTS_U1' (UNIQUE)
504196 TABLE ACCESS GOAL: ANALYZED (BY INDEX ROWID) OF 'OE_ORDER_LINES_ALL'
9126865 INDEX GOAL: ANALYZED (RANGE SCAN) OF 'OE_ORDER_LINES_N1' (NON-UNIQUE)
455389 INDEX GOAL: ANALYZED (RANGE SCAN) OF 'FND_LOOKUP_VALUES_U1' (UNIQUE)
504196 INDEX GOAL: ANALYZED (UNIQUE SCAN) OF 'MTL_PARAMETERS_U1' (UNIQUE)
504196 INDEX GOAL: ANALYZED (RANGE SCAN) OF 'OE_TRANSACTION_TYPES_TL_U1' (UNIQUE)
44662 TABLE ACCESS GOAL: ANALYZED (BY INDEX ROWID) OF 'WSH_DELIVERY_DETAILS'
491282 INDEX GOAL: ANALYZED (RANGE SCAN) OF 'WSH_DELIVERY_DETAILS_N3' (NON-UNIQUE)
44662 INDEX GOAL: ANALYZED (UNIQUE SCAN) OF 'HZ_PARTIES_U1' (UNIQUE)
2505 TABLE ACCESS GOAL: ANALYZED (BY INDEX ROWID) OF 'OE_ORDER_HOLDS_ALL'
2505 INDEX GOAL: ANALYZED (RANGE SCAN) OF 'OE_ORDER_HOLDS_ALL_N2' (NON-UNIQUE)
44667 INDEX GOAL: ANALYZED (RANGE SCAN) OF 'WSH_DELIVERY_ASSIGNMENTS_N3' (NON-UNIQUE)
44667 INDEX GOAL: ANALYZED (RANGE SCAN) OF 'MTL_SYSTEM_ITEMS_B_N1' (NON-UNIQUE)
1013286 TABLE ACCESS GOAL: ANALYZED (FULL) OF 'GEMS_POM_SROM_HDR_EXT'


Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 2 0.00 0.00
global cache cr request 254875 0.06 83.96
db file sequential read 405109 1.80 1685.63
db file scattered read 8343 0.41 72.68
db file parallel read 117 0.10 2.92
latch free 14 0.01 0.01
global cache s to x 1 0.00 0.00

more

Connor and Chris don't just spend all day on AskTOM. You can also catch regular content via Connor's blog and Chris's blog. Or if video is more your thing, check out Connor's channel and Chris's channel from their Youtube channels. And of course, keep up to date with AskTOM via the official twitter account.

More to Explore

PL/SQL demos

Check out more PL/SQL tutorials on our LiveSQL tool.

PL/SQL docs

PL/SQL reference manual from the Oracle documentation library