Lesson Learned #254: Checking Execution Timeouts in Azure Log Analytics

Posted on by — No Comments ↓

This post has been republished via RSS; it originally appeared at: Azure Database Support Blog articles.

Today, I worked on a service request when our customer needs to know several details about the command timeout captured (attention event) and sent to Log Analytics from Azure Diagnostic settings. In this article I would like to share my findings. 

 

Question #1: What is the meaning of error_state_d?

 

 

AzureDiagnostics | where Category == "Timeouts"

 

 

  • Listing the columns and values, our customer asked about the meaning of error_state_d:
    • This column is "A numeric state value associated with the query timeout (an attention event)" and represents the part of SQL Server engine code that the query was executing before raising the timeout. For example, if my client commandTimeout is 5 seconds, executing the following TSQL code an execution timeout will be raised with error_state_d value associated with WAITFOR execution. In other situations, for example, CREATE INDEX, could be depending on the stage of the process, if for reading rows, accesing metadata, etc.. For us, the most important thing will be that it is a timeout in our code nothing else.

 

SELECT 1 WAITFOR DELAY '00:00:10'

 

 

Question #2: Is possible to identify the query hash or query text of this timeout? 

 

  • For this specific scenario, I think that will be more useful to use the Query Data Store Runtime Dataset instead of using Timeout Dataset, because we could find more information about query text, number of executions, execution plan, etc.., for example: 
    • We have an execution timeout causing by an incorrect command timeout setting in C# code.

Jose_Manuel_Jurado_0-1671584108935.png

 

  • Once we have recorded this command timeout we could use:
    • Query Data Store, running the following query:

 

SELECT qst.query_sql_text, qrs.execution_type, qrs.execution_type_desc, qpx.query_plan_xml, qrs.count_executions, qrs.last_execution_time FROM sys.query_store_query AS qsq JOIN sys.query_store_plan AS qsp on qsq.query_id=qsp.query_id JOIN sys.query_store_query_text AS qst on qsq.query_text_id=qst.query_text_id OUTER APPLY (SELECT TRY_CONVERT(XML, qsp.query_plan) AS query_plan_xml) AS qpx JOIN sys.query_store_runtime_stats qrs on qsp.plan_id = qrs.plan_id WHERE qrs.execution_type =3 ORDER BY qrs.last_execution_time DESC; GO

 

    • Log Analystics

 

AzureDiagnostics | where Category == "QueryStoreRuntimeStatistics" | where execution_type_d == 3

 

 

    • In both cases, we need to connect to the database to obtain the query_text or other details based on the Query_Hash obtained in the previous filter.

 

SELECT qt.query_sql_text query_text, q.query_hash FROM sys.query_store_query q JOIN sys.query_store_query_text qt ON q.query_text_id = qt.query_text_id WHERE q.query_hash = <QueryHash>

 

 

Finally, if you need to customize your own Command Timeout report, you could read this link: Lesson Learned #1: Capturing a TSQL Command Timeout - Microsoft Community Hub

 

Enjoy!

Leave a Reply

Your email address will not be published. Required fields are marked *

*

This site uses Akismet to reduce spam. Learn how your comment data is processed.