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 been experiencing “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.