Lesson Learned #525: Tracking Command Timeouts in Azure SQL: Beyond Query Store with Extended Events
A few days ago, we were working on a support case where our customer was intermittently experiencing command timeouts. What made the case interesting was that queries which usually completed in under one second suddenly started taking more than 10 seconds to execute. Since the application — developed in Python using the ODBC Driver 18 for SQL Server — had a command timeout set to 5 seconds, the following error was triggered every time the threshold was exceeded: Error executing command, retrying in 5 seconds. Attempt 1 of 3 with new timeout 5. Error: ('HYT00', '[HYT00] [Microsoft][ODBC Driver 18 for SQL Server]Query timeout expired (0) (SQLExecDirectW)') The application had built-in retry logic, dynamically increasing the timeout in each of the three retry attempts, to allow time for the query to complete and to log enough data for post-error analysis. Example logs from the retry logic: (RunCommandTimeout) - Thread: 39808 - Error executing command, retrying in 5 seconds. Attempt 1 of 3 with new timeout 5. Error: ('HYT00', '[HYT00] [Microsoft][ODBC Driver 18 for SQL Server]Query timeout expired (0) (SQLExecDirectW)') INFO:root:Connecting to the DB jmjuradotestdb1 - Thread id 39808 - (Attempt 1/3) INFO:root:Connected to the Database in jmjuradotestdb1 - Thread id 39808 - 0.0445 seconds --- (RunCommandTimeout) - Thread: 39808 - Error executing command, retrying in 9 seconds. Attempt 2 of 3 with new timeout 9. Error: ('HYT00', '[HYT00] [Microsoft][ODBC Driver 18 for SQL Server]Query timeout expired (0) (SQLExecDirectW)') INFO:root:Connecting to the DB jmjuradotestdb1 - Thread id 39808 - (Attempt 1/3) INFO:root:Connected to the Database in jmjuradotestdb1 - Thread id 39808 - 0.0532 seconds --- (RunCommandTimeout) - Thread: 39808 - Error executing command, retrying in 13 seconds. Attempt 3 of 3 with new timeout 13. Error: ('HYT00', '[HYT00] [Microsoft][ODBC Driver 18 for SQL Server]Query timeout expired (0) (SQLExecDirectW)') (RunCommandTimeout) - Thread: 39808 - Loop:2/5 Execution Time: 9.7537 seconds My first prompt using SSMS Copilot was this "Review the queries that experienced a command timeout or were aborted in the last 30 minutes. Include query text, queryid, duration, and the reason and code for the abort if available." and I got the following results. So, all points that the query 216 got command timeouts. My next question, was, for query ID 216, show the number of total executions reporting that is 28 executions. The response showed 28 executions, but this number didn’t match the number of aborted and non-aborted executions observed in the application logs, why this difference? Checking the table sys.query_store_runtime_stats I found 10 rows all having execution_type = 3, and total executions 28. So, that's mean that Query Store aggregates query execution data over a fixed interval. So, the execution_type is an indicator that at least an execution during this runtime interval was aborted. So, at least several of them were aborted and other not. To obtain a more granular and accurate picture, I created an Extended Events session to capture these events using ring_buffer target. CREATE EVENT SESSION [CommandAborted] ON DATABASE ADD EVENT sqlserver.attention( ACTION ( sqlserver.client_app_name, sqlserver.client_hostname, sqlserver.username, sqlserver.database_name, sqlserver.sql_text ) ) ADD TARGET package0.ring_buffer WITH (MAX_MEMORY = 4096KB, EVENT_RETENTION_MODE = ALLOW_SINGLE_EVENT_LOSS); GO ALTER EVENT SESSION [CommandAborted] ON DATABASE STATE = START; after reproducing the command timeout scenario again, I was able to see only the aborted executions. So, in this case, 28 executions were executed and 7 executions were aborted. WITH RingBufferXML AS ( SELECT CAST(t.target_data AS XML) AS target_data FROM sys.dm_xe_database_session_targets t JOIN sys.dm_xe_database_sessions s ON t.event_session_address = s.address WHERE t.target_name = 'ring_buffer' AND s.name = 'CommandAborted' ) SELECT x.value('@name', 'varchar(50)') AS event_name, x.value('@timestamp', 'datetime2') AS event_time, x.value('(action[@name="client_app_name"]/value)[1]', 'nvarchar(256)') AS client_app_name, x.value('(action[@name="sql_text"]/value)[1]', 'nvarchar(max)') AS sql_text, x.value('(data[@name="duration"]/value)[1]', 'bigint') AS duration_microseconds, CAST(x.value('(data[@name="duration"]/value)[1]', 'bigint') / 1000000.0 AS decimal(10,3)) AS duration_seconds FROM RingBufferXML CROSS APPLY target_data.nodes('//event') AS tab(x) WHERE x.value('@name', 'varchar(50)') = 'attention' and x.value('(action[@name="client_app_name"]/value)[1]', 'nvarchar(256)') = 'TEST-DataCon' ORDER BY event_time DESC;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!Lesson Learned #364: Getting all conversion implicit warnings using Query Data Store Repository
During our last session in SQL Data Saturday, we received a question about if it is possible to know all the conversion implicit captured by Query Data Store. In the following example, I would like to share with you an example how to capture this considering among of SQL antipatterns.Lesson Learned #387:Monitoring Query Data Store State Changes in Azure SQL Database using PowerShell
This morning, I have been working on a support case where our client was not able to see certain queries when querying the Query Data Store. We have observed that the cause is due to the Query Data Store changing to a read-only mode due to the volume of data and the limitation our client had on the QDS database space. Therefore, I would like to share the following PowerShell script that can be executed at regular intervals to check and retrieve when the state of QDS has changed. Unfortunately, in Azure SQL Database, we cannot use the Extended Event 'qds.query_store_db_diagnostics'.
