SQL Server, How to find deadlocks: the easy way DBCC TRACEON (1204, 1222,-1)

Hi Guys!

While in the previous post we talked about finding who's locking our table today i want to show you how to find deadlock!

How many times does the customer call you to tell you that they were all blocked?
Yeah, today let's talk about how to identify deadlocks!

However, we use a method that can trace them in such a way as to avoid being called by the customer when the block occurs.

Enjoy the reading!

Activate trace flags


First of all we need to activate two trace flags through the T-SQL commands below: 
       

DBCC TRACEON (1204,-1)
GO

DBCC TRACEON (1222,-1)
GO

Now deadlocks will be stored in the SQL Server error log

Important: Just remember to disable these trace flag after detected your deadlock.
Remember that in this manner these trace flag are enabled until the SQL Server restart

Where is located the Error Log


You can locate the error log under the SQL Server Agent menu.
Look at the image below:


Now click on the check highlighted below in yellow:


Now  "between other informations" you can see also the information related to deadlock.


How to simulate a deadlock


Let’s now take two minutes to see how to simulate a deadlock.
I suggest personally to try these T-SQL command in order to understand how deadlock works

Create our 2 tables:


CREATE TABLE TestTableA(
    Code    integer,
    Descr    VARCHAR(100)
    ,Qty        INT
)

CREATE TABLE TestTableB(
    Code    integer,
    Descr    VARCHAR(100)
    ,Qty        INT
)

Populate them with some data

       
INSERT INTO dbo.TestTableA(
    Code,
    Descr,
    Qty
)
VALUES
    (1,'TORX T10', 1)
   ,(2, 'TORX T20', 2)

INSERT INTO dbo.TestTableB(
    Code
    ,Descr
    ,Qty
)
VALUES
    (3,'TORX T30', 2)
   ,(4, 'TORX T40', 3)


And now execute updates below:

In a first session (open a new windows of the management studio)


BEGIN TRAN
UPDATE dbo.TestTableA SET Qty = 100 WHERE Code = 1
WAITFOR DELAY '00:00:30'
UPDATE dbo.TestTableB SET Qty = 200 WHERE Code = 3


In a second session (open another windows in SSMS)

       
BEGIN TRAN
WAITFOR DELAY '00:00:10'
UPDATE dbo.TestTableB SET Qty = 300 WHERE Code = 3
UPDATE dbo.TestTableA SET Qty = 400 WHERE Code = 1
 
We get this error:

       
(1 riga interessata)
Messaggio 1205, livello 13, stato 45, riga 6
La transazione (ID di processo 61) è stata interrotta a causa di un deadlock delle risorse blocco con un altro processo. Ripetere la transazione.

This is a deadlock!


How to decode the deadlock informations


Below i reported the deadlock generated by the T-SQL commands of the previous paragraph. 
Now let's see where to find just some basic but useful informations.

First, note that every lock have the same date for example: "01/28/2020 17:05:38".

       

Data,Origine,Gravità,Messaggio

01/28/2020 17:05:38,spid23s,Sconosciuta,waiter id=process17b8d047848 mode=U requestType=wait
01/28/2020 17:05:38,spid23s,Sconosciuta,waiter-list
01/28/2020 17:05:38,spid23s,Sconosciuta,owner id=process17b8d047c28 mode=X
01/28/2020 17:05:38,spid23s,Sconosciuta,owner-list
01/28/2020 17:05:38,spid23s,Sconosciuta,ridlock fileid=1 pageid=560856 dbid=24 objectname=SAMA0.dbo.TestTableB id=lock17b34ac3900 mode=X associatedObjectId=72057984635699200
01/28/2020 17:05:38,spid23s,Sconosciuta,waiter id=process17b8d047c28 mode=U requestType=wait
01/28/2020 17:05:38,spid23s,Sconosciuta,waiter-list
01/28/2020 17:05:38,spid23s,Sconosciuta,owner id=process17b8d047848 mode=X
01/28/2020 17:05:38,spid23s,Sconosciuta,owner-list
01/28/2020 17:05:38,spid23s,Sconosciuta,ridlock fileid=1 pageid=552528 dbid=24 objectname=SAMA0.dbo.TestTableA id=lock17b7a358300 mode=X associatedObjectId=72057984635633664
01/28/2020 17:05:38,spid23s,Sconosciuta,resource-list

