Wishful Thinking: Monitoring Plans In Production

Updated November 25, 2013: This "April Fools' Day" article was originally published with the title "Monitoring Plans In Production". Sadly, it continues to show up in Google searches for "GRAPHICAL_PLAN", continuing to fool readers long past the original publishing date... hence, the new title, and this comment.

---

(This article is reprinted here with permission. It was first published on April 1, 2014.)

---

Folks often know exactly which queries qualify as Queries From Hell, and they often have ongoing problems with execution plans that change over time to cause performance to oscillate by orders of magnitude.

The most recent version of SQL Anywhere introduced a new feature for monitoring execution plans in production, called "Log Expensive Queries", similar to the older GRAPHICAL_PLAN function. Here's what the syntax looks like:

SET TEMPORARY OPTION LOG_EXPENSIVE_QUERIES = { 'ON' | 'OFF' };

SELECT [ other-clauses ] ...
[ LOG_EXPENSIVE_QUERY ( xml-plan, threshold-milliseconds ) ]

When a query containing a LOG_EXPENSIVE_QUERY clause is encountered during execution, the clause is ignored if the connection option LOG_EXPENSIVE_QUERIES is currently 'OFF'; there is no performance penalty in this case.

If LOG_EXPENSIVE_QUERIES is 'ON', however, the query engine preserves information about the execution plan until the query finishes executing. At that point, if the actual run time for the query was equal to or greater than the threshold-milliseconds argument in the LOG_EXPENSIVE_QUERY clause, the XML version of the plan is returned in the xml-plan argument. It is then up to the application to do something with value in xml-plan; e.g., save it in a table or write it to a file.

If LOG_EXPENSIVE_QUERIES is 'ON' but the actual run time does not reach threshold-milliseconds, the xml-plan argument is set to NULL.

To demonstrate, here is an excerpt from a large stored procedure showing a query that took almost 123 seconds to run:

CREATE PROCEDURE ...
...
SELECT TOP 1 rroad_sample_set.sample_set_number
INTO @month_older_sample_set_number
FROM rroad_sample_set
WHERE rroad_sample_set.sampling_id = @sampling_id
AND rroad_sample_set.sample_finished_at
<= DATEADD ( MONTH, -1, @sample_finished_at )
ORDER BY rroad_sample_set.sample_set_number DESC;
...
END;

Here's how the code was modified to use the new Log Expensive Queries feature:

CREATE TABLE saplan (
pkey       INTEGER NOT NULL DEFAULT AUTOINCREMENT PRIMARY KEY,
xml_plan   XML );

CREATE PROCEDURE ...
...
DECLARE @xml_plan XML;
...

SELECT TOP 1 rroad_sample_set.sample_set_number
INTO @month_older_sample_set_number
FROM rroad_sample_set
WHERE rroad_sample_set.sampling_id = @sampling_id
AND rroad_sample_set.sample_finished_at
<= DATEADD ( WEEK, -1, @sample_finished_at )
ORDER BY rroad_sample_set.sample_set_number DESC
LOG_EXPENSIVE_QUERY ( @xml_plan, 10000 );

IF @xml_plan IS NOT NULL THEN
INSERT saplan ( xml_plan ) VALUES ( @xml_plan );
SET TEMPORARY OPTION LOG_EXPENSIVE_QUERIES = 'OFF'; 
END IF;
...
END;

The table defined on lines 1 to 3 is used to store the plans captured at run time. The variable declared on line 7 is used as the first argument to the LOG_EXPENSIVE_QUERY clause. The LOG_EXPENSIVE_QUERY clause on line 17 names @xml_plan as the variable to receive the plan, and sets the threshold to 10,000 milliseconds. The code on lines 19 to 22 checks to see if the LOG_EXPENSIVE_QUERY clause did in fact capture a plan, and if so, it saves that plan in the saplan table and sets the LOG_EXPENSIVE_QUERIES option to 'OFF' so no more plans are captured. After the procedure ran in production and the code save the first plan, here's what the saplan table looks like: The dbisql utility has been enhanced to recognize XML values that contain graphical plans so that when you doubleclick on a plan it opens the Plan Viewer: Note that the Plan Viewer SQL pane shows the query after all rewrite optimizations have been performed, and after the actual values 8 and '2011 04 07 13:43:05.932' have been substituted for the host variables @sampling_id and @sample_finished_at.

---

(There is, of course, no such thing as the LOG_EXPENSIVE_QUERY clause... but there should be :)