My report used to complete in seconds and now is running for hours! Do you know what is going on?
Sounds familiar? It is very common in Data Warehouses to experience a sudden performance degradation in the execution time of a report, or of an individual ETL mapping. The query was running fast for months and then one day everything changed!
Such a behavior is a sign of a change in the execution plan. Of course there are a million other reasons that might have caused the performance degradation but a change in the execution plan is one of the most common. The reasons for such a change are numerous (stale statistics, change triggered by some DDL -e.g. a new index created, a change in the optimizer environment -e.g., by changing the value of some relevant parameter at the session level etc.)
In this post, we want to show how easy it is to detect a change in the execution plan of a statement (technically represented by a unique sql id) with the help of historic data maintained by Oracle in the AWR. To this end we will present some examples and some simple scripts to do it. However, we will not deal at all with the reasons that might trigger the change of plan. This is a long discussion ...
A. in the shared pool (cursor cache) for a short period of time until it is aged out,
B. or in the AWR repository for up to 7 days (default retention period for AWR),
C. or in both places
Please note that AWR does not store all queries, only the top SQL statements based on a set of criteria and exposes them via the DBA_HIST_SQLSTAT view. So there is a chance that there is no historical info for your query in the database. In this case, you cannot detect the change of plan. In this previous post we have shown how you can retrieve all the available execution plans of a specific sql_id residing either in the cursor cache or in the AWR. These plans where returned in ascending order of plan cost.
To activate the AWR feature, you must set the pfile/spfile’s parameter STATISTICS_LEVEL to the appropriate value. The values assigned to this parameter determine the depth of the statistics that the MMON process gathers. In order to enable this feature this paremeter must be set to either TYPICAL or ALL.
Collection Level Description
BASIC: Disables the AWR and most other diagnostic monitoring and advisory activities. Few database statistics are gathered at each collection interval when operating the instance in this mode.
TYPICAL: Activates the standard level of collection activity. This is the default value for AWR and is appropriate for most environments.
ALL: Captures all the statistics gathered by the TYPICAL collection level, plus the execution plans and timing information from the operating system.
Step 1: Find the sql_id of the problematic statement
----------------------------------------------------------------------------
It is important to understand that when you review the history of executions of a specific sql id and you see the list of various execution plans that were used, you must be sure which one of these is the "good" one. The simplest way to verify this is from your ETL execution history (e.g. from your ETL tool metadata), or directly from the user experience saying when did this report run fast etc. Once you know which plan is the good one, and you see that currently you are using a different plan, plus you are experiencing a performance issue, then you know that the change of plan is the one to blame.
------------------------------------------------------------------
------------------------------------------------------------------
Sounds familiar? It is very common in Data Warehouses to experience a sudden performance degradation in the execution time of a report, or of an individual ETL mapping. The query was running fast for months and then one day everything changed!
Such a behavior is a sign of a change in the execution plan. Of course there are a million other reasons that might have caused the performance degradation but a change in the execution plan is one of the most common. The reasons for such a change are numerous (stale statistics, change triggered by some DDL -e.g. a new index created, a change in the optimizer environment -e.g., by changing the value of some relevant parameter at the session level etc.)
In this post, we want to show how easy it is to detect a change in the execution plan of a statement (technically represented by a unique sql id) with the help of historic data maintained by Oracle in the AWR. To this end we will present some examples and some simple scripts to do it. However, we will not deal at all with the reasons that might trigger the change of plan. This is a long discussion ...
Some Background First
Every query that has been executed in your database resides:A. in the shared pool (cursor cache) for a short period of time until it is aged out,
B. or in the AWR repository for up to 7 days (default retention period for AWR),
C. or in both places
Please note that AWR does not store all queries, only the top SQL statements based on a set of criteria and exposes them via the DBA_HIST_SQLSTAT view. So there is a chance that there is no historical info for your query in the database. In this case, you cannot detect the change of plan. In this previous post we have shown how you can retrieve all the available execution plans of a specific sql_id residing either in the cursor cache or in the AWR. These plans where returned in ascending order of plan cost.
Sidenote (AWR - Automatic Workload Repository)
---------------------------------------------------------------------------------------
The Automatic Workload Repository, uses the MMON background process to gather statistics from the SGA and store them in a collection of tables owned by the user SYSMAN in the SYSAUX tablespace. By default, database statistics are retained in the AWR for seven days. You can change the default duration using the EM Database Control Automatic Workload Repository link on the Performance tab or using the DBMS_WORKLOAD_REPOSITORY PL/SQL package.To activate the AWR feature, you must set the pfile/spfile’s parameter STATISTICS_LEVEL to the appropriate value. The values assigned to this parameter determine the depth of the statistics that the MMON process gathers. In order to enable this feature this paremeter must be set to either TYPICAL or ALL.
Collection Level Description
BASIC: Disables the AWR and most other diagnostic monitoring and advisory activities. Few database statistics are gathered at each collection interval when operating the instance in this mode.
TYPICAL: Activates the standard level of collection activity. This is the default value for AWR and is appropriate for most environments.
ALL: Captures all the statistics gathered by the TYPICAL collection level, plus the execution plans and timing information from the operating system.
So make sure that you haven't set STATISTICS_LEVEL to BASIC.
---------------------------------------------------------------------------------------
Now, assuming that our problematic query has some history stored in AWR, lets proceed with the detection of a change in the execution plan.
3 Simple Steps
Actually the whole process is quite simple and consists of 3 simple steps:
Step 1: Find the sql_id of the problematic statement
There are many ways to get the sql_id of a query that is running, or has run recently. For example, if you know the username of the session you can query V$SESSION to find the relevant session and and the sql_id that this session executes.
Another approach is to query V$SQL which is the view with which Oracle exposes all the child cursors in the shared pool. If you dont know what is a child cursor, dont feel uncomfortable, just go on and read this previous post. Here is a simple example where we query V$SQL searching for a specific part of the SQL text in order to retrieve the sql id of the query we are interested. The sql id equals with "5atbdngau3u7d".
nkarag@DWHPRD> select /* this is my query */ count(*) from t;
COUNT(*)
----------
2
Elapsed: 00:00:00.01
nkarag@DWHPRD> @fs
Session altered.
Elapsed: 00:00:00.01
Enter value for sql_text: %this is my query%
Enter value for sql_id:
PARSING_SCHEMA_NAME INST_ID SQL_ID CHILD PLAN_HASH EXECS AVG_ETIME_SECS AVG_LIO LAST_ACTIVE_TIME SQL_PROFILE IS_SHAREABLE IS_BIND_SENSITIVE IS_BIND_AWARE SQL_TEXT OFFLOAD IO_SAVED_%
------------------------------ ---------- -------------------- ------ ---------- ---------- -------------- ------------ ------------------- ---------------------------------------------------------------- ------------ ----------------- -------------- ---------------------------------------------------------------------- ------- -----
NKARAG 1 5atbdngau3u7d 0 2966233522 1 .00 4 10-02-2015 12:13:52 Y N N select /* this is my query */ count(*) from t No 0
Elapsed: 00:00:00.33
----------------------------------------------------------------------------
The script can be found at the end of this post
Step 2: Get the plan with which the performance problem is related.
Let's call it the "bad plan". Note that each plan in Oracle is uniquely represented by a plan hash value (phv). Once you have the sql_id is fairly simple to get the execution plan. V$SQL once more has all the info we need. As you can see in Listing 1 the plan hash value in our example is 2966233522.
Step 3: Query DBA_HIST_SQLSTAT (i.e., the AWR) to get the plan in previous executions
OK. We know the sql id and the plan hash value of the problematic plan. How do we get the "good" plan?
As we have noted above, we have a great chance that Oracle has stored the execution history of our sql id in AWR and expose it via the DBA_HIST_SQLSTAT view. So the only thing we have to do is to query this view. Note that AWR stores hourly snapshots and therefore in order to get the rough time that the execution took place you must join to DBA_HIST_SNAPSHOT.
As we have noted above, we have a great chance that Oracle has stored the execution history of our sql id in AWR and expose it via the DBA_HIST_SQLSTAT view. So the only thing we have to do is to query this view. Note that AWR stores hourly snapshots and therefore in order to get the rough time that the execution took place you must join to DBA_HIST_SNAPSHOT.
It is important to understand that when you review the history of executions of a specific sql id and you see the list of various execution plans that were used, you must be sure which one of these is the "good" one. The simplest way to verify this is from your ETL execution history (e.g. from your ETL tool metadata), or directly from the user experience saying when did this report run fast etc. Once you know which plan is the good one, and you see that currently you are using a different plan, plus you are experiencing a performance issue, then you know that the change of plan is the one to blame.
Lets see an example of a change of plan detected from the execution history in AWR. In Listing 2 we have a specific sql id for which we search the execution history in the last 40 days. We are particularly interested in the executions that took place in the 1st of the month (because it is a monthly flow that has the problem). We have highlighted with a green background the executions of interest. The good execution on the 1st of January took place with execution plan 3441090710, while the execution on the 1st February (the problematic one) took place with plan 3335085460.
This is the verification we need for the assumption that a change of plan has caused the performance problem. At the end of this post we provide the script used in Listing 2.
This is the verification we need for the assumption that a change of plan has caused the performance problem. At the end of this post we provide the script used in Listing 2.
INSTANCE_NUMBER SNAP_ID BEGIN_INTERVAL_TIME END_INTERVAL_TIME PARSING_SCHEMA_NAME SQL_ID PLAN_HASH_VALUE COMMAND_TYPE_DESC SQL_PROFILE EXECUTIONS_TOTAL OPTIMIZER_COST AVG_ETIME AVG_PX AVG_LIO NOCHILD_CURSORS OFFLOAD IO_SAVED_% SQL_TEXT
--------------- ---------- ------------------------------ ------------------------------ ------------------------------ --------------- --------------- ---------------------------- ---------------------------------------------------------------- ----------------- -------------- ------------------- ------- ------------------- ---------------- ------- ---------- --------------------------------------------------------------
2 22950 10-FEB-15 06.00.26.175 AM 10-FEB-15 07.00.01.423 AM KPI_DW 4sk1dmw4q3zkb 1097924584 INSERT 1 6029 89.99 1 2,243,246.00 1 No 0 INSERT /*+ BYPASS_RECURSIVE_CHECK APPEND */ INTO "KPI_DW"."P02_ADSL_E
....
2 22752 02-FEB-15 12.00.08.512 AM 02-FEB-15 01.00.12.224 AM KPI_DW 3335085460 INSERT 0 27 43,646.66 1 407,025,475.00 1 No 0 INSERT /*+ BYPASS_RECURSIVE_CHECK APPEND */ INTO "KPI_DW"."P02_ADSL_E
2 22751 01-FEB-15 11.00.05.492 PM 02-FEB-15 12.00.08.534 AM KPI_DW 3335085460 INSERT 0 27 40,040.21 1 350,267,429.00 1 No 0 INSERT /*+ BYPASS_RECURSIVE_CHECK APPEND */ INTO "KPI_DW"."P02_ADSL_E
2 22751 01-FEB-15 11.00.05.491 PM 02-FEB-15 12.00.08.534 AM KPI_DW 3335085460 INSERT 0 27 40,040.21 1 350,267,429.00 1 No 0 INSERT /*+ BYPASS_RECURSIVE_CHECK APPEND */ INTO "KPI_DW"."P02_ADSL_E
2 22751 01-FEB-15 11.00.05.491 PM 02-FEB-15 12.00.08.534 AM KPI_DW 3335085460 INSERT 0 27 40,040.21 1 350,267,429.00 1 No 0 INSERT /*+ BYPASS_RECURSIVE_CHECK APPEND */ INTO "KPI_DW"."P02_ADSL_E
2 22751 01-FEB-15 11.00.05.456 PM 02-FEB-15 12.00.08.512 AM KPI_DW 3335085460 INSERT 0 27 40,040.21 1 350,267,429.00 1 No 0 INSERT /*+ BYPASS_RECURSIVE_CHECK APPEND */ INTO "KPI_DW"."P02_ADSL_E
2 22750 01-FEB-15 10.00.02.284 PM 01-FEB-15 11.00.05.491 PM KPI_DW 3335085460 INSERT 0 27 36,446.70 1 293,438,068.00 1 No 0 INSERT /*+ BYPASS_RECURSIVE_CHECK APPEND */ INTO "KPI_DW"."P02_ADSL_E
2 22750 01-FEB-15 10.00.02.272 PM 01-FEB-15 11.00.05.492 PM KPI_DW 3335085460 INSERT 0 27 36,446.70 1 293,438,068.00 1 No 0 INSERT /*+ BYPASS_RECURSIVE_CHECK APPEND */ INTO "KPI_DW"."P02_ADSL_E
2 22750 01-FEB-15 10.00.02.272 PM 01-FEB-15 11.00.05.491 PM KPI_DW 3335085460 INSERT 0 27 36,446.70 1 293,438,068.00 1 No 0 INSERT /*+ BYPASS_RECURSIVE_CHECK APPEND */ INTO "KPI_DW"."P02_ADSL_E
2 22750 01-FEB-15 10.00.02.238 PM 01-FEB-15 11.00.05.456 PM KPI_DW 3335085460 INSERT 0 27 36,446.70 1 293,438,068.00 1 No 0 INSERT /*+ BYPASS_RECURSIVE_CHECK APPEND */ INTO "KPI_DW"."P02_ADSL_E
2 22749 01-FEB-15 09.00.15.240 PM 01-FEB-15 10.00.02.238 PM KPI_DW 3335085460 INSERT 0 27 32,840.22 1 235,820,229.00 1 No 0 INSERT /*+ BYPASS_RECURSIVE_CHECK APPEND */ INTO "KPI_DW"."P02_ADSL_E
2 22749 01-FEB-15 09.00.15.239 PM 01-FEB-15 10.00.02.272 PM KPI_DW 3335085460 INSERT 0 27 32,840.22 1 235,820,229.00 1 No 0 INSERT /*+ BYPASS_RECURSIVE_CHECK APPEND */ INTO "KPI_DW"."P02_ADSL_E
2 22749 01-FEB-15 09.00.15.232 PM 01-FEB-15 10.00.02.272 PM KPI_DW 3335085460 INSERT 0 27 32,840.22 1 235,820,229.00 1 No 0 INSERT /*+ BYPASS_RECURSIVE_CHECK APPEND */ INTO "KPI_DW"."P02_ADSL_E
2 22749 01-FEB-15 09.00.15.212 PM 01-FEB-15 10.00.02.284 PM KPI_DW 3335085460 INSERT 0 27 32,840.22 1 235,820,229.00 1 No 0 INSERT /*+ BYPASS_RECURSIVE_CHECK APPEND */ INTO "KPI_DW"."P02_ADSL_E
2 22748 01-FEB-15 08.00.01.379 PM 01-FEB-15 09.00.15.232 PM KPI_DW 3335085460 INSERT 0 27 29,247.55 1 179,211,311.00 1 No 0 INSERT /*+ BYPASS_RECURSIVE_CHECK APPEND */ INTO "KPI_DW"."P02_ADSL_E
2 22748 01-FEB-15 08.00.01.379 PM 01-FEB-15 09.00.15.212 PM KPI_DW 3335085460 INSERT 0 27 29,247.55 1 179,211,311.00 1 No 0 INSERT /*+ BYPASS_RECURSIVE_CHECK APPEND */ INTO "KPI_DW"."P02_ADSL_E
2 22748 01-FEB-15 08.00.01.379 PM 01-FEB-15 09.00.15.240 PM KPI_DW 3335085460 INSERT 0 27 29,247.55 1 179,211,311.00 1 No 0 INSERT /*+ BYPASS_RECURSIVE_CHECK APPEND */ INTO "KPI_DW"."P02_ADSL_E
2 22748 01-FEB-15 08.00.01.346 PM 01-FEB-15 09.00.15.239 PM KPI_DW 3335085460 INSERT 0 27 29,247.55 1 179,211,311.00 1 No 0 INSERT /*+ BYPASS_RECURSIVE_CHECK APPEND */ INTO "KPI_DW"."P02_ADSL_E
2 22747 01-FEB-15 07.00.33.882 PM 01-FEB-15 08.00.01.379 PM KPI_DW 3335085460 INSERT 0 27 25,633.89 1 122,143,890.00 1 No 0 INSERT /*+ BYPASS_RECURSIVE_CHECK APPEND */ INTO "KPI_DW"."P02_ADSL_E
2 22747 01-FEB-15 07.00.33.581 PM 01-FEB-15 08.00.01.379 PM KPI_DW 3335085460 INSERT 0 27 25,633.89 1 122,143,890.00 1 No 0 INSERT /*+ BYPASS_RECURSIVE_CHECK APPEND */ INTO "KPI_DW"."P02_ADSL_E
2 22747 01-FEB-15 07.00.33.579 PM 01-FEB-15 08.00.01.346 PM KPI_DW 3335085460 INSERT 0 27 25,633.89 1 122,143,890.00 1 No 0 INSERT /*+ BYPASS_RECURSIVE_CHECK APPEND */ INTO "KPI_DW"."P02_ADSL_E
2 22747 01-FEB-15 07.00.33.541 PM 01-FEB-15 08.00.01.379 PM KPI_DW 3335085460 INSERT 0 27 25,633.89 1 122,143,890.00 1 No 0 INSERT /*+ BYPASS_RECURSIVE_CHECK APPEND */ INTO "KPI_DW"."P02_ADSL_E
2 22746 01-FEB-15 06.00.20.808 PM 01-FEB-15 07.00.33.882 PM KPI_DW 3335085460 INSERT 0 27 22,098.67 1 74,967,553.00 1 No 0 INSERT /*+ BYPASS_RECURSIVE_CHECK APPEND */ INTO "KPI_DW"."P02_ADSL_E
2 22746 01-FEB-15 06.00.20.775 PM 01-FEB-15 07.00.33.579 PM KPI_DW 3335085460 INSERT 0 27 22,098.67 1 74,967,553.00 1 No 0 INSERT /*+ BYPASS_RECURSIVE_CHECK APPEND */ INTO "KPI_DW"."P02_ADSL_E
2 22746 01-FEB-15 06.00.20.760 PM 01-FEB-15 07.00.33.581 PM KPI_DW 3335085460 INSERT 0 27 22,098.67 1 74,967,553.00 1 No 0 INSERT /*+ BYPASS_RECURSIVE_CHECK APPEND */ INTO "KPI_DW"."P02_ADSL_E
2 22746 01-FEB-15 06.00.20.715 PM 01-FEB-15 07.00.33.541 PM KPI_DW 3335085460 INSERT 0 27 22,098.67 1 74,967,553.00 1 No 0 INSERT /*+ BYPASS_RECURSIVE_CHECK APPEND */ INTO "KPI_DW"."P02_ADSL_E
2 22745 01-FEB-15 05.00.07.902 PM 01-FEB-15 06.00.20.808 PM KPI_DW 3335085460 INSERT 0 27 18,457.38 1 43,945,086.00 1 No 0 INSERT /*+ BYPASS_RECURSIVE_CHECK APPEND */ INTO "KPI_DW"."P02_ADSL_E
2 22745 01-FEB-15 05.00.07.710 PM 01-FEB-15 06.00.20.760 PM KPI_DW 3335085460 INSERT 0 27 18,457.38 1 43,945,086.00 1 No 0 INSERT /*+ BYPASS_RECURSIVE_CHECK APPEND */ INTO "KPI_DW"."P02_ADSL_E
2 22745 01-FEB-15 05.00.07.706 PM 01-FEB-15 06.00.20.775 PM KPI_DW 3335085460 INSERT 0 27 18,457.38 1 43,945,086.00 1 No 0 INSERT /*+ BYPASS_RECURSIVE_CHECK APPEND */ INTO "KPI_DW"."P02_ADSL_E
2 22745 01-FEB-15 05.00.07.662 PM 01-FEB-15 06.00.20.715 PM KPI_DW 3335085460 INSERT 0 27 18,457.38 1 43,945,086.00 1 No 0 INSERT /*+ BYPASS_RECURSIVE_CHECK APPEND */ INTO "KPI_DW"."P02_ADSL_E
2 22744 01-FEB-15 04.00.12.351 PM 01-FEB-15 05.00.07.710 PM KPI_DW 3335085460 INSERT 0 27 14,849.22 1 14,563,203.00 1 No 0 INSERT /*+ BYPASS_RECURSIVE_CHECK APPEND */ INTO "KPI_DW"."P02_ADSL_E
2 22744 01-FEB-15 04.00.12.108 PM 01-FEB-15 05.00.07.902 PM KPI_DW 3335085460 INSERT 0 27 14,849.22 1 14,563,203.00 1 No 0 INSERT /*+ BYPASS_RECURSIVE_CHECK APPEND */ INTO "KPI_DW"."P02_ADSL_E
2 22744 01-FEB-15 04.00.12.083 PM 01-FEB-15 05.00.07.662 PM KPI_DW 3335085460 INSERT 0 27 14,849.22 1 14,563,203.00 1 No 0 INSERT /*+ BYPASS_RECURSIVE_CHECK APPEND */ INTO "KPI_DW"."P02_ADSL_E
2 22744 01-FEB-15 04.00.12.028 PM 01-FEB-15 05.00.07.706 PM KPI_DW 3335085460 INSERT 0 27 14,849.22 1 14,563,203.00 1 No 0 INSERT /*+ BYPASS_RECURSIVE_CHECK APPEND */ INTO "KPI_DW"."P02_ADSL_E
2 22396 18-JAN-15 04.03.59.726 AM 18-JAN-15 05.00.13.653 AM KPI_DW 3997204181 INSERT 1 1282 57.97 1 1,239,789.00 1 No 0 INSERT /*+ BYPASS_RECURSIVE_CHECK APPEND */ INTO "KPI_DW"."P02_ADSL_E
2 22396 18-JAN-15 04.00.07.104 AM 18-JAN-15 05.00.13.781 AM KPI_DW 3997204181 INSERT 1 1282 57.97 1 1,239,789.00 1 No 0 INSERT /*+ BYPASS_RECURSIVE_CHECK APPEND */ INTO "KPI_DW"."P02_ADSL_E
2 22396 18-JAN-15 04.00.07.100 AM 18-JAN-15 05.00.13.780 AM KPI_DW 3997204181 INSERT 1 1282 57.97 1 1,239,789.00 1 No 0 INSERT /*+ BYPASS_RECURSIVE_CHECK APPEND */ INTO "KPI_DW"."P02_ADSL_E
2 22396 18-JAN-15 04.00.07.052 AM 18-JAN-15 05.00.13.791 AM KPI_DW 3997204181 INSERT 1 1282 57.97 1 1,239,789.00 1 No 0 INSERT /*+ BYPASS_RECURSIVE_CHECK APPEND */ INTO "KPI_DW"."P02_ADSL_E
4 22002 01-JAN-15 06.00.06.052 PM 01-JAN-15 07.00.04.447 PM KPI_DW 3441090710 INSERT 1 6074 1,374.79 1 539,451.00 1 No 0 INSERT /*+ BYPASS_RECURSIVE_CHECK APPEND */ INTO "KPI_DW"."P02_ADSL_E
4 22002 01-JAN-15 06.00.06.031 PM 01-JAN-15 07.00.04.513 PM KPI_DW 3441090710 INSERT 1 6074 1,374.79 1 539,451.00 1 No 0 INSERT /*+ BYPASS_RECURSIVE_CHECK APPEND */ INTO "KPI_DW"."P02_ADSL_E
4 22002 01-JAN-15 06.00.06.030 PM 01-JAN-15 07.00.04.516 PM KPI_DW 3441090710 INSERT 1 6074 1,374.79 1 539,451.00 1 No 0 INSERT /*+ BYPASS_RECURSIVE_CHECK APPEND */ INTO "KPI_DW"."P02_ADSL_E
4 22002 01-JAN-15 06.00.05.996 PM 01-JAN-15 07.00.04.514 PM KPI_DW 3441090710 INSERT 1 6074 1,374.79 1 539,451.00 1 No 0 INSERT /*+ BYPASS_RECURSIVE_CHECK APPEND */ INTO "KPI_DW"."P02_ADSL_E
4 22000 01-JAN-15 04.00.26.725 PM 01-JAN-15 05.00.12.921 PM KPI_DW 3441090710 INSERT 1 6074 1,166.20 1 540,304.00 1 No 0 INSERT /*+ BYPASS_RECURSIVE_CHECK APPEND */ INTO "KPI_DW"."P02_ADSL_E
4 22000 01-JAN-15 04.00.26.725 PM 01-JAN-15 05.00.12.827 PM KPI_DW 3441090710 INSERT 1 6074 1,166.20 1 540,304.00 1 No 0 INSERT /*+ BYPASS_RECURSIVE_CHECK APPEND */ INTO "KPI_DW"."P02_ADSL_E
4 22000 01-JAN-15 04.00.26.725 PM 01-JAN-15 05.00.12.865 PM KPI_DW 3441090710 INSERT 1 6074 1,166.20 1 540,304.00 1 No 0 INSERT /*+ BYPASS_RECURSIVE_CHECK APPEND */ INTO "KPI_DW"."P02_ADSL_E
4 22000 01-JAN-15 04.00.26.689 PM 01-JAN-15 05.00.12.985 PM KPI_DW 3441090710 INSERT 1 6074 1,166.20 1 540,304.00 1 No 0 INSERT /*+ BYPASS_RECURSIVE_CHECK APPEND */ INTO "KPI_DW"."P02_ADSL_E
80 rows selected.
Elapsed: 00:00:00.24
INSTANCE_NUMBER SNAP_ID BEGIN_INTERVAL_TIME END_INTERVAL_TIME PARSING_SCHEMA_NAME SQL_ID PLAN_HASH_VALUE COMMAND_TYPE_DESC SQL_PROFILE EXECUTIONS_TOTAL OPTIMIZER_COST AVG_ETIME AVG_PX AVG_LIO NOCHILD_CURSORS OFFLOAD IO_SAVED_% SQL_TEXT
--------------- ---------- ------------------------------ ------------------------------ ------------------------------ --------------- --------------- ---------------------------- ---------------------------------------------------------------- ----------------- -------------- ------------------- ------- ------------------- ---------------- ------- ---------- --------------------------------------------------------------
2 22950 10-FEB-15 06.00.26.175 AM 10-FEB-15 07.00.01.423 AM KPI_DW 4sk1dmw4q3zkb 1097924584 INSERT 1 6029 89.99 1 2,243,246.00 1 No 0 INSERT /*+ BYPASS_RECURSIVE_CHECK APPEND */ INTO "KPI_DW"."P02_ADSL_E
....
2 22752 02-FEB-15 12.00.08.512 AM 02-FEB-15 01.00.12.224 AM KPI_DW 3335085460 INSERT 0 27 43,646.66 1 407,025,475.00 1 No 0 INSERT /*+ BYPASS_RECURSIVE_CHECK APPEND */ INTO "KPI_DW"."P02_ADSL_E
2 22751 01-FEB-15 11.00.05.492 PM 02-FEB-15 12.00.08.534 AM KPI_DW 3335085460 INSERT 0 27 40,040.21 1 350,267,429.00 1 No 0 INSERT /*+ BYPASS_RECURSIVE_CHECK APPEND */ INTO "KPI_DW"."P02_ADSL_E
2 22751 01-FEB-15 11.00.05.491 PM 02-FEB-15 12.00.08.534 AM KPI_DW 3335085460 INSERT 0 27 40,040.21 1 350,267,429.00 1 No 0 INSERT /*+ BYPASS_RECURSIVE_CHECK APPEND */ INTO "KPI_DW"."P02_ADSL_E
2 22751 01-FEB-15 11.00.05.491 PM 02-FEB-15 12.00.08.534 AM KPI_DW 3335085460 INSERT 0 27 40,040.21 1 350,267,429.00 1 No 0 INSERT /*+ BYPASS_RECURSIVE_CHECK APPEND */ INTO "KPI_DW"."P02_ADSL_E
2 22751 01-FEB-15 11.00.05.456 PM 02-FEB-15 12.00.08.512 AM KPI_DW 3335085460 INSERT 0 27 40,040.21 1 350,267,429.00 1 No 0 INSERT /*+ BYPASS_RECURSIVE_CHECK APPEND */ INTO "KPI_DW"."P02_ADSL_E
2 22750 01-FEB-15 10.00.02.284 PM 01-FEB-15 11.00.05.491 PM KPI_DW 3335085460 INSERT 0 27 36,446.70 1 293,438,068.00 1 No 0 INSERT /*+ BYPASS_RECURSIVE_CHECK APPEND */ INTO "KPI_DW"."P02_ADSL_E
2 22750 01-FEB-15 10.00.02.272 PM 01-FEB-15 11.00.05.492 PM KPI_DW 3335085460 INSERT 0 27 36,446.70 1 293,438,068.00 1 No 0 INSERT /*+ BYPASS_RECURSIVE_CHECK APPEND */ INTO "KPI_DW"."P02_ADSL_E
2 22750 01-FEB-15 10.00.02.272 PM 01-FEB-15 11.00.05.491 PM KPI_DW 3335085460 INSERT 0 27 36,446.70 1 293,438,068.00 1 No 0 INSERT /*+ BYPASS_RECURSIVE_CHECK APPEND */ INTO "KPI_DW"."P02_ADSL_E
2 22750 01-FEB-15 10.00.02.238 PM 01-FEB-15 11.00.05.456 PM KPI_DW 3335085460 INSERT 0 27 36,446.70 1 293,438,068.00 1 No 0 INSERT /*+ BYPASS_RECURSIVE_CHECK APPEND */ INTO "KPI_DW"."P02_ADSL_E
2 22749 01-FEB-15 09.00.15.240 PM 01-FEB-15 10.00.02.238 PM KPI_DW 3335085460 INSERT 0 27 32,840.22 1 235,820,229.00 1 No 0 INSERT /*+ BYPASS_RECURSIVE_CHECK APPEND */ INTO "KPI_DW"."P02_ADSL_E
2 22749 01-FEB-15 09.00.15.239 PM 01-FEB-15 10.00.02.272 PM KPI_DW 3335085460 INSERT 0 27 32,840.22 1 235,820,229.00 1 No 0 INSERT /*+ BYPASS_RECURSIVE_CHECK APPEND */ INTO "KPI_DW"."P02_ADSL_E
2 22749 01-FEB-15 09.00.15.232 PM 01-FEB-15 10.00.02.272 PM KPI_DW 3335085460 INSERT 0 27 32,840.22 1 235,820,229.00 1 No 0 INSERT /*+ BYPASS_RECURSIVE_CHECK APPEND */ INTO "KPI_DW"."P02_ADSL_E
2 22749 01-FEB-15 09.00.15.212 PM 01-FEB-15 10.00.02.284 PM KPI_DW 3335085460 INSERT 0 27 32,840.22 1 235,820,229.00 1 No 0 INSERT /*+ BYPASS_RECURSIVE_CHECK APPEND */ INTO "KPI_DW"."P02_ADSL_E
2 22748 01-FEB-15 08.00.01.379 PM 01-FEB-15 09.00.15.232 PM KPI_DW 3335085460 INSERT 0 27 29,247.55 1 179,211,311.00 1 No 0 INSERT /*+ BYPASS_RECURSIVE_CHECK APPEND */ INTO "KPI_DW"."P02_ADSL_E
2 22748 01-FEB-15 08.00.01.379 PM 01-FEB-15 09.00.15.212 PM KPI_DW 3335085460 INSERT 0 27 29,247.55 1 179,211,311.00 1 No 0 INSERT /*+ BYPASS_RECURSIVE_CHECK APPEND */ INTO "KPI_DW"."P02_ADSL_E
2 22748 01-FEB-15 08.00.01.379 PM 01-FEB-15 09.00.15.240 PM KPI_DW 3335085460 INSERT 0 27 29,247.55 1 179,211,311.00 1 No 0 INSERT /*+ BYPASS_RECURSIVE_CHECK APPEND */ INTO "KPI_DW"."P02_ADSL_E
2 22748 01-FEB-15 08.00.01.346 PM 01-FEB-15 09.00.15.239 PM KPI_DW 3335085460 INSERT 0 27 29,247.55 1 179,211,311.00 1 No 0 INSERT /*+ BYPASS_RECURSIVE_CHECK APPEND */ INTO "KPI_DW"."P02_ADSL_E
2 22747 01-FEB-15 07.00.33.882 PM 01-FEB-15 08.00.01.379 PM KPI_DW 3335085460 INSERT 0 27 25,633.89 1 122,143,890.00 1 No 0 INSERT /*+ BYPASS_RECURSIVE_CHECK APPEND */ INTO "KPI_DW"."P02_ADSL_E
2 22747 01-FEB-15 07.00.33.581 PM 01-FEB-15 08.00.01.379 PM KPI_DW 3335085460 INSERT 0 27 25,633.89 1 122,143,890.00 1 No 0 INSERT /*+ BYPASS_RECURSIVE_CHECK APPEND */ INTO "KPI_DW"."P02_ADSL_E
2 22747 01-FEB-15 07.00.33.579 PM 01-FEB-15 08.00.01.346 PM KPI_DW 3335085460 INSERT 0 27 25,633.89 1 122,143,890.00 1 No 0 INSERT /*+ BYPASS_RECURSIVE_CHECK APPEND */ INTO "KPI_DW"."P02_ADSL_E
2 22747 01-FEB-15 07.00.33.541 PM 01-FEB-15 08.00.01.379 PM KPI_DW 3335085460 INSERT 0 27 25,633.89 1 122,143,890.00 1 No 0 INSERT /*+ BYPASS_RECURSIVE_CHECK APPEND */ INTO "KPI_DW"."P02_ADSL_E
2 22746 01-FEB-15 06.00.20.808 PM 01-FEB-15 07.00.33.882 PM KPI_DW 3335085460 INSERT 0 27 22,098.67 1 74,967,553.00 1 No 0 INSERT /*+ BYPASS_RECURSIVE_CHECK APPEND */ INTO "KPI_DW"."P02_ADSL_E
2 22746 01-FEB-15 06.00.20.775 PM 01-FEB-15 07.00.33.579 PM KPI_DW 3335085460 INSERT 0 27 22,098.67 1 74,967,553.00 1 No 0 INSERT /*+ BYPASS_RECURSIVE_CHECK APPEND */ INTO "KPI_DW"."P02_ADSL_E
2 22746 01-FEB-15 06.00.20.760 PM 01-FEB-15 07.00.33.581 PM KPI_DW 3335085460 INSERT 0 27 22,098.67 1 74,967,553.00 1 No 0 INSERT /*+ BYPASS_RECURSIVE_CHECK APPEND */ INTO "KPI_DW"."P02_ADSL_E
2 22746 01-FEB-15 06.00.20.715 PM 01-FEB-15 07.00.33.541 PM KPI_DW 3335085460 INSERT 0 27 22,098.67 1 74,967,553.00 1 No 0 INSERT /*+ BYPASS_RECURSIVE_CHECK APPEND */ INTO "KPI_DW"."P02_ADSL_E
2 22745 01-FEB-15 05.00.07.902 PM 01-FEB-15 06.00.20.808 PM KPI_DW 3335085460 INSERT 0 27 18,457.38 1 43,945,086.00 1 No 0 INSERT /*+ BYPASS_RECURSIVE_CHECK APPEND */ INTO "KPI_DW"."P02_ADSL_E
2 22745 01-FEB-15 05.00.07.710 PM 01-FEB-15 06.00.20.760 PM KPI_DW 3335085460 INSERT 0 27 18,457.38 1 43,945,086.00 1 No 0 INSERT /*+ BYPASS_RECURSIVE_CHECK APPEND */ INTO "KPI_DW"."P02_ADSL_E
2 22745 01-FEB-15 05.00.07.706 PM 01-FEB-15 06.00.20.775 PM KPI_DW 3335085460 INSERT 0 27 18,457.38 1 43,945,086.00 1 No 0 INSERT /*+ BYPASS_RECURSIVE_CHECK APPEND */ INTO "KPI_DW"."P02_ADSL_E
2 22745 01-FEB-15 05.00.07.662 PM 01-FEB-15 06.00.20.715 PM KPI_DW 3335085460 INSERT 0 27 18,457.38 1 43,945,086.00 1 No 0 INSERT /*+ BYPASS_RECURSIVE_CHECK APPEND */ INTO "KPI_DW"."P02_ADSL_E
2 22744 01-FEB-15 04.00.12.351 PM 01-FEB-15 05.00.07.710 PM KPI_DW 3335085460 INSERT 0 27 14,849.22 1 14,563,203.00 1 No 0 INSERT /*+ BYPASS_RECURSIVE_CHECK APPEND */ INTO "KPI_DW"."P02_ADSL_E
2 22744 01-FEB-15 04.00.12.108 PM 01-FEB-15 05.00.07.902 PM KPI_DW 3335085460 INSERT 0 27 14,849.22 1 14,563,203.00 1 No 0 INSERT /*+ BYPASS_RECURSIVE_CHECK APPEND */ INTO "KPI_DW"."P02_ADSL_E
2 22744 01-FEB-15 04.00.12.083 PM 01-FEB-15 05.00.07.662 PM KPI_DW 3335085460 INSERT 0 27 14,849.22 1 14,563,203.00 1 No 0 INSERT /*+ BYPASS_RECURSIVE_CHECK APPEND */ INTO "KPI_DW"."P02_ADSL_E
2 22744 01-FEB-15 04.00.12.028 PM 01-FEB-15 05.00.07.706 PM KPI_DW 3335085460 INSERT 0 27 14,849.22 1 14,563,203.00 1 No 0 INSERT /*+ BYPASS_RECURSIVE_CHECK APPEND */ INTO "KPI_DW"."P02_ADSL_E
2 22396 18-JAN-15 04.03.59.726 AM 18-JAN-15 05.00.13.653 AM KPI_DW 3997204181 INSERT 1 1282 57.97 1 1,239,789.00 1 No 0 INSERT /*+ BYPASS_RECURSIVE_CHECK APPEND */ INTO "KPI_DW"."P02_ADSL_E
2 22396 18-JAN-15 04.00.07.104 AM 18-JAN-15 05.00.13.781 AM KPI_DW 3997204181 INSERT 1 1282 57.97 1 1,239,789.00 1 No 0 INSERT /*+ BYPASS_RECURSIVE_CHECK APPEND */ INTO "KPI_DW"."P02_ADSL_E
2 22396 18-JAN-15 04.00.07.100 AM 18-JAN-15 05.00.13.780 AM KPI_DW 3997204181 INSERT 1 1282 57.97 1 1,239,789.00 1 No 0 INSERT /*+ BYPASS_RECURSIVE_CHECK APPEND */ INTO "KPI_DW"."P02_ADSL_E
2 22396 18-JAN-15 04.00.07.052 AM 18-JAN-15 05.00.13.791 AM KPI_DW 3997204181 INSERT 1 1282 57.97 1 1,239,789.00 1 No 0 INSERT /*+ BYPASS_RECURSIVE_CHECK APPEND */ INTO "KPI_DW"."P02_ADSL_E
4 22002 01-JAN-15 06.00.06.052 PM 01-JAN-15 07.00.04.447 PM KPI_DW 3441090710 INSERT 1 6074 1,374.79 1 539,451.00 1 No 0 INSERT /*+ BYPASS_RECURSIVE_CHECK APPEND */ INTO "KPI_DW"."P02_ADSL_E
4 22002 01-JAN-15 06.00.06.031 PM 01-JAN-15 07.00.04.513 PM KPI_DW 3441090710 INSERT 1 6074 1,374.79 1 539,451.00 1 No 0 INSERT /*+ BYPASS_RECURSIVE_CHECK APPEND */ INTO "KPI_DW"."P02_ADSL_E
4 22002 01-JAN-15 06.00.06.030 PM 01-JAN-15 07.00.04.516 PM KPI_DW 3441090710 INSERT 1 6074 1,374.79 1 539,451.00 1 No 0 INSERT /*+ BYPASS_RECURSIVE_CHECK APPEND */ INTO "KPI_DW"."P02_ADSL_E
4 22002 01-JAN-15 06.00.05.996 PM 01-JAN-15 07.00.04.514 PM KPI_DW 3441090710 INSERT 1 6074 1,374.79 1 539,451.00 1 No 0 INSERT /*+ BYPASS_RECURSIVE_CHECK APPEND */ INTO "KPI_DW"."P02_ADSL_E
4 22000 01-JAN-15 04.00.26.725 PM 01-JAN-15 05.00.12.921 PM KPI_DW 3441090710 INSERT 1 6074 1,166.20 1 540,304.00 1 No 0 INSERT /*+ BYPASS_RECURSIVE_CHECK APPEND */ INTO "KPI_DW"."P02_ADSL_E
4 22000 01-JAN-15 04.00.26.725 PM 01-JAN-15 05.00.12.827 PM KPI_DW 3441090710 INSERT 1 6074 1,166.20 1 540,304.00 1 No 0 INSERT /*+ BYPASS_RECURSIVE_CHECK APPEND */ INTO "KPI_DW"."P02_ADSL_E
4 22000 01-JAN-15 04.00.26.725 PM 01-JAN-15 05.00.12.865 PM KPI_DW 3441090710 INSERT 1 6074 1,166.20 1 540,304.00 1 No 0 INSERT /*+ BYPASS_RECURSIVE_CHECK APPEND */ INTO "KPI_DW"."P02_ADSL_E
4 22000 01-JAN-15 04.00.26.689 PM 01-JAN-15 05.00.12.985 PM KPI_DW 3441090710 INSERT 1 6074 1,166.20 1 540,304.00 1 No 0 INSERT /*+ BYPASS_RECURSIVE_CHECK APPEND */ INTO "KPI_DW"."P02_ADSL_E
80 rows selected.
Elapsed: 00:00:00.24
Listing 2: Searching the execution history for an sql id in AWR.
----------------------------------------------------------------------------
Summary
Performance problems in queries due to a change of plan is something quite common in data warehouses. In this post we have shown how easy it is to detect a change in the execution plan of a query. Once you get the sql id and the problematic execution plan, it is only a matter of querying AWR in order to browse the execution history of the query in question and verify the change of plan.
In a future post (check out post "Using SQL Plan Baselines to Revert to an Older Plan"),
we will show how you can revert to the good plan in an very fast manner with the use of SQL Plan Baselines Note that in this previous post we have already shown how to use SQL Profiles in order to force a specific execution plan.
we will show how you can revert to the good plan in an very fast manner with the use of SQL Plan Baselines Note that in this previous post we have already shown how to use SQL Profiles in order to force a specific execution plan.
The Scripts
fs.sql
You can always find the latest version of this script on my GitHub repository here.
nkarag@DWHPRD> host cat fs.sql
-- This script can be used to locate statements in the shared pool and
-- determine (among other) whether they have been executed via Smart Scans.
--
-- It is based on the observation that the IO_CELL_OFFLOAD_ELIGIBLE_BYTES
-- column in V$SQL is only greater than 0 when a statement is executed
-- using a Smart Scan. The IO_SAVED_% column attempts to show the ratio of
-- of data received from the storage cells to the actual amount of data
-- that would have had to be retrieved on non-Exadata storage. Note that
-- as of 11.2.0.2, there are issues calculating this value with some queries.
--
-- Note that the AVG_ETIME will not be acurate for parallel queries. The
-- ELAPSED_TIME column contains the sum of all parallel slaves. So the
-- script divides the value by the number of PX slaves used which gives an
-- approximation.
--
-- Note also that if parallel slaves are spread across multiple nodes on
-- a RAC database the PX_SERVERS_EXECUTIONS column will not be set.
--
-- (C) Nikos Karagiannidis - http://oradwstories.blogspot.com
col sql_text for a70 wrap
set verify off
set pagesize 999
set lines 999
col username format a13
col prog format a22
col sid format 999
col child_number format 99999 heading CHILD
col ocategory format a10
col avg_etime_secs format 9,999,999.99
col avg_pio format 9,999,999.99
col avg_lio format 999,999,999
col etime format 9,999,999.99
col is_shareable format a12
col is_bind_sensitive format a17
col is_bind_aware format a14
col offload for a7
alter session set NLS_DATE_FORMAT = 'dd-mm-yyyy HH24:mi:ss'
/
select PARSING_SCHEMA_NAME, inst_id, sql_id, child_number, plan_hash_value plan_hash, executions execs,
(elapsed_time/1000000)/decode(nvl(executions,0),0,1,executions) avg_etime_secs,
buffer_gets/decode(nvl(executions,0),0,1,executions) avg_lio,
last_active_time,
SQL_PROFILE,
is_shareable, is_bind_sensitive, is_bind_aware,
sql_text,
decode(IO_CELL_OFFLOAD_ELIGIBLE_BYTES,0,'No','Yes') Offload,
decode(IO_CELL_OFFLOAD_ELIGIBLE_BYTES,0,0,100*(IO_CELL_OFFLOAD_ELIGIBLE_BYTES-IO_INTERCONNECT_BYTES)
/decode(IO_CELL_OFFLOAD_ELIGIBLE_BYTES,0,1,IO_CELL_OFFLOAD_ELIGIBLE_BYTES)) "IO_SAVED_%"
from gv$sql s
where upper(sql_text) like upper(nvl('&sql_text',sql_text))
and sql_text not like '%from gv$sql where upper(sql_text) like nvl(%'
and sql_id like nvl(trim('&sql_id'),sql_id)
order by 1, 2, 3
/
------------------------------------------------------------------
fs_awr.sql
You can always find the latest version of this script on my GitHub repository here.nkarag@DWHPRD> host cat fs_awr.sql
------------------------------------------------------------------------------------------------------------------
-- Find executions history of an SQL_ID in the AWR repository
--
--- The offloading info is based on the observation that the IO_CELL_OFFLOAD_ELIGIBLE_BYTES
-- column in V$SQL is only greater than 0 when a statement is executed
-- using a Smart Scan. The IO_SAVED_% column attempts to show the ratio of
-- of data received from the storage cells to the actual amount of data
-- that would have had to be retrieved on non-Exadata storage. Note that
-- as of 11.2.0.2, there are issues calculating this value with some queries.
--
-- Note that the AVG_ETIME will not be acurate for parallel queries. The
-- ELAPSED_TIME column contains the sum of all parallel slaves. So the
-- script divides the value by the number of PX slaves used which gives an
-- approximation.
--
-- Note also that if parallel slaves are spread across multiple nodes on
-- a RAC database the PX_SERVERS_EXECUTIONS column will not be set.
--
-- author: (C) Nikos Karagiannidis - http://oradwstories.blogspot.com
------------------------------------------------------------------------------------------------------------------
set pagesize 999
set lines 999
col sql_text format a70 trunc
col child format 99999
col sql_id for a15
col plan_hash_value for 9999999999999
col executions_total format 9999999999999999
col avg_etime format 999,999,999,999.99
col avg_lio format 999,999,999,999.99
col NOCHILD_CURSORS for 999999999999999
col "OFFLOADED_%" format a11
col avg_px format 999999
col offload for a7
col BEGIN_INTERVAL_TIME format a30
col END_INTERVAL_TIME format a30
-- using dba_hist_sqlstat
select a.INSTANCE_NUMBER, snap_id, BEGIN_INTERVAL_TIME, END_INTERVAL_TIME,
PARSING_SCHEMA_NAME,
sql_id, PLAN_HASH_VALUE,
aa.name command_type_desc,
SQL_PROFILE,
executions_total,
OPTIMIZER_COST,
(ELAPSED_TIME_TOTAL/1e6)/decode(nvl(EXECUTIONS_TOTAL,0),0,1,EXECUTIONS_TOTAL)/
decode(PX_SERVERS_EXECS_TOTAL,0,1,PX_SERVERS_EXECS_TOTAL)/decode(nvl(EXECUTIONS_TOTAL,0),0,1,EXECUTIONS_TOTAL) avg_etime,
decode(PX_SERVERS_EXECS_TOTAL,0,1,PX_SERVERS_EXECS_TOTAL)/decode(nvl(EXECUTIONS_TOTAL,0),0,1,EXECUTIONS_TOTAL) avg_px,
BUFFER_GETS_TOTAL/decode(nvl(EXECUTIONS_TOTAL,0),0,1,EXECUTIONS_TOTAL) avg_lio,
VERSION_COUNT nochild_cursors,
decode(IO_OFFLOAD_ELIG_BYTES_TOTAL,0,'No','Yes') Offload,
decode(IO_OFFLOAD_ELIG_BYTES_TOTAL,0,0,100*(IO_OFFLOAD_ELIG_BYTES_TOTAL-IO_INTERCONNECT_BYTES_TOTAL))
/decode(IO_OFFLOAD_ELIG_BYTES_TOTAL,0,1,IO_OFFLOAD_ELIG_BYTES_TOTAL) "IO_SAVED_%",
c.sql_text
from DBA_HIST_SQLSTAT a left outer join
DBA_HIST_SNAPSHOT b using (SNAP_ID) left outer join
DBA_HIST_SQLTEXT c using (SQL_ID) left outer join
audit_actions aa on (COMMAND_TYPE = aa.ACTION)
where
upper(dbms_lob.substr(sql_text, 4000, 1)) like upper(nvl('&sql_text',upper(dbms_lob.substr(sql_text, 4000, 1)))) --use dbms_lob.substr in order not to get an "ORA-22835: Buffer too small for CLOB to CHAR or BLOB to RAW conversion"
and sql_id = nvl(trim('&sql_id'),sql_id)
and b.begin_interval_time > sysdate - &days_back
order by 2 desc,3 desc;
undef days_back
------------------------------------------------------------------
No comments:
Post a Comment