Lesson Learned #1: Capturing a TSQL Command Timeout

Published 03-13-2019 06:12 PM 883 Views

In many support cases that we worked our customer needs to know that is the query that caused a Command Timeout issue, for example, receiving an error message like Execution Timeout Expired. The timeout period elapsed prior to completion of the operation or the server is not responding. In this example below, you could find out the extended event that we share to our customers in order to capture it.

 

 

CREATE MASTER KEY ENCRYPTION BY PASSWORD = 'Password123!!!!'
CREATE DATABASE SCOPED CREDENTIAL [https://azureblobcontainer.blob.core.windows.net/xe-container] WITH IDENTITY = 'SHARED ACCESS SIGNATURE', SECRET = 'sv=2019-12-12&ss=b&srt=sco&sp=rwdlacx&se=2020-10-28T23:38:22Z&st=2020-09-29T14:38:22Z&spr=https&sig=24TJMAf1hOzE2DDVqw1QRs....'

CREATE EVENT SESSION ssEventoTimeout 
ON DATABASE 
ADD EVENT sqlserver.sql_batch_completed ( 
ACTION  (sqlserver.client_app_name,sqlserver.client_connection_id,sqlserver.client_hostname,sqlserver.client_pid,sqlserver.database_id,sqlserver.database_name,sqlserver.session_id,sqlserver.sql_text,sqlserver.username) 
WHERE ([result] <> (0))) 
ADD TARGET package0.asynchronous_file_target( 
SET filename='https://azureblobcontainer.blob.core.windows.net/xe-container/DemoPersistedTimeout.xel')

ALTER EVENT SESSION ssEventoTimeout ON DATABASE STATE=START

 

 

If you need to reproduce a TSQL command timeout, basically you need to:

Create a stored procedure that takes more time that you expected in your application:

 

 

create PROC usp_Timeout 
as 
select 1 
waitfor delay '00:00:10'

 

 

Try to specify in the SQL SERVER Management Studio->Command Timeout or in your application change the command timeout parameter with a value less than you have in waitfor (in this case, 5 seconds)

 

 

using (SqlConnection awConnectionDb = new SqlConnection(connectionStringDb)) 
{ 
awConnectionDb.Open(); 
SqlCommand cmd1 = awConnectionDb.CreateCommand(); 
cmd1.CommandTimeout = 5; 
cmd1.CommandText = string.Format("usp_Timeout"); 
cmd1.ExecuteNonQuery(); 
}

 

 

Right now, we need to stop the extended event running the following query and review the file generated in our blob storage.

 

 

ALTER EVENT SESSION ssEventoTimeout ON DATABASE STATE=STOP

 


Enjoy!

%3CLINGO-SUB%20id%3D%22lingo-sub-368791%22%20slang%3D%22en-US%22%3ELesson%20Learned%20%231%3A%20Capturing%20a%20TSQL%20Command%20Timeout%3C%2FLINGO-SUB%3E%3CLINGO-BODY%20id%3D%22lingo-body-368791%22%20slang%3D%22en-US%22%3E%3CP%3EIn%20many%20support%20cases%20that%20we%20worked%20our%20customer%20needs%20to%20know%20that%20is%20the%20query%20%3CSTRONG%3E%20that%20caused%26nbsp%3Ba%20Command%20Timeout%20issue%2C%20for%20example%2C%20receiving%20an%20error%20message%20like%20Execution%20Timeout%20Expired.%20The%20timeout%20period%20elapsed%20prior%20to%20completion%20of%20the%20operation%20or%20the%20server%20is%20not%20responding%3C%2FSTRONG%3E.%20In%20this%20example%20below%2C%20you%20could%20find%20out%20the%20%3CA%20href%3D%22https%3A%2F%2Fazure.microsoft.com%2Fen-in%2Fdocumentation%2Farticles%2Fsql-database-xevent-db-diff-from-svr%2F%22%20target%3D%22_blank%22%20rel%3D%22noopener%20noreferrer%22%3E%20extended%20event%20%3C%2FA%3E%20that%20we%20share%20to%20our%20customers%20in%20order%20to%20capture%20it.%3C%2FP%3E%0A%3CP%3E%26nbsp%3B%3C%2FP%3E%0A%3CP%3E%26nbsp%3B%3C%2FP%3E%0A%3CPRE%20class%3D%22lia-code-sample%20language-sql%22%3E%3CCODE%3ECREATE%20MASTER%20KEY%20ENCRYPTION%20BY%20PASSWORD%20%3D%20'Password123!!!!'%0ACREATE%20DATABASE%20SCOPED%20CREDENTIAL%20%5Bhttps%3A%2F%2Fazureblobcontainer.blob.core.windows.net%2Fxe-container%5D%20WITH%20IDENTITY%20%3D%20'SHARED%20ACCESS%20SIGNATURE'%2C%20SECRET%20%3D%20'sv%3D2019-12-12%26amp%3Bss%3Db%26amp%3Bsrt%3Dsco%26amp%3Bsp%3Drwdlacx%26amp%3Bse%3D2020-10-28T23%3A38%3A22Z%26amp%3Bst%3D2020-09-29T14%3A38%3A22Z%26amp%3Bspr%3Dhttps%26amp%3Bsig%3D24TJMAf1hOzE2DDVqw1QRs....'%0A%0ACREATE%20EVENT%20SESSION%20ssEventoTimeout%20%0AON%20DATABASE%20%0AADD%20EVENT%20sqlserver.sql_batch_completed%20(%20%0AACTION%26nbsp%3B%20(sqlserver.client_app_name%2Csqlserver.client_connection_id%2Csqlserver.client_hostname%2Csqlserver.client_pid%2Csqlserver.database_id%2Csqlserver.database_name%2Csqlserver.session_id%2Csqlserver.sql_text%2Csqlserver.username)%20%0AWHERE%20(%5Bresult%5D%20%26lt%3B%26gt%3B%20(0)))%20%0AADD%20TARGET%20package0.asynchronous_file_target(%20%0ASET%20filename%3D'https%3A%2F%2Fazureblobcontainer.blob.core.windows.net%2Fxe-container%2FDemoPersistedTimeout.xel')%0A%0AALTER%20EVENT%20SESSION%20ssEventoTimeout%20ON%20DATABASE%20STATE%3DSTART%3C%2FCODE%3E%3C%2FPRE%3E%0A%3CP%3E%26nbsp%3B%3C%2FP%3E%0A%3CP%3E%26nbsp%3B%3C%2FP%3E%0A%3CP%3EIf%20you%20need%20to%20reproduce%20a%20TSQL%20command%20timeout%2C%20basically%20you%20need%20to%3A%20%3CBR%20%2F%3E%3CBR%20%2F%3E%3C%2FP%3E%0A%3CP%3E%3CSTRONG%3E%20Create%20a%20stored%20procedure%20that%20takes%20more%20time%20that%20you%20expected%20in%20your%20application%3A%3C%2FSTRONG%3E%3C%2FP%3E%0A%3CP%3E%26nbsp%3B%3C%2FP%3E%0A%3CP%3E%26nbsp%3B%3C%2FP%3E%0A%3CPRE%20class%3D%22lia-code-sample%20language-sql%22%3E%3CCODE%3Ecreate%20PROC%20usp_Timeout%20%0Aas%20%0Aselect%201%20%0Awaitfor%20delay%20'00%3A00%3A10'%3C%2FCODE%3E%3C%2FPRE%3E%0A%3CP%3E%26nbsp%3B%3C%2FP%3E%0A%3CP%3E%26nbsp%3B%3C%2FP%3E%0A%3CP%3E%3CSTRONG%3E%20Try%20to%20specify%20in%20the%20SQL%20SERVER%20Management%20Studio-%26gt%3BCommand%20Timeout%20or%20in%20your%20application%20change%20the%20command%20timeout%20parameter%20with%20a%20value%20less%20than%20you%20have%20in%20waitfor%20(in%20this%20case%2C%26nbsp%3B5%20seconds)%3C%2FSTRONG%3E%3C%2FP%3E%0A%3CP%3E%26nbsp%3B%3C%2FP%3E%0A%3CP%3E%26nbsp%3B%3C%2FP%3E%0A%3CPRE%20class%3D%22lia-code-sample%20language-csharp%22%3E%3CCODE%3Eusing%20(SqlConnection%20awConnectionDb%20%3D%20new%20SqlConnection(connectionStringDb))%20%0A%7B%20%0AawConnectionDb.Open()%3B%20%0ASqlCommand%20cmd1%20%3D%20awConnectionDb.CreateCommand()%3B%20%0Acmd1.CommandTimeout%20%3D%205%3B%20%0Acmd1.CommandText%20%3D%20string.Format(%22usp_Timeout%22)%3B%20%0Acmd1.ExecuteNonQuery()%3B%20%0A%7D%3C%2FCODE%3E%3C%2FPRE%3E%0A%3CP%3E%26nbsp%3B%3C%2FP%3E%0A%3CP%3E%26nbsp%3B%3C%2FP%3E%0A%3CP%3E%3CSTRONG%3ERight%20now%2C%20we%20need%20to%20stop%20the%20extended%20event%20running%20the%20following%20query%20and%20review%20the%20file%20generated%20in%20our%20blob%20storage.%20%3C%2FSTRONG%3E%3C%2FP%3E%0A%3CP%3E%26nbsp%3B%3C%2FP%3E%0A%3CP%3E%26nbsp%3B%3C%2FP%3E%0A%3CPRE%20class%3D%22lia-code-sample%20language-sql%22%3E%3CCODE%3EALTER%20EVENT%20SESSION%20ssEventoTimeout%20ON%20DATABASE%20STATE%3DSTOP%3C%2FCODE%3E%3C%2FPRE%3E%0A%3CP%3E%26nbsp%3B%3C%2FP%3E%0A%3CP%3E%3CBR%20%2F%3EEnjoy!%3C%2FP%3E%3C%2FLINGO-BODY%3E%3CLINGO-TEASER%20id%3D%22lingo-teaser-368791%22%20slang%3D%22en-US%22%3E%3CP%3EIn%20many%20support%20cases%20that%20we%20worked%20our%20customer%20needs%20to%20know%20that%20is%20the%20query%20%3CSTRONG%3E%20that%20caused%26nbsp%3Ba%20Command%20Timeout%20issue%2C%20for%20example%2C%20receiving%20an%20error%20message%20like%20Execution%20Timeout%20Expired.%20The%20timeout%20period%20elapsed%20prior%20to%20completion%20of%20the%20operation%20or%20the%20server%20is%20not%20responding%3C%2FSTRONG%3E.%20In%20this%20example%20below%2C%20you%20could%20find%20out%20the%20%3CA%20href%3D%22https%3A%2F%2Fazure.microsoft.com%2Fen-in%2Fdocumentation%2Farticles%2Fsql-database-xevent-db-diff-from-svr%2F%22%20target%3D%22_blank%22%20rel%3D%22noopener%20noreferrer%22%3E%20extended%20event%20%3C%2FA%3E%20that%20we%20share%20to%20our%20customers%20in%20order%20to%20capture%20it.%3C%2FP%3E%0A%3CP%3E%26nbsp%3B%3C%2FP%3E%3C%2FLINGO-TEASER%3E%3CLINGO-LABS%20id%3D%22lingo-labs-368791%22%20slang%3D%22en-US%22%3E%3CLINGO-LABEL%3EAzure%20SQL%3C%2FLINGO-LABEL%3E%3CLINGO-LABEL%3Ecommand%20timeout%3C%2FLINGO-LABEL%3E%3CLINGO-LABEL%3Eextended%20event%3C%2FLINGO-LABEL%3E%3C%2FLINGO-LABS%3E
Version history
Last update:
‎Oct 23 2020 08:47 AM
Updated by: