[Oracle Maintenance Engineer's Notebook series] run slow analysis after an upgrade

Customer reports,
When he 11.1.0.7 from Oracle, he migrated to the cloud and upgraded to 12.1.0.2.
Run the customer's application test and find it slower than before.

Information such as "Top Foreground Events by Total wait time" and "Wait Classes by Total wait time" from the AWR report,
You can see that the CPU value has risen.

Preliminary thinking, suspected due to environmental differences, resulting in different performance. But customers say that the CPU/memory size of the two environments is exactly the same.
Then consider the other reasons.

Compared to the pre-migration environment and the post-migration environment, you can see from the AWR report that the proportion of "hard parse" after migration is significantly higher.

Before migration
Load profile
Per Second per Transaction per Exec per call
DB time (s): 1.1 0.0 0.00 0.00
DB CPU (s): 0.3 0.0 0.00 0.00
parses:158.3 4.8
Hard parses:8.8 0.3 <<<<<<<<<<<<<<<<<<<<<<< <<<<<<<
executes:620.2 18.2

After migration
Load profile
Per Second per Transaction per Exec per call
DB time (s): 0.8 0.0 0.00 0.00
DB CPU (s): 0.6 0.0 0.00 0.00
Parses (SQL): 375.8 14.7
Hard parses (SQL): 75.2 3.0 <<<<<<<<<<<<<<<<<<<<< <<<< hard parse greatly increased
Executes (SQL): 702.7 28.3

Customer report, in the new environment, set up all the SQL text in the application is appended with a similar
"Select/*+ optimizer_features_enable (' 11.1.0.7 ') ORDERED INDEX (T0001 t0001_001) No_use_hash (FBM10) */" hint,
The discovery performance is basically back to the pre-migration level.

From this point of view, optimizer_features_enable may be affecting the Optimizer_adaptive_features function. This feature will be executed in the SQL text
, dynamically judging there is no better plan of execution. While it is likely that a portion of the client program's SQL text, instead of dynamically adjusting the execution plan produces a lot of hard Parse,
The overall delay in execution time.

The customer also suspects that the 12.1 optimizer_adaptive_features feature that is mentioned in document 2312911.1 is not perfect and causes problems. Document 2312911.1
mentioned, 12.1 of the Optimizer_adaptive_features function is not perfect, can be special treatment, to achieve 12.2 effect (12.2, optimizer_adaptive_
Features has been improved and has been split into two parameters).

So, is this the case, the customer would like to conduct further analysis and investigation.

Comparing with the awr before and after the migration, the interesting situation was found: in fact, from top N SQL, the pre-migration SQL text, the post-migration execution time has actually been greatly shortened.

Pre-migration environment
========================
SQL ordered by Elapsed time
Resources reported for PL/SQL code includes the resources used by the "all" statements called by the code.
% Total DB time is the Elapsed time of the SQL statement divided to the total Database time multiplied by 100
Total DB time (s): 2,597
Captured SQL account for 58.8% of total <<<<<<<<<<<<top 10, which occupies 59% of the overall execution time (1532 Seconds
Total DB time (s): 2,597
Captured PL/SQL account for 0.3% of total
========================

After migration (when optimizer_features_enable hint is not appended)
========================
SQL ordered by Elapsed time★
Resources reported for PL/SQL code includes the resources used by the "all" statements called by the code.
% Total DB time is the Elapsed time of the SQL statement divided to the total Database time multiplied by 100
%total-elapsed time as a percentage of total DB time
%cpu-cpu time as a percentage of Elapsed time
%io-user I/O time as a percentage of Elapsed time
Captured SQL account for 27.9% of total DB time (s): 1,771 <<<<<<<<<<<<top 10 in SQL, accounting for 28% (500 seconds) of overall execution time
Captured PL/SQL account-1.3% of total DB time (s): 1,771
========================

From the specific top-ten SQL execution time, you can also see:

++++++++++++++++++++++++++++++++++++++++++++++
2ac8g6tagg67x after migration >>17,122 back to execution CPU time 13.27s, Elapsed time 139.03s
>>21,018 back to execution CPU time 16s, Elapsed time 839s before migration

5mt3dyz3r6af8 after migration >>425 back to execution CPU time 25.28s, Elapsed time 33.10s
>>509 back to execution CPU time 44s, Elapsed time 105s before migration

7tjhsnk6ruw6m after migration >>165 back to execution CPU time 16.67s, Elapsed time 21.69s
>>165 back to execution CPU time 25s, Elapsed time 50s before migration

......

Baq2zs9gns3co after migration >>51,730 back to execution CPU time 9.92s, Elapsed time 16.57s
Pre-migration >>67,66 4 back execution CPU time 10s, Elapsed time 26s
++++++++++++++++++++++++++++++++++++++++++++++

So where does the problem lie? My guess is this: although the execution time of TOPN those SQL is reduced. But there are a lot of short-lived SQL texts that are executed because of dynamic execution
Planned adjustments, resulting in an increase in events.

It's also easy to understand:

If the execution time of an SQL statement is originally 200MS, if the dynamic execution plan adjusts to 5ms, the execution time is less than 20ms due to a better execution plan, in general
is to make it.

But if you have a small SQL execution statement, the original execution time is 20ms, if the dynamic execution plan to adjust the 5ms, so that the implementation of a better execution plan and less execution time 2ms,
Instead the execution time increased.

What if this small SQL execution statement is executed repeatedly? The problem got worse.

It is like: Although sharpening does not mistake chopping wood work, but if each cut a small branch, must grind a knife, that is a bit of a waste of time ah.

For this speculation, the customer still wants to know more details, well, let's take a look at the ash situation:

Before migration

"In Hard parse" ==> 15 line "in Hard parse" ratio: 37.5%
2018/03/12 15:26:36---> 2018/03/12 15:37:25.693000000
Sql_id:30 A

After migration

"In Hard parse" ==> 252 line "in Hard parse" ratio: 76.6%
2018/03/20 11:33:50---> 2018/03/20 12:25:58.591000000
sql_id:292 A


The overall time after the migration has not only been significantly prolonged, but the sql_id in ash has increased significantly. So it is possible to speculate on a lot of SQL statements that have been executed for a short time because the execution plan
The reason for the adjustment is that the time of the call was hard Parse, so when Ash sampled it, it was more in Ash's CV because it was not executed.

So, as a conclusion, the 12c implementation plan adjustment is not suitable for all SQL text, for the poor effect of the statement, may wish to add optimizer_features_enable to fine tune.

[Oracle Maintenance Engineer's Notebook series] run slow analysis after an upgrade