CODEWITHSUNDEEP
sql-servert-sqldeadlockdatabase-deadlocks
Hunter Nelson
Hunter Nelson

Reputation: 1995

How do I interpret this deadlock text file?

I know based off the error message I am troubleshooting that the report that failed with a deadlock error was process ID 1017. What I am confused about is what is causing the deadlock? There are several statements in this text file below all with the same timestamp as the error and they all appear to be part of the same deadlock. Are multiple sql statements causing the deadlock? Looking for some help on how to interpret this deadlock file.

08/01/2017 17:47:09,spid7s,Unknown,Deadlock encountered .... Printing deadlock information
08/01/2017 17:47:09,spid7s,Unknown,Wait-for graph
08/01/2017 17:47:09,spid7s,Unknown,
08/01/2017 17:47:09,spid7s,Unknown,Node:1
08/01/2017 17:47:09,spid7s,Unknown,PAGE: 8:11:14583091            CleanCnt:2 Mode:IX Flags: 0x3
08/01/2017 17:47:09,spid7s,Unknown,Grant List 2:
08/01/2017 17:47:09,spid7s,Unknown,Owner:0x0000001A725D4100 Mode: IX       Flg:0x40 Ref:0 Life:02000000 SPID:1127 ECID:0 XactLockInfo: 0x0000000E8BEAD400
08/01/2017 17:47:09,spid7s,Unknown,SPID: 1127 ECID: 0 Statement Type: UPDATE Line #: 130
08/01/2017 17:47:09,spid7s,Unknown,Input Buf: RPC Event: Proc [Database Id = 8 Object Id = 1454029057]
08/01/2017 17:47:09,spid7s,Unknown,Requested by:
08/01/2017 17:47:09,spid7s,Unknown,ResType:LockOwner Stype:'OR'Xdes:0x000000090209A1C0 Mode: S SPID:1017 BatchID:0 ECID:0 TaskProxy:(0x00000008341A8540) Value:0x7380fc00 Cost:(0/0)
08/01/2017 17:47:09,spid7s,Unknown,
08/01/2017 17:47:09,spid7s,Unknown,Node:2
08/01/2017 17:47:09,spid7s,Unknown,PAGE: 8:14:14546741            CleanCnt:2 Mode:S Flags: 0x3
08/01/2017 17:47:09,spid7s,Unknown,Grant List 0:
08/01/2017 17:47:09,spid7s,Unknown,Owner:0x0000001A6160EFC0 Mode: S        Flg:0x40 Ref:0 Life:00000001 SPID:1017 ECID:0 XactLockInfo: 0x000000090209A200
08/01/2017 17:47:09,spid7s,Unknown,SPID: 1017 ECID: 0 Statement Type: SELECT Line #: 1
08/01/2017 17:47:09,spid7s,Unknown,Input Buf: RPC Event: Proc [Database Id = 8 Object Id = 1584229640]
08/01/2017 17:47:09,spid7s,Unknown,Requested by:
08/01/2017 17:47:09,spid7s,Unknown,ResType:LockOwner Stype:'OR'Xdes:0x0000000E8BEAD3C0 Mode: IX SPID:1127 BatchID:0 ECID:0 TaskProxy:(0x0000000E3D92A540) Value:0xee1af100 Cost:(0/5112)
08/01/2017 17:47:09,spid7s,Unknown,
08/01/2017 17:47:09,spid7s,Unknown,Victim Resource Owner:
08/01/2017 17:47:09,spid7s,Unknown,ResType:LockOwner Stype:'OR'Xdes:0x000000090209A1C0 Mode: S SPID:1017 BatchID:0 ECID:0 TaskProxy:(0x00000008341A8540) Value:0x7380fc00 Cost:(0/0)
08/01/2017 17:47:09,spid16s,Unknown,deadlock-list
08/01/2017 17:47:09,spid16s,Unknown,deadlock victim=process623b4c8
08/01/2017 17:47:09,spid16s,Unknown,process-list
08/01/2017 17:47:09,spid16s,Unknown,process id=process623b4c8 taskpriority=0 logused=0 waitresource=PAGE: 8:11:14583091 waittime=928 ownerId=10726052208 transactionname=SELECT lasttranstarted=2017-08-01T17:47:08.273 XDES=0x90209a1c0 lockMode=S schedulerid=6 kpid=17108 status=suspended spid=1017 sbid=0 ecid=0 priority=0 trancount=0 lastbatchstarted=2017-08-01T17:47:08.273 lastbatchcompleted=2017-08-01T17:47:08.263 clientapp=.Net SqlClient Data Provider hostname=***hostpid=8368 loginname=***isolationlevel=read committed (2) xactid=10726052208 currentdb=8 lockTimeout=4294967295 clientoption1=673185824 clientoption2=128056
08/01/2017 17:47:09,spid16s,Unknown,executionStack
08/01/2017 17:47:09,spid16s,Unknown,frame procname=adhoc line=1 stmtstart=2 sqlhandle=0x020000004bafe30b4e652e881b86ef71b9df0ed329054914
08/01/2017 17:47:09,spid16s,Unknown,@1 varchar(8000)<c/>@2 smallint)SELECT * FROM [vw_OutstandingAdjustedInvoices] WHERE [VendorID]=@1 AND [ServicerRegionCodeID]=@2
08/01/2017 17:47:09,spid16s,Unknown,frame procname=adhoc line=1 stmtstart=2 sqlhandle=0x020000003e0235301d588b82abcced6d1ecdb62efc65b46d
08/01/2017 17:47:09,spid16s,Unknown,SELECT * FROM vw_OutstandingAdjustedInvoices WHERE VendorID='13867' AND ServicerRegionCodeID=1076
08/01/2017 17:47:09,spid16s,Unknown,frame procname=NewInvoice.dbo.sp_ExecuteMySQL line=41 stmtstart=2986 stmtend=3012 sqlhandle=0x03000800086d6d5eeed84b0165a500000100000000000000
08/01/2017 17:47:09,spid16s,Unknown,EXEC (@SQL)
08/01/2017 17:47:09,spid16s,Unknown,inputbuf
08/01/2017 17:47:09,spid16s,Unknown,Proc [Database Id = 8 Object Id = 1584229640]
08/01/2017 17:47:09,spid16s,Unknown,process id=process62e5dc8 taskpriority=0 logused=5112 waitresource=PAGE: 8:14:14546741 waittime=1016 ownerId=10726056691 transactionname=UPDATE lasttranstarted=2017-08-01T17:47:08.440 XDES=0xe8bead3c0 lockMode=IX schedulerid=23 kpid=30140 status=suspended spid=1127 sbid=0 ecid=0 priority=0 trancount=2 lastbatchstarted=2017-08-01T17:47:08.440 lastbatchcompleted=2017-08-01T17:47:08.440 lastattention=2017-08-01T10:26:17.713 clientapp=.Net SqlClient Data Provider hostname=****hostpid=7512 loginname=****isolationlevel=read committed (2) xactid=10726056691 currentdb=8 lockTimeout=4294967295 clientoption1=673185824 clientoption2=128056
08/01/2017 17:47:09,spid16s,Unknown,executionStack
08/01/2017 17:47:09,spid16s,Unknown,frame procname=NewInvoice.dbo.usp_EInvoice_UpdateReviewedDate line=130 stmtstart=8334 stmtend=9454 sqlhandle=0x0300080001b9aa5699653d00cea200000100000000000000
08/01/2017 17:47:09,spid16s,Unknown,UPDATE
08/01/2017 17:47:09,spid16s,Unknown,dbo.EInvoice
08/01/2017 17:47:09,spid16s,Unknown,SET
08/01/2017 17:47:09,spid16s,Unknown,ReviewedDate = @ReviewedDate
08/01/2017 17:47:09,spid16s,Unknown,<c/>FirstReviewedDate = @FirstReviewedDate
08/01/2017 17:47:09,spid16s,Unknown,<c/>EInvoiceStatusID = @EInvoiceStatusID
08/01/2017 17:47:09,spid16s,Unknown,<c/>DateUpdated = GETDATE()
08/01/2017 17:47:09,spid16s,Unknown,<c/>ServicerClickChargeDate = @ServicerClickChargeDate
08/01/2017 17:47:09,spid16s,Unknown,<c/>ServicerClickChargeAmount = @ServicerClickChargeAmount
08/01/2017 17:47:09,spid16s,Unknown,<c/>OrdinalNumForDptLoanVnd = @OrdinalNumForDptLoanVnd
08/01/2017 17:47:09,spid16s,Unknown,<c/>OrdinalNumForDptLoanReferral = @OrdinalNumForDptLoanReferral
08/01/2017 17:47:09,spid16s,Unknown,<c/>OrdinalNumForReferralTypeLoanVnd = @OrdinalNumForReferralTypeLoanVnd
08/01/2017 17:47:09,spid16s,Unknown,WHERE   EInvoiceID = @EInvoiceID
08/01/2017 17:47:09,spid16s,Unknown,inputbuf
08/01/2017 17:47:09,spid16s,Unknown,Proc [Database Id = 8 Object Id = 1454029057]
08/01/2017 17:47:09,spid16s,Unknown,resource-list
08/01/2017 17:47:09,spid16s,Unknown,pagelock fileid=11 pageid=14583091 dbid=8 objectname=NewInvoice.dbo.EInvoice id=lock1a6ead2200 mode=IX associatedObjectId=72057596262678528
08/01/2017 17:47:09,spid16s,Unknown,owner-list
08/01/2017 17:47:09,spid16s,Unknown,owner id=process62e5dc8 mode=IX
08/01/2017 17:47:09,spid16s,Unknown,waiter-list
08/01/2017 17:47:09,spid16s,Unknown,waiter id=process623b4c8 mode=S requestType=wait
08/01/2017 17:47:09,spid16s,Unknown,pagelock fileid=14 pageid=14546741 dbid=8 objectname=NewInvoice.dbo.EInvoice id=lock1a5cbad580 mode=S associatedObjectId=72057596262678528
08/01/2017 17:47:09,spid16s,Unknown,owner-list
08/01/2017 17:47:09,spid16s,Unknown,owner id=process623b4c8 mode=S
08/01/2017 17:47:09,spid16s,Unknown,waiter-list
08/01/2017 17:47:09,spid16s,Unknown,waiter id=process62e5dc8 mode=IX requestType=wait

