Extended Events – Lock Timeouts

Background

Back to Extended Events, let us start looking at what we have been collecting.

 

Lock Timeouts

We are noticing quite a bit of lock timeouts, and so created an Extended Event Trace to collect them.

Outline

Saved events are saved in binary files.

We need the SQL Engine to extract the compressed XML files and parse its data into elements and attributes.

Query

Table Value Function – extendedEvent.itvf_EventsReview

Script


use master
go

if schema_id('extendedEvent') is null
begin

	exec('create schema [extendedEvent] authorization [dbo]');

end
go


/*

	drop function [extendedEvent].[itvf_EventsReviewFull]

*/

if object_id('[extendedEvent].[itvf_EventsReview]') is null
begin

	exec('create function [extendedEvent].[itvf_EventsReview]() returns table return select [shell] = 1/0 ')

end
go

alter function [extendedEvent].[itvf_EventsReview] 
(
	  @folderXEL sysname
	, @folderXEM sysname = null
	, @maxNumberofRecords int = 1E6
)
returns table

return

	with cte
	(
		  [objectName] 
		, [eventData] 
	)
	as
	(
		SELECT
 
			  [objectName] = tblFNXE.[object_name]
			, [eventData] = cast(tblFNXE.event_data as xml)
 
		FROM sys.fn_xe_file_target_read_file
			(
				  @folderXEL + '\' + '*.xel'
				, isNull(@folderXEM, @folderXEL) + '\' + '*.xem'
				, null
				, null
		   ) tblFNXE
	)
	select top ( 
				  @maxNumberofRecords
			   )
 
			  [objectName] = isNull(cte.[objectName], '')
 
			, [eventData] = cast(cte.eventData as xml)
			--, [XMLFragment] = [event].[node].query('.')
 
			--timestamp on root node
			--, [tsAsDateTimeUTC] 
			--	= [event].[node].value('@timestamp', 'datetimeoffset')     
 
			--collect system time
			, [systemTSAsValueUTC]
				 = cast
				   (
						cast
						(
								([event].[node].query('/event/action[@name="collect_system_time"]/value/text()'))
									as varchar(60)
						)
						as datetime
					)

			-- collect system time to locale time
			, [systemTSAsLocale] 
				 = cast
				   (
						cast
						(

							dateadd
							(
								 minute
							   , [dbo].[udfn_getTimeDifferenceBetweenUTCAndSystemTimeInMinutes]() * -1
 							   , cast
								 (
								   cast
								   (
									  ([event].[node].query('/event/action[@name="collect_system_time"]/value/text()')) 
									   as varchar(60)
								   )
								   as datetime
								)
							)
							as varchar(40)
					)
					as datetime
				)

			--is system
			, [isSystem] 
				= case 
						cast
						(
							([event].[node].query('/event/action[@name="is_system"]/value/text()'))
							as varchar(5)
                        )
						when 'true' then 'Y'
						else 'N'
                  end
				
			--session ID
			, [sessionID] 
				= cast
					(	
						cast
						(
							[event].[node].query('/event/action[@name="session_id"]/value/text()')
							as varchar(60)
						)
						as int
					)

 
			-- client Host Name
			, [clientHostName] 
				= cast
					(
						[event].[node].query('/event/action[@name="client_hostname"]/value/text()')
						as sysname
					)
 
			-- username
			, [username] 
				--= [event].[node].query('/event/action[@name="username"]/value/text()')
				= cast
					(
						[event].[node].query('/event/action[@name="session_server_principal_name"]/value/text()')
						as sysname
					)

			-- client App Name
			, [clientAppName] 
				= cast
					(
						[event].[node].query('/event/action[@name="client_app_name"]/value/text()')
						as sysname
					)
 
			-- SQL Text
			, [sqlText] 
				= cast
					(
						[event].[node].query('/event/action[@name="sql_text"]/value/text()')
						as nvarchar(max)
					)

			, [errorNumber]
				 = cast
					(
						[event].[node].value('(/event/data[@name="error_number"]/value)[1]', 'int')
						as int
					)

			, [result]
				 = cast
					(
						[event].[node].value('(/event/data[@name="result"]/text)[1]', 'nvarchar(30)')
						 as nvarchar(30)
					)

			-- Message
			, [message] 
				= cast
					(
						[event].[node].value('(/event/data[@name="message"]/value)[1]', 'nvarchar(4000)')
						as nvarchar(600)
					)
 
	from   cte
 
	cross apply cte.eventData.nodes(N'//event') event(node)


go


grant select on [extendedEvent].[itvf_EventsReview] to [public]
go

Invoke


select *

from   [extendedEvent].[itvf_EventsReview] 
	(
	    'C:\Assist\ExtendedEvents\TraceFiles\Prod'
	  , 'C:\Assist\ExtendedEvents\TraceFiles\Prod'
	  , default
       )

 

Output

lockTimeouts_20170411_0802PM

 

Persist Data

It is a lot less expensive to parse the XML data once and store the extracted data into an actual SQL Server table.

All queries will thereafter query the relational table.

Relational Table

extendedEvent.events

Create Table

if schema_id('extendedEvent') is null
begin

	exec('create schema [extendedEvent] authorization [dbo]; ')

end
go

if object_id('[extendedEvent].[events]') is null
begin

	create table [extendedEvent].[events]
	(

		  [id]							   bigint		not null identity(1,1)

		, [objectName]                     nvarchar(120) not null 
		, [eventData]                      xml not null 
		, [systemTSAsValueUTC]             datetime not null 
		, [systemTSAsLocale]               datetime not null 
		, [isSystem]                       varchar(1)  null 
		, [sessionID]                      int not null 
		, [clientHostName]                 sysname not null 
		, [username]                       sysname not null 
		, [clientAppName]                  sysname not null 
		, [sqlText]                        nvarchar(max)  not null 
		, [errorNumber]                    int null 
		, [result]                         nvarchar(600)  null 
		, [message]                        nvarchar(1200) null 


	)

end
go

if not exists
(
	select *
	from   sys.objects tblSO
	where   tblSO.parent_object_id = object_id('[extendedEvent].[events]')
)
begin

	alter table [extendedEvent].[events]
		add constraint [PK_ExtendedEvent.events]
			primary key
				(
					  [systemTSAsLocale] 
					, [objectName]
					, [sessionID]
					, [id]
				)
end
go

if not exists
(
	select *
	from   sys.indexes tblSI
	where  tblSI.object_id = object_id('[extendedEvent].[events]')
	and    tbLSI.[name] = 'INDX_ObjectName'
)
begin

	create index [INDX_ObjectName]
	on [extendedEvent].[events]
	(
		  [objectName]
		, [isSystem]
	)

end
go



Load Table

set nocount on;
go

use [AdminDB]
go

truncate table [extendedEvent].[events]
go

insert into [extendedEvent].[events]
(
       [objectName]
      ,[eventData]
      ,[systemTSAsValueUTC]
      ,[systemTSAsLocale]
      ,[isSystem]
      ,[sessionID]
      ,[clientHostName]
      ,[username]
      ,[clientAppName]
      ,[sqlText]
      ,[errorNumber]
      ,[result]
      ,[message]
)
select 
       [objectName]
      ,[eventData]
      ,[systemTSAsValueUTC]
      ,[systemTSAsLocale]
      ,[isSystem]
      ,[sessionID]
      ,[clientHostName]
      ,[username]
      ,[clientAppName]
      ,[sqlText]
      ,[errorNumber]
      ,[result]
      ,[message]
from   [master].[extendedEvent].[itvf_EventsReview] 
	(
		  'C:\Assist\ExtendedEvents\TraceFiles\Prod'
		, 'C:\Assist\ExtendedEvents\TraceFiles\Prod'
		, default
	)

Analyze Data
Script
; with cteCategory
as
(
	select 
			  tblEE.objectName
			, [count] = count(*)

	from   [extendedEvent].[events] tblEE

	group by
			  tblEE.objectName
)
select 
		  tblEE.objectName
		, tblEE.isSystem
		, tblEE.[sqlText]
		, tblEE.[message]		    
		, [count] = count(*)
		, [%] =
				cast
				(
					(
						  ( count(*) * 100)
						/ tblEEC.[count]
					)
					as decimal(6, 2)
				)
			

