Lesson Learned #521: Query Performance Regression with Multiple Execution Plans in Azure SQL

Some days ago, we were working on a service request where our customer asked why a query had degraded in performance. One possible issue could be that more than one execution plan is being used for a specific query. So I would like to share the steps we followed using QDS with DMVs.

First, we executed this query to identify any queries that had more than one plan_id, which is often a sign that the optimizer has compiled multiple strategies to run the same query:

SELECT
    q.query_id,
    qt.query_sql_text,
    q.query_hash,
    COUNT(DISTINCT p.plan_id) AS num_plans,
    STRING_AGG(CAST(p.plan_id AS VARCHAR), ', ') AS plan_ids
FROM sys.query_store_query_text qt
JOIN sys.query_store_query q ON qt.query_text_id = q.query_text_id
JOIN sys.query_store_plan p ON q.query_id = p.query_id
GROUP BY q.query_id, qt.query_sql_text, q.query_hash
HAVING COUNT(DISTINCT p.plan_id) > 1
ORDER BY num_plans DESC;

We got a list of queries and after some analysis, we found the one the customer was referring to.

The query in question was a simple aggregate with a parameter: 

(@N int)SELECT count(Name),name FROM Notes where ID<@n group by Name

As we found that they query has two plans, we executed the following TSQL to obtain the details of the executions. 

SELECT
    rs.execution_type_desc,                    
    rs.avg_duration / 1000 AS avg_duration_ms, 
    rs.avg_cpu_time / 1000 AS avg_cpu_ms,      
    rs.last_duration / 1000 AS last_duration_ms,
    rs.count_executions,
    rs.first_execution_time,
    rs.last_execution_time,
    p.plan_id,
    p.is_forced_plan,
    TRY_CONVERT(XML, p.query_plan) AS execution_plan_xml
FROM sys.query_store_runtime_stats rs
JOIN sys.query_store_plan p ON rs.plan_id = p.plan_id
WHERE p.query_id = 2
ORDER BY rs.last_execution_time DESC;

We got the following results: 

We could see the execution plan number 2 was executed less time but taking more time in average. Checking the execution plan XML we were able to identify an automatic update statistics was executed causing a new execution plan. 

Trying to give insights about possible causes, we wrote the following TSQL giving us when the statistics were updated directly from the execution plan XML.

;WITH XMLNAMESPACES (DEFAULT 'http://schemas.microsoft.com/sqlserver/2004/07/showplan')
SELECT 
    p.plan_id,
    stat.value('@Statistics', 'VARCHAR(200)') AS stats_name,
    stat.value('@LastUpdate', 'DATETIME') AS stats_last_updated,
    stat.value('@SamplingPercent', 'FLOAT') AS stats_sampling_percent
FROM sys.query_store_plan AS p
CROSS APPLY (
    SELECT CAST(p.query_plan AS XML) AS xml_plan
) AS x
OUTER APPLY  x.xml_plan.nodes('
    /ShowPlanXML/BatchSequence/Batch/Statements/StmtSimple/QueryPlan/OptimizerStatsUsage/StatisticsInfo'
) AS t(stat)
WHERE p.query_id = 2;

Well, we found another way to query directly the execution plan and include other information from Query Data Store. 

Enjoy!