How to effectively tune a query that does not even finish (SQL Monitoring and ASH in action)
Have you ever been called to tune a query that runs forever?
Even worse, what if the query is very complex, you don't know anything about the "logic"
behind the SQL - since it was written by someone else - and when you see the execution
plan it is several pages long?
Moreover, what if the query is for retrieving a list of customers for a business critical
campaign that has to run asap, and therefore the beloved management is over your shoulder,
waiting for you to solve the problem!
Problem Definition
Never ending queries, or at least queries that cannot finish within an acceptable time
frame are quite common in large Data Warehouses. Unfortunately, in this situation one
cannot use methods where execution statistics are gathered first and then analysi
s of the execution steps can take place. Simply because the query does not finish!
For example such a great tuning method would be the following:
- execute the query with the hint /*+ gather_plan_statistics */
- (or alternatively issuing an ALTER SESSION SET STATISTICS_LEVEL=ALL prior to query execution), in order to enable the collection of the so-called "row-source statistics"
- (i.e., execution statistics for each operation (row-source) in the execution plan).
- After the completion of the query, use DBMS_XPLAN.DISPLAY_CURSOR, or directly query V$SQL_PLAN_STATISTICS_ALL, in order to:
- Identify problematic cardinality estimations by the optimizer by comparing actual rows
- retrieved in each step of the plan versus estimated rows.
- Identify bottlenecks in the plan, i.e., operations that take too long to complete.
(By the way, two great posts that describe how to use DBMS_XPLAN.DISPLAY_CURSOR to tune a query, can be found here(by Kyle Hailey) and here (by Nikolay Savvinov)).
So what can we do? We need a way to get accurate execution statistics at the individual operation level, so as to easily identify the bottlenecks, while the query is still running. What are our options?
11g has the Solution!
Well, from version 11g and onwards there is a great feature called Real-Time SQL Monitoring that allows you to monitor a query executing in real-time and provides useful statistics at an individual plan operation level that help you easily (and quickly!) identify the bottleneck in an execution plan. (Note that the Real-Time SQL Monitoring feature is licensed with Oracle Tuning Pack in order to use it in production). If you want a more detailed description of this feature check out this Oracle white paper and of course the documentation (here).
Another option is to use one of the greatest-ever Oracle features (available since 10g), the Active Session History (ASH) (licensed with Oracle Diagnostic Pack). Note that from version 11g, ASH has become even greater since it includes columns indicating the individual execution plan operation and thus making the identification of time-consuming steps very easy.
In this post, we will give an example of a complex query, that runs forever and describe how we can tune it (i.e., to identify the bottleneck and then try to fix it) with the use of both of these tools (SQL monitoring and ASH).
A real-life Example
So we have a complex query that has been running for some hours and the execution plan, which is retrieved with a call like this:
Listing 1: How we retrieve the plan of a running query based on sql_id. ---------------------------------------------------------------------------------------------------------------------
looks like this:
Plan hash value: 2144277924
Listing 2: The execution plan of the problematic query. ---------------------------------------------------------------------------------------------------------------------
Take a look how easy it is to identify the bottleneck with SQL monitoring. Here is the srcipt I use:
nkarag@DWHPRD> host cat mons_text.sql
Listing 3: A script for retrieving SQL Monitor results for a specific sql_id ---------------------------------------------------------------------------------------------------------------------
and here are the results:
SQL Plan Monitoring Details (Plan Hash Value=2144277924)
Listing 4: SQL Monitoring results for the problematic query. ---------------------------------------------------------------------------------------------------------------------
Look at line 13 in listing 4 (the FILTER operation). The arrow on the left indicates that this step is currently executing. It has been running for 4168 seconds as the column "Time Active(s)" reports. So for sure it is among the bottlenecks that we search for. In our case, this filter operation has two children operations. Among these, one of the ones that is running for the longest period is operation 44 (TABLE ACCESS STORAGE FULL on a temp table). It is also running for 4168 seconds. If we look a bit to the right, we can immediately see the the "Execs" column for this operation is 627K, which means that this operation has been executed up to now for 627K times! Oops that's a lot of times for doing a full table scan on a large table, isn't it? Moreover, if we look a bit further to the right we will see that up to now this operation has returned (output rows) 4G rows!
So, it is quite easy to understand the problem of this execution plan is this extremely inefficient filter operation (which executes in a nested loop fashion). See how easy it was, when you use the right tools?
Can we have the same results with ASH? Oh yes we can!
Here is a little script that identifies the plan operation that runs for the largest percent of wall-clock time (the script gives you an option to choose sorting of plan operations by wall-clock time descending or by DB time descending. With the former you can identify the most time consuming step while with the latter you can identify the most resource consuming step of the plan):
Listing 5: A script for returning the plan operation of a running query that consumed the most wall-clock time based on ASH. ---------------------------------------------------------------------------------------------------------------------
and here are the results when we run the above script for the problematic query which is executing:
Listing 6: Results of ASH for the problematic query. ---------------------------------------------------------------------------------------------------------------------
We have run the script for a 60 minute window (the maximun retention period for ASH) and we clearly see that the most delay is in operations 43 and 44. The results in listing 6 are sorted in descending order of percent of wall-clock time consumed by an operation.
An even better approach would be to first run the ASH script in order to identify the most consuming operation and then, run the SQL monitoring script to get an overall view of the plan and get the more accurate execution time metrics, execution counts of each step etc. Imagine that in a very long plan, it is difficult for the human eye to catch the largest values in column "Time Active(s)".
So clearly SQL monitoring ans ASH have helped us easily and quickly identify the problem. Now, of course we have to find a fix.
How to fix the problem
In the previous section we showed how easy it is to identify the "bottleneck operations" of a running query with the help of SQL monitoring and/or ASH in version 11g. Once you identify the problem, then you have only traveled half-way because you also have to fix it. The fix of course depends by the specific case at hand (see some brief categorization of problems here).
For our running example the problem lies in the FILTER operation (operation 13 in Listing 4). The problematic full table scan (operation 44) is a child operation of this filter. The FILTER operation with two child sources is a clear indicator that the optimizer did not manage to unnest a subquery. After some careful examination of the SQL statement, we easily managed to find the pain point! It was an IN subquery after an OR condition. Something with the following form:
SELECT
FROM
WHERE
<condition1>
AND <condition2>
AND (
<confition3>
OR <condition 4>
OR <condition 5>
OR <values> IN (subquery)
)
Once we removed the bold part above from the problematic statement the query finished in 35 seconds! Actually as it turned out the this condition was redundant and could be discarded all together.
Summary
In this post we have shown a real-life example of how to identify efficiently the most time consuming operation in the execution plan of a running query that does not finish. We have used two great 11g features, namely:
- Real-time SQL Monitoring
- Active Session History (essentially the new columns added in 11g that reveal the operation running)
A similar example with the use of ASH we have posted in the past here.
If you have to tune queries as your daily job then you must learn to use SQL monitoring and ASH really good. They are great life saviors!
No comments:
Post a Comment