Here we can read what is the first Query involved in the deadlock

01/28/2020 17:05:38,spid23s,Sconosciuta,UPDATE dbo.TestTableB SET Qty = 200 WHERE Code = 3
01/28/2020 17:05:38,spid23s,Sconosciuta,WAITFOR DELAY '00:00:30'
01/28/2020 17:05:38,spid23s,Sconosciuta,UPDATE dbo.TestTableA SET Qty = 100 WHERE Code = 1
01/28/2020 17:05:38,spid23s,Sconosciuta,BEGIN TRAN

01/28/2020 17:05:38,spid23s,Sconosciuta,inputbuf
01/28/2020 17:05:38,spid23s,Sconosciuta,unknown
01/28/2020 17:05:38,spid23s,Sconosciuta,frame procname=adhoc line=5 stmtstart=190 stmtend=288 sqlhandle=0x020000009dc0853694817179d005df97fe420c91151af1a50000000000000000000000000000000000000000
01/28/2020 17:05:38,spid23s,Sconosciuta,unknown
01/28/2020 17:05:38,spid23s,Sconosciuta,frame procname=adhoc line=5 stmtstart=38 stmtend=150 sqlhandle=0x02000000d54d1620448d72442ea35f826f4168cb3dedcdfc0000000000000000000000000000000000000000
01/28/2020 17:05:38,spid23s,Sconosciuta,executionStack


Here below in blu we can read who is the second Query involved

In red some useful infos: 

The process id  of the Query
The spid of the process who performed the Query
The name of the application who performed the Query (clientApp)
The name of the host (hostname)
The login name (loginname)
01/28/2020 17:05:38,spid23s,Sconosciuta,
process id=process17b8d047848 
taskpriority=0 
logused=248 
waitresource=RID: 24:1:560856:0 
waittime=4690 
ownerId=72433616 
transactionname=user_transaction lasttranstarted=2020-01-28T17:05:03.470
XDES=0x17b8ddf0490 
lockMode=U 
schedulerid=6 
kpid=92324 
status=suspended  
spid=59 
sbid=0 
ecid=0 
priority=0 
trancount=2 
lastbatchstarted=2020-01-28T17:05:03.460 lastbatchcompleted=2020-01-28T17:05:03.457 lastattention=1900-01-01T00:00:00.457
clientapp=Microsoft SQL Server Management Studio - Query hostname=XXXXXX 
hostpid=11308  
loginname=BOHDE\BiondiL 
isolationlevel=read committed (2) 
xactid=72433616 currentdb=24 
lockTimeout=4294967295 
clientoption1=671090784 
clientoption2=390200
01/28/2020 17:05:38,spid23s,Sconosciuta,UPDATE dbo.TestTableA SET Qty = 400 WHERE Code = 1
01/28/2020 17:05:38,spid23s,Sconosciuta,UPDATE dbo.TestTableB SET Qty = 300 WHERE Code = 3
01/28/2020 17:05:38,spid23s,Sconosciuta,WAITFOR DELAY '00:00:10'
01/28/2020 17:05:38,spid23s,Sconosciuta,BEGIN TRAN

01/28/2020 17:05:38,spid23s,Sconosciuta,inputbuf
01/28/2020 17:05:38,spid23s,Sconosciuta,unknown
01/28/2020 17:05:38,spid23s,Sconosciuta,frame procname=adhoc line=6 stmtstart=188 stmtend=286 sqlhandle=0x0200000043cda20c74e0f5ba1b8276de9e516513f9eed60b0000000000000000000000000000000000000000
01/28/2020 17:05:38,spid23s,Sconosciuta,unknown
01/28/2020 17:05:38,spid23s,Sconosciuta,frame procname=adhoc line=6 stmtstart=38 stmtend=150 sqlhandle=0x02000000d5c9eb146ddfb3f4519b827e7972019c17de44070000000000000000000000000000000000000000
01/28/2020 17:05:38,spid23s,Sconosciuta,executionStack

