Thank you Jonathan.
Do you mean to say the plan which shows actually exactly the same if we see
the first 11 steps in both cases below is not actually the case, when it's
been opted in run time. Basically all of the steps 4,5,8,9 are not opted by
both of the cases. The "nested loops outer" at step-5 and step-9 are
actually opted in runtime while optimizer_adaptive_reporting_only = true,
whereas step-8 and step-4 i.e. "hash join outer" are the ones which were
followed in run time by the optimizer while we had
optimizer_adaptive_reporting_only=false. But the sql monitor contains all
of those four combinations just because of its adaptive plan. Is this
understanding correct?
And yes, it's currently using the first_rows hint. I will check with
first_rows_100 hint rather than first_rows hint to see if the behaviour
changes.
with optimizer_adaptive_reporting_only = False
====================================================================================================================================================================================================================================
| Id | Operation |
Name | Rows | Cost | Time | Start | Execs | Rows
| Read | Read | Write | Write | Mem | Temp | Activity | Activity
Detail |
| | |
| (Estim) | | Active(s) | Active | | (Actual) |
Reqs | Bytes | Reqs | Bytes | (Max) | (Max) | (%) | (# samples) |
====================================================================================================================================================================================================================================
| 0 | SELECT STATEMENT |
| | | 512 | +157 | 1 | 2M |
| | | | . | . | | |
| 1 | FILTER |
| | | 512 | +157 | 1 | 2M |
| | | | . | . | | |
| 2 | NESTED LOOPS OUTER |
| 1 | 3M | 512 | +157 | 1 | 2M |
| | | | . | . | | |
| 3 | NESTED LOOPS OUTER |
| 1 | 3M | 512 | +157 | 1 | 2M |
| | | | . | . | | |
| 4 | HASH JOIN OUTER |
| 1 | 3M | 538 | +131 | 1 | 2M |
3387 | 2GB | 3387 | 2GB | 450MB | 2GB | | |
| 5 | NESTED LOOPS OUTER |
| 1 | 3M | 27 | +131 | 1 | 2M |
| | | | . | . | | |
| 6 | STATISTICS COLLECTOR |
| | | 27 | +131 | 1 | 2M |
| | | | . | . | | |
| 7 | NESTED LOOPS OUTER |
| 1 | 3M | 27 | +131 | 1 | 2M |
| | | | . | . | | |
| 8 | HASH JOIN OUTER |
| 1 | 3M | 155 | +3 | 1 | 2M |
3035 | 1GB | 3035 | 1GB | 309MB | 1GB | | |
| 9 | NESTED LOOPS OUTER |
| 1 | 3M | 129 | +3 | 1 | 2M |
| | | | . | . | | |
| 10 | STATISTICS COLLECTOR |
| | | 129 | +3 | 1 | 2M |
| | | | . | . | | |
| 11 | NESTED LOOPS OUTER |
| 1 | 3M | 129 | +3 | 1 | 2M |
| | | | . | . | | |
optimizer_adaptive_reporting_only = true
SQL Plan Monitoring Details (Plan Hash Value=250668601)
============================================================================================================================================================================================================
| Id | Operation |
Name | Rows | Cost | Time | Start | Execs | Rows
| Read | Read | Mem | Activity | Activity Detail |
| | |
| (Estim) | | Active(s) | Active | | (Actual) |
Reqs | Bytes | (Max) | (%) | (# samples) |
============================================================================================================================================================================================================
| 0 | SELECT STATEMENT |
| | | 279 | +2 | 1 | 2M |
| | . | | |
| 1 | FILTER |
| | | 279 | +2 | 1 | 2M |
| | . | | |
| 2 | NESTED LOOPS OUTER |
| 1 | 3M | 279 | +2 | 1 | 2M |
| | . | | |
| 3 | NESTED LOOPS OUTER |
| 1 | 3M | 279 | +2 | 1 | 2M |
| | . | | |
| 4 | HASH JOIN OUTER |
| 1 | 3M | 279 | +2 | 1 | 2M |
| | . | | |
| 5 | NESTED LOOPS OUTER |
| 1 | 3M | 279 | +2 | 1 | 2M |
| | . | | |
| 6 | STATISTICS COLLECTOR |
| | | 279 | +2 | 1 | 2M |
| | . | | |
| 7 | NESTED LOOPS OUTER |
| 1 | 3M | 279 | +2 | 1 | 2M |
| | . | | |
| 8 | HASH JOIN OUTER |
| 1 | 3M | 279 | +2 | 1 | 2M |
| | . | | |
| 9 | NESTED LOOPS OUTER |
| 1 | 3M | 279 | +2 | 1 | 2M |
| | . | | |
| 10 | STATISTICS COLLECTOR |
| | | 279 | +2 | 1 | 2M |
| | . | | |
| 11 | NESTED LOOPS OUTER |
| 1 | 3M | 279 | +2 | 1 | 2M |
| | . | | |
On Sun, Oct 10, 2021 at 11:44 PM Jonathan Lewis <jlewisoracle@xxxxxxxxx>
wrote:
You're a little unlucky with this query, and there's a lot in the SQL
Monitor to take in - especially since the SQL Monitor reporting has shown
you all the possible adaptations the plan might take, and that makes it
harder to interpret what actually happened.
The key point is that when the plan is allowed to adapt there are two
places where the optimizer had a prediction of 1 row (that's operations 7
and 11 - the lines after the Statistics Collector lines). In both cases
the run-time engine found that far too many rows were being produced (the
counting done by the statistics collector wouldn't have taken much time, it
would probably just have been buffering a few (hundred) rows before making
the decision to use a hash join).
With optimizer_adaptive_reporting_only = true the run-time engine has just
carried on with the nested loop and as you can see from the "Time Start"
column it ha actually got the first row of its response ready in the first
two seconds.
With optimizer_adaptive_report_only = false, the run-time engine has
switched to a hash join in both cases. So operation 11 provided 2M rows
(taking 129 seconds) to operation 8 to allow the first hash table build.
Operation 8 called operation 42 to supply the probe table, joined it then
passed the results up to the nested loop in operation 7 which took 27
seconds to get the data from operations 43 and 44 to pass up to the hash
join at operation 4 to create the build table. Operation 4 then called
operations 47 and 49 as the second child of the nested loop - this started
at +157 seconds (which is roughly the 131 + 27 I've mentioned).
Don't be alarmed by the TABLE ACCESS STORAGE FULL FIRST ROWS at operation
49, it takes virtually no time (even though it happens 2M times); and a key
detail that says that is that the first active operation of the "VIEW
PUSHED PREDICATE" also happens at +156.
The time AFTER the first 157 seconds is mostly the 661K read requests that
accumulate from that point onwards.
==================================
Bottom line - in this case the adaptive feature was unlucky. The
cardinality estimates were very low, but the actual was very high, so the
run-time engine switched to a pair of hash joins. The hash joins were
unlucky and resulted in a very long latency (time to first row), but the
fact that the order that the data passed on upwards from each hash join
meant that your access to a critical table was randomised and resulted in
far more I/O, adding considerably to the run time.
For this query you don't AT PRESENT want an adaptive plan. If this is a
controlled query then hinting /*+ no_adaptive_plan */ would be a nice
workaround. (Or adding an SQL Patch if the query text is fixed). It would
not be a good thing to change the parameter globally to address one query
that was unlucky.
Of course there is still the question of why the cardinality estimates are
so bad, but that might be a side effect of your statement that you're
running this query with first_rows optimisation. If that is EXACTLY what
you are doing, rather than first_rows_1 or first_rows_10 (or 100, or 1000)
then you shouldn't be, and changing to one of the cost-base first_rows_N
optimisation strategies should be your first change.
This leads to a couple of things I've noted down as something to test or
check for my own benefit, viz:
Does adaptive optimization co-operate correctly with first_rows_N
optimisation?
Is there a way in the call do dbms_monitor to show the used execution
plan rather than the full adaptive path - it would be a lot easier to read
(and I assume there is if I check the manuals or MOS.)
Regards
Jonathan Lewis
On Sat, 9 Oct 2021 at 17:19, Pap <oracle.developer35@xxxxxxxxx> wrote:
Thank you Jonathan.
There is a difference of ~350+ seconds between the run time of both the
plans and out of this, ~131 seconds is contributed by the statistics
collector which does the additional mathematics/counting to opt for the
best path at that moment (must be based on the runtime/actual cardinality
information). This query was actually a search query and running with
first_rows hint and customer expecting to see the result as first ~50 odd
rows asap on the screen but with the optimizer_adaptive_reporting_only
'false' it was using another set of mathematics(or as you mentioned
multipasses) in this query adding significant overhead for this quick
query. So is it recommended to have this parameter set as 'true' mainly in
the oltp kind of environment ? Or should totally turn the key driver i.e.
optimizer_adpative_plan as false?
Note -- Just to note, after the upgrade , I think the infra team just
kept it all default i.e. optimizer_adaptive_plan- true,
optimizer_adaptive_reporting_only- false, optimizer_adaptive_statistics-
false. So wondering if it's advisable/ and safe to change few to non
default?
As you rightly explained, there seems to be no role of rowid batching in
this performance issue. Again, not much experience in reading
complex execution paths, but from the path initially I was interpreting, it
as both plans are exactly the same , with just the difference in 'rowid
batching operation. But from your explanation, I see I was completely
wrong. Now, I can see in the good plan case it has read ~28million at step
~46 for index TP_PK but in the bad plan case it is not noted in the sql
monitor. but conversely , ~5GB data being read in the bad plan, at
step-59 with ~661k read requests and it resulted in ~770k rows there. But
in case of a good plan those bytes read and number of read requests are not
noted. So does this point to the fact that the statistics collector is
really playing a role in the order in which data results out from one
operation/step to another?
On Sat, Oct 9, 2021 at 4:49 PM Jonathan Lewis <jlewisoracle@xxxxxxxxx>
wrote:
Remember I was talking POSSIBILITIES in my previous post, not
certainties.
With the extra information you have now supplied I have a better
hypothesis, based on the fact that you have adaptive_plans_enabled (which I
should have realised in the first place), and that the plans you've
supplied are different in exactly the TYPE of reason I suggested, but not
for the exact reason. My basic hypothesis now is that when you enabled
adaptive plans but set it to reporting only Oracle will always include the
statistics collector operations, but it will not use them (i.e. not
counting etc,) to make a decision about whether to take a hash join or a
nested loop join. It will simply generate a path based on its first pass
calculations.
(You could check this with a suitable set of examples and testing with
(a) adaptive plans enable (b) adaptive plans enabled but reporting only (c)
adaptive plans disabled. You'd need to set up 4 possibilities: nlj
changing to hj due to adaptive plans, hj changing to nlj due to adaptive
plans, nlj not changing, hj not changing).
So Looking at your SQL Monitor reports - lines 41 and 42 as a starting
point:
WIth reporting only = TRUE
==============================================================================================================================================================================
| Id | Operation |
Name | Rows | Cost | Time | Start | Execs | Rows
| Read | Read | Mem |
| | |
| (Estim) | | Active(s) | Active | |
(Actual) | Reqs | Bytes | (Max) |
===============================================================================================================================================================================
| 41 | INDEX RANGE SCAN | TCX_PK
| 1 | 2 | 279 | +2 | 2M |
2M | | | . |
| 42 | INDEX RANGE SCAN | TCX_PK
| 1 | 2 | | | |
| | | . |
With reporting only = FALSE
===============================================================================================================================================================================================
| Id | Operation |
Name | Rows | Cost | Time | Start | Execs | Rows
| Read | Read | Write | Write | Mem |
| | |
| (Estim) | | Active(s) | Active | |
(Actual) | Reqs | Bytes | Reqs | Bytes | (Max) |
===============================================================================================================================================================================================
| 41 | INDEX RANGE SCAN | TCX_PK
| 1 | 2 | | | |
| | | | | . |
| 42 | INDEX RANGE SCAN | TCX_PK
| 1 | 2 | 1 | +131 | 1 |
976K | | | | | . |
These two lines are the options available as a result of a statistics
collector further up the plan, and one plan takes operation 41, the other
takes operation 42
Putting them into context (adding in some parent and sibling rows)
Reporting only = true ... plan based on estimates
==============================================================================================================================================================================
| Id | Operation |
Name | Rows | Cost | Time | Start | Execs | Rows
| Read | Read | Mem |
| | |
| (Estim) | | Active(s) | Active | |
(Actual) | Reqs | Bytes | (Max) |
===============================================================================================================================================================================
| 7 | NESTED LOOPS OUTER |
| 1 | 3M | 279 | +2 | 1 |
2M | | | . | | |
| 8 | HASH JOIN OUTER |
| 1 | 3M | 279 | +2 | 1 |
2M | | | . |
| 9 | NESTED LOOPS OUTER |
| 1 | 3M | 279 | +2 | 1 |
2M | | | . |
| 10 | STATISTICS COLLECTOR |
| | | 279 | +2 | 1 |
2M | | | . |
| 11 | NESTED LOOPS OUTER |
| 1 | 3M | 279 | +2 | 1 |
2M | | | . |
...
| 41 | INDEX RANGE SCAN | TCX_PK
| 1 | 2 | 279 | +2 | 2M |
2M | | | . |
| 42 | INDEX RANGE SCAN | TCX_PK
| 1 | 2 | | | |
| | | . |
| 43 | TABLE ACCESS BY INDEX ROWID | TC
| 1 | 2 | 279 | +2 | 2M |
2M | 16037 | 125MB | . | | |
Reporting only = false ... plan adapts to counting
(OPTERATION 10 dictates a HASH JOIN where the estimated stats suggested
NLJ)
===============================================================================================================================================================================================
| Id | Operation |
Name | Rows | Cost | Time | Start | Execs | Rows
| Read | Read | Write | Write | Mem |
| | |
| (Estim) | | Active(s) | Active | |
(Actual) | Reqs | Bytes | Reqs | Bytes | (Max) |
===============================================================================================================================================================================================
| 7 | NESTED LOOPS OUTER |
| 1 | 3M | 27 | +131 | 1 |
2M | | | | | . |
| 8 | HASH JOIN OUTER |
| 1 | 3M | 155 | +3 | 1 |
2M | 3035 | 1GB | 3035 | 1GB | 309MB |
| 9 | NESTED LOOPS OUTER |
| 1 | 3M | 129 | +3 | 1 |
2M | | | | | . |
| 10 | STATISTICS COLLECTOR |
| | | 129 | +3 | 1 |
2M | | | | | . |
| 11 | NESTED LOOPS OUTER |
| 1 | 3M | 129 | +3 | 1 |
2M | | | | | . |
...
| 41 | INDEX RANGE SCAN | TCX_PK
| 1 | 2 | | | |
| | | | | . |
| 42 | INDEX RANGE SCAN | TCX_PK
| 1 | 2 | 1 | +131 | 1 |
976K | | | | | . |
| 43 | TABLE ACCESS BY INDEX ROWID | TC
| 1 | 2 | 27 | +131 | 2M |
2M | 21549 | 168MB | | | . |
As you can see, the ability to switch plans makes a big difference to
the amount of time Oracle spends working before it starts executing step 7
(start time = +2 seconds vs. +131 seconds).
This one extract from the plans doesn't answer the question about why
"table access by index rowid batched" has appeared; nor does it explain the
total difference between the two executions because you also need to look
at the statistics collector at operation 6 and the impact that has on which
of operation 45/46 and 47/48 get chosen. The other point that then comes up
is that the order in which data appears from a hash join is (almost
certainly) different from the order it appears from a nested loop join -
which means that when you use the result of the join to probe other tables
by index the order of the driving data from one join may be roughly in line
with the indexes and data from the next table(s) in the join and benefit
from a lot of "self-induced" caching, while the other join might produce
data in what is effectively a randomised order resulting in "self-flushing"
and more random reads - and that might explain what happens at operations
60/61
What my observations suggest is a good argument for why you had such a
difference in performance, and that it had nothing to do with the batching
or not of the table access by rowid.
I may write this up in more detail as a blog some day, but I don't have
time right now.
Regards
Jonathan Lewis
On Fri, 8 Oct 2021 at 18:34, Pap <oracle.developer35@xxxxxxxxx> wrote:
It's fluctuating. I am now not able to reproduce the scenario for
that same small query for which I had posted here just before. And you are
correct , I was luckily having sql monitors saved. I am attaching those
here. If you see that, the main query was showing those rowid batched
operations when we have the optimizer_adaptive_reporting_only set as
default/false and was taking a long time to finish and also the first few
rows were also taking longer to get produced out of the query. But the
sample small query which i had posted a cursor plan for was just showing
the opposite behaviour. That is going for a rowid batched path when
optimizer_adaptive_reporting_only sets as true.
However, now I am seeing that same small query in both the cases
(irrespective of value of optimizer_adaptive_reporting_only) going for
'rowid batched' execution path. Not sure if it's just stats or
anything else influencing and I am seeing different things behaviour. Just
to note we have 'optimizer_adaptive_plans' set to true ,
'optimizer_adaptive_statistics' set to false. The only change we made was
moving ' optimizer_adaptive_reporting_only' from false to true.
And Jonathan when you said the optimizer_adaptive_reporting_only = true
will introduce 'statistics collector' operation, but if you see the
attached sql monitor for the main query, i am seeing 'statistics collector'
even when optimizer_adaptive_reporting_only is = false. Is that expected
behaviour?
