Skip to Main Content
  • Questions
  • Query (much) slower with optimizer_features_enable=12.1.0.2.1

Breadcrumb

Question and Answer

Connor McDonald

Thanks for the question, Antonio.

Asked: February 08, 2016 - 4:39 pm UTC

Last updated: February 09, 2016 - 12:58 pm UTC

Version: 12.1.0.2

Viewed 10K+ times! This question is

You Asked

I migrated a DB from 11.2.0.3 to 12.1.0.2 and some queries are much slower, one query in particular is taking much longer to run:

SELECT OALV.SEQ_NO, OALV.OBJECT_TYPE
FROM AGREEMENT_LINE_IN_POLICY_VIEW ALPV, OBJECT_IN_AGREEMENT_LINE_VIEW OALV
WHERE ALPV.AGR_LINE_SEQ_NO = OALV.AGR_LINE_SEQ_NO AND ALPV.POLICY_SEQ_NO = 2522249
AND ALPV.PRODUCT_LINE_ID = 'CV1D' AND EXISTS ( SELECT AL.AGR_LINE_SEQ_NO FROM AGREEMENT_LINE AL
WHERE AL.AGR_LINE_SEQ_NO = OALV.AGR_LINE_SEQ_NO AND AL.CANCEL_CODE IN (0 , 92 , 97 , 98 ))
ORDER BY OALV.SEQ_NO ASC;

I did some tests and get this:
optimizer_features_enable=11.2.0.3 query runned in 1s
optimizer_features_enable=12.1.0.2.1 query runned in 1m 26s

I did a trace and get this:
with optimizer_features_enable=11.2.0.3

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.11 0.27 0 4 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 1 0.00 0.00 0 20 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.11 0.28 0 24 0 1

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 85 (TIA)
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ----------------------------------------------
-----
1 1 1 SORT ORDER BY (cr=20 pr=0 pw=0 time=1620 us co
st=11 size=74 card=1)
1 1 1 NESTED LOOPS SEMI (cr=20 pr=0 pw=0 time=1573
us cost=10 size=74 card=1)
1 1 1 NESTED LOOPS (cr=16 pr=0 pw=0 time=1510 us
cost=9 size=65 card=1)
......................
================================================================================
and with optimizer_features_enable=12.1.0.2.1
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.10 0.25 4 33 0 0
Execute 1 0.00 0.21 0 5 0 0
Fetch 1 0.01 36.34 4 8 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.11 36.81 8 46 0 1

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 85 (TIA)
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ----------------------------------------------
-----
1 1 1 PX COORDINATOR (cr=13 pr=4 pw=0 time=36560643
us)
0 0 0 PX SEND QC (ORDER) :TQ10006 (cr=0 pr=0 pw=0 t
ime=0 us cost=23507 size=36 card=1)
0 0 0 SORT ORDER BY (cr=0 pr=0 pw=0 time=0 us cost
=23507 size=36 card=1)
.......

I can see the parallelism seems to be the cause, but why ?

thanks


Update
On both excutions the parameters are all the same except the optimizer_features_enable;

parallel_adaptive_multi_user TRUE
parallel_automatic_tuning FALSE
parallel_degree_level 100
parallel_degree_limit CPU
parallel_degree_policy MANUAL
parallel_execution_message_size 16384
parallel_force_local FALSE
parallel_io_cap_enabled FALSE
parallel_max_servers 5
parallel_min_percent 0
parallel_min_servers 4
parallel_min_time_threshold AUTO
parallel_server FALSE
parallel_server_instances 1
parallel_servers_target 2
parallel_threads_per_cpu 2

optimizer_dynamic_sampling 2
optimizer_adaptive_features TRUE
optimizer_adaptive_reporting_only FALSE

The traces are big here goes the explain -> with optimizer_features_enable=12.1.0.2.1
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
1 1 1 PX COORDINATOR (cr=13 pr=4 pw=0 time=36560643 us)
0 0 0 PX SEND QC (ORDER) :TQ10006 (cr=0 pr=0 pw=0 time=0 us cost=23507 size=36 card=1)
0 0 0 SORT ORDER BY (cr=0 pr=0 pw=0 time=0 us cost=23507 size=36 card=1)
0 0 0 PX RECEIVE (cr=0 pr=0 pw=0 time=0 us cost=23506 size=36 card=1)
0 0 0 PX SEND RANGE :TQ10005 (cr=0 pr=0 pw=0 time=0 us cost=23506 size=36 card=1)
0 0 0 BUFFER SORT (cr=0 pr=0 pw=0 time=0 us)
0 0 0 NESTED LOOPS (cr=0 pr=0 pw=0 time=0 us cost=23506 size=36 card=1)
0 0 0 NESTED LOOPS (cr=0 pr=0 pw=0 time=0 us cost=23506 size=36 card=1)
0 0 0 HASH JOIN (cr=0 pr=0 pw=0 time=0 us cost=23506 size=39 card=1)
0 0 0 BUFFER SORT (cr=0 pr=0 pw=0 time=0 us)
0 0 0 PX RECEIVE (cr=0 pr=0 pw=0 time=0 us cost=7 size=6 card=1)
0 0 0 PX SEND HYBRID HASH :TQ10000 (cr=0 pr=0 pw=0 time=0 us cost=7 size=6 card=1)
1 1 1 STATISTICS COLLECTOR (cr=8 pr=4 pw=0 time=1003 us)
1 1 1 VIEW AGREEMENT_LINE_IN_POLICY_VIEW (cr=8 pr=4 pw=0 time=979 us cost=7 size=6 card=1)
1 1 1 HASH GROUP BY (cr=8 pr=4 pw=0 time=974 us cost=7 size=73 card=1)
1 1 1 NESTED LOOPS (cr=8 pr=4 pw=0 time=587 us cost=7 size=73 card=1)
1 1 1 NESTED LOOPS (cr=7 pr=4 pw=0 time=553 us cost=7 size=73 card=1)
1 1 1 TABLE ACCESS BY INDEX ROWID BATCHED POLICY (cr=4 pr=2 pw=0 time=378 us cost=4 size=35 card=1)
1 1 1 INDEX RANGE SCAN POLICY_PRIME (cr=3 pr=2 pw=0 time=342 us cost=3 size=0 card=1)(object id 855870)
1 1 1 INDEX RANGE SCAN SDK_AGR_LINE_IDX_2 (cr=3 pr=2 pw=0 time=167 us cost=2 size=0 card=1)(object id 856202)
1 1 1 TABLE ACCESS BY INDEX ROWID AGREEMENT_LINE (cr=1 pr=0 pw=0 time=25 us cost=3 size=52 card=1)
0 0 0 PX RECEIVE (cr=0 pr=0 pw=0 time=0 us cost=23498 size=7573455 card=168299)
0 0 0 PX SEND HYBRID HASH :TQ10004 (cr=0 pr=0 pw=0 time=0 us cost=23498 size=7573455 card=168299)
0 0 0 VIEW OBJECT_IN_AGREEMENT_LINE_VIEW (cr=0 pr=0 pw=0 time=0 us cost=23498 size=7573455 card=168299)
0 0 0 HASH GROUP BY (cr=0 pr=0 pw=0 time=0 us cost=23498 size=9593043 card=168299)
0 0 0 PX RECEIVE (cr=0 pr=0 pw=0 time=0 us cost=23498 size=9593043 card=168299)
0 0 0 PX SEND HASH :TQ10003 (cr=0 pr=0 pw=0 time=0 us cost=23498 size=9593043 card=168299)
0 0 0 HASH GROUP BY (cr=0 pr=0 pw=0 time=0 us cost=23498 size=9593043 card=168299)
0 0 0 HASH JOIN (cr=0 pr=0 pw=0 time=0 us cost=22909 size=9593043 card=168299)
0 0 0 PX RECEIVE (cr=0 pr=0 pw=0 time=0 us cost=3286 size=37632296 card=1447396)
0 0 0 PX SEND HYBRID HASH :TQ10001 (cr=0 pr=0 pw=0 time=0 us cost=3286 size=37632296 card=1447396)
0 0 0 STATISTICS COLLECTOR (cr=0 pr=0 pw=0 time=0 us)
0 0 0 PX BLOCK ITERATOR (cr=0 pr=0 pw=0 time=0 us cost=3286 size=37632296 card=1447396)
0 0 0 TABLE ACCESS FULL AGREEMENT_LINE (cr=0 pr=0 pw=0 time=0 us cost=3286 size=37632296 card=1447396)
0 0 0 PX RECEIVE (cr=0 pr=0 pw=0 time=0 us cost=19597 size=65765146 card=1529422)
0 0 0 PX SEND HYBRID HASH :TQ10002 (cr=0 pr=0 pw=0 time=0 us cost=19597 size=65765146 card=1529422)
0 0 0 PX SELECTOR (cr=0 pr=0 pw=0 time=0 us)
0 0 0 TABLE ACCESS FULL OBJECT (cr=0 pr=0 pw=0 time=0 us cost=19597 size=65765146 card=1529422)
0 0 0 INDEX UNIQUE SCAN AGR_LINE_PRIME (cr=0 pr=0 pw=0 time=0 us cost=1 size=0 card=1)(object id 855691)
0 0 0 TABLE ACCESS BY INDEX ROWID AGREEMENT_LINE (cr=0 pr=0 pw=0 time=0 us cost=2 size=9 card=1)


Rows Execution Plan
------- ---------------------------------------------------
0 SELECT STATEMENT MODE: ALL_ROWS
1 SORT (ORDER BY)
0 FILTER
0 NESTED LOOPS
0 VIEW OF 'AGREEMENT_LINE_IN_POLICY_VIEW' (VIEW)
0 HASH (GROUP BY)
0 FILTER
0 NESTED LOOPS
0 NESTED LOOPS
0 TABLE ACCESS MODE: ANALYZED (BY INDEX ROWID
BATCHED) OF 'POLICY' (TABLE)
0 INDEX MODE: ANALYZED (RANGE SCAN) OF
'POLICY_PRIME' (INDEX)
0 INDEX MODE: ANALYZED (RANGE SCAN) OF
'SDK_AGR_LINE_IDX_2' (INDEX)
0 TABLE ACCESS MODE: ANALYZED (BY INDEX ROWID) OF
'AGREEMENT_LINE' (TABLE)
1 VIEW PUSHED PREDICATE OF 'OBJECT_IN_AGREEMENT_LINE_VIEW'
(VIEW)
1 SORT (GROUP BY)
1 FILTER
1 NESTED LOOPS
1 TABLE ACCESS MODE: ANALYZED (BY INDEX ROWID) OF
'AGREEMENT_LINE' (TABLE)
1 INDEX MODE: ANALYZED (UNIQUE SCAN) OF
'AGR_LINE_PRIME' (INDEX (UNIQUE))
1 TABLE ACCESS MODE: ANALYZED (BY INDEX ROWID
BATCHED) OF 'OBJECT' (TABLE)
1 INDEX MODE: ANALYZED (RANGE SCAN) OF
'OBJ_AGR_LINE_NO' (INDEX)


Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
PX Deq: Join ACK 10 0.00 0.02
enq: PS - contention 1 0.01 0.01
PX Deq: Parse Reply 4 0.16 0.17
SQL*Net message to client 1 0.00 0.00
PX Deq: Execute Reply 94 25.21 34.19
db file sequential read 4 0.00 0.00
PX Deq Credit: send blkd 1 1.99 1.99
PX Deq: Table Q qref 2 0.00 0.00
PX Deq: Signal ACK EXT 4 0.10 0.12
PX Deq: Slave Session Stats 4 0.00 0.00
SQL*Net message from client 1 0.05 0.05
********************************************************************************
SQL ID: drrmp9cqzjwp3 Plan Hash: 4286272657

SELECT /* DS_SVC */ /*+ dynamic_sampling(0) no_sql_tune no_monitoring
optimizer_features_enable(default) no_parallel result_cache(snapshot=3600)
*/ SUM(C1)
FROM
(SELECT /*+ qb_name("innerQuery") NO_INDEX_FFS( "OBJECT#1") */ 1 AS C1 FROM
"TIA"."OBJECT" SAMPLE BLOCK(0.712625, 8) SEED(1) "OBJECT#1",
"TIA"."AGREEMENT_LINE" "AGREEMENT_LINE#0" WHERE ("OBJECT#1"."AGR_LINE_NO"=
"AGREEMENT_LINE#0"."AGR_LINE_NO") AND ("OBJECT#1"."TRANS_ID"<=
"AGREEMENT_LINE#0"."TRANS_ID") AND (TRUNC("OBJECT#1"."COVER_START_DATE")<=
TRUNC("AGREEMENT_LINE#0"."COVER_START_DATE") OR
"OBJECT#1"."COVER_START_DATE" IS NULL)) innerQuery


call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.01 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 1 0.68 1.43 10438 12981 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.68 1.44 10438 12981 0 1


with optimizer_features_enable=11.2.0.3

Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
1 1 1 SORT ORDER BY (cr=20 pr=0 pw=0 time=1620 us cost=11 size=74 card=1)
1 1 1 NESTED LOOPS SEMI (cr=20 pr=0 pw=0 time=1573 us cost=10 size=74 card=1)
1 1 1 NESTED LOOPS (cr=16 pr=0 pw=0 time=1510 us cost=9 size=65 card=1)
1 1 1 VIEW AGREEMENT_LINE_IN_POLICY_VIEW (cr=8 pr=0 pw=0 time=1356 us cost=7 size=13 card=1)
1 1 1 HASH GROUP BY (cr=8 pr=0 pw=0 time=1351 us cost=7 size=87 card=1)
1 1 1 NESTED LOOPS (cr=8 pr=0 pw=0 time=116 us)
1 1 1 NESTED LOOPS (cr=7 pr=0 pw=0 time=90 us cost=7 size=87 card=1)
1 1 1 TABLE ACCESS BY INDEX ROWID POLICY (cr=4 pr=0 pw=0 time=53 us cost=4 size=35 card=1)
1 1 1 INDEX RANGE SCAN POLICY_PRIME (cr=3 pr=0 pw=0 time=33 us cost=3 size=0 card=1)(object id 855870)
1 1 1 INDEX RANGE SCAN SDK_AGR_LINE_IDX_2 (cr=3 pr=0 pw=0 time=31 us cost=2 size=0 card=1)(object id 856202)
1 1 1 TABLE ACCESS BY INDEX ROWID AGREEMENT_LINE (cr=1 pr=0 pw=0 time=20 us cost=3 size=52 card=1)
1 1 1 VIEW PUSHED PREDICATE OBJECT_IN_AGREEMENT_LINE_VIEW (cr=8 pr=0 pw=0 time=148 us cost=8 size=52 card=1)
1 1 1 SORT GROUP BY (cr=8 pr=0 pw=0 time=145 us cost=8 size=76 card=1)
1 1 1 NESTED LOOPS (cr=8 pr=0 pw=0 time=107 us cost=7 size=76 card=1)
1 1 1 TABLE ACCESS BY INDEX ROWID AGREEMENT_LINE (cr=4 pr=0 pw=0 time=41 us cost=3 size=33 card=1)
1 1 1 INDEX UNIQUE SCAN AGR_LINE_PRIME (cr=3 pr=0 pw=0 time=31 us cost=2 size=0 card=1)(object id 855691)
1 1 1 TABLE ACCESS BY INDEX ROWID OBJECT (cr=4 pr=0 pw=0 time=59 us cost=4 size=43 card=1)
1 1 1 INDEX RANGE SCAN OBJ_AGR_LINE_NO (cr=3 pr=0 pw=0 time=34 us cost=2 size=0 card=2)(object id 855864)
1 1 1 TABLE ACCESS BY INDEX ROWID AGREEMENT_LINE (cr=4 pr=0 pw=0 time=27 us cost=2 size=11277144 card=1253016)
1 1 1 INDEX UNIQUE SCAN AGR_LINE_PRIME (cr=3 pr=0 pw=0 time=9 us cost=1 size=0 card=1)(object id 855691)


Rows Execution Plan
------- ---------------------------------------------------
0 SELECT STATEMENT MODE: ALL_ROWS
1 SORT (ORDER BY)
1 FILTER
1 NESTED LOOPS (SEMI)
1 NESTED LOOPS
1 VIEW OF 'AGREEMENT_LINE_IN_POLICY_VIEW' (VIEW)
1 HASH (GROUP BY)
1 FILTER
1 NESTED LOOPS
1 NESTED LOOPS
1 TABLE ACCESS MODE: ANALYZED (BY INDEX ROWID)
OF 'POLICY' (TABLE)
1 INDEX MODE: ANALYZED (RANGE SCAN) OF
'POLICY_PRIME' (INDEX)
1 INDEX MODE: ANALYZED (RANGE SCAN) OF
'SDK_AGR_LINE_IDX_2' (INDEX)
1 TABLE ACCESS MODE: ANALYZED (BY INDEX ROWID)
OF 'AGREEMENT_LINE' (TABLE)
1 VIEW PUSHED PREDICATE OF 'OBJECT_IN_AGREEMENT_LINE_VIEW'
(VIEW)
1 SORT (GROUP BY)
1 FILTER
1 NESTED LOOPS
1 TABLE ACCESS MODE: ANALYZED (BY INDEX ROWID)
OF 'AGREEMENT_LINE' (TABLE)
1 INDEX MODE: ANALYZED (UNIQUE SCAN) OF
'AGR_LINE_PRIME' (INDEX (UNIQUE))
1 TABLE ACCESS MODE: ANALYZED (BY INDEX ROWID)
OF 'OBJECT' (TABLE)
0 INDEX MODE: ANALYZED (RANGE SCAN) OF
'OBJ_AGR_LINE_NO' (INDEX)
0 TABLE ACCESS MODE: ANALYZED (BY INDEX ROWID) OF
'AGREEMENT_LINE' (TABLE)
0 INDEX MODE: ANALYZED (UNIQUE SCAN) OF 'AGR_LINE_PRIME'
(INDEX (UNIQUE))


Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 1 0.00 0.00
SQL*Net message from client 1 0.05 0.05
********************************************************************************
SQL ID: 7k377km0q8xj3 Plan Hash: 95221674

SELECT /* OPT_DYN_SAMP */ /*+ ALL_ROWS IGNORE_WHERE_CLAUSE
NO_PARALLEL(SAMPLESUB) opt_param('parallel_execution_enabled', 'false')
NO_PARALLEL_INDEX(SAMPLESUB) NO_SQL_TUNE */ NVL(SUM(C1),:"SYS_B_0"),
NVL(SUM(C2),:"SYS_B_1")
FROM
(SELECT /*+ IGNORE_WHERE_CLAUSE NO_PARALLEL("AGREEMENT_LINE")
FULL("AGREEMENT_LINE") NO_PARALLEL_INDEX("AGREEMENT_LINE") */ :"SYS_B_2" AS
C1, CASE WHEN "AGREEMENT_LINE"."PRODUCT_LINE_ID"=:"SYS_B_3" AND
"AGREEMENT_LINE"."POLICY_SEQ_NO"<=:"SYS_B_4" THEN :"SYS_B_5" ELSE
:"SYS_B_6" END AS C2 FROM "TIA"."AGREEMENT_LINE" SAMPLE BLOCK (:"SYS_B_7" ,
:"SYS_B_8") SEED (:"SYS_B_9") "AGREEMENT_LINE") SAMPLESUB


call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 4 0.00 0.00 0 0 0 0
Execute 4 0.00 0.00 0 0 0 0
Fetch 4 0.00 0.01 0 176 0 4
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 12 0.01 0.02 0 176 0 4

and Chris said...

12c introduced adaptive execution plans. These enable the optimizer to consider multiple different plans and choose between them at runtime.

This enables it to switch between

- hash and nested loops joins
- different levels of parallel execution

The "STATISTICS COLLECTOR" step in the plan monitors the rows coming out of the steps below it. It the chooses between the different plans appropriately.

In this case Oracle considered a plan with a full table scans. It expected these to return 1 million+ rows. So parallel would have been suitable.

But the query only returned one row. So parallel would be unsuitable. It looks like the "PX COORDINATOR" step was still active though. I suggest you raise this with support.

In the meantime you can disable this by:

- Using the hint: /*+ NO_ADAPTIVE_PLAN */ (*undocumented*, but in MOS note 2031605.1)
- The documented hint: /*+ opt_param('optimizer_features_enable', '11.2.0.4') */
- Setting "OPTIMIZER_ADAPTIVE_FEATURES = false" at the system or session level

It's worth checking that the table stats are up-to-date and representative of the table too.

For further reading on adaptive plans, take a look at:

http://www.oracle.com/technetwork/database/bi-datawarehousing/twp-optimizer-with-oracledb-12c-1963236.pdf

https://oracle-base.com/articles/12c/adaptive-plans-12cr1

Rating

  (2 ratings)

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

Comments

tkprof on parallel sessions?

Rajeshwaran, Jeyabal, February 09, 2016 - 12:23 pm UTC

The "STATISTICS COLLECTOR" step in the plan monitors the rows coming out of the steps below it. It the chooses between the different plans appropriately.
In this case Oracle considered a plan with a full table scans. It expected these to return 1 million+ rows. So parallel would have been suitable. But the query only returned one row.


0 0 0 STATISTICS COLLECTOR (cr=0 pr=0 pw=0 time=0 us)
0 0 0 PX BLOCK ITERATOR (cr=0 pr=0 pw=0 time=0 us cost=3286 size=37632296 card=1447396)


Cris - the estimates is 1,447,396 and the reality is missing from tkprof. since in-place of parallel queries the session trace will be available on all px slave session. so tkprof dont help much but sql-monitor report does.

i am able to understand estimate 1+million rows in this contents, how do you concluded the query returned only one row. is that from looking at rows=1 from Fetch phase of the report?
Chris Saxon
February 09, 2016 - 12:58 pm UTC

Yes

Thanks for confirming !

Rajeshwaran, Jeyabal, February 09, 2016 - 1:00 pm UTC


More to Explore

Performance

Get all the information about database performance in the Database Performance guide.