A question about reading execution plans and optimising queries arrived on the ODC database forum a little while ago; the owner says the following statement is taking 14 minutes to return 30,000 rows and wants some help understanding why.
If you look at the original posting you’ll see that we’ve been given the text of the query and the execution plan including rowsource execution stats. There’s an inconsistency between the supplied information and the question asked, and I’ll get back to that shortly, but to keep this note fairly short I’ve excluded the 2nd half of the query (which is a UNION ALL) because the plan says the first part of the query took 13 minutes and 20 second and the user is worried about a total of 14 minutes.
SELECT /*+ gather_plan_statistics*/ DISTINCT
rct.org_id,
hzp.party_name,
hca.account_number,
rct.interface_header_attribute1 order_number,
rct.customer_trx_id,
rct.trx_number,
rct.trx_date,
rctd.gl_date,
rct.creation_date,
rctl.line_number,
rct.invoice_currency_code inv_currency,
(
SELECT SUM (rct_1.extended_amount)
FROM apps.ra_customer_trx_lines_all rct_1
WHERE rct_1.customer_trx_id = rct.customer_trx_id
AND rct_1.line_type = 'LINE') inv_net_amount,
(
SELECT SUM (rct_2.extended_amount)
FROM apps.ra_customer_trx_lines_all rct_2
WHERE rct_2.customer_trx_id = rct.customer_trx_id
AND rct_2.line_type = 'TAX') inv_tax_amount,
(
SELECT SUM (rct_3.extended_amount)
FROM apps.ra_customer_trx_lines_all rct_3
WHERE rct_3.customer_trx_id = rct.customer_trx_id) inv_gross_amount,
gll.currency_code func_currency,
Round((
(
SELECT SUM (rct_4.extended_amount)
FROM apps.ra_customer_trx_lines_all rct_4
WHERE rct_4.customer_trx_id = rct.customer_trx_id
AND rct_4.line_type = 'LINE')*gdr.conversion_rate),2) func_net_amount,
Round((
(
SELECT SUM (rct_5.extended_amount)
FROM apps.ra_customer_trx_lines_all rct_5
WHERE rct_5.customer_trx_id = rct.customer_trx_id
AND rct_5.line_type = 'TAX')*gdr.conversion_rate),2) func_tax_amount,
Round((
(
SELECT SUM (rct_6.extended_amount)
FROM apps.ra_customer_trx_lines_all rct_6
WHERE rct_6.customer_trx_id = rct.customer_trx_id)*gdr.conversion_rate),2) func_gross_amount,
glcc.segment1 company,
glcc.segment2 account,
hg.geography_name billing_country,
gdr.conversion_rate
FROM apps.hz_parties hzp,
apps.hz_cust_accounts hca,
apps.ra_customer_trx_all rct,
apps.ra_customer_trx_lines_all rctl,
apps.ra_cust_trx_line_gl_dist_all rctd,
apps.gl_code_combinations_kfv glcc,
apps.hz_cust_site_uses_all hcsua,
apps.hz_cust_acct_sites_all hcasa,
apps.hz_party_sites hps,
apps.hz_locations hl,
apps.hz_geographies hg,
apps.gl_ledgers gll,
apps.gl_daily_rates gdr
WHERE hzp.party_id = hca.party_id
AND hca.cust_account_id = rct.bill_to_customer_id
AND hca.cust_account_id = hcasa.cust_account_id
AND rct.customer_trx_id = rctl.customer_trx_id
AND rctl.customer_trx_line_id = rctd.customer_trx_line_id
AND glcc.code_combination_id = rctd.code_combination_id
AND rct.bill_to_site_use_id = hcsua.site_use_id
AND hcsua.cust_acct_site_id = hcasa.cust_acct_site_id
AND hcasa.party_site_id = hps.party_site_id
AND hps.location_id = hl.location_id
AND hl.country = hg.country_code
AND hg.geography_type = 'COUNTRY'
AND rctl.line_type = 'TAX'
AND gll.ledger_id = rct.set_of_books_id
AND gdr.from_currency = rct.invoice_currency_code
AND gdr.to_currency = gll.currency_code
AND to_date(gdr.conversion_date) = to_date(rctd.gl_date)
AND gdr.conversion_type = 'Corporate'
AND rctd.gl_date BETWEEN To_date ('01-JAN-2018', 'DD-MON-YYYY') AND To_date ('31-JAN-2018', 'DD-MON-YYYY')
AND glcc.segment1 = '2600'
AND glcc.segment2 = '206911'
GROUP BY hzp.party_name,
hca.account_number,
rct.interface_header_attribute1,
rct.trx_number,
rct.trx_date,
rct.creation_date,
rctl.line_number,
rctl.unit_selling_price,
rct.org_id,
rctd.gl_date,
rct.customer_trx_id,
glcc.segment1,
glcc.segment2,
hg.geography_name,
rct.invoice_currency_code,
gll.currency_code,
gdr.conversion_rate
We note that there are six scalar subqueries in the text I’ve reported – and they form two groups of three, and the difference between the two groups is that one group is multiplied by a conversion rate while the other isn’t; moreover in each group the three subqueries are simply querying subsets of the same correlated data set. So it looks as if all 6 scalar subqueries could be eliminated and replaced by the inclusion of an aggregate view in the from clause and the projection of 6 columns from that view.
However, before pursuing that option, take a look at the plan with the rowsource execution stats – where is the time going ?
----------------------------------------------------------------------------------------------------------------------------------------------------- | Id | Operation | Name | Starts | E-Rows | A-Rows | A-Time | Buffers | ----------------------------------------------------------------------------------------------------------------------------------------------------- | 0 | SELECT STATEMENT | | 1 | | 501 |00:13:20.17 | 3579K| | 1 | UNION-ALL | | 1 | | 501 |00:13:20.17 | 3579K| | 2 | HASH UNIQUE | | 1 | 1 | 501 |00:13:20.17 | 3579K| | 3 | HASH GROUP BY | | 1 | 1 | 19827 |00:13:20.15 | 3579K| | 4 | NESTED LOOPS | | 1 | | 21808 |00:13:10.26 | 3579K| | 5 | NESTED LOOPS | | 1 | 1 | 21808 |00:13:10.11 | 3578K| | 6 | NESTED LOOPS OUTER | | 1 | 1 | 21808 |00:13:09.90 | 3576K| | 7 | NESTED LOOPS OUTER | | 1 | 1 | 21808 |00:13:09.25 | 3501K| | 8 | NESTED LOOPS OUTER | | 1 | 1 | 21808 |00:13:08.48 | 3426K| | 9 | NESTED LOOPS OUTER | | 1 | 1 | 21808 |00:13:07.66 | 3333K| | 10 | NESTED LOOPS OUTER | | 1 | 1 | 21808 |00:13:06.92 | 3258K| | 11 | NESTED LOOPS OUTER | | 1 | 1 | 21808 |00:13:06.08 | 3183K| | 12 | NESTED LOOPS | | 1 | 1 | 21808 |00:13:04.69 | 3090K| | 13 | NESTED LOOPS | | 1 | 1 | 21808 |00:13:05.75 | 3026K| | 14 | NESTED LOOPS | | 1 | 1 | 21808 |00:13:03.30 | 2961K| | 15 | NESTED LOOPS | | 1 | 1 | 33459 |00:00:04.33 | 1123K| | 16 | NESTED LOOPS | | 1 | 351 | 33459 |00:00:03.67 | 1025K| | 17 | NESTED LOOPS | | 1 | 351 | 33459 |00:00:03.06 | 926K| | 18 | NESTED LOOPS | | 1 | 351 | 33459 |00:00:02.47 | 827K| |* 19 | HASH JOIN | | 1 | 351 | 33459 |00:00:01.90 | 730K| | 20 | TABLE ACCESS FULL | GL_LEDGERS | 1 | 38 | 39 |00:00:00.01 | 15 | | 21 | NESTED LOOPS | | 1 | | 33459 |00:00:01.75 | 730K| | 22 | NESTED LOOPS | | 1 | 351 | 33459 |00:00:01.44 | 696K| | 23 | NESTED LOOPS | | 1 | 351 | 33459 |00:00:01.11 | 646K| |* 24 | HASH JOIN | | 1 | 385 | 33459 |00:00:00.40 | 526K| |* 25 | TABLE ACCESS BY INDEX ROWID BATCHED| GL_CODE_COMBINATIONS | 1 | 35 | 1 |00:00:00.01 | 108 | |* 26 | INDEX RANGE SCAN | GL_CODE_COMBINATIONS_N2 | 1 | 499 | 77 |00:00:00.01 | 3 | |* 27 | TABLE ACCESS BY INDEX ROWID BATCHED| RA_CUST_TRX_LINE_GL_DIST_ALL | 1 | 651K| 1458K|00:00:02.22 | 526K| |* 28 | INDEX RANGE SCAN | RA_CUST_TRX_LINE_GL_DIST_N2 | 1 | 728K| 1820K|00:00:01.60 | 11147 | |* 29 | TABLE ACCESS BY INDEX ROWID | RA_CUSTOMER_TRX_LINES_ALL | 33459 | 1 | 33459 |00:00:00.53 | 119K| |* 30 | INDEX UNIQUE SCAN | RA_CUSTOMER_TRX_LINES_U1 | 33459 | 1 | 33459 |00:00:00.31 | 86364 | |* 31 | INDEX UNIQUE SCAN | RA_CUSTOMER_TRX_U1 | 33459 | 1 | 33459 |00:00:00.21 | 49850 | | 32 | TABLE ACCESS BY INDEX ROWID | RA_CUSTOMER_TRX_ALL | 33459 | 1 | 33459 |00:00:00.20 | 33459 | | 33 | TABLE ACCESS BY INDEX ROWID | HZ_CUST_ACCOUNTS | 33459 | 1 | 33459 |00:00:00.42 | 97887 | |* 34 | INDEX UNIQUE SCAN | HZ_CUST_ACCOUNTS_U1 | 33459 | 1 | 33459 |00:00:00.24 | 64428 | | 35 | TABLE ACCESS BY INDEX ROWID | HZ_PARTIES | 33459 | 1 | 33459 |00:00:00.44 | 98783 | |* 36 | INDEX UNIQUE SCAN | HZ_PARTIES_U1 | 33459 | 1 | 33459 |00:00:00.26 | 65175 | | 37 | TABLE ACCESS BY INDEX ROWID | HZ_CUST_SITE_USES_ALL | 33459 | 1 | 33459 |00:00:00.46 | 98374 | |* 38 | INDEX UNIQUE SCAN | HZ_CUST_SITE_USES_U1 | 33459 | 1 | 33459 |00:00:00.28 | 64915 | |* 39 | TABLE ACCESS BY INDEX ROWID | HZ_CUST_ACCT_SITES_ALL | 33459 | 1 | 33459 |00:00:00.45 | 98195 | |* 40 | INDEX UNIQUE SCAN | HZ_CUST_ACCT_SITES_U1 | 33459 | 1 | 33459 |00:00:00.26 | 64736 | | 41 | TABLE ACCESS BY INDEX ROWID BATCHED | GL_DAILY_RATES | 33459 | 1 | 21808 |00:12:44.59 | 1838K| |* 42 | INDEX RANGE SCAN | GL_DAILY_RATES_U1 | 33459 | 1 | 21808 |00:13:08.16 | 1837K| | 43 | TABLE ACCESS BY INDEX ROWID | HZ_PARTY_SITES | 21808 | 1 | 21808 |00:00:00.35 | 64339 | |* 44 | INDEX UNIQUE SCAN | HZ_PARTY_SITES_U1 | 21808 | 1 | 21808 |00:00:00.23 | 42531 | | 45 | TABLE ACCESS BY INDEX ROWID | HZ_LOCATIONS | 21808 | 1 | 21808 |00:00:00.33 | 64353 | |* 46 | INDEX UNIQUE SCAN | HZ_LOCATIONS_U1 | 21808 | 1 | 21808 |00:00:00.18 | 42545 | | 47 | VIEW PUSHED PREDICATE | VW_SSQ_1 | 21808 | 1 | 21808 |00:00:01.17 | 93476 | | 48 | SORT GROUP BY | | 21808 | 1 | 21808 |00:00:01.06 | 93476 | | 49 | TABLE ACCESS BY INDEX ROWID BATCHED | RA_CUSTOMER_TRX_LINES_ALL | 21808 | 16 | 145K|00:00:00.84 | 93476 | |* 50 | INDEX RANGE SCAN | XXC_CUSTOMER_GETPAID | 21808 | 16 | 145K|00:00:00.36 | 59938 | | 51 | VIEW PUSHED PREDICATE | VW_SSQ_2 | 21808 | 1 | 21808 |00:00:00.69 | 74433 | | 52 | SORT GROUP BY | | 21808 | 1 | 21808 |00:00:00.59 | 74433 | | 53 | TABLE ACCESS BY INDEX ROWID BATCHED | RA_CUSTOMER_TRX_LINES_ALL | 21808 | 8 | 92201 |00:00:00.49 | 74433 | |* 54 | INDEX RANGE SCAN | XXC_CUSTOMER_GETPAID | 21808 | 12 | 92201 |00:00:00.24 | 59903 | | 55 | VIEW PUSHED PREDICATE | VW_SSQ_3 | 21808 | 1 | 21808 |00:00:00.61 | 74852 | | 56 | SORT GROUP BY | | 21808 | 1 | 21808 |00:00:00.51 | 74852 | | 57 | TABLE ACCESS BY INDEX ROWID BATCHED | RA_CUSTOMER_TRX_LINES_ALL | 21808 | 8 | 53060 |00:00:00.38 | 74852 | |* 58 | INDEX RANGE SCAN | XXC_CUSTOMER_GETPAID | 21808 | 12 | 53060 |00:00:00.19 | 59148 | | 59 | VIEW PUSHED PREDICATE | VW_SSQ_4 | 21808 | 1 | 21808 |00:00:00.70 | 93490 | | 60 | SORT GROUP BY | | 21808 | 1 | 21808 |00:00:00.61 | 93490 | | 61 | TABLE ACCESS BY INDEX ROWID BATCHED | RA_CUSTOMER_TRX_LINES_ALL | 21808 | 16 | 145K|00:00:00.63 | 93490 | |* 62 | INDEX RANGE SCAN | XXC_CUSTOMER_GETPAID | 21808 | 16 | 145K|00:00:00.25 | 59950 | | 63 | VIEW PUSHED PREDICATE | VW_SSQ_5 | 21808 | 1 | 21808 |00:00:00.63 | 74427 | | 64 | SORT GROUP BY | | 21808 | 1 | 21808 |00:00:00.54 | 74427 | | 65 | TABLE ACCESS BY INDEX ROWID BATCHED | RA_CUSTOMER_TRX_LINES_ALL | 21808 | 8 | 92201 |00:00:00.44 | 74427 | |* 66 | INDEX RANGE SCAN | XXC_CUSTOMER_GETPAID | 21808 | 12 | 92201 |00:00:00.21 | 59900 | | 67 | VIEW PUSHED PREDICATE | VW_SSQ_6 | 21808 | 1 | 21808 |00:00:00.59 | 74846 | | 68 | SORT GROUP BY | | 21808 | 1 | 21808 |00:00:00.50 | 74846 | | 69 | TABLE ACCESS BY INDEX ROWID BATCHED | RA_CUSTOMER_TRX_LINES_ALL | 21808 | 8 | 53060 |00:00:00.35 | 74846 | |* 70 | INDEX RANGE SCAN | XXC_CUSTOMER_GETPAID | 21808 | 12 | 53060 |00:00:00.17 | 59144 | |* 71 | INDEX RANGE SCAN | HZ_GEOGRAPHIES_N11 | 21808 | 5812 | 21808 |00:00:00.13 | 2684 | | 72 | TABLE ACCESS BY INDEX ROWID | HZ_GEOGRAPHIES | 21808 | 168 | 21808 |00:00:00.07 | 620 | -----------------------------------------------------------------------------------------------------------------------------------------------------
Let’s start by raising some concerns about the quality of information available.
First, the OP says it takes 14 minutes to return 30,000 rows: but the top line of the plan says it has taken 13 minutes and 20 seconds to return the first 501 rows, and if we look a little further down the plan operation 3 (Hash Group By) reports 00:13:20.15 to aggregate down to 19,827 rows. So this half of the plan cannot return more than 19,827 rows, and the half I have discarded (for the moment) must be returning the other 10,000+ rows. The information we have is incomplete.
Of course you may think that whatever the rest of the plan does is fairly irrelevant – it’s only going to be responsible for at most another 40 seconds of processing – except my previous experience of rowsource execution statistics tells me that when you do a large number of small operations the times reported can be subject to fairly large rounding errors and that enabling the measurement can increase the execution time by a factor of three or four. It’s perfectly feasible that this half of the query is actually the faster half under normal run-time circumstances but runs much more slowly (with a much higher level of CPU utilisation) when rowsource execution stats is in enabled. So let’s not get too confident.
With that warning in mind, what can we see in this half of the plan.
Big picture: the inline scalar subqueries have disappeared. In 12c the optimimzer can unnest scalar subqueries in the select list and turn them into outer joins, and we can see that there are 6 “Nested Loop Outer” operations, corresponding to 6 “View Pushed Predicate” operations against views labelled VW_SSQ1 through to VW_SSQ6 (SSQ = Scalar Sub Query ?). This goes back to my early comment – a person could probably rewrite the 6 scalar subqueries as a single aggregate view in the from clause: the optimizer isn’t quite clever enough to manage that in this case, but in simpler cases it might be able to do exactly that.
Big picture 2: most of the 13 minutes 20 seconds appears at operation 14 as it processes the 33,459 rows supplied to it from the 4.33 seconds of work done by operation 15 and its descendants. Reducing this part of the execution plan to the smallest relevant section we get the following:
----------------------------------------------------------------------------------------------------------------------------------------------------- | Id | Operation | Name | Starts | E-Rows | A-Rows | A-Time | Buffers | ----------------------------------------------------------------------------------------------------------------------------------------------------- | 14 | NESTED LOOPS | | 1 | 1 | 21808 |00:13:03.30 | 2961K| | 15 | NESTED LOOPS | | 1 | 1 | 33459 |00:00:04.33 | 1123K| | 41 | TABLE ACCESS BY INDEX ROWID BATCHED | GL_DAILY_RATES | 33459 | 1 | 21808 |00:12:44.59 | 1838K| |* 42 | INDEX RANGE SCAN | GL_DAILY_RATES_U1 | 33459 | 1 | 21808 |00:13:08.16 | 1837K| -----------------------------------------------------------------------------------------------------------------------------------------------------
For each row supplied by operation 15 Oracle calls operation 41, which calls operation 42 to do an index range scan to supply a set of rowids so that operation 41 can access a table and return rows. Apparently the total time spent by operation 41 waiting for operation 42 to return rowids and then doing its own work is 12 minutes 44 seconds, while the range scans alone (all 33,459 of them) take 13 minutes and 8 seconds. Remember, though, that “lots of small operations = scope of rounding errors” when you look at these timings. Despite the inconsistency between the timings for operations 41 and 42 it’s reasonable to conclude that between them that’s where most of the execution time went.
Two questions – (a) can we refine our analysis of how the time is split between the two operations and (b) why do these lines take so much time.
Check the Starts and the A-rows: (reminder: for comparison, we expect A-rows to be approximately E-rows * Starts) for both operations we see 33,459 starts and 21,808 rows. The index range scans return (on average) a single rowid about two-thirds of the time, and every time a range scan returns a rowid the corresponding row is returned from the table (If you check the Id column there’s no asterisk on operation 41 so no extra predicate is applied as Oracle accesses the table row – but even if there were an extra predicate we’d still be happy to infer that if 21,808 rowids returned from operation 42 turned into 21,808 rows returned from the table then there are no wasted accesses to the table).
Now look at the Buffers for the index range scan – 1.837M: that’s roughly 56 buffers per range scan – that’s a lot of index to range through to find one rowid, which is a good clue that perhaps we do a lot of work with each Start and really do use up a lot of CPU on this operation. Let’s see what the Predicate Section of the plan tells us about this range scan:
Predicate Information (identified by operation id):
---------------------------------------------------
42 - access("GDR"."FROM_CURRENCY"="RCT"."INVOICE_CURRENCY_CODE" AND "GDR"."TO_CURRENCY"="GLL"."CURRENCY_CODE" AND
"GDR"."CONVERSION_TYPE"='Corporate')
filter(("GDR"."CONVERSION_TYPE"='Corporate' AND TO_DATE(INTERNAL_FUNCTION("GDR"."CONVERSION_DATE"))=TO_DATE(INTERNAL_FUNCTION("RCTD"."
GL_DATE"))))
We have access predicates (things which narrow down the number of leaf blocks that we walk through) and filter predicates (things we do to test every key entry we access). Notably the gdr.conversion type is a filter predciate as well as an access predicate – and that suggests that our set of predicates has “skipped over” a column in the index: from_currency and to_currency might be the first two columns in the index, but conversion_type is then NOT the third.
More significantly, though, there’s a column called conversion_date in the index (maybe that’s column 3 in the index – it feels like it ought to be); but for every index entry we’ve selected from the 56 blocks we walk through we do some sort of internal conversion (or un-translated transformation) to the column then convert the result to a date to compare it with another date (similarly processed from an earlier operation). What is that “internal function” – let’s check the query:
AND gdr.from_currency = rct.invoice_currency_code
AND gdr.to_currency = gll.currency_code
AND gdr.conversion_type = 'Corporate'
AND to_date(gdr.conversion_date) = to_date(rctd.gl_date)
AND rctd.gl_date BETWEEN To_date ('01-JAN-2018', 'DD-MON-YYYY') AND To_date ('31-JAN-2018', 'DD-MON-YYYY')
(I’ve swapped the order of a couple of lines to highlight a detail).
The filter predicate is comparing gdr.conversion_date with rctd.gl_date – and we can probably assume that both columns really are dates because (a) the word “date” is in their names and (b) the rctd.gl_date is being compared with genuine date values in the next predicate down (and – though I haven’t shown it – the way the plan reports the next predicate proves that the column really is a date datatype).
So the predicate in the SQL applies the to_date() function to two columns that are dates – which means the optimizer has to convert the date columns to some default character format and then convert them back to dates. The “internal function” is a to_char() call. Conversions between date and character formats are CPU-intensive, and we’re doing a double conversion (to_date(to_char(column_value)) to every data value in roughly 56 blocks of an index each time we call that line of the plan. It’s not surprising we spend a lot of time in that line.
Initial strategy:
Check the column types for those two columns, if they are both date types decide whether or not the predicate could be modified to a simple gdr.conversion_date = rctd.gl_date (though it’s possible that something slightly more sophisticated should be used) but whatever you do avoid the redundant conversion through character format.
Ideally, of course, if we can avoid this conversion we may find that Oracle can be more accurate in its range scan through the index, but we may still find that we do a large range scan even if we do manage to do it a little more efficiently, in which case we may want to see if there is an alternative index which will allow us to pick the one rowid we need from the index without visiting so many leaf blocks in the index.
Warning
Simply eliminating the to_date() calls may changes the results. Here’s a demonstration of how nasty things happen when you apply to_date() to a date:
SQL> desc t1 Name Null? Type ----------------------------- -------- -------------------- D1 DATE D2 DATE SQL> insert into t1 values(sysdate, sysdate + 10/86400); 1 row created. SQL> select * from t1 where d1 = d2; no rows selected SQL> select * from t1 where to_date(d1) = to_date(d2); D1 D2 --------- --------- 30-SEP-18 30-SEP-18 1 row selected. SQL> alter session set nls_date_format = 'yyyy-mm-dd hh24:mi:ss'; Session altered. SQL> select * from d1 where to_date(d1) = to_date(d2); no rows selected
Different users could get different results because they have different settings for their nls_date_format.
Reminder
I started my analysis with two comments about the quality of information – first, we don’t really know whether or not this half of the union all would be responsble for most of the time if rowsource execution statistics were not enabled; secondly large number of small operations can lead to a lot of rounding errors in timing. There are six occurrences of unnested scalar subqueries which are all called 21,808 times – and the recorded time for all 6 of them is remarkably small given the number of executions, even when allowing for the precision with which they operate; it’s possible that these subqueries take a larger fraction of the total time than the plan indicates, in which case it might become necessary (rather than just nice) to do a manual unnesting and reduce the number of inline views to 3 (one for each line_type), 2 (one with, one without, conversion_rate) or just one.
Footnote
Once again I’ve spent a couple of hours writing notes to explain the thoughts that went through my mind in roughly 10 minutes of reading the original posting. It’s a measure really of how many bits of information you can pull together, and possibly discard, very quickly once you understand how many things the optimizer is capable of doing and how the execution plan tries to show you how a statement was (or will be) handled.
Update (5th Oct 2018)
Another way of looking for the best strategy for tuning this statement, given the available information, is this:
Where, in the sequence of events, does the data volume we’re processing drop to the right scale for the output. If we don’t drop to the right scale very early in the plan execution then we may need to re-arrange the order in which we visit tables; if we are operating at the right volume almost immediately then there’s a good chance that we’ve started the right way. Take a look at the first few lines of this plan (remembering that the query was interrupted before returning the whole result set):
----------------------------------------------------------------------------------------------------------------------------------------------------- | Id | Operation | Name | Starts | E-Rows | A-Rows | A-Time | Buffers | ----------------------------------------------------------------------------------------------------------------------------------------------------- | 0 | SELECT STATEMENT | | 1 | | 501 |00:13:20.17 | 3579K| | 1 | UNION-ALL | | 1 | | 501 |00:13:20.17 | 3579K| | 2 | HASH UNIQUE | | 1 | 1 | 501 |00:13:20.17 | 3579K| | 3 | HASH GROUP BY | | 1 | 1 | 19827 |00:13:20.15 | 3579K| | 4 | NESTED LOOPS | | 1 | | 21808 |00:13:10.26 | 3579K| -----------------------------------------------------------------------------------------------------------------------------------------------------
At line 4 we generate 21,808 rows which we aggregate down to 19,827, which we then hash down to distinct values – the original user told us that the query returns 30,000 rows so we shouldn’t assume that the uniqueness requirement has reduced 19,827 rows to the 501 reported so far, there may be more to come. What we can say about these numbers, particularly lines 3 and 4 is that prior to the aggregation we need to find about 22,000 rows and carry them through the rest of the plan.
Now look at lines 24 – 28 where the heavy duty action starts (the first physical operation is actually at lines 19/20 where (thanks to swapping join inputs) Oracle scans the gl_ledger table and hashes it into memory in anticipation of incoming probe data – but that’s a tiny blip on the way to the big join):
----------------------------------------------------------------------------------------------------------------------------------------------------- | Id | Operation | Name | Starts | E-Rows | A-Rows | A-Time | Buffers | ----------------------------------------------------------------------------------------------------------------------------------------------------- |* 24 | HASH JOIN | | 1 | 385 | 33459 |00:00:00.40 | 526K| |* 25 | TABLE ACCESS BY INDEX ROWID BATCHED| GL_CODE_COMBINATIONS | 1 | 35 | 1 |00:00:00.01 | 108 | |* 26 | INDEX RANGE SCAN | GL_CODE_COMBINATIONS_N2 | 1 | 499 | 77 |00:00:00.01 | 3 | |* 27 | TABLE ACCESS BY INDEX ROWID BATCHED| RA_CUST_TRX_LINE_GL_DIST_ALL | 1 | 651K| 1458K|00:00:02.22 | 526K| |* 28 | INDEX RANGE SCAN | RA_CUST_TRX_LINE_GL_DIST_N2 | 1 | 728K| 1820K|00:00:01.60 | 11147 | -----------------------------------------------------------------------------------------------------------------------------------------------------
The important thing we see here is that the very first hash join identifies 33,459 rows: we’re immediately into the right ball-park for the final output. The timings are a bit suspect – I really don’t like seeing the time for hash join (0.4 seconds) being smaller than one of its direct child operations (the 2.22 seconds) – but this bit of the work seems to get to the right scale very quickly: this looks as if it’s likely to be a good way to start the final join order.
We might question whether the optimizer has been wise to use an index range scan to identify 1.45 million rows in a table (and probing it 1.82 million times). Maybe that was quick because all the data had previously been buffered and perhaps thisrange scan will be extremely slow on a busy production system; maybe a tablescan would be better, maybe there’s a way of getting to this big table through a different join order that means we only visit it roughly 33,459 times through an index that identifies exactly the rows we really need. Without good knowledge of what the data looks like (and without understanding what the query is supposed to achieve and how often it runs) we can only look at the supplied execution plan and work out where the time went and whether that suggests the plan is doing roughly the right thing or doing something that is clearly silly. This plan looks like a reasonable starting point with one minor (we hope) glitch around line 42 that we identified earlier on.
Oracle Scratchpad 
Hi Jonathan,
Coming across many posts about execution plans posted by you and really appreciate this work.Because in internet,we have very few posts about execution plans.
I can read small to medium execution plans like below 50 lines.But sometimes,as the one you posted here in this blog,its like bushy tree and tough to know the order of execution plan.Can you please share some tips to read these kind of large plans.
Thank you,
Satish
Comment by satish — April 22, 2020 @ 7:55 am BST Apr 22,2020 |
I mean any tips that will be useful for reading a large bushy tree execution plans
Comment by satish — April 22, 2020 @ 8:14 am BST Apr 22,2020 |
Satish,
Obviously you need to understand what each of the possible operations does and what the simplest possible plan involving that operation would look like, but once you have that information available the best tip I can give is that you can pick any operation in the plan and say one of two things:
1) let’s remove this line of the plan and all its descendents and replace it with a single line reading “generate a rowsource” – does this make it easier to understand what the rest of the plan is doing
2) let’s examine this line of the plan and all its descendents in isolation and work out how that “sub-plan” generates its rowsource.
For example – look at operation 14 – it’s a nested loop so its first child operation is operation 15, and by scanning vertically down the plan we can see its second child operation is operation 41, so we can “rename” operation 15 and eliminate operations 16 to 40:
And we can look at operations 15 – 40 separately:
This chunk of plan then turns out to be a very simple section of a single query block that succumbs to “first child first – recursive descent”.
This approach is effectively just what OEM, TOAD, SQL Developer and a few other graphic tools do when they display a plan with little + or – symbols by each line: the “-” hides a section of plan to make everything look simpler; the “+” puts it back in.
Comment by Jonathan Lewis — April 22, 2020 @ 10:10 am BST Apr 22,2020 |
Dear Jonathan,
I could not stop saying the way you explained this post is awesome.
In initial strategy section,you have updated “we may want to see if there is an alternative index which will allow us to pick the one rowid we need from the index without visiting so many leaf blocks in the index.”
Can you please give us some idea like how to overcome this?i mean what does help in these kind of situations.
Thank you
Comment by satish — April 22, 2020 @ 1:38 pm BST Apr 22,2020 |
Satish,
I’ve just run a few quick tests and written up a short note (see pingback at comment #5) that suggests that there’s no possible workaround through indexing and the leaf-block problem is an unavoiadable side-effect of the use of “to_date(date_column)”
Regards
Jonathan Lewis
Comment by Jonathan Lewis — April 23, 2020 @ 12:05 pm BST Apr 23,2020 |
Dear Jonathan,
Thank you,it really helps.
Comment by satish — April 22, 2020 @ 1:55 pm BST Apr 22,2020 |
[…] for several reasons – not the least being the type of performance problem that showed up in a post from a couple of years back that has just been […]
Pingback by date_to_date | Oracle Scratchpad — April 23, 2020 @ 12:00 pm BST Apr 23,2020 |