from   [extendedEvent].[events] tblEE

inner join cteCategory tblEEC

	on tblEE.[objectName] = tblEEC.[objectName]

group by
		  tblEE.objectName
		, tblEE.isSystem
		, tblEE.[sqlText]    
		, tblEE.[message]
		, tblEEC.[count]

order by
	      count(*) desc
		, tblEE.objectName
		, tblEE.isSystem
		, tblEE.[sqlText]    

Output

Explanation
  1. Lock TimeOut
    • 60% of the timeouts are system timeouts
      • They have is System=true
      • Username is sa
    • 36% of the timeouts are user and application timeouts attributed to HangFire
      • An easy way to perform background processing in .NET and .NET Core applications.
        No Windows Service or separate process required.

        Backed by persistent storage. Open and free for commercial use.
        Link
  2. Error Reported
    • Cannot drop the table ‘#CourseSequence’, because it does not exist or you do not have permission.
    • Invalid or Expired Session: nvjpqa3efiy3nrajzhpf1kud
    • The query processor ran out of internal resources and could not produce a query plan.
      This is a rare event and only expected for extremely complex queries or queries that reference a very large number of tables or partitions. Please simplify the query. If you believe you have received this message in error, contact Customer Support Services for more information.

SQL Server – “Lock Timeouts” – Identify Using “Extended Events”

Background

In this exercise we will create an Extended Event from Scratch and see if are able to successfully monitor “Lock Requests” timeout.

 

Previous Posts

  1. SQL Server – “Lock Timeouts” – ErrorLog
    Link
  2. SQL Server – Identify Lock TimeOuts via Extended Events ( from converted Trace File )
    Link
  3. SQL Server – “Lock Timeouts” – Trigger Timeouts – SSMS – Table Designer
    Link
  4. SQL Server – “Lock Timeouts” – Identifying through SQL Server Profiler
    Link

 

 

Prerequisite

v2008-R2+

Extended Events was introduced with SQL Server 2008, the GUI came a release later, v2008-R2 to be exact.

And, so your SSMS client to be on at least v2008/R2 and your targeted Server should be on v2008.

 

Design Extended Event

Create new Extended Event

Initiate Wizard

Initiate a new Extended Event Session Creation by selecting the SQL Instance, accessing Object Explorer and traversing the tree “Management“\ “Extended Events” \ “Sessions“.  Right click on the Sessions node and from the drop-down menu select “New Session Wizard“.

Image

 

Screen Shot

Image

Introduction
Image

 

 

Set Session Properties
Outline
  1. Session name :- lockTimeOut
  2. Schedule
    • Start the event session at server startup
      • Off
        • For now we will choose not to affect the Trace to happen at startup
Image

 

Choose Templates
Outline
  1. Use this event session template: Query Detail Tracking
    • This template collects detailed statement and error information.
      • What MSFT says
        • You can use this template to track each statement has executed on your system as a result of query batches or stored procedures and then track errors back to the specific statement that caused them.
        • This template also collects the query hash and query plan hash for every statement it tracks.
        • All statement events are collected in this session so collection size may be very large.
        • To reduce the collection size consider using the Query Detail Sampling template, which already includes a filter.
    • Might want to use Query Detail Sampling template
      • Events are only collected from 20% of the active sessions on the server at any given time.
      • You can change the sampling rate by modifying the filter for the event session.
Image

 

Select Events to Capture
Outline
  1. Error Reported
  2. Lock Cancel
  3. Lock Deadlock
  4. Lock Deadlock Chain
  5. Lock Timeout
  6. Lock Timeout Greater Than
  7. RPC Completed
  8. SQL batch Completed
  9. XML Deadlock Report
Tabulate
Event Event Detail Explanation  Link
Error Reported Occurs when an error is reported.  Link
 Lock Cancel Occurs when the request for a lock was canceled, such as when the query requesting the lock was canceled. Use this event to monitor locks. The Lock:Cancel event class indicates that acquisition of a lock on a resource has been canceled; for example, due to a query being canceled.  Link
 Lock Deadlock  Occurs when an attempt to acquire a lock is canceled for the victim of a deadlock. The Lock:Deadlock Chain event class is produced for each participant in a deadlock.

