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

[Guest Jose_Manuel_Jurado]

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?

 

 

 

 

• When an execution timeout (attention) is happending a dataset with this error (MSSQLSERVER_3617 - SQL Server | Microsoft Learn) is saved in the table AzureDiagnostics of Log Analytics workspace.
  
• You could run the following KQL to obtain these details:
  

 

 

 

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.
    

 

 

 

 

• 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!

 

Continue reading...