01/28/2020 17:05:38,spid23s,Sconosciuta,process id=process17b8d047c28 
taskpriority=0 
logused=248 
waitresource=RID: 24:1:552528:0 
waittime=22051 
ownerId=72433662 
transactionname=user_transaction lasttranstarted=2020-01-28T17:05:06.110
XDES=0x17b0084c490 
lockMode=U 
schedulerid=6 
kpid=105860 
status=suspended 
spid=61 
sbid=0 
ecid=0 
priority=0 
trancount=2 
lastbatchstarted=2020-01-28T17:05:06.110 lastbatchcompleted=2020-01-28T17:05:06.107 lastattention=1900-01-01T00:00:00.107
clientapp=Microsoft SQL Server Management Studio - Query hostname=XXXXX 
hostpid=11308 
loginname=BOHDE\BiondiL 
isolationlevel=read committed (2) 
xactid=72433662 
currentdb=24 
lockTimeout=4294967295 
clientoption1=671090784 
clientoption2=390200


Important: in blu some info about the victim process


01/28/2020 17:05:38,spid23s,Sconosciuta,process-list
01/28/2020 17:05:38,spid23s,Sconosciuta,deadlock victim=process17b8d047c28
01/28/2020 17:05:38,spid23s,Sconosciuta,deadlock-list

01/28/2020 17:05:38,spid5s,Sconosciuta,
ResType:LockOwner 
Stype:'OR'
Xdes:0x0000017B0084C490 
Mode: U 
SPID:61 
BatchID:0 
ECID:0 
TaskProxy:(0x0000017B08882988) 
Value:0x872bdb40 
Cost:(0/248)

01/28/2020 17:05:38,spid5s,Sconosciuta,Victim Resource Owner:
01/28/2020 17:05:38,spid5s,Sconosciuta,

01/28/2020 17:05:38,spid5s,Sconosciuta,
ResType:LockOwner 
Stype:'OR'
Xdes:0x0000017B8DDF0490 
Mode: U 
SPID:59 
BatchID:0 
ECID:0 
TaskProxy:(0x0000017B7C788988) 
Value:0x7dfe1900 Cost:(0/248)

01/28/2020 17:05:38,spid5s,Sconosciuta,Requested by:
01/28/2020 17:05:38,spid5s,Sconosciuta,Input Buf: Language Event: BEGIN TRANWAITFOR DELAY '00:00:10'UPDATE dbo.TestTableB SET Qty = 300 WHERE Code = 3UPDATE dbo.TestTableA SET Qty = 400 WHERE Code = 1
01/28/2020 17:05:38,spid5s,Sconosciuta, SPID: 61 ECID: 0 Statement Type: UPDATE Line #: 6

01/28/2020 17:05:38,spid5s,Sconosciuta,Owner:0x0000017B872B1740 Mode: X        Flg:0x40 Ref:0 Life:02000000 SPID:61 ECID:0 XactLockInfo: 0x0000017B0084C4C8
01/28/2020 17:05:38,spid5s,Sconosciuta,Grant List 2:
01/28/2020 17:05:38,spid5s,Sconosciuta,RID: 24:1:560856:0             CleanCnt:2 Mode:X Flags: 0x3
01/28/2020 17:05:38,spid5s,Sconosciuta,Node:2
01/28/2020 17:05:38,spid5s,Sconosciuta,
01/28/2020 17:05:38,spid5s,Sconosciuta,ResType:LockOwner Stype:'OR'Xdes:0x0000017B0084C490 Mode: U SPID:61 BatchID:0 ECID:0 TaskProxy:(0x0000017B08882988) Value:0x872bdb40 Cost:(0/248)
01/28/2020 17:05:38,spid5s,Sconosciuta,Requested by:
01/28/2020 17:05:38,spid5s,Sconosciuta,Input Buf: Language Event:    BEGIN TRANUPDATE dbo.TestTableA SET Qty = 100 WHERE Code = 1WAITFOR DELAY '00:00:30'UPDATE dbo.TestTableB SET Qty = 200 WHERE Code = 3
01/28/2020 17:05:38,spid5s,Sconosciuta,SPID: 59 ECID: 0 Statement Type: UPDATE Line #: 5

01/28/2020 17:05:38,spid5s,Sconosciuta,Owner:0x0000017B757B34C0 Mode: X        Flg:0x40 Ref:0 Life:02000000 SPID:59 ECID:0 XactLockInfo: 0x0000017B8DDF04C8
01/28/2020 17:05:38,spid5s,Sconosciuta,Grant List 2:
01/28/2020 17:05:38,spid5s,Sconosciuta,RID: 24:1:552528:0             CleanCnt:2 Mode:X Flags: 0x3
01/28/2020 17:05:38,spid5s,Sconosciuta,Node:1
01/28/2020 17:05:38,spid5s,Sconosciuta,
01/28/2020 17:05:38,spid5s,Sconosciuta,Wait-for graph
01/28/2020 17:05:38,spid5s,Sconosciuta,Deadlock encountered .... Printing deadlock information

End of the our deadlock and start of another lock. here ...

01/28/2020 16:26:16,spid10s,Sconosciuta,A significant part of sql server process memory has been paged out. This may result in a performance degradation. Duration: 3613 seconds. Working set (KB): 237792 committed (KB): 774632 memory utilization: 30%.

01/28/2020 15:56:44,spid10s,Sconosciuta,A significant part of sql server process memory has been paged out. This may result in a performance degradation. Duration: 1841 seconds. Working set (KB): 263532 committed (KB): 781032 memory utilization: 33%.

[...]

That all for today.
I hope You enjoy this Post!


Luca Biondi @ SQLServerPerformance blog!



 

 

 

 

Next post: SQL Server and the Plan Guides, An easy way create and utilize!
Previous post: SQL Server, Why doesn't my update come to an end? a light post!

A song with the mood of the day: Blue (Da Ba Dee)

Comments

Post a Comment

I Post più popolari

SQL Server, execution plan and the lazy spool (clearly explained)

Image
Hi Guys, Welcome back! In one of the last posts we talked about Table Spool . We had explained what Spool are for by telling the somewhat curious story of the halloween problem . Here we specifically talked about a type of spool called Eager Spool   You can look to the execution plan below where the eager Spool is used to avoid the halloween problem in classic query of the "salary increase".. i suggest Well, if the story of the eager spool intrigued you, today instead we will speak about another type of Spool, the Lazy Spool . The Lazy spool Let's take a small step back. So, what is a Spool operation?  As we have already understood a spool operation is simply a temporary storage of data . Data are read from a source table and stored inside a worktable in the Tempdb database . While an Eager Spool is used to prevent the Halloween problem, the Lazy Spool is instead used to store data that will later be needed again when running a query . So, when a Lazy spool is used?  ...
Read more

SQL Server, datetime vs. datetime2

Image
Hi guys, This time, in this post we will speak about datetime and datetime2 datatypes. We will talk about the pros and cons. We will talk about all the differences between the two types of data. Write me in the comments which type of data do you prefer between the two. Enjoy the reading!     Datetime Vs. Datetime2 First of all, it must be said that the datatype datetime is certainly the best known native format for storing a date in SQL Server. However, Microsoft has also been introducing a new type of data for many years now, also used to manage dates. It is in fact from SQL server 2008 that it is present in datetime2 data type. This "new" type of data was born primarily to have higher accuracy . Let's in fact talk about ... precision ! Datetime Certainly the datetime data type is not very precise and certainly there are many cases in which its precision is simply not sufficient. Let's see it with an example. Open the SQL Management studio (SSMS) and write the fo...
Read more

La clausola NOLOCK. Approfondiamo e facciamo chiarezza!

Image
Ehi ragazzi! La domanda è di quelle importanti! Siete pronti per scoprire tutto ma proprio tutto sulla clausola NOLOCK?   Se la riposta è si, allora seguitemi! Oggi ne spiegheremo il funzionamento in maniera approfondita. Faremo una introduzione al concetto di tipi di LOCK Ed infine vedremo come mai una SELECT ne può bloccare un'altra. Non vi nascondo che il motivo di questo articolo è fare chiarezza. Su questo argomento si sentono spesso affermazioni “curiose” ma tra le tante questa è la prima: “ uso la SELECT con l’opzione WITH(LOCK) così non blocco le altre tabelle ”.   Ma, è proprio vero quanto affermato? Beh oggi facciamo il punto!   Buona lettura!     La clausola NOLOCK Diciamo subito per iniziare che cos’è la NOLOCK. NOLOCK è il nome di una clausola che è possibile specificare all’interno di uno statement di tipo SELECT utilizzando la seguente sintassi: SELECT * FROM TABELLA WITH (NOLOCK) Si noti che non possiamo ...
Read more