We've got deadlocks occurring on our SQL server. I've read many pages on Stack Overflow and elsewhere, but I can't find a step by step instruction list for how to read the trace log. Can someone tell me how to interpret this? Obviously right now I need to know how to interpret this specific log, but what I really need long term is to learn how to read future logs as well.
The full trace log is below. Let me explain how we're interpreting this. Then you can tell me what we're doing wrong and how to read it correctly.
We're thinking these lines:
06/14/2018 14:56:25,spid8s,Unknown,ResType:LockOwner Stype:'OR'Xdes:0x000000086D8ECD90 Mode: U SPID:171 BatchID:2 ECID:0 TaskProxy:(0x0000000125F1C768) Value:0x2dade880 Cost:(0/2000) 06/14/2018 14:56:25,spid8s,Unknown,Victim Resource Owner:
that says "victim" and "Xdes:0x000000086D8ECD90" mean that process 0x000000086D8ECD90 was the process closed because there was a deadlock on some resource.
Then the mention again of 0x000000086D8ECD90 in these lines:
06/14/2018 14:56:25,spid24s,Unknown,delete from site_updates where table_name = 'order_head' and update_type = 'update' and row_id in (select id from inserted 06/14/2018 14:56:25,spid24s,Unknown,frame procname=MyDatabase.dbo.update_order_head line=5 stmtstart=168 stmtend=412 sqlhandle=0x03000700a2b0aa21d638280131a7000000000000000000000000000000000000000000000000000000000000 06/14/2018 14:56:25,spid24s,Unknown,executionStack 06/14/2018 14:56:25,spid24s,Unknown,process id=process624d9c108 taskpriority=0 logused=2000 waitresource=KEY: 7:345803707580416 (a1de22506108) waittime=9019 ownerId=3985897338 transactionname=user_transaction lasttranstarted=2018-06-14T14:56:16.413 XDES=0x86d8ecd90 lockMode=U schedulerid=3 kpid=10664 status=suspended spid=171 sbid=2 ecid=0 priority=0 trancount=2 lastbatchstarted=2018-06-14T14:56:16.423 lastbatchcompleted=2018-06-14T14:56:16.423 lastattention=1900-01-01T00:00:00.423 clientapp=.Net SqlClient Data Provider hostname=NTSWKS56 hostpid=12396 loginname=MyDomain\user2 isolationlevel=read committed (2) xactid=3985897338 currentdb=7 lockTimeout=4294967295 clientoption1=671219744 clientoption2=128056 06/14/2018 14:56:25,spid24s,Unknown,process-list
mean that the command delete from site_updates was the command stopped because of a deadlock on the table site_updates
then this line:
06/14/2018 14:56:25,spid24s,Unknown,delete from site_updates where table_name = 'shipment_head' and update_type = 'inserted' and row_id in (select id from inserted
shows that this command was the one that caused the deadlock in the first place on site_update.
Are we close? Way off base? Is there any way to determine exactly what happened and/or how to fix it? (Such as "the first delete on table site_updates got an exclusive lock on the table so it caused a deadlock when the second delete was run. To fix this, add XXXX before the 1st delete so the table won't be locked.)
Full deadlock trace:
06/14/2018 14:56:25,spid24s,Unknown,keylock hobtid=345803707580416 dbid=7 objectname=MyDatabase.dbo.site_updates indexname=PK_site_updates id=lock140bfd400 mode=X associatedObjectId=345803707580416
06/14/2018 14:56:25,spid24s,Unknown,resource-list
06/14/2018 14:56:25,spid24s,Unknown,IF @@TRANCOUNT > 0 BEGIN exec sp_add_shipment 6379785<c/> 'GND'<c/> '4.00'<c/> 'CLCH105 (6pcs)'<c/> '6x83066'<c/> 'fedexsmartpost'<c/> 'MyDomain\user1'<c/> 'MyDomain\user1' END
06/14/2018 14:56:25,spid24s,Unknown,delete from site_updates where table_name = 'shipment_head' and update_type = 'inserted' and row_id in (select id from inserted
06/14/2018 14:56:25,spid24s,Unknown,frame procname=MyDatabase.dbo.insert_shipment_head line=5 stmtstart=152 stmtend=406 sqlhandle=0x030007000e51c2768d206101239e000000000000000000000000000000000000000000000000000000000000
06/14/2018 14:56:25,spid24s,Unknown,executionStack
06/14/2018 14:56:25,spid24s,Unknown,process id=process7a5313c28 taskpriority=0 logused=88216 waitresource=KEY: 7:345803707580416 (c8ec095a9952) waittime=8911 ownerId=3985893541 transactionname=user_transaction lasttranstarted=2018-06-14T14:56:09.940 XDES=0x152b64d90 lockMode=U schedulerid=3 kpid=8252 status=suspended spid=277 sbid=2 ecid=0 priority=0 trancount=2 lastbatchstarted=2018-06-14T14:56:16.507 lastbatchcompleted=2018-06-14T14:56:16.453 lastattention=1900-01-01T00:00:00.453 clientapp=.Net SqlClient Data Provider hostname=NTSWKS01 hostpid=1340 loginname=MyDomain\ups isolationlevel=read committed (2) xactid=3985893541 currentdb=7 lockTimeout=4294967295 clientoption1=671219744 clientoption2=128056
06/14/2018 14:56:25,spid24s,Unknown,IF @@TRANCOUNT > 0 BEGIN update order_head set address_flag = 'UR'<c/>customer_id = 0<c/> ship_name = '17106'<c/> 06/14/2018 14:56:25,spid24s,Unknown,delete from site_updates where table_name = 'order_head' and update_type = 'update' and row_id in (select id from inserted
06/14/2018 14:56:25,spid24s,Unknown,frame procname=MyDatabase.dbo.update_order_head line=5 stmtstart=168 stmtend=412 sqlhandle=0x03000700a2b0aa21d638280131a7000000000000000000000000000000000000000000000000000000000000
06/14/2018 14:56:25,spid24s,Unknown,executionStack
06/14/2018 14:56:25,spid24s,Unknown,process id=process624d9c108 taskpriority=0 logused=2000 waitresource=KEY: 7:345803707580416 (a1de22506108) waittime=9019 ownerId=3985897338 transactionname=user_transaction lasttranstarted=2018-06-14T14:56:16.413 XDES=0x86d8ecd90 lockMode=U schedulerid=3 kpid=10664 status=suspended spid=171 sbid=2 ecid=0 priority=0 trancount=2 lastbatchstarted=2018-06-14T14:56:16.423 lastbatchcompleted=2018-06-14T14:56:16.423 lastattention=1900-01-01T00:00:00.423 clientapp=.Net SqlClient Data Provider hostname=NTSWKS56 hostpid=12396 loginname=MyDomain\user2 isolationlevel=read committed (2) xactid=3985897338 currentdb=7 lockTimeout=4294967295 clientoption1=671219744 clientoption2=128056
06/14/2018 14:56:25,spid24s,Unknown,process-list
06/14/2018 14:56:25,spid24s,Unknown,deadlock victim=process624d9c108
06/14/2018 14:56:25,spid24s,Unknown,deadlock-list
06/14/2018 14:56:25,spid8s,Unknown,ResType:LockOwner Stype:'OR'Xdes:0x000000086D8ECD90 Mode: U SPID:171 BatchID:2 ECID:0 TaskProxy:(0x0000000125F1C768) Value:0x2dade880 Cost:(0/2000)
06/14/2018 14:56:25,spid8s,Unknown,Victim Resource Owner:
06/14/2018 14:56:25,spid8s,Unknown,
06/14/2018 14:56:25,spid8s,Unknown,ResType:LockOwner Stype:'OR'Xdes:0x0000000152B64D90 Mode: U SPID:277 BatchID:2 ECID:0 TaskProxy:(0x00000006E682E768) Value:0xbbe1a740 Cost:(0/88216)
06/14/2018 14:56:25,spid8s,Unknown,Requested by:
06/14/2018 14:56:25,spid8s,Unknown,Owner:0x0000000338998680 Mode: X Flg:0x40 Ref:0 Life:02000000 SPID:171 ECID:0 XactLockInfo: 0x000000086D8ECDC8
06/14/2018 14:56:25,spid8s,Unknown,Grant List 1:
06/14/2018 14:56:25,spid8s,Unknown,KEY: 7:345803707580416 (c8ec095a9952) CleanCnt:2 Mode:X Flags: 0x1
06/14/2018 14:56:25,spid8s,Unknown,Node:2
06/14/2018 14:56:25,spid8s,Unknown,
06/14/2018 14:56:25,spid8s,Unknown,ResType:LockOwner Stype:'OR'Xdes:0x000000086D8ECD90 Mode: U SPID:171 BatchID:2 ECID:0 TaskProxy:(0x0000000125F1C768) Value:0x2dade880 Cost:(0/2000)
06/14/2018 14:56:25,spid8s,Unknown,Requested by:
06/14/2018 14:56:25,spid8s,Unknown,Owner:0x00000004E373B900 Mode: X Flg:0x40 Ref:0 Life:02000000 SPID:277 ECID:0 XactLockInfo: 0x0000000152B64DC8
06/14/2018 14:56:25,spid8s,Unknown,Grant List 0:
06/14/2018 14:56:25,spid8s,Unknown,KEY: 7:345803707580416 (a1de22506108) CleanCnt:2 Mode:X Flags: 0x1
06/14/2018 14:56:25,spid8s,Unknown,Node:1
06/14/2018 14:56:25,spid8s,Unknown,
06/14/2018 14:56:25,spid8s,Unknown,Wait-for graph
06/14/2018 14:56:25,spid8s,Unknown,Deadlock encountered .... Printing deadlock information
* Update * Here's part of the BlitzLock output that was suggested. Still not sure how to interpret this.
