SQL Server – Identify Lock TimeOuts via Extended Events ( from converted Trace File )

 

This is the 3rd in a series of posts on Identifying Lock Timeouts.

Here are earlier posts:

  1. SQL Server – “Lock Timeouts” – Identifying through SQL Server Profiler
    Link
  2. SQL Server – “Lock Timeouts” – Trigger Timeouts – SSMS – Table Designer
    Link

Extended Events

Extended Events introduced in SQL 2008 is lighter to run on a system compared to client side SQL Server Profiler or Server Side Trace.

Design Tooling

Unfortunately, when first introduced with SQL 2008 tooling for creating events was not included.

SQL 2008-R2 came with tooling for designing new Extended Events ( EE ) and modifying existing ones.

But, unfortunately, in my humble estimation, the tooling did not sufficiently expand on what is available via SQL Server Profiler.

In  a later post, we will touch on some items that can be bettered in the GUI for creating and modifying Extended Events.

 

 

Convert SQL Server Profiler to Extended Event

Jonathan Kehayias

SQLSkills has a very good Stored Procedure ( SP ) that generates a script for extended event from a running trace.

It is available here.

As always I am late as this tool was released back in 2012.

 

Create SP

Once downloaded, please create the SP, sp_SQLskills_ConvertTraceToExtendedEvents.

 

Use SP

To use the SP, please do the following:

  1. Start SQL Server Profiler Trace
  2. Get the Trace Number by running “select * from sys.traces
  3. Generate Extended Event Script – Pass along Trace ID
  4. Capture & Appy Generated Script
  5. Review and amend generated Extended Event
  6. Start Extended Event
  7. View Life Data

 

Get Trace Number
Code

select *

from sys.traces tblST

-- Not Default Trace
where tblST.[is_default] = 0

-- Trace is running
and tblST.[status] = 1

order by
tblST.start_time desc

 

Output

 

Generate Extended Event Script
Code
use master
go

declare	@TraceID INT
declare	@SessionName NVARCHAR(128)
declare	@PrintOutput BIT
declare	@Execute BIT

set		@TraceID = 4
set		@SessionName = 'IdentifyLockTimeOut'
set 	@PrintOutput = 1
set	    @Execute = 0


exec sp_SQLskills_ConvertTraceToExtendedEvents
		  @TraceID = @TraceID
		, @SessionName = @SessionName
		, @PrintOutput = @PrintOutput
		, @Execute = @Execute

 

Output

IF EXISTS (SELECT 1 FROM sys.server_event_sessions WHERE name = 'IdentifyLockTimeOut')
	DROP EVENT SESSION [IdentifyLockTimeOut] ON SERVER;
GO
CREATE EVENT SESSION [IdentifyLockTimeOut]
ON SERVER
ADD EVENT sqlserver.lock_cancel(
	ACTION 
	(
			  sqlserver.client_app_name	-- ApplicationName from SQLTrace
			, sqlserver.client_hostname	-- HostName from SQLTrace
			, sqlserver.client_pid	-- ClientProcessID from SQLTrace
			, package0.event_sequence	-- EventSequence from SQLTrace
			, sqlserver.is_system	-- IsSystem from SQLTrace
			, sqlserver.nt_username	-- NTDomainName from SQLTrace
			, sqlserver.request_id	-- RequestID from SQLTrace
			, sqlserver.server_instance_name	-- ServerName from SQLTrace
			, sqlserver.server_principal_name	-- LoginName from SQLTrace
			, sqlserver.server_principal_sid	-- LoginSid from SQLTrace
			, sqlserver.session_id	-- SPID from SQLTrace
			, sqlserver.session_resource_group_id	-- GroupID from SQLTrace
			, sqlserver.session_server_principal_name	-- SessionLoginName from SQLTrace
			, sqlserver.transaction_id	-- TransactionID from SQLTrace
			-- IntegerData2 not implemented in XE for this event
	)
	WHERE 
	(
			duration >= 30000000
	)
),
ADD EVENT sqlserver.rpc_completed(
	ACTION 
	(
			  sqlserver.client_app_name	-- ApplicationName from SQLTrace
			, sqlserver.client_hostname	-- HostName from SQLTrace
			, sqlserver.client_pid	-- ClientProcessID from SQLTrace
			, sqlserver.database_id	-- DatabaseID from SQLTrace
			, sqlserver.database_name	-- DatabaseName from SQLTrace
			, package0.event_sequence	-- EventSequence from SQLTrace
			, sqlserver.is_system	-- IsSystem from SQLTrace
			, sqlserver.request_id	-- RequestID from SQLTrace
			, sqlserver.server_instance_name	-- ServerName from SQLTrace
			, sqlserver.server_principal_name	-- LoginName from SQLTrace
			, sqlserver.session_id	-- SPID from SQLTrace
			, sqlserver.session_resource_group_id	-- GroupID from SQLTrace
			, sqlserver.session_server_principal_name	-- SessionLoginName from SQLTrace
			, sqlserver.transaction_id	-- TransactionID from SQLTrace
			-- IntegerData not implemented in XE for this event
			-- BinaryData not implemented in XE for this event
	)
	WHERE 
	(
			duration >= 30000000
	)
),
ADD EVENT sqlserver.sql_batch_completed(
	ACTION 
	(
			  sqlserver.client_app_name	-- ApplicationName from SQLTrace
			, sqlserver.client_hostname	-- HostName from SQLTrace
			, sqlserver.client_pid	-- ClientProcessID from SQLTrace
			, sqlserver.database_id	-- DatabaseID from SQLTrace
			, sqlserver.database_name	-- DatabaseName from SQLTrace
			, package0.event_sequence	-- EventSequence from SQLTrace
			, sqlserver.is_system	-- IsSystem from SQLTrace
			, sqlserver.nt_username	-- NTDomainName from SQLTrace
			, sqlserver.request_id	-- RequestID from SQLTrace
			, sqlserver.server_instance_name	-- ServerName from SQLTrace
			, sqlserver.server_principal_name	-- LoginName from SQLTrace
			, sqlserver.server_principal_sid	-- LoginSid from SQLTrace
			, sqlserver.session_id	-- SPID from SQLTrace
			, sqlserver.session_resource_group_id	-- GroupID from SQLTrace
			, sqlserver.session_server_principal_name	-- SessionLoginName from SQLTrace
			, sqlserver.transaction_id	-- TransactionID from SQLTrace
	)
	WHERE 
	(
			duration >= 30000000
	)
),
ADD EVENT sqlserver.sql_statement_completed(
	ACTION 
	(
			  sqlserver.client_app_name	-- ApplicationName from SQLTrace
			, sqlserver.client_hostname	-- HostName from SQLTrace
			, sqlserver.client_pid	-- ClientProcessID from SQLTrace
			, sqlserver.database_id	-- DatabaseID from SQLTrace
			, sqlserver.database_name	-- DatabaseName from SQLTrace
			, package0.event_sequence	-- EventSequence from SQLTrace
			, sqlserver.is_system	-- IsSystem from SQLTrace
			, sqlserver.nt_username	-- NTDomainName from SQLTrace
			, sqlserver.request_id	-- RequestID from SQLTrace
			, sqlserver.server_instance_name	-- ServerName from SQLTrace
			, sqlserver.server_principal_name	-- LoginName from SQLTrace
			, sqlserver.server_principal_sid	-- LoginSid from SQLTrace
			, sqlserver.session_id	-- SPID from SQLTrace
			, sqlserver.session_resource_group_id	-- GroupID from SQLTrace
			, sqlserver.session_server_principal_name	-- SessionLoginName from SQLTrace
			, sqlserver.transaction_id	-- TransactionID from SQLTrace
	)
	WHERE 
	(
			duration >= 30000000
	)
),
ADD EVENT sqlserver.xml_deadlock_report(
	ACTION 
	(
			  sqlserver.server_instance_name	-- ServerName from SQLTrace
			, sqlserver.server_principal_name	-- LoginName from SQLTrace
			, sqlserver.session_id	-- SPID from SQLTrace
	)
)
ADD TARGET package0.ring_buffer


Review and amend generated Extended Event

Once Extended Event is created, view and amend it through GUI

Object Explorer

Here is the Object Explorer view, please select the Session, view and amend the targeted Session

 

Live Data

Once the EE is reviewed, please select the EE, start it and select the “Watch Live Data“.

We created a new transaction, added data to the table, and tried to modify the same table.

A short while later, we were able to trigger lock timeout.

Thankfully, our new EE captured same and here is what is captured

 

Live Data – lock-cancel ( Image )

 

Live Data – lock-cancel ( Tabulated )

 

Field Value
 associated_object_id  110623437
 client_app_name  Microsoft SQL Server Management Studio
 client_hostname  DADENIJI
 databse_id  7
 database_name
 duration  89997000
 owner_type  Transaction
 resource_o  110623437
 server_instance_name  DADENIJI\v2014
 server_principal_name dadeniji

 

 

 

Live Data – sql_batch_completed ( Image )

 

Live Data – sql_batch_completed ( Tabulated )

 

Field Value
batch_text  ALTER TABLE dbo.person ADD   gender char(1) NULL
 client_app_name  Microsoft SQL Server Management Studio
 client_hostname  DADENIJI
 databse_id  7
 database_name  DBLab
 duration  89993130
 result  Abort
 row_count  0
 server_instance_name  OBJECT
 server_principal_name dadeniji
 logical_reads  0
 physical_reads  0
 writes  0

 

 

 

Analysis

Processing Time Out

Previous to triggering the error, we increased our timeout by accessing Options\  Designers \ Table and Database Designers.

 

Captured Data

The two events we are tracking offers different dataset.

The “Lock Cancel” captures the following:

  1. The Database ID & Object ID of the Targeted Object
  2. Mode :- SCH_M – Schema Modification
  3. Forensics such as Application Name, Host Name, Database ID

On the other hand, the “SQL Batch Completed” captures the following:

  1. Batch Text :- “ALTER TABLE dbo.person ADD   gender char(1) NULL
  2. Pertinent Data such as Duration, Result – Abort in this case, Rowcount ( 0 )
  3. Forensics such as Application Name, Host Name, Database ID, Database name

 

Dedicated

Can’t go anywhere else but JK as in Jonathan Kehayias.

 

Summary

In later posts will discuss creating Extended Events, Monitoring, and measuring impact on the system.

One thought on “SQL Server – Identify Lock TimeOuts via Extended Events ( from converted Trace File )

Leave a Reply

Please log in using one of these methods to post your comment:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s