Click here to monitor SSC
SQLServerCentral is supported by Red Gate Software Ltd.
 
Log in  ::  Register  ::  Not logged in
 
 
 

Catching Deadlock Information in SQL Logs

By Alejandro Pelc,

Introduction

It's not uncommon that a few months after a new project is released, the database performance degrades. Several things could be responsible for this degradation, but the one I’ve seen more often is data and structure related. In these cases, I noticed that the database was not designed with any consideration for the volume of data it will have, so the structure of the database (columns, indexes) and the queries became a problem. Of course, adding more and more data to the database, increasing the quantity of users accessing it and having poor performing queries can increase the possibility of a deadlock’s occurrence.

For those not familiar with deadlocks, here is a brief explanation of what it is. A deadlock occurs when, for instance, two processes are blocking each other. For instance, User1 begins a transaction and updates TableA. At the same time, User2 begins a transaction and updates TableB. Next, User1 performs a Select on TableB and User2 performs a Select on TableA. In this simple example, User1 gets blocked by User2 because the update on TableB was not yet committed. Also, User2 gets blocked by User1 because TableA update was not committed. When things like this happen, a deadlock occurs, so SQL needs to choose which process to rollback, letting the other one to complete.

There are several ways to solve deadlocking, but that's not the topic I'll cover here. I'll show a simple way to get the needed information to address the problems.

Analysis

Some time ago I faced a deadlock issue in one of the production databases. It was kind of strange as there were no structural changes to the database or queries changed, and the number of users and applications accessing it didn’t change either. The only difference was more data stored in the database as one legacy system was incorporated into this database. In order to analyze the deadlock errors, I enabled the 1222 trace flag on the server to capture the deadlocks on the error log.

DBCC TRACEON (1222, -1)

Now all deadlock information was getting captured into the error log, but of course there was another problem, which was the order of the information. With this I mean that in the error log I was seeing entries ordered not on the deadlock-sequence way but on the occurrence date. I needed to sort that information into a more readable way.

To do so, the following code gets the deadlock information from the error log and presents it in a more readable way:

declare @RawLogs table (id int IDENTITY (1, 1), logdate datetime, processinfo nvarchar(50), logtext nvarchar(max))

insert into @RawLogs
exec sp_readerrorlog

declare @results table (id int IDENTITY (1,1), logdate datetime, processinfo nvarchar(50), logtext nvarchar(max))
declare @ids table (id int, processinfo nvarchar(50))

insert into @ids
select id, processinfo
from @RawLogs
where logteXt = 'deadlock-list'
order by id

declare @Startid int, @endid int, @processinfo nvarchar(50)
select top 1 @Startid = id from @ids order by id
while(@@rowcount<>0)
begin
	select @processinfo = processinfo from @ids where id = @Startid
	select top 1 @endid = id from @ids where id > @Startid and processinfo = @processinfo order by id
	insert into @results (logdate, processinfo, logtext)
	select logdate, processinfo, logtext
	from @RawLogs
	where
	   id >=@Startid and
	   processinfo = @processinfo and
	   id < @endid
	order by id
	delete @ids where id = @Startid
	select top 1 @Startid = id from @ids order by id
end

select logdate, processinfo, logtext
from @results
order by id

The result of the above query gives something similar to this:

 

 

From the results, I highlighted certain things than can help identifying the deadlock occurred. The first thing is the ID of the deadlock victim, which is the process that was rolled back. If you look for that ID on the following rows, you'll see (in this case) that the SELECT statement was the cancelled one, and the UPDATE process was the one that completed.

You can see also relevant information regarding the database ID, the object IDs, etc. that can help identify the root cause and all the "players" involved.

Conclusion

Although enabling this on a production server for a long time is not the best option, it can definitely help identifying deadlocks on-the-fly without configuring a profiler or a trace and have that info stored on the server's logs. The intended purpose of this is having an easy way to catch those deadlocks and read that info from the logs.

Total article views: 8244 | Views in the last 30 days: 11
 
Related Articles
FORUM

DeadLock

DeadLock

FORUM

deadlock

deadlock

FORUM

SQL Deadlock in Reporting Database

SQL 2005 deadlock due to select query

FORUM

deadlock

deadlock

FORUM

Deadlocks

How many deadlocks is normal?

Tags
deadlocks    
trace flags    
 
Contribute

Join the most active online SQL Server Community

SQL knowledge, delivered daily, free:

Email address:  

You make SSC a better place

As a member of SQLServerCentral, you get free access to loads of fresh content: thousands of articles and SQL scripts, a library of free eBooks, a weekly database news roundup, a great Q & A platform… And it’s our huge, buzzing community of SQL Server Professionals that makes it such a success.

Join us!

Steve Jones
Editor, SQLServerCentral.com

Already a member? Jump in:

Email address:   Password:   Remember me: Forgotten your password?
Steve Jones