Upvotes: 1

Views: 950

Answers (2)

Ross Bush
Ross Bush

Reputation: 15185

I am not familiar with that format so I can't help with deciphering your deadlock. It looks like a text version of a deadlock graph.

There is always going to be more than one statement involved in a deadlock. In the sql server world a deadlock is a competition for resources(locks) between two or more processes. Almost every time a deadlock victim is chosen, it will be a select statement. Select commands (reads) hold the least amount of resources and are the easiest to rollback. Sql server will rollback the process holding the least amount of resources. This is probably why your reporting procedure was the chosen victim. The commands from other processes you are seeing were all active queries when you ran the report.

Reading a deadlock graph is not trivial. Deadlocks usually occur when long read processes are running during a time of heavy writes. There are ways to attempt to prevent deadlocks. If you do a web search for deadlock prevention then you will find some useful information on the subject, however, No matter what precautions you take, you are going to run into one or many deadlocks when your system gets busy enough.

Ideally, you would try and split up a write heavy and read heavy system into two worlds, OLTP and OLAP, however, this is not always practical.

If your report will not be adversely affected by possibly reading uncommitted data then you can avoid this problem in your reporting stored procedures by placing NOLOCK hints on your joins and table select statements or specifying a read uncommitted transaction isolation level for your stored procedure. This is not always ideal but neither are deadlocks :)

Upvotes: 1

David Browne - Microsoft
David Browne - Microsoft

Reputation: 89361

This database is not using READ COMMITTED SNAPSHOT isolation, and the report session is not using SNAPSHOT isolation, so the SELECT query requires S locks to run. With RCSI the SELECT would not require any locks, and wouldn't conflict with the updating transaction. See Snapshot Isolation in SQL Server

It's conflicting with a stored procedure that is updating the table dbo.EInvoice

08/01/2017 17:47:09,spid16s,Unknown,frame procname=NewInvoice.dbo.usp_EInvoice_UpdateReviewedDate line=130 stmtstart=8334 stmtend=9454 sqlhandle=0x0300080001b9aa5699653d00cea200000100000000000000
08/01/2017 17:47:09,spid16s,Unknown,UPDATE
08/01/2017 17:47:09,spid16s,Unknown,dbo.EInvoice
08/01/2017 17:47:09,spid16s,Unknown,SET
08/01/2017 17:47:09,spid16s,Unknown,ReviewedDate = @ReviewedDate
08/01/2017 17:47:09,spid16s,Unknown,<c/>FirstReviewedDate = @FirstReviewedDate
08/01/2017 17:47:09,spid16s,Unknown,<c/>EInvoiceStatusID = @EInvoiceStatusID
08/01/2017 17:47:09,spid16s,Unknown,<c/>DateUpdated = GETDATE()
08/01/2017 17:47:09,spid16s,Unknown,<c/>ServicerClickChargeDate = @ServicerClickChargeDate
08/01/2017 17:47:09,spid16s,Unknown,<c/>ServicerClickChargeAmount = @ServicerClickChargeAmount
08/01/2017 17:47:09,spid16s,Unknown,<c/>OrdinalNumForDptLoanVnd = @OrdinalNumForDptLoanVnd
08/01/2017 17:47:09,spid16s,Unknown,<c/>OrdinalNumForDptLoanReferral = @OrdinalNumForDptLoanReferral
08/01/2017 17:47:09,spid16s,Unknown,<c/>OrdinalNumForReferralTypeLoanVnd = @OrdinalNumForReferralTypeLoanVnd
08/01/2017 17:47:09,spid16s,Unknown,WHERE   EInvoiceID = @EInvoiceID

The updating session owns an IX lock on one page of this table, and is attempting to acquire an IX lock on another page of this table. Probably it's a multi-statement transaction and it has already updated some other EInvoice row.

Options:

  • Switch the database to RCSI, but this requires testing.
  • Switch the report to use SNAPSHOT isolation, but this requires app code changes.
  • Force one of the sessions use a Table lock so that it will block before acquiring any conflicting locks.

Upvotes: 3

Related Questions