Use the Lock:Deadlock Chain event class to monitor when deadlock conditions occur. This information is useful to determine if deadlocks are significantly affecting the performance of your application, and which objects are involved. You can examine the application code that modifies these objects to determine if changes to minimize deadlocks can be made.

 Link
 Lock Deadlock Chain  Occurs when an attempt to acquire a lock generates a deadlock. This event is raised for each participant in the deadlock.  The Lock:Deadlock Chain event class is produced for each participant in a deadlock.
Use the Lock:Deadlock Chain event class to monitor when deadlock conditions occur. This information is useful to determine if deadlocks are significantly affecting the performance of your application, and which objects are involved. You can examine the application code that modifies these objects to determine if changes to minimize deadlocks can be made.
 Link
 Lock Timeout Occurs when a request for a lock times out because another transaction holds a blocking lock on the required resource. The time-out duration is determined by the @@LOCK_TIMEOUT system function. Use this event to help troubleshoot blocking issues. The Lock:Timeout event class indicates that a request for a lock on a resource, such as a page, has timed out because another transaction is holding a blocking lock on the required resource. Time-out is determined by the @@LOCK_TIMEOUT system function and can be set with the SET LOCK_TIMEOUT statement.

Use the Lock:Timeout event class to monitor when time-out conditions occur. This information is useful to determine if time-outs are significantly affecting the performance of your application, and which objects are involved. You can examine the application code that modifies these objects to determine if changes to minimize time-outs can be made.

 Link
 Lock Timeout Greater Than 0  Occurs when a request for a lock times out because of a blocking lock that is being held by a different resource. This event is identical to lock_timeout, but excludes cases in which the time-out value is 0, such as when lock probes are used. Time-outs with a duration of 0 do not necessarily indicate a blocking problem.  The Lock:Timeout (timeout > 0) event class indicates that a request for a lock on a resource, such as a page, has timed out because another transaction is holding a blocking lock on the required resource. This event class behaves the same as the Lock:Timeout event class, except it does not include any events where the timeout value is 0.
Include the Lock:Timeout (timeout > 0) event class in traces where you are using lock probes or other processes that have timeout values of zero. This allows you to see where actual time-outs are occurring without seeing time-out values of zero.
 Link
 RPC Completed  Occurs when a remote procedure call has completed.  The RPC:Completed event class indicates that a remote procedure call has been completed.  Link
 SQL Batch completed  Occurs when a Transact-SQL batch has finished executing.  The SQL:BatchCompleted event class indicates that the Transact-SQL batch has completed.  Link
 XML Deadlock Report  Produces a deadlock report in XML format.

 

 

Image

 

Capture Global Fields
Outline
  1. client app name
  2. client hostname
  3. collect system time
  4. database id
  5. database name
  6. is system
  7. server instance name
  8. server principal name
  9. session id
  10. session server principal name
  11. sql text
Image

 

Set Session Event Filters
Outline

Once we have the Session created, we will come back and add filtering elements.

Image

 

Specify Session Data Storage
Outline

Again we will come back and persistence once we have had things running for a while…

Image

 

Summary
Outline

We get a nice summary of our choices in tree view.  And, can click and review each choice.

Image

 

Create Event Session
Outline

The Wizard submits the SQL for creating the Session to the SQL Engine and it works behind the scene to create the event.

Image

 

Edit Extended Event

Initiate Wizard

Outline

Access the list of Extended Event Sessions by selecting the SQL Instance, accessing Object Explorer and traversing the tree “Management“\ “Extended Events” \ “Sessions“.

Review the list of existing Extended Event Sessions and right clicking on the one you will like to edit.

From the drop-down menu, select “Properties“.

Image

 

Edit Session Wizard

Session Properties – General

Outline

  1. Session Name :- lockTimeOut
  2. Template :- <Blank>
  3. Start the event Session at server startup
    • Checkbox that can be turned on or off
    • Indicates whether Session should be scheduled to start upon SQL Instance restart
  4. Start event session once Session is initially created
  5. Watch live data on screen at is captured
  6. Causality Tracking
    • very important as it allows to tie seemingly independent events will likely sources
    • AI Stuff
