Fix performance regression with SQL plan baseline

Recently one of our clients complained about some slow queries and here is what I found out.

I first used ashtop and snapper to spot the sql_id of the slow sql. Thanks, Tanel!

And thanks to Maris Elsins for the excellent work of awr trending.

@awr_sqlid_perf_trend_by_plan.sql f1nbddjxk6d4v 8 1

INST TIME                      PLAN_HASH_VALUE  EXECUTIONS ELAPSED_TIME_S CPU_TIME_S   IOWAIT_S   CLWAIT_S   APWAIT_S   CCWAIT_S ROWS_PROCESSED BUFFER_GETS DISK_READS DIRECT_WRITES
---------- ------------------- --------------- ----------- -------------- ---------- ---------- ---------- ---------- ---------- -------------- ----------- ---------- -------------
         1 17.10.2016 10:00:00      3605623538        7018        331.426      5.447    330.548          0          0       .023           7117      864235      17975             0
         1 24.10.2016 08:00:00       536694814          88         832.19    180.272    609.531     36.508          0       .085             87     5844838     108809             0
         1 24.10.2016 09:00:00       536694814        6065      15296.067   9530.681   5249.588    430.062          0       .368           6200   416631734     394492             0
         1 24.10.2016 10:00:00       536694814        2218       9527.578    4410.81   4849.158    205.452          0       .096           2221   159973189     534923             0

You can see that the plan had changed and elapsed_time_1exec had increased from 331/7018=0.047 seconds to 15296/6065=2.52 seconds. OOPS!

Just like the presentation he mentioned during OOW2016, this is the typical scenario that plan change leads to performance regression. And surely the action plan is to create sql plan baseline for the specific statement.

Here are the steps.

grant ADMINISTER SQL TUNING SET to cms;

conn cms/xxx

BEGIN
 DBMS_SQLTUNE.CREATE_SQLSET(
	sqlset_name => 'STS_CMS', 
	description => 'Plan for sql_id f1nbddjxk6d4v',
	SQLSET_OWNER => 'CMS');
END;
/

DECLARE
cur sys_refcursor;
BEGIN
	OPEN cur FOR 
		SELECT VALUE(P) 
		FROM table(dbms_sqltune.select_workload_repository(38497,38498,'sql_id=''f1nbddjxk6d4v'' and 
		plan_hash_value=3605623538' , NULL, NULL, NULL, NULL, NULL, NULL, 'ALL')) P;

	DBMS_SQLTUNE.LOAD_SQLSET(load_option=>'MERGE',sqlset_name => 'STS_CMS', populate_cursor => cur);
	CLOSE cur;
END;
/

set serveroutput on
VARIABLE cnt NUMBER
EXECUTE :cnt := DBMS_SPM.LOAD_PLANS_FROM_SQLSET( -
sqlset_name => 'STS_CMS', -
basic_filter => 'sql_id=''f1nbddjxk6d4v''');

print :cnt

However, after completing the job, I wanted to make sure the accepted plan was the plan that I wanted. Again, it seemed so odd that DISPLAY_SQL_PLAN_BASELINE and DISPLAY_SQLSET reported different plans. Why?

select SQL_HANDLE, PLAN_NAME, SQL_TEXT, ENABLED, ACCEPTED
from DBA_SQL_PLAN_BASELINES
where PARSING_SCHEMA_NAME='CMS';

SQL_HANDLE                     PLAN_NAME                      SQL_TEXT                                                                         ENA ACC
------------------------------ ------------------------------ -------------------------------------------------------------------------------- --- ---
SQL_93c91718f992c348           SQL_PLAN_97k8r33wt5hu8178259df SELECT SUM(A.INTEREST - A.PREV_INTEREST) INTEREST, SUM(A.CAP_COST) CAP_COST FROM YES YES
                                                               SECURITY_PORTFOLIO A WHERE A.SECURITY_CODE = :B5 AND A.PORTFOLIO = :B4 AND A.MT
                                                              M_TYPE = :B3 AND A.TRADE_DATE BETWEEN :B2 AND :B1



select * from table(dbms_xplan.DISPLAY_SQL_PLAN_BASELINE('SQL_93c91718f992c348','SQL_PLAN_97k8r33wt5hu8178259df',NULL));

Plan hash value: 1755258069

--------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                           | Name               | Rows  | Bytes | Cost (%CPU)| Time     | Pstart| Pstop |
--------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                    |                    |     1 |    75 |     5   (0)| 00:00:01 |       |       |
|   1 |  SORT AGGREGATE                     |                    |     1 |    75 |            |          |       |       |
|   2 |   TABLE ACCESS BY GLOBAL INDEX ROWID| SECURITY_PORTFOLIO |     1 |    75 |     5   (0)| 00:00:01 | ROWID | ROWID |
|*  3 |    INDEX RANGE SCAN                 | PK_SECURITY_PF     |     1 |       |     4   (0)| 00:00:01 |       |       |
--------------------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   3 - access("A"."PORTFOLIO"=TO_NUMBER(:B4) AND "A"."SECURITY_CODE"=:B5 AND "A"."TRADE_DATE">=:B2 AND
              "A"."MTM_TYPE"=:B3 AND "A"."TRADE_DATE"<=:B1)
       filter("A"."MTM_TYPE"=:B3)
select SQLSET_NAME, SQL_ID, PLAN_HASH_VALUE, TIMESTAMP
from DBA_SQLSET_PLANS
where SQLSET_NAME='STS_CMS';

select * from table(dbms_xplan.DISPLAY_SQLSET('STS_CMS','f1nbddjxk6d4v',3605623538,NULL,'CMS'));

Plan hash value: 3605623538

---------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                            | Name               | Rows  | Bytes | Cost (%CPU)| Time     | Pstart| Pstop |
---------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                     |                    |       |       |     5 (100)|          |       |       |
|   1 |  SORT AGGREGATE                      |                    |     1 |    75 |            |          |       |       |
|   2 |   FILTER                             |                    |       |       |            |          |       |       |
|   3 |    TABLE ACCESS BY GLOBAL INDEX ROWID| SECURITY_PORTFOLIO |     1 |    75 |     5   (0)| 00:00:01 | ROWID | ROWID |
|   4 |     INDEX RANGE SCAN                 | PK_SECURITY_PF     |     1 |       |     4   (0)| 00:00:01 |       |       |
---------------------------------------------------------------------------------------------------------------------------

After searching on MOS, I found that this is due to the following BUG:

Bug 12588179  different plan reported by dbms_xplan.display_sql_plan_baseline than captured one.

in 11g , the dbms_xplan.display_sql_plan_baseline parses the query with the baseline to display the plan and can display a different plan than the one generated when the original baseline was captured.

This fix captures what the original execution plan looks like along with the baseline for future reference.
 
At the time of this document was written the CBO does not generate all
the hints necessary to force an execution plan with 100% certainty.
it is possible not to reproduce the original plan using a baseline, sql profile , outline or hints.

Nevertheless, after re-executing the SQL, I still managed to determine that the better plan was indeed executed and the baseline did fix the problem.

Advertisements

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s