Help interpreting deadlock output

  • James Lavery

    Say Hey Kid

    Points: 698

    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 &lt;&gt; @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 &lt;&gt; @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 &lt;&gt; @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 &lt;&gt; @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 &lt;&gt; @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>

  • John Mitchell-245523

    SSC Guru

    Points: 148218

    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

    Say Hey Kid

    Points: 698

    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: 148218

    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

    Say Hey Kid

    Points: 698

    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: 148218

    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: 993661

    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.
    "If you think its expensive to hire a professional to do the job, wait until you hire an amateur."--Red Adair
    "Change is inevitable... change for the better is not."
    When you put the right degree of spin on it, the number 3|8 is also a glyph that describes the nature of a DBAs job. 😉

    Helpful Links:
    How to post code problems

  • James Lavery

    Say Hey Kid

    Points: 698

    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!

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

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