Image

 

Session Properties – Events

Outline

  1. Session Name :- lockTimeOut
  2. Template :- <Blank>
  3. Start the event Session at server startup
    • Checkbox that can be turned on or off
    • Indicates whether Session should be scheduled to start upon SQL Instance restart
  4. Start event session once Session is initially created
  5. Watch live data on screen at is captured
  6. Causality Tracking
    • very important as it allows to tie seemingly independent events will likely sources
    • AI Stuff
Image

 

Session Properties – Events

Outline

  1. This is the most important screen
  2. We add in events and leave out those not pertinent to our current use case
  3. And, can click the “Configure” button to add filtering to
Image

Session Properties – Selected Events – Configure

Event – “Error Reported”
Outline

The configure screen allows us to choose the fields we want to collect, and the filtering predicates.

Global Fields
Tabulate

We chose to follow the following fields for all events:

  1. client app name
  2. client hostname
  3. collect system time
  4. database id
  5. database name
  6. is system
  7. server instance name
  8. server principal name
  9. session id
  10. session server principal name
  11. sql text

 

Global Fields – Image

Filter Predicates
Filter Predicates – Matrix
Error Number Message Explanation
 2528  DBCC execution completed. If DBCC printed error messages, contact your system administrator.
 5701  Changed database context to ‘%.*ls’.
 5703  Changed language setting to %.*ls.

 

 

Filter Predicates – Image

 

Image – Error Reported – Error Number – 2528

Image – Error Reported – Error Number – 5701

 

Image – Error Reported – Error Number – 5703

Event – “lock cancel”,” lock deadlock”, “lock deadlock chain”, “lock timeout”, “lock timeout greater than”, “xml deadlock report”
Outline

This event captures Lock Requests that are cancelled.

We did not make any changes, but ensured that the request’s SQL text is captured, as well.

Event Fields – Tabulate

Here are specific fields that are captured

  1. database id
  2. mode
  3. object id
  4. resource 0, resource 1, resource 2
  5. resource description

 

Event Fields – Image

 

Watch Live Data

Events

 

Event – Lock Timeout

Outline

Raised when “Lock Timeout” occurs…

Image

Tabulated

 

Error Number Sample Explanation
 Associated Object ID  110623437 Issue object_schema_name({Associated Object ID}, Database_ID) to get schema nameIssue object_name({Associated Object ID}, Database_ID) to get Object Name
 Client Hostname  […DADENIJI-…]
 Database ID  7  Database D
 Database Name
 Database Name ( Action )  DBLab  Issue db_name([Database ID]) if null
 Duration  29999000  Value is is microseconds ( 30 seconds )
 Is System  False  Is request targeting a system or user object
 Mode  SCH_M  Schema Modification
 Object ID  110623437 Please see explanation for “Associated ID“, but replace “Associated Object ID” with Object ID
 Owner Type  Transaction
 Client Hostname  […DADENIJI-…]  Client’s workstation name
 Resource_0  110623437 Search for guide and code on the Net on how to find Resource Name when one has Resource  ID
 Resource Type  OBJECT  Resource Type granularity
 Server Instance Name  [DADENIJI\v2014]  SQL Instance Sever Name
 Server Principal Name  [Domain Name]\dadeniji Login Name
 Session Server Principal Name  [Domain Name]\dadeniji Same as Login name, except when in the middle of an “Execute As Login” code block
 SQL Text  ALTER TABLE dbo.person ADD   gender char(1) NULL  Underlying SQL

 

 

 

Event – Lock Timeout Greater Than 0

Outline

Raised when “Lock Timeout greater than 0” occurs…

Please keep in mind that Lock TimeOut is raise anytime that Lock Request Timed Out; while Lock Timeout only occurs when a time limit has been set on how long to wait.

In our scenario, we raised Lock Timeout greater than 0, as well.

 

Event – Error Reported

Outline

Raised when “Lock Timeout” occurs…

Image

Tabulated

Error Number Sample Explanation
Client Application Name  Microsoft SQL Server Management Studio Application Name
 Client Hostname  […DADENIJI-…]
