3

We are experiencing an issue with Microsoft SQL Server where every few days of running our application against the database, it goes into a state where it keeps deadlocking. It logs a deadlock about every 5 seconds, but unexpectedly, all spids involved in the deadlock keep running indefinitely. It selects the same spid as deadlock victim every time, but even the selected spid keeps running as well and holds many locks. We are unsure what is causing this, and don’t understand why the transaction for the deadlock victim spid isn’t being rolled back?

The deadlock graph: Deadlock Graph

The deadlock graph XML:

<deadlock>
   <victim-list>
      <victimProcess id="process2ad1b567c28" />
   </victim-list>
   <process-list>
      <process id="process2ad1b567c28" taskpriority="0" logused="10000" waittime="109" schedulerid="1" kpid="3236" status="suspended" spid="223" sbid="0" ecid="1" priority="0" trancount="0" lastbatchstarted="2022-12-22T17:10:09.697" lastbatchcompleted="2022-12-22T17:10:09.697" lastattention="1900-01-01T00:00:00.697" clientapp="Microsoft JDBC Driver for SQL Server" hostname="srv-testbat" hostpid="5364" isolationlevel="read committed (2)" xactid="162697393" currentdb="5" currentdbname="testbat" lockTimeout="4294967295" clientoption1="671088672" clientoption2="128058">
         <executionStack>
            <frame procname="adhoc" line="1" stmtstart="176" stmtend="2080" sqlhandle="0x02000000fc7e8f089321170306a3f57816eddd19b455b7620000000000000000000000000000000000000000">unknown</frame>
            <frame procname="unknown" line="1" sqlhandle="0x0000000000000000000000000000000000000000000000000000000000000000000000000000000000000000">unknown</frame>
         </executionStack>
         <inputbuf>(@P0 int,@P1 int,@P2 bit,@P3 datetime2,@P4 nvarchar(4000),@P5 datetime2,@P6 int,@P7 int)SELECT t2.ID, t2.BAT_RUNTIME_SECONDS, t2.BATCH_ID, t2.READS, t2.CUTOFF, t2.CREATION_DATE, t2.DATA_HASH, t2.ENDTIME, t2.ENABLED, t2.DATA_ID, t2.ANALYSIS_DATA, t2.LAST_CHANGE, t2.NAME, t2.REF_ID, t2.UNIQUE_ID, t2.CONV_DATA, t2.PREVIOUS_GROUP_ID, t2.ANALYSIS_ID, t2.GROUP_ID FROM BAT_DATA_TASK t2 LEFT OUTER JOIN (BAT_DATA_COMPONENT t3 JOIN BAT_DATA_TASK_STATE t4 ON (t4.ID = t3.ID)) ON (t3.ID = t2.PREVIOUS_GROUP_ID), BAT_DATA t5, BAT_DATA_TASK_STATE t1, BAT_DATA_COMPONENT t0 WHERE ((((((t2.GROUP_ID = @P0) AND (t2.ANALYSIS_ID = @P1)) AND (t2.BATCH_ID IS NULL)) AND (t2.ENABLED = @P2)) AND ((t2.CUTOFF IS NULL) OR ((t2.CUTOFF IS NOT NULL) AND (t2.CUTOFF &lt; @P3)))) AND (((t0.ID = t2.GROUP_ID) AND ((t1.ID = t0.ID) AND (t0.COMPONENT_TYPE = @P4))) AND (t5.ID = t2.ANALYSIS_ID))) ORDER BY COALESCE(t2.ENDTIME, @P5) ASC, t2.LAST_CHANGE ASC OFFSET @P6 ROWS FETCH</inputbuf>
      </process>
      <process id="process2ad219e44e8" taskpriority="0" logused="0" waitresource="PAGE: 5:1:1276173 " waittime="60477823" ownerId="162697393" transactionname="implicit_transaction" lasttranstarted="2022-12-22T17:10:09.527" XDES="0x2ad3adb3aa0" lockMode="S" schedulerid="2" kpid="5032" status="suspended" spid="223" sbid="0" ecid="2" priority="0" trancount="0" lastbatchstarted="2022-12-22T17:10:09.697" lastbatchcompleted="2022-12-22T17:10:09.697" lastattention="1900-01-01T00:00:00.697" clientapp="Microsoft JDBC Driver for SQL Server" hostname="srv-testbat" hostpid="5364" isolationlevel="read committed (2)" xactid="162697393" currentdb="5" currentdbname="testbat" lockTimeout="4294967295" clientoption1="671088672" clientoption2="128058">
         <executionStack>
            <frame procname="adhoc" line="1" stmtstart="176" stmtend="2080" sqlhandle="0x02000000fc7e8f089321170306a3f57816eddd19b455b7620000000000000000000000000000000000000000">unknown</frame>
            <frame procname="unknown" line="1" sqlhandle="0x0000000000000000000000000000000000000000000000000000000000000000000000000000000000000000">unknown</frame>
         </executionStack>
         <inputbuf>(@P0 int,@P1 int,@P2 bit,@P3 datetime2,@P4 nvarchar(4000),@P5 datetime2,@P6 int,@P7 int)SELECT t2.ID, t2.BAT_RUNTIME_SECONDS, t2.BATCH_ID, t2.READS, t2.CUTOFF, t2.CREATION_DATE, t2.DATA_HASH, t2.ENDTIME, t2.ENABLED, t2.DATA_ID, t2.ANALYSIS_DATA, t2.LAST_CHANGE, t2.NAME, t2.REF_ID, t2.UNIQUE_ID, t2.CONV_DATA, t2.PREVIOUS_GROUP_ID, t2.ANALYSIS_ID, t2.GROUP_ID FROM BAT_DATA_TASK t2 LEFT OUTER JOIN (BAT_DATA_COMPONENT t3 JOIN BAT_DATA_TASK_STATE t4 ON (t4.ID = t3.ID)) ON (t3.ID = t2.PREVIOUS_GROUP_ID), BAT_DATA t5, BAT_DATA_TASK_STATE t1, BAT_DATA_COMPONENT t0 WHERE ((((((t2.GROUP_ID = @P0) AND (t2.ANALYSIS_ID = @P1)) AND (t2.BATCH_ID IS NULL)) AND (t2.ENABLED = @P2)) AND ((t2.CUTOFF IS NULL) OR ((t2.CUTOFF IS NOT NULL) AND (t2.CUTOFF &lt; @P3)))) AND (((t0.ID = t2.GROUP_ID) AND ((t1.ID = t0.ID) AND (t0.COMPONENT_TYPE = @P4))) AND (t5.ID = t2.ANALYSIS_ID))) ORDER BY COALESCE(t2.ENDTIME, @P5) ASC, t2.LAST_CHANGE ASC OFFSET @P6 ROWS FETCH</inputbuf>
      </process>
      <process id="process2ad15155468" taskpriority="0" logused="479404" waitresource="PAGE: 5:1:1325247 " waittime="60477814" ownerId="162697085" transactionname="implicit_transaction" lasttranstarted="2022-12-22T17:10:09.280" XDES="0x2b0726b4460" lockMode="IX" schedulerid="2" kpid="5000" status="suspended" spid="116" sbid="0" ecid="0" priority="0" trancount="2" lastbatchstarted="2022-12-22T17:10:09.613" lastbatchcompleted="2022-12-22T17:10:09.610" lastattention="1900-01-01T00:00:00.610" clientapp="Microsoft JDBC Driver for SQL Server" hostname="srv-testbat" hostpid="5364" loginname="COM\svc-testbat" isolationlevel="read committed (2)" xactid="162697085" currentdb="5" currentdbname="testbat" lockTimeout="4294967295" clientoption1="671088672" clientoption2="128058">
         <executionStack>
            <frame procname="adhoc" line="1" stmtstart="666" stmtend="1106" sqlhandle="0x0200000064cac70ecbccb22a928fe3b34964378a3400bb8f0000000000000000000000000000000000000000">unknown</frame>
            <frame procname="unknown" line="1" sqlhandle="0x0000000000000000000000000000000000000000000000000000000000000000000000000000000000000000">unknown</frame>
         </executionStack>
         <inputbuf>(@P0 int,@P1 int,@P2 int,@P3 int,@P4 int,@P5 int,@P6 int,@P7 int,@P8 int,@P9 int,@P10 int,@P11 int,@P12 int,@P13 int,@P14 int,@P15 int,@P16 int,@P17 int,@P18 int,@P19 int,@P20 int,@P21 int,@P22 int,@P23 int,@P24 int,@P25 int,@P26 int,@P27 int,@P28 int,@P29 int,@P30 int,@P31 int,@P32 int,@P33 int,@P34 int,@P35 int,@P36 int,@P37 int)DELETE FROM BAT_DATA_TASK WHERE (ID IN (@P0,@P1,@P2,@P3,@P4,@P5,@P6,@P7,@P8,@P9,@P10,@P11,@P12,@P13,@P14,@P15,@P16,@P17,@P18,@P19,@P20,@P21,@P22,@P23,@P24,@P25,@P26,@P27,@P28,@P29,@P30,@P31,@P32,@P33,@P34,@P35,@P36,@P37))</inputbuf>
      </process>
   </process-list>
   <resource-list>
      <exchangeEvent id="Port2ad130f2e00" WaitType="e_waitPortOpen" waiterType="Producer" nodeId="1" tid="1" ownerActivity="notYetOpened" waiterActivity="waitForAllOwnersToOpen">
         <owner-list>
            <owner id="process2ad219e44e8" />
         </owner-list>
         <waiter-list>
            <waiter id="process2ad1b567c28" />
         </waiter-list>
      </exchangeEvent>
      <pagelock fileid="1" pageid="1276173" dbid="5" subresource="FULL" objectname="testbat.dbo.BAT_DATA_TASK" id="lock2aee10ac700" mode="IX" associatedObjectId="72057594048086016">
         <owner-list>
            <owner id="process2ad15155468" mode="IX" />
         </owner-list>
         <waiter-list>
            <waiter id="process2ad219e44e8" mode="S" requestType="wait" />
         </waiter-list>
      </pagelock>
      <pagelock fileid="1" pageid="1325247" dbid="5" subresource="FULL" objectname="testbat.dbo.BAT_DATA_TASK" id="lock2ade2506180" mode="SIU" associatedObjectId="72057594048086016">
         <owner-list>
            <owner id="process2ad1b567c28" mode="S" />
         </owner-list>
         <waiter-list>
            <waiter id="process2ad15155468" mode="IX" requestType="convert" />
         </waiter-list>
      </pagelock>
   </resource-list>
</deadlock>

Here is a comparison of 3 deadlocks at:

  • 2022-12-23 07.55.25.9629738
  • 2022-12-23 08.22.03.6194797
  • 2022-12-23 09.58.21.5587345

There are 3 differences, but they are only in the waittime values: deadlock at 2022-12-23 07.55.25.9629738 deadlock at 2022-12-23 08.22.03.6194797 deadlock at 2022-12-23 09.58.21.5587345

Additionally, from the sys.dm_exec_requests, we see that the deadlock victim (spid = 223) is never actually stopped. Its cpu_time keeps growing a by a couple of milliseconds every 10 seconds. cpu time for query

Finally, here is the result of running sp_who2 for the affected database: sp_who2

We are unsure of how to approach this issue, since the cause is unknown to us, but we can definitively confirm that it is specific to our application. We have double-checked the database configuration settings of the application to ensure that no specific settings related to deadlocks were enabled.

Some extra environment information:

Microsoft SQL Server 2019 (RTM-CU18) (KB5017593) - 15.0.4261.1 (X64) 
Sep 12 2022 15:07:06 
Copyright (C) 2019 Microsoft Corporation
Developer Edition (64-bit) on Windows Server 2019 Datacenter 10.0 <X64> (Build 17763: ) (Hypervisor)
9
  • 1
    Your server is missing three years' worth of bugfixes, having been kept up to date only with security updates. You may try wading through the list of builds and all associated changes to see if this is a known (fixed) issue. Dec 20, 2022 at 11:20
  • I don't use sql-server but as an interested fly-on-the-wall observer ... for multiple deadlock graphs do you see the same details (eg, transaction descriptors, page ids, etc)? does sql-server have any configs that address deadlock retries and if so could any of said settings be set excessively high (eg, instead of 5 it's set to 5 mil)? have you tracked down the front-end/application that owns the query(s) being run by spid 190 and if so, how is it coded to handle a deadlock situation? (wondering if it could be (re)connecting, perhaps on a persistent pool connection)?
    – markp-fuso
    Dec 20, 2022 at 22:25
  • @JeroenMostert We have updated our SQL Server, and are still experiencing the same symptoms. I have updated the question with the equivalent data, recorded post-update.
    – Mads K
    Dec 23, 2022 at 9:25
  • I'd imagine you can probably resolve this by rewriting the query to be more efficient so it doesn't take page locks and or go parallel ORDER BY COALESCE(t2.ENDTIME, @P5) ASC is very yucky as is the mix of ANSI 89 and 92 join syntaxes. but that doesn't answer why the deadlock resolution isn't working. Spid 223 has two process elements in the graph - Dec 23, 2022 at 12:31
  • When you get the next deadlock graph 5 seconds later what elements change compared to the previous one? Are any of the pages involved different or <process id different? Dec 23, 2022 at 12:41

0

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge that you have read and understand our privacy policy and code of conduct.

Browse other questions tagged or ask your own question.