There’s a question on the Oracle Forums at the moment about a query that’s taking a long time to parse. Even after being reduced to one prebuilt (currently remote) table with two non-correlated outer joins to it the parse time is several hundred seconds. This seems fairly bizarre – I have seen some very long parse times from Oracle, but 10 minutes for 3 tables is well over the top; it did remind me, though of a note I started a few years ago of a 4 table join taking 4 seconds to parse, so I thought I’d present the query, the plan, and a little chat on debugging. Here’s the query:
select
/*+ parallel(t4,3) */
t1.small_vc,
t2.small_vc,
t3.small_vc,
count(t4.small_vc)
from
t4,
t1,
t2,
t3
where
t1.id = t4.id1
and t2.id = t4.id2
and t3.id = t4.id3
and t1.small_vc in (1,2,3)
and t2.small_vc in (1,2,3,4)
and t3.small_vc in (1,2,3,4,5)
group by
t1.small_vc,
t2.small_vc,
t3.small_vc
;
I’m expecting a simple cascade of hash joins, with t1, t2 and t3 – the “small” tables – turning into “build” tables, then t4 – the “large” table – passing through each of them in turn until the penultimate rowsource is aggregated.
Here’s the execution plan — which looks pretty much as I expected it to – but there’s something wrong about it that isn’t visible in the output. Why is the query (plan) saying it took 0.07 seconds to complete (A-time), returning only 60 rows, when my SQL*Plus session didn’t return any data for 4 seconds
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows | Cost (%CPU)| E-Time | TQ |IN-OUT| PQ Distrib | A-Rows | A-Time | Buffers | Reads | OMem | 1Mem | O/1/M |
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | | 300 (100)| | | | | 60 |00:00:00.07 | 5 | 0 | | | |
| 1 | PX COORDINATOR | | 1 | | | | | | | 60 |00:00:00.07 | 5 | 0 | 73728 | 73728 | |
| 2 | PX SEND QC (RANDOM) | :TQ10004 | 0 | 1 | 300 (4)| 00:00:01 | Q1,04 | P->S | QC (RAND) | 0 |00:00:00.01 | 0 | 0 | | | |
| 3 | HASH GROUP BY | | 3 | 1 | 300 (4)| 00:00:01 | Q1,04 | PCWP | | 60 |00:00:00.01 | 0 | 0 | 1394K| 1394K| 3/0/0|
| 4 | PX RECEIVE | | 3 | 1 | 300 (4)| 00:00:01 | Q1,04 | PCWP | | 180 |00:00:00.01 | 0 | 0 | | | |
| 5 | PX SEND HASH | :TQ10003 | 0 | 1 | 300 (4)| 00:00:01 | Q1,03 | P->P | HASH | 0 |00:00:00.01 | 0 | 0 | | | |
| 6 | HASH GROUP BY | | 3 | 1 | 300 (4)| 00:00:01 | Q1,03 | PCWP | | 180 |00:00:00.14 | 6114 | 6018 | 1394K| 1394K| 3/0/0|
|* 7 | HASH JOIN | | 3 | 8460 | 299 (4)| 00:00:01 | Q1,03 | PCWP | | 12600 |00:00:00.14 | 6114 | 6018 | 2171K| 2171K| 3/0/0|
| 8 | JOIN FILTER CREATE | :BF0000 | 3 | 22 | 2 (0)| 00:00:01 | Q1,03 | PCWP | | 75 |00:00:00.02 | 0 | 0 | | | |
| 9 | PX RECEIVE | | 3 | 22 | 2 (0)| 00:00:01 | Q1,03 | PCWP | | 75 |00:00:00.02 | 0 | 0 | | | |
| 10 | PX SEND BROADCAST | :TQ10000 | 0 | 22 | 2 (0)| 00:00:01 | Q1,00 | S->P | BROADCAST | 0 |00:00:00.01 | 0 | 0 | | | |
| 11 | PX SELECTOR | | 3 | | | | Q1,00 | SCWC | | 25 |00:00:00.01 | 3 | 0 | | | |
|* 12 | TABLE ACCESS FULL | T3 | 1 | 22 | 2 (0)| 00:00:01 | Q1,00 | SCWP | | 25 |00:00:00.01 | 3 | 0 | | | |
|* 13 | HASH JOIN | | 3 | 27322 | 297 (4)| 00:00:01 | Q1,03 | PCWP | | 12600 |00:00:00.10 | 6114 | 6018 | 2171K| 2171K| 3/0/0|
| 14 | JOIN FILTER CREATE | :BF0001 | 3 | 21 | 2 (0)| 00:00:01 | Q1,03 | PCWP | | 72 |00:00:00.01 | 0 | 0 | | | |
| 15 | PX RECEIVE | | 3 | 21 | 2 (0)| 00:00:01 | Q1,03 | PCWP | | 72 |00:00:00.01 | 0 | 0 | | | |
| 16 | PX SEND BROADCAST | :TQ10001 | 0 | 21 | 2 (0)| 00:00:01 | Q1,01 | S->P | BROADCAST | 0 |00:00:00.01 | 0 | 0 | | | |
| 17 | PX SELECTOR | | 3 | | | | Q1,01 | SCWC | | 24 |00:00:00.01 | 3 | 0 | | | |
|* 18 | TABLE ACCESS FULL | T2 | 1 | 21 | 2 (0)| 00:00:01 | Q1,01 | SCWP | | 24 |00:00:00.01 | 3 | 0 | | | |
|* 19 | HASH JOIN | | 3 | 92953 | 294 (3)| 00:00:01 | Q1,03 | PCWP | | 12600 |00:00:00.10 | 6114 | 6018 | 2171K| 2171K| 3/0/0|
| 20 | JOIN FILTER CREATE | :BF0002 | 3 | 19 | 2 (0)| 00:00:01 | Q1,03 | PCWP | | 63 |00:00:00.01 | 0 | 0 | | | |
| 21 | PX RECEIVE | | 3 | 19 | 2 (0)| 00:00:01 | Q1,03 | PCWP | | 63 |00:00:00.01 | 0 | 0 | | | |
| 22 | PX SEND BROADCAST | :TQ10002 | 0 | 19 | 2 (0)| 00:00:01 | Q1,02 | S->P | BROADCAST | 0 |00:00:00.01 | 0 | 0 | | | |
| 23 | PX SELECTOR | | 3 | | | | Q1,02 | SCWC | | 21 |00:00:00.01 | 3 | 0 | | | |
|* 24 | TABLE ACCESS FULL| T1 | 1 | 19 | 2 (0)| 00:00:01 | Q1,02 | SCWP | | 21 |00:00:00.01 | 3 | 0 | | | |
| 25 | JOIN FILTER USE | :BF0000 | 3 | 343K| 289 (2)| 00:00:01 | Q1,03 | PCWP | | 19517 |00:00:00.09 | 6114 | 6018 | | | |
| 26 | JOIN FILTER USE | :BF0001 | 3 | 343K| 289 (2)| 00:00:01 | Q1,03 | PCWP | | 19517 |00:00:00.09 | 6114 | 6018 | | | |
| 27 | JOIN FILTER USE | :BF0002 | 3 | 343K| 289 (2)| 00:00:01 | Q1,03 | PCWP | | 19517 |00:00:00.09 | 6114 | 6018 | | | |
| 28 | PX BLOCK ITERATOR | | 3 | 343K| 289 (2)| 00:00:01 | Q1,03 | PCWC | | 19517 |00:00:00.09 | 6114 | 6018 | | | |
|* 29 | TABLE ACCESS FULL| T4 | 48 | 343K| 289 (2)| 00:00:01 | Q1,03 | PCWP | | 19517 |00:00:00.06 | 6114 | 6018 | | | |
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Query Block Name / Object Alias (identified by operation id):
-------------------------------------------------------------
1 - SEL$1
12 - SEL$1 / T3@SEL$1
18 - SEL$1 / T2@SEL$1
24 - SEL$1 / T1@SEL$1
29 - SEL$1 / T4@SEL$1
Outline Data
-------------
/*+
BEGIN_OUTLINE_DATA
IGNORE_OPTIM_EMBEDDED_HINTS
OPTIMIZER_FEATURES_ENABLE('19.1.0')
DB_VERSION('19.1.0')
OPT_PARAM('_fix_control' '16923858:5')
ALL_ROWS
OUTLINE_LEAF(@"SEL$1")
FULL(@"SEL$1" "T1"@"SEL$1")
FULL(@"SEL$1" "T4"@"SEL$1")
FULL(@"SEL$1" "T2"@"SEL$1")
FULL(@"SEL$1" "T3"@"SEL$1")
LEADING(@"SEL$1" "T1"@"SEL$1" "T4"@"SEL$1" "T2"@"SEL$1" "T3"@"SEL$1")
USE_HASH(@"SEL$1" "T4"@"SEL$1")
USE_HASH(@"SEL$1" "T2"@"SEL$1")
USE_HASH(@"SEL$1" "T3"@"SEL$1")
PQ_DISTRIBUTE(@"SEL$1" "T4"@"SEL$1" BROADCAST NONE)
PX_JOIN_FILTER(@"SEL$1" "T4"@"SEL$1")
PQ_DISTRIBUTE(@"SEL$1" "T2"@"SEL$1" NONE BROADCAST)
PX_JOIN_FILTER(@"SEL$1" "T2"@"SEL$1")
PQ_DISTRIBUTE(@"SEL$1" "T3"@"SEL$1" NONE BROADCAST)
PX_JOIN_FILTER(@"SEL$1" "T3"@"SEL$1")
SWAP_JOIN_INPUTS(@"SEL$1" "T2"@"SEL$1")
SWAP_JOIN_INPUTS(@"SEL$1" "T3"@"SEL$1")
GBY_PUSHDOWN(@"SEL$1")
USE_HASH_AGGREGATION(@"SEL$1")
END_OUTLINE_DATA
*/
Predicate Information (identified by operation id):
---------------------------------------------------
7 - access("T3"."ID"="T4"."ID3")
12 - filter((TO_NUMBER("T3"."SMALL_VC")=1 OR TO_NUMBER("T3"."SMALL_VC")=2 OR TO_NUMBER("T3"."SMALL_VC")=3 OR TO_NUMBER("T3"."SMALL_VC")=4 OR TO_NUMBER("T3"."SMALL_VC")=5))
13 - access("T2"."ID"="T4"."ID2")
18 - filter((TO_NUMBER("T2"."SMALL_VC")=1 OR TO_NUMBER("T2"."SMALL_VC")=2 OR TO_NUMBER("T2"."SMALL_VC")=3 OR TO_NUMBER("T2"."SMALL_VC")=4))
19 - access("T1"."ID"="T4"."ID1")
24 - filter((TO_NUMBER("T1"."SMALL_VC")=1 OR TO_NUMBER("T1"."SMALL_VC")=2 OR TO_NUMBER("T1"."SMALL_VC")=3))
29 - access(:Z>=:Z AND :Z<=:Z)
filter(SYS_OP_BLOOM_FILTER_LIST(SYS_OP_BLOOM_FILTER(:BF0002,"T4"."ID1"),SYS_OP_BLOOM_FILTER(:BF0001,"T4"."ID2"),SYS_OP_BLOOM_FILTER(:BF0000,"T4"."ID3")))
One possible trouble-shooting step is simply to re-run the query, taking a snapshot of the session activity stats (v$mystat) and the session events (v$session_event) to see what they tell you (if anything) – here’s the critical extract from the session stats:
Name Value
---- -----
CPU used when call started 423
CPU used by this session 429
parse time cpu 411
parse time elapsed 419
Most of the time is parse time, spent on the CPU. (If this had been a much larger scale problem and had occurred in the recent past I might have looked at ASH (v$active_session_hsitory) for any samples for the correct SQL_ID, and seen the problem revealed in the in_parse, in_hard_parse columns.
So let’s enable event 10053 and run the query again – but since it’s “only” 4 seconds, let’s tweak the timer option to report any step that took longer than 0.1 seconds. The default timer setting is a whole second (10^6 microseconds), so we set the fix-control to 5 to get 0.1 seconds (10^5 microseconds).
alter session set "_fix_control"='16923858:5';
alter session set events '10053 trace name context forever';
-- run the query, find the trace file
grep TIMER or19_ora_23370.trc
Here’s the output from the call to grep: it looks like group by placement (GBP) is causing a problem.
TIMER: GBP: costing SEL$1 cpu: 0.303 sec elapsed: 0.309 sec
TIMER: GBP: iteration (#1) SEL$1 cpu: 0.303 sec elapsed: 0.309 sec
TIMER: GBP: costing SEL$1565E019 cpu: 0.293 sec elapsed: 0.298 sec
TIMER: GBP: iteration (#2) SEL$1565E019 cpu: 0.294 sec elapsed: 0.299 sec
TIMER: GBP: costing SEL$23EAFE84 cpu: 0.528 sec elapsed: 0.533 sec
TIMER: GBP: iteration (#3) SEL$23EAFE84 cpu: 0.528 sec elapsed: 0.533 sec
TIMER: GBP: costing SEL$B5D97CA0 cpu: 0.533 sec elapsed: 0.540 sec
TIMER: GBP: iteration (#4) SEL$B5D97CA0 cpu: 0.534 sec elapsed: 0.540 sec
TIMER: GBP: costing SEL$6C9B46B6 cpu: 0.531 sec elapsed: 0.531 sec
TIMER: GBP: iteration (#5) SEL$6C9B46B6 cpu: 0.531 sec elapsed: 0.532 sec
TIMER: GBP: costing SEL$ED1298E3 cpu: 0.522 sec elapsed: 0.523 sec
TIMER: GBP: iteration (#8) SEL$ED1298E3 cpu: 0.523 sec elapsed: 0.524 sec
TIMER: GBP: costing SEL$5968095A cpu: 0.523 sec elapsed: 0.523 sec
TIMER: GBP: iteration (#9) SEL$5968095A cpu: 0.524 sec elapsed: 0.523 sec
TIMER: GBP: costing SEL$4CA81688 cpu: 0.525 sec elapsed: 0.527 sec
TIMER: GBP: iteration (#12) SEL$4CA81688 cpu: 0.526 sec elapsed: 0.528 sec
TIMER: Group-By Placement SEL$1 cpu: 3.766 sec elapsed: 3.793 sec
TIMER: Cost-Based Transformations (Overall) SEL$1 cpu: 3.769 sec elapsed: 3.795 sec
TIMER: Access Path Analysis (Final) SEL$1 cpu: 0.288 sec elapsed: 0.289 sec
TIMER: SQL Optimization (Overall) SEL$1 cpu: 4.072 sec elapsed: 4.108 sec
If you check further up the page, though, you’ll see in the Outline Information that Oracle has not used group by placement (it has done a “group by pushdown” but that’s different, and relates to aggregation in parallel execution. So one quick hack we could try is to add the hint /*+ no_place_group_by(@sel$1) */ to the query just to see what happens – and here’s the effect on the parse time:
Name Value
---- -----
parse time cpu 33
parse time elapsed 34
Problem solved – provided we can get the hint into the code (by hand, or SQL Patch, etc.) But the question still remains: where did the time go? The trace file was fairly long (375,000 lines for the original, compared to 32,000 for the hinted) but a rapid scan seemed in order – and something very quickly caught my attention. It was pretty easy to spot because something big and nasty had happened 8 times.
The answer was in “Adaptive Plans”, which (mostly) get flagged with the label “AP:” in the 10053 trace file, for example:
AP: Computing costs for inflection point at min value 0.00
AP: Using binary search for inflection point search
AP: Costing Join for ADM inflection point at card 0.00
AP: Costing Join for ADM inflection point at card 0.00
You can see here that the optimizer is searching for an “inflection point”, that means it’s “thinking about” an adaptive join, and searching for the number of rows where a switch between a nested loop join and a hash join makes sense.
Notice particularly the comment about “using binary search”. After calculating the cost of the “best” join using the current estimates of cardinality for the incoming rowsource the optimizer starts calculating the possible costs (nested loop or hash, it ignores merge) for a set of alternative cardinalities until it finds the cardinality where the nested loop join and hash join have the same cost. That’s the number of rows that Oracle will use at run time to decide whether it should switch from its initial selection of join method to the alternative.
If the initial join selection was a hash join (i.e. large volume startegy) Oracle will use an alternative cardinality of 1 to start its list of estimates – on the assumption that that would produce a nested loop plan and then keep doubling the estimate until the resulting plan switched to a hash join, then close in on the break point by halving and doubling the remaining gap between the NL estimate and the HJ estimate.
If the initial join selection was a nested loop join Oracle will use a “worst case scenario” for the incoming estimate (acting, broadly speaking, as if every filter at that point had had a selectivity of 1 – i.e. 100% of the available data), and start by halving the estimate. This is fine when the starting estimate is (for example) for the first table in the join order and the esimate is just a few million rows.
Here’s the first estimate in my case (you’ll need a wide screen, or very small print):
6772:AP: Computing costs for inflection point at max value 179769313486231570814527423731704356798070567525844996598917476803157260780028538760589558632766878171540458953514382464234321326889464182768467546703537516986049910576551282076245490090389328944075868508455133942304583236903222948165808559332123348274797826204144723168738177180919299881250404026184124858368.00
After you’ve halved that number about 1,000 times you’re down to values in the region of a few thousand. And when you have to cost a couple of joins every time you halve, and when you’ve gone through the whole process 8 times that’s a lot of CPU.
In fact, with the no_place_group_by hint there was still one point where the optimizer did this adaptive join work – which probably accounts for most of the final 0.33 CPU seconds – but it didn’t show up in any separately reported timer events.
Of course the final little test of this parse time hypothesis is to add the hint /*+ no_adaptive_plan */ – so I did that, and the parse time was still about 0.3 seconds! Investigation of the 10053 trace showed that even with the hint in place the optimizer still went through that one huge binary chop – but when it had worked out the inflection point it printed the message:
AP: Adaptive plans bypassed for query block SEL$1 due to disabled by hint (no_adaptive_plan)
AP: Adaptive joins bypassed for query block SEL$1 due to adaptive plans disabled
According to the hint report the hint was valid, however, so that behaviour looks a little buggy. It then occurred to me that maybe I could have hinted /*+ no_adaptive_plan(@sel$1) */ – and that worked properly with the trace reporting:
AP: Checking validity for query block SEL$1, sqlid=7fjtvwktcmsgq
AP: Adaptive plans bypassed for query block SEL$1 due to disabled by hint (no_adaptive_plan)
AP: Adaptive joins bypassed for query block SEL$1 due to adaptive plans disabled
Had I not realised that this was possible I have fallen back on the hint /*+ opt_param() */ to set the parameter optimizer_adaptive_plans to false for the query in which case the following message (and no other “AP:” message) appeared near the start of the trace:
AP: Adaptive joins bypassed for query block SEL$1 due to disabled by adaptive join parameter
If you want to experiment on your own system here’s the script to create the data – the script name reflects the fact that I found this example by accident while working on something completely different:
rem
rem Script: 12c_vector_transform_c.sql
rem Author: Jonathan Lewis
rem Dated: June 2015
rem Purpose:
rem
rem Last tested
rem 19.11.0.0
rem 12.2.0.1
rem 12.1.0.2
drop table t1;
drop table t2;
drop table t3;
drop table t4;
purge recyclebin;
create table t1
as
select
rownum id,
to_char(mod(rownum,10)) small_vc,
rpad('x',100) padding
from
all_objects
where
rownum <= 70
;
alter table t1
add constraint t1_pk primary key(id)
;
create table t2
as
select
rownum id,
to_char(mod(rownum,12)) small_vc,
rpad('x',100) padding
from
all_objects
where
rownum <= 70
;
alter table t2
add constraint t2_pk primary key(id)
;
create table t3
as
select
rownum id,
to_char(mod(rownum,14)) small_vc,
rpad('x',100) padding
from
all_objects
where
rownum <= 70
;
alter table t3
add constraint t3_pk primary key(id)
;
create table t4
nologging
as
select
t1.id id1,
t2.id id2,
t3.id id3,
rpad(rownum,10) small_vc,
rpad('x',100) padding
from
t1, t2, t3
;
spool 12c_vector_transform_c
set timing on
set linesize 255
set trimspool on
set pagesize 90
set arraysize 100
set serveroutput off
execute snap_my_stats.start_snap
alter session set statistics_level = all;
alter session set "_fix_control"='16923858:5';
alter session set events '10053 trace name context forever';
select
/*+
-- opt_param('optimizer_adaptive_plans' 'false')
-- no_adaptive_plan
-- no_adaptive_plan(@sel$1)
-- no_place_group_by(@sel$1)
parallel(t4,3)
*/
t1.small_vc,
t2.small_vc,
t3.small_vc,
count(t4.small_vc)
from
t4,
t1,
t2,
t3
where
t1.id = t4.id1
and t2.id = t4.id2
and t3.id = t4.id3
and t1.small_vc in (1,2,3)
and t2.small_vc in (1,2,3,4)
and t3.small_vc in (1,2,3,4,5)
group by
t1.small_vc,
t2.small_vc,
t3.small_vc
;
select * from table(dbms_xplan.display_cursor(null,null,'cost outline allstats all note -bytes'));
alter session set events '10053 trace name context off';
set serveroutput on
execute snap_my_stats.end_snap
spool off
Oracle Scratchpad 