Collect System Time  2017-03-31 12:41 PM System Time
 Database ID  7  Database D
 Database Name
 Database Name ( Action )  DBLab  Issue db_name([Database ID]) if null
Error Number  1222  Lock request time out period exceeded.
 Is System  False  Is request targeting a system or user object
 Message message Lock request time out period exceeded.
Severity  16 Please seek out extended documentation to get insight on the various severity levels
 SQL State  56  ???
 User Defined  false  SQL Server supports User defined errors.  If the error is triggered by the user through raiserror or  throw, this flag is set to true
 SQL State  56  ???
 User Defined  false  SQL Server supports User defined errors.  If the error is triggered by the user through raiserror or  throw, this flag is set to true

 

 

 

Event – SQL Batch Completed

Outline

Raised once the SQL Batch completes.

In our case, we are only capturing the ones that fail.

Image

 

Tabulated

Error Number Sample Explanation
 Batch Text ALTER TABLE dbo.person ADD   gender char(1) NULL
Client Application Name  Microsoft SQL Server Management Studio Application Name
 Client Hostname  […DADENIJI-…]
Collect System Time  2017-03-31 12:41 PM System Time
CPU Time  0 How much time the system has spent on the batch.
Please keep in mind this is different than the time expended wait time.
 Database ID  7  Database D
 Database Name
 Database Name ( Action )  DBLab  Issue db_name([Database ID]) if null
 Duration  30001486 30001486 is 30 million micro-seconds
30001 is 30 thousand milli-seconds
or 30 seconds
 Is System  False  Is request targeting a system or user object
Logical Reads 0  How much Logical Reads has been engaged
Physical Reads 0  How much physical Reads has been engaged
Result Error Has we said all of events will be Error
Row Count  false Aggregated Number of Records affected
SQL Text ALTER TABLE dbo.person ADD   gender char(1) NULL SQL Text
Writes  0 Measurement of Writes

 

 

 

Summary

We will let things run for a while.

Watch thing through Live Data.

And, come back and configure persisting of events.

And, in another post review and analysis of the saved events.

SQL Server – “Lock Timeouts” – ErrorLog

Background

Unlike some other database platforms database lock timeouts are not written into SQL Server Error Log.

 

Why

Let us quickly see why?

Code


set nocount on;
go

declare @tblError TABLE
(
	[errorNumber] int
)

declare @languageID int

set @languageID = 1033

/*
	Get list of error numbers
*/
insert into @tblError
(
	[errorNumber] 
)
select 1222

/* 
	Using master.dbo.sysmessages 
*/
select 

		  tblSM.[error]
		, tblSM.[description]
		, tblSM.[severity]
		, tblSM.[dlevel]
		, isEventLogged
			= CONVERT(INT,dlevel & 0x80) / 128 

from   master.dbo.sysmessages tblSM

inner join @tblError tblE
		on tblSM.error = tblE.errorNumber

where  tblSM.msglangid = @languageID 


/* 
	Using sys.messages 
*/
SELECT 
		  [messageID] = message_id
		, tblSM.severity
		, [isEventLogged] = is_event_logged
		, [text] = [text]

FROM sys.messages  tblSM

inner join @tblError tblE

		on tblSM.[message_id] = tblE.errorNumber

where  tblSM.language_id = @languageID 

Output

Explanation

We can quickly see that the error number, 1222, that corresponds to “Lock request time out period exceeded” is not logged, by default.

 

Log

Code


use [master]
go

set nocount on;
set XACT_ABORT on;
go

declare @tblError TABLE
(
	  [id]		    int not null
						identity(1,1)

	, [messageID]   int not null

)

declare @id int
declare @iMessageID int
declare @strMessageID	varchar(10)
declare @strMessageText nvarchar(600)
declare @languageID int

declare @idMax			int
declare @isEventLogged	bit

declare @FORMAT_EVENT_LOGGED_ALREADY varchar(600)
declare @FORMAT_EVENT_LOGGED_ACTION varchar(600)
declare @strLog						 nvarchar(600) 

declare @CHAR_LINE_BREAK					varchar(600)

declare @commit								bit

set @commit = 0
--set @commit = 1

set @languageID = 1033
set @FORMAT_EVENT_LOGGED_ALREADY = 'Error %s with message "%s" is already being logged!'
set @FORMAT_EVENT_LOGGED_ACTION = 'Error %s with message "%s" will now be logged!'

set @CHAR_LINE_BREAK = replicate('=', 120)

insert into @tblError
(
	[messageID] 
)
select 1222

set @id = 1
set @idMax = ( select max([id]) from @tblError )



begin tran

	select 
			   = 'Before'
			, tblErr.messageID
			, tblSM.[text]
			, [isEventLogged] = tblSM.is_event_logged

	from    @tblError   tblErr

	inner join sys.messages  tblSM

			on tblErr.messageID = tblSM.message_id

	where tblSM.[language_id] = @languageID  

	order by
			tblErr.[messageID] asc


	while (@id <= @idMax) begin select @iMessageID = tblErr.messageID , @strMessageText = tblSM.[text] , @isEventLogged = tblSM.is_event_logged from @tblError tblErr inner join sys.messages tblSM on tblErr.messageID = tblSM.message_id where tblSM.[language_id] = @languageID and tblErr.[id] = @id set @strMessageID = cast(@iMessageID as varchar(6)) if (@isEventLogged = 1) begin exec master.dbo.xp_sprintf @strLog output , @FORMAT_EVENT_LOGGED_ALREADY , @strMessageID , @strMessageText print @strLog end else begin exec master.dbo.xp_sprintf @strLog output , @FORMAT_EVENT_LOGGED_ACTION , @strMessageID , @strMessageText print @strLog EXECUTE sp_altermessage @iMessageID , 'WITH_LOG' , 'true' ; end print @CHAR_LINE_BREAK set @id = @id + 1 end select  = 'After' , tblErr.messageID , tblSM.[text] , [isEventLogged] = tblSM.is_event_logged from @tblError tblErr inner join sys.messages tblSM on tblErr.messageID = tblSM.message_id where tblSM.[language_id] = @languageID order by tblErr.[messageID] asc print ''; print ''; while (@@TRANCOUNT > 0)
begin

	if (@commit = 1)
	begin

		print 'commit'
		commit tran

	end
	else
	begin

		print 'rollback'
		rollback tran

	end

end -- while (@@TRANCOUNT > 0)

go

 

Output

 

Error Log

Observe

Now whenever lock timeouts occur, it will be logged in SQL Server ErrorLog

Explanation

Obviously we do not have any metadata about the Lok timeout.  All we have is a timestamp.

 

References

  1. Jon Gurgul
    • Suppress messages in SQL log
      Link
  2. Jason Strate
    • Lost In Translation – Deprecated System Tables – Sysmessages
      Link

 

SQL Server – “Lock Timeouts” – Trigger Timeouts – SSMS – Table Designer

Background

In our initial post we spoke about experiencing an Outage.

Our Clients in the Development side of the house explained they have being logging “Lock Timeouts“.

We wanted to see what tools we can use to detect similar occurrences on the DB.  And, we cited SQL Server Profiler as one of those tools.

In this post, we will attempt to simulate time outs due to expired Lock requests and see how well SQL Server Profiler performs.

 

Lab

Outline

  1. Start SQL Server Profiler and set to capture event
  2. Create a bare minimum table
  3. Add data
    • Start Transaction
    • Add a couple of records
    • Temporarily leave Transaction Uncommitted
  4. In another session, return to Table designer & initiate changes
    • Add one or two new columns, attempting to make design changes

Steps

SQL Server Profiler

Here are the events that we said we will capture:

Image

Image – Events Selection

Image – Edit Filter

 

Tabulation

Tabulation – Events Selection
Event Category Event
 Locks  Lock:Cancel
 Stored Procedures  RPC:Completed
 TSQL  SQL:Batch Completed

 

 

Tabulation – Filter
Column Value
 Duration  30000

 

 

Create a Bare Minimum Table

Image

Explanation

In the screen above, we have created a table and added a couple of columns ( personID and personName).

 

Attempt to add data

Script


set nocount on
go
set XACT_ABORT on
go

use [DBLab]
go

declare @transactionComplete bit

set @transactionComplete = 0

begin tran

	insert into [dbo].[person]
	default values;


 

Table Designer

Table Designer – Adding new column – dateAdded

Image

 

Table Designer – Execution Timeout Expired

Image

Textual

'person' table
- Unable to modify table.
Execution Timeout Expired. The timeout period elapsed prior to completion of the operation or the server is not responding.

 

SQL Server Profiler

Image

Lock:Cancel

Tabulated
Event Category Event Columns Values
 Lock  
 Lock:Cancel
 TextData
 Application  Microsoft SQL Server Management Studio
 NTUserName  dadeniji
 Duration  29999
 StartTime  2017-03-25 16:23:18.190
 EndTime  2017-03-25 16:23:18.190
 Mode  2-SCH-M
 ObjectID 110623437
 ObjectID2  110623437
 OwnerID  1-TRANSACTION
 DatabaseID  7
 DatabaseName  DBLAB
 Hostname  DADENIJI
 IntegerData2  0-LOCK

 

 

Explanation
  • You want to pay attention to ObjectID and Database ID
    • Those two will lead you to Database, Schema, and Object name
  • Mode
    • Will lead you to desired Lock
      • In our case, 2-SCH-M or Schema Modification Lock
  • And, of course Application, Host, and Username, and TextData
    • Determine causation and forensics

 

SQL: Batch Completed

Tabulated
Event Category Event Columns Values
 T-SQL  
SQL: Batch Completed
 TextData  ALTER TABLE dbo.person ADD dateAdded null
 Application  Microsoft SQL Server Management Studio
 NTUserName  dadeniji
 Duration  29999
 StartTime  2017-03-25 16:22:48.190
 EndTime  2017-03-25 16:23:18.190

 

 

Explanation
  • You want to pay attention to ObjectID and Database ID
    • Those two will lead you to Database, Schema, and Object name
  • Mode
    • Will lead you to desired Lock
      • In our case, 2-SCH-M or Schema Modification Lock
  • And, of course Application, Host, and Username, and TextData
    • Determine causation and forensics

 

 

Dedicated

Dedicated to MSFT’s SQL Server Team.

 

 

SQL Server – “Lock Timeouts” – Identifying through SQL Server Profiler

Preface

We experienced an outage this last Monday.

One of the errors logged in the WebSphere log file is the one pasted below:

Lock request time out period exceeded.

TroubleShooting

SQL Server Profiler

One of the most formidable tool for SQL Server TroubleShooting is SQL Server Profiler.

It allows the DBA to monitor several activities.

 

SQL Server Profiler – Take Care

Because it is an expensive to run it, I will suggest the following:

  1. Carefully choose which events you will like tracked
  2. Convert from Client Tracking to Server Tracing

 

SQL Server Profiler – Events

Here are the events to track on…

Tabulated

Events File Version
 Locks  
 Lock: Cancel
 Lock: Timeout
 Lock:Timeout ( timeout > 0)
 Stored Procedures
 RPC:Completed
 TSQL  
 SQL: BatchCompleted

 

Image

SQL Server Profiler – Filter

To augment the events we need to place filters and thus ensure we are not overloaded.

Tabulated

 Attribute Clause Qualifier
 Duration  
 Greater or equal to
 30000  ( Please note value is in milliseconds, and so we have it set for 30 seconds )
 Exclude rows that do not contain values

 

 

Image

 

 

Dedicated

Duckworth & Borris Callens

How to find timed out statements in SQL 2005 profiler
Link

 

References

  1. How to find timed out statements in SQL 2005 profiler
    Link
  2. Transcender
    • Application Deadlock
      You are the database administrator for a banking company. You manage all the SQL Server 2008 R2 databases of the company. The company stores customer-related data in the database named Cust01. This database is accessed by most users in the company for different purposes. The users daily perform insert and updates to the database through a .NET application.
      Eric, a user in the database, complains that his transaction has frozen and that he is not able to perform any operation in the database. You find out that the problem is due to a deadlock. You want to find out the user who is the other participant in the deadlock.
      Link

 

Summary

In follow-up posts, we will take things to the Lab and do things that will trigger timeouts.