Help interpreting deadlock output

Question

Help interpreting deadlock output

James Lavery

SSC Eights!

Points: 808
More actions
October 17, 2018 at 7:46 am

#151611
We're maintaining an inherited system with a complex (overly-complex in our opinioin) database.
We've recently had reports from users of 'data not being saved'. Investigation shows that we're getting occasional deadlocks. Setting up a deadlock graph trace (and also turning on trace flag 1222 so we get info in the SQL log file) has given us deadlock output. Now our challenge is interpreting it!
The deadlock graph is below.
Articles I've read on interpreting deadlock output have indicated that we should see the sql being run. However, below it appears to have been truncated.
I can see that process 1061 is the victim, and it's doing a shared read on the OH30_STATUS table. So I assume I should be checking the indexes on this table in relation to the query.
However, I think the deadlock is on a page, not index or row. So is this a red herring?
One thing to note is these issues have only started being reported since general resource/performance problems have been reported (and seen) on the server . These are to do with disk space (and are slowly being dealt with by the infrastructure team - we have no control of that aspect).
Also - the updates are complex, with SQL being issued from the application rather than Stored Procedures (we inherited the application) - and multiple triggers.
So short questions:
- Anything obvious from the output below?
- Should we actually wait until performance/disk space are resolved before investigating these deadlocks (I suspect the answer is 'yes')
<deadlock-list>
<deadlock victim="process1c2d76ca8">
<process-list>
<process id="process1c2d76ca8" taskpriority="0" logused="3764" waitresource="PAGE: 7:1:6980092 " waittime="4740" ownerId="30499457" transactionname="UPDATE" lasttranstarted="2018-10-16T17:32:35.500" XDES="0x1652acc90" lockMode="S" schedulerid="1" kpid="7524" status="suspended" spid="1061" sbid="0" ecid="1" priority="0" trancount="0" lastbatchstarted="2018-10-16T17:32:35.500" lastbatchcompleted="2018-10-16T17:32:35.507" lastattention="1900-01-01T00:00:00.507" clientapp=".Net SqlClient Data Provider" hostname="RS-WEBLIVE-01" hostpid="3140" isolationlevel="read committed (2)" xactid="30499457" currentdb="7" lockTimeout="4294967295" clientoption1="671219744" clientoption2="128056">
<executionStack>
<frame procname="MyDb.dbo.T$_OH30_UPDATESTATUS" line="37" stmtstart="2250" stmtend="2384" sqlhandle="0x03000700a6a6b3707c712d0154a6000000000000000000000000000000000000000000000000000000000000">
SELECT @COUNT = COUNT(*) FROM OH30 WHERE OH30_STATUS <> @OH30_STATU </frame>
<frame procname="adhoc" line="1" stmtstart="1320" stmtend="3360" sqlhandle="0x02000000686c2a1e88611ed58f1b188ce246ef7d48fc91b60000000000000000000000000000000000000000">
unknown </frame>
<frame procname="unknown" line="1" sqlhandle="0x0000000000000000000000000000000000000000000000000000000000000000000000000000000000000000">
unknown </frame>
</executionStack>
<inputbuf>
(@ABSENT_10 varchar(8),@ABSENT_10_DETAILS ntext,@DISABILITY varchar(8),@DISABILITY_DETAILS ntext,@GIVE_UP_WORK varchar(8),@GIVE_UP_WORK_DETAILS ntext,@GOOD_HEALTH varchar(8),@GOOD_HEALTH_DETAILS ntext,@ADJUSTMENT varchar(8),@ADJUSTMENT_DETAILS ntext,@AVAILABILITY varchar(8),@AVAILABILITY_DETAILS ntext,@AGGRAVATED varchar(8),@AGGRAVATED_DETAILS ntext,@RESTRICTED_HEALTH varchar(8),@RESTRICTED_HEALTH_DETAILS ntext,@PRESC_MEDICATION varchar(8),@PRESC_MEDICATION_DETAILS ntext,@HOSPITAL_ADMISSION varchar(8),@HOSPITAL_ADMISSION_DETAILS ntext,@OTHER_HEALTH varchar(8),@OTHER_HEALTH_DETAILS ntext,@RESTRICTED varchar(8),@RESTRICTED_DETAILS ntext,@Original_ID int)UPDATE
OH30
SET
ABSENT_10 = @ABSENT_10,
ABSENT_10_DETAILS = @ABSENT_10_DETAILS,
DISABILITY = @DISABILITY,
DISABILITY_DETAILS = @DISABILITY_DETAILS,
GIVE_UP_WORK = @GIVE_UP_WORK,
GIVE_UP_WORK_DETAILS = @GIVE_UP_WORK_DETAILS,
GOOD_HEALTH = @GOOD_HEALTH,
GOOD_HEALTH_DETAILS = @GOOD_HEALTH_DETAILS,
ADJUSTMENT = @ADJUSTMENT,
ADJUSTME </inputbuf>
</process>
<process id="process19f3f3468" taskpriority="0" logused="4616" waitresource="PAGE: 7:1:6973419 " waittime="4773" ownerId="30499452" transactionname="INSERT" lasttranstarted="2018-10-16T17:32:35.350" XDES="0x1be0778e0" lockMode="S" schedulerid="2" kpid="4304" status="suspended" spid="1563" sbid="0" ecid="1" priority="0" trancount="0" lastbatchstarted="2018-10-16T17:32:35.350" lastbatchcompleted="2018-10-16T17:32:35.350" lastattention="1900-01-01T00:00:00.350" clientapp=".Net SqlClient Data Provider" hostname="RS-WEBLIVE-01" hostpid="3140" isolationlevel="read committed (2)" xactid="30499452" currentdb="7" lockTimeout="4294967295" clientoption1="671219744" clientoption2="128056">
<executionStack>
<frame procname="MyDb.dbo.T$_OH30_UPDATESTATUS" line="37" stmtstart="2250" stmtend="2384" sqlhandle="0x03000700a6a6b3707c712d0154a6000000000000000000000000000000000000000000000000000000000000">
SELECT @COUNT = COUNT(*) FROM OH30 WHERE OH30_STATUS <> @OH30_STATU </frame>
<frame procname="MyDb.dbo.T$_OH30_ID" line="58" stmtstart="4916" stmtend="5110" sqlhandle="0x03000700dfcaa77184712d0154a6000000000000000000000000000000000000000000000000000000000000">
update oh30 set OH30_TIMESTAMP_AMENDED=@OH30_TIMESTAMP_AMENDED where id =(select id from inserted </frame>
<frame procname="adhoc" line="1" stmtstart="1516" stmtend="4096" sqlhandle="0x02000000149d890623385926630a3934668f9c99cb0ab5740000000000000000000000000000000000000000">
unknown </frame>
<frame procname="unknown" line="1" sqlhandle="0x0000000000000000000000000000000000000000000000000000000000000000000000000000000000000000">
unknown </frame>
</executionStack>
<inputbuf>
(@OH30_CLIENT_EMAIL varchar(255),@OH30_CLIENT_CONTACT_TEL varchar(50),@OH30_CLIENT_USERNAME varchar(90),@OH30_CONTACT_NAME varchar(100),@OH30_COMPANY_REF varchar(10),@OH30_SITE_NAME varchar(70),@OH30_SITE_LINKNO varchar(15),@OH30_COMPANY_NAME varchar(100),@OH30_NSC_OR_FIXED varchar(10),@OH30_JOB_TITLE varchar(100),@OH30_CONTRACT_TYPE varchar(100),@OH30_CAND_SURNAME varchar(100),@OH30_CAND_FORENAMES varchar(100),@OH30_CAND_TITLE varchar(100),@OH30_CAND_SEX varchar(100),@OH30_CAND_EMAIL varchar(100),@HR_REFNO int,@REGION_REFNO int,@DIVISION_REFNO int,@OH30_COMPANY_ADDRESS ntext,@OH30_CAND_CODE varchar(100),@OUTCOMEID int,@IRCCODE int,@OH30_START_DATE varchar(100),@OH30_CLIENT_EMAIL_2 varchar(255),@OH30_COST_CODE varchar(100),@OH30_HAZARD_OTHER ntext)INSERT INTO OH30
        (EPISODELINKNO, OH30_STATUS, OH30_CLIENT_EMAIL, OH30_CLIENT_CONTACT_TEL, OH30_CLIENT_USERNAME, OH30_CONTACT_NAME,
        OH30_COMPANY_REF, OH30_SITE_NAME, OH30_SITE_LINKNO, OH30_COMPANY_NAME, OH30_NSC_OR_FIXE </inputbuf>
</process>
<process id="process1a4147848" taskpriority="0" logused="10000" waittime="4864" schedulerid="2" kpid="6548" status="suspended" spid="1563" sbid="0" ecid="0" priority="0" trancount="1" lastbatchstarted="2018-10-16T17:32:35.350" lastbatchcompleted="2018-10-16T17:32:35.350" lastattention="1900-01-01T00:00:00.350" clientapp=".Net SqlClient Data Provider" hostname="RS-WEBLIVE-01" hostpid="3140" loginname="ep@ch" isolationlevel="read committed (2)" xactid="30499452" currentdb="7" lockTimeout="4294967295" clientoption1="671219744" clientoption2="128056">
<executionStack>
<frame procname="MyDb.dbo.T$_OH30_UPDATESTATUS" line="37" stmtstart="2250" stmtend="2384" sqlhandle="0x03000700a6a6b3707c712d0154a6000000000000000000000000000000000000000000000000000000000000">
SELECT @COUNT = COUNT(*) FROM OH30 WHERE OH30_STATUS <> @OH30_STATU </frame>
<frame procname="MyDb.dbo.T$_OH30_ID" line="58" stmtstart="4916" stmtend="5110" sqlhandle="0x03000700dfcaa77184712d0154a6000000000000000000000000000000000000000000000000000000000000">
update oh30 set OH30_TIMESTAMP_AMENDED=@OH30_TIMESTAMP_AMENDED where id =(select id from inserted </frame>
<frame procname="adhoc" line="1" stmtstart="1516" stmtend="4096" sqlhandle="0x02000000149d890623385926630a3934668f9c99cb0ab5740000000000000000000000000000000000000000">
unknown </frame>
<frame procname="unknown" line="1" sqlhandle="0x0000000000000000000000000000000000000000000000000000000000000000000000000000000000000000">
unknown </frame>
</executionStack>
<inputbuf>
(@OH30_CLIENT_EMAIL varchar(255),@OH30_CLIENT_CONTACT_TEL varchar(50),@OH30_CLIENT_USERNAME varchar(90),@OH30_CONTACT_NAME varchar(100),@OH30_COMPANY_REF varchar(10),@OH30_SITE_NAME varchar(70),@OH30_SITE_LINKNO varchar(15),@OH30_COMPANY_NAME varchar(100),@OH30_NSC_OR_FIXED varchar(10),@OH30_JOB_TITLE varchar(100),@OH30_CONTRACT_TYPE varchar(100),@OH30_CAND_SURNAME varchar(100),@OH30_CAND_FORENAMES varchar(100),@OH30_CAND_TITLE varchar(100),@OH30_CAND_SEX varchar(100),@OH30_CAND_EMAIL varchar(100),@HR_REFNO int,@REGION_REFNO int,@DIVISION_REFNO int,@OH30_COMPANY_ADDRESS ntext,@OH30_CAND_CODE varchar(100),@OUTCOMEID int,@IRCCODE int,@OH30_START_DATE varchar(100),@OH30_CLIENT_EMAIL_2 varchar(255),@OH30_COST_CODE varchar(100),@OH30_HAZARD_OTHER ntext)INSERT INTO OH30
        (EPISODELINKNO, OH30_STATUS, OH30_CLIENT_EMAIL, OH30_CLIENT_CONTACT_TEL, OH30_CLIENT_USERNAME, OH30_CONTACT_NAME,
        OH30_COMPANY_REF, OH30_SITE_NAME, OH30_SITE_LINKNO, OH30_COMPANY_NAME, OH30_NSC_OR_FIXE </inputbuf>
</process>
<process id="process1cb7304e8" taskpriority="0" logused="10000" waittime="4819" schedulerid="2" kpid="5140" status="suspended" spid="1061" sbid="0" ecid="0" priority="0" trancount="1" lastbatchstarted="2018-10-16T17:32:35.500" lastbatchcompleted="2018-10-16T17:32:35.507" lastattention="1900-01-01T00:00:00.507" clientapp=".Net SqlClient Data Provider" hostname="RS-WEBLIVE-01" hostpid="3140" loginname="ep@ch" isolationlevel="read committed (2)" xactid="30499457" currentdb="7" lockTimeout="4294967295" clientoption1="671219744" clientoption2="128056">
<executionStack>
<frame procname="MyDb.dbo.T$_OH30_UPDATESTATUS" line="37" stmtstart="2250" stmtend="2384" sqlhandle="0x03000700a6a6b3707c712d0154a6000000000000000000000000000000000000000000000000000000000000">
SELECT @COUNT = COUNT(*) FROM OH30 WHERE OH30_STATUS <> @OH30_STATU </frame>
<frame procname="adhoc" line="1" stmtstart="1320" stmtend="3360" sqlhandle="0x02000000686c2a1e88611ed58f1b188ce246ef7d48fc91b60000000000000000000000000000000000000000">
unknown </frame>
<frame procname="unknown" line="1" sqlhandle="0x0000000000000000000000000000000000000000000000000000000000000000000000000000000000000000">
unknown </frame>
</executionStack>
<inputbuf>
(@ABSENT_10 varchar(8),@ABSENT_10_DETAILS ntext,@DISABILITY varchar(8),@DISABILITY_DETAILS ntext,@GIVE_UP_WORK varchar(8),@GIVE_UP_WORK_DETAILS ntext,@GOOD_HEALTH varchar(8),@GOOD_HEALTH_DETAILS ntext,@ADJUSTMENT varchar(8),@ADJUSTMENT_DETAILS ntext,@AVAILABILITY varchar(8),@AVAILABILITY_DETAILS ntext,@AGGRAVATED varchar(8),@AGGRAVATED_DETAILS ntext,@RESTRICTED_HEALTH varchar(8),@RESTRICTED_HEALTH_DETAILS ntext,@PRESC_MEDICATION varchar(8),@PRESC_MEDICATION_DETAILS ntext,@HOSPITAL_ADMISSION varchar(8),@HOSPITAL_ADMISSION_DETAILS ntext,@OTHER_HEALTH varchar(8),@OTHER_HEALTH_DETAILS ntext,@RESTRICTED varchar(8),@RESTRICTED_DETAILS ntext,@Original_ID int)UPDATE
OH30
SET
ABSENT_10 = @ABSENT_10,
ABSENT_10_DETAILS = @ABSENT_10_DETAILS,
DISABILITY = @DISABILITY,
DISABILITY_DETAILS = @DISABILITY_DETAILS,
GIVE_UP_WORK = @GIVE_UP_WORK,
GIVE_UP_WORK_DETAILS = @GIVE_UP_WORK_DETAILS,
GOOD_HEALTH = @GOOD_HEALTH,
GOOD_HEALTH_DETAILS = @GOOD_HEALTH_DETAILS,
ADJUSTMENT = @ADJUSTMENT,
ADJUSTME </inputbuf>
</process>
<process id="process161039088" taskpriority="0" logused="10000" waittime="4773" schedulerid="1" kpid="4100" status="suspended" spid="1563" sbid="0" ecid="2" priority="0" trancount="0" lastbatchstarted="2018-10-16T17:32:35.350" lastbatchcompleted="2018-10-16T17:32:35.350" lastattention="1900-01-01T00:00:00.350" clientapp=".Net SqlClient Data Provider" hostname="RS-WEBLIVE-01" hostpid="3140" isolationlevel="read committed (2)" xactid="30499452" currentdb="7" lockTimeout="4294967295" clientoption1="671219744" clientoption2="128056">
<executionStack>
<frame procname="MyDb.dbo.T$_OH30_UPDATESTATUS" line="37" stmtstart="2250" stmtend="2384" sqlhandle="0x03000700a6a6b3707c712d0154a6000000000000000000000000000000000000000000000000000000000000">
SELECT @COUNT = COUNT(*) FROM OH30 WHERE OH30_STATUS <> @OH30_STATU </frame>
<frame procname="MyDb.dbo.T$_OH30_ID" line="58" stmtstart="4916" stmtend="5110" sqlhandle="0x03000700dfcaa77184712d0154a6000000000000000000000000000000000000000000000000000000000000">
update oh30 set OH30_TIMESTAMP_AMENDED=@OH30_TIMESTAMP_AMENDED where id =(select id from inserted </frame>
<frame procname="adhoc" line="1" stmtstart="1516" stmtend="4096" sqlhandle="0x02000000149d890623385926630a3934668f9c99cb0ab5740000000000000000000000000000000000000000">
unknown </frame>
<frame procname="unknown" line="1" sqlhandle="0x0000000000000000000000000000000000000000000000000000000000000000000000000000000000000000">
unknown </frame>
</executionStack>
<inputbuf>
(@OH30_CLIENT_EMAIL varchar(255),@OH30_CLIENT_CONTACT_TEL varchar(50),@OH30_CLIENT_USERNAME varchar(90),@OH30_CONTACT_NAME varchar(100),@OH30_COMPANY_REF varchar(10),@OH30_SITE_NAME varchar(70),@OH30_SITE_LINKNO varchar(15),@OH30_COMPANY_NAME varchar(100),@OH30_NSC_OR_FIXED varchar(10),@OH30_JOB_TITLE varchar(100),@OH30_CONTRACT_TYPE varchar(100),@OH30_CAND_SURNAME varchar(100),@OH30_CAND_FORENAMES varchar(100),@OH30_CAND_TITLE varchar(100),@OH30_CAND_SEX varchar(100),@OH30_CAND_EMAIL varchar(100),@HR_REFNO int,@REGION_REFNO int,@DIVISION_REFNO int,@OH30_COMPANY_ADDRESS ntext,@OH30_CAND_CODE varchar(100),@OUTCOMEID int,@IRCCODE int,@OH30_START_DATE varchar(100),@OH30_CLIENT_EMAIL_2 varchar(255),@OH30_COST_CODE varchar(100),@OH30_HAZARD_OTHER ntext)INSERT INTO OH30
        (EPISODELINKNO, OH30_STATUS, OH30_CLIENT_EMAIL, OH30_CLIENT_CONTACT_TEL, OH30_CLIENT_USERNAME, OH30_CONTACT_NAME,
        OH30_COMPANY_REF, OH30_SITE_NAME, OH30_SITE_LINKNO, OH30_COMPANY_NAME, OH30_NSC_OR_FIXE </inputbuf>
</process>
</process-list>
<resource-list>
<pagelock fileid="1" pageid="6980092" dbid="7" subresource="FULL" objectname="MyDb.dbo.OH30" id="lock3c8b66300" mode="IX" associatedObjectId="72057594999734272">
<owner-list>
<owner id="process1a4147848" mode="IX"/>
</owner-list>
<waiter-list>
<waiter id="process1c2d76ca8" mode="S" requestType="wait"/>
</waiter-list>
</pagelock>
<pagelock fileid="1" pageid="6973419" dbid="7" subresource="FULL" objectname="MyDb.dbo.OH30" id="lock2a1ed1b80" mode="IX" associatedObjectId="72057594999734272">
<owner-list>
<owner id="process1cb7304e8" mode="IX"/>
</owner-list>
<waiter-list>
<waiter id="process19f3f3468" mode="S" requestType="wait"/>
</waiter-list>
</pagelock>
<exchangeEvent id="Port426727f00" WaitType="e_waitPortOpen" nodeId="3">
<owner-list>
<owner id="process161039088"/>
</owner-list>
<waiter-list>
<waiter id="process1a4147848"/>
</waiter-list>
</exchangeEvent>
<exchangeEvent id="Port426727300" WaitType="e_waitPortOpen" nodeId="3">
<owner-list>
<owner id="process1c2d76ca8"/>
</owner-list>
<waiter-list>
<waiter id="process1cb7304e8"/>
</waiter-list>
</exchangeEvent>
<exchangeEvent id="Port426727f00" WaitType="e_waitPortOpen" nodeId="3">
<owner-list>
<owner id="process19f3f3468"/>
</owner-list>
<waiter-list>
<waiter id="process161039088"/>
</waiter-list>
</exchangeEvent>
</resource-list>
</deadlock>
</deadlock-list>

Viewing 9 posts - 1 through 8 (of 8 total)

You must be logged in to reply to this topic. Login to reply

John Mitchell-245523 SSC Guru Points: 148809 More actions · Answer 1

I say no, investigate now! Start by fetching the execution plans (and the full query) for those statements. You can also get aggregate execution stats such as numbers of reads and writes, CPU time and overall execution time. Please post back if you need help with any of that.

John

James Lavery SSC Eights! Points: 808 More actions · Answer 2

Hi John,
Thanks for the reply.
My problem is getting the full query for the statements. I assume I'm going to have to trawl the application source and stored procedures for the SQL we're seeing here.
the procnames like MyDb.dbo.T$_OH30_UPDATESTATUS look suspiciously like trigger names though, so I think I've got a clue there.

John Mitchell-245523 SSC Guru Points: 148809 More actions · Answer 3

Yes, where it's triggers and stored procedures, it's easy - just look up the definition. But where it's adhoc, you need to get it from the plan cache. There are loads of queries out there that do that for you. Let me know if you're struggling to find one and I'll post a link.

John

James Lavery SSC Eights! Points: 808 More actions · Answer 4

So for adhoc (i.e. SQL from the application), we can get the query from the plan cache? Excellent! I'm clearly behind on what's possible in SQL Server.

How far back does the plan cache go? These deadlocks were yesterday.

If you could post a link to suitable resources, that would be great.

John Mitchell-245523 SSC Guru Points: 148809 More actions · Answer 5

The plan will stay in the cache until it's recompiled, or until it gets chucked out because a newer plan needs the space. Look at the plan's creation_time to make sure that the plan isn't newer than your deadlock. Bear in mind that if optimize for ad hoc workloads is set to 1 in sys.configurations then the plan any particular statement won't be cached until the second time it's executed. Here's an example of how you can query the plan cache.

John

Jeff Moden SSC Guru Points: 1003857 More actions · Answer 6

James Lavery - Wednesday, October 17, 2018 7:46 AM
One thing to note is these issues have only started being reported since general resource/performance problems have been reported (and seen) on the server . These are to do with disk space (and are slowly being dealt with by the infrastructure team - we have no control of that aspect).

Is the Infrastructure Team (or anyone else) doing any type of index maintenance in an attempt to recover disk space? And, yeah no... I'm not kidding.

--Jeff Moden

RBAR is pronounced "ree-bar" and is a "Modenism" for Row-By-Agonizing-Row.
First step towards the paradigm shift of writing Set Based code:
________Stop thinking about what you want to do to a ROW... think, instead, of what you want to do to a COLUMN.

Change is inevitable... Change for the better is not.

Helpful Links:
How to post code problems
How to Post Performance Problems
Create a Tally Function (fnTally)

James Lavery SSC Eights! Points: 808 More actions · Answer 7

Jeff Moden - Wednesday, October 17, 2018 12:04 PM
James Lavery - Wednesday, October 17, 2018 7:46 AM
One thing to note is these issues have only started being reported since general resource/performance problems have been reported (and seen) on the server . These are to do with disk space (and are slowly being dealt with by the infrastructure team - we have no control of that aspect).
Is the Infrastructure Team (or anyone else) doing any type of index maintenance in an attempt to recover disk space? And, yeah no... I'm not kidding.

Hi Jeff,

No, not that I'm aware of. The customer and infrastructure guys accept that the server's creaking in terms of disk space - there's not much to recover, it really just needs more space. But we've been nagging them for weeks now!

Rachel Gomez Valued Member Points: 68 More actions · Answer 8

To Fix SQL Server Deadlock follow this process-

The only way to resolve a SQL Server deadlock is to terminate one of the processes and free up the locked resource so the process can complete.
This occurs automatically when SQL Server detects a deadlock and kills off one of the competing processes (i.e., the victim).
SQL Server normally chooses which connection to kill at random, but it is possible to set deadlock priorities to determine which connection is killed during a deadlock.
When two connections have different priority settings, SQL Server will kill off the transaction with the lowest priority.

This may help you,

Rachel Gomez