0

I have a query that is run as part of a larger transaction. The query usually completes in under .5 seconds. It looks like it became stuck in a suspended state indefinitely until I killed the query.

I have an extended event to monitor blocking. The query didn't have any updates to lastbatchcompleted during the time it was blocking.

I would expect the status of this query to be sleeping if there was no work to perform. Any ideas that what caused this? The disk IO/CPU usage was normal during this issue.

Excerpt from 4 different extended events for blocking:

  <process status="suspended" waittime="198644" spid="1265" sbid="0" ecid="0" priority="0" trancount="1" lastbatchstarted="2019-08-25T13:29:42.290" lastbatchcompleted="2019-08-25T13:29:42.290" lastattention="1900-01-01T00:00:00.290" clientapp="Nest" hostname="BDC5619" hostpid="63476143" loginname="webwriter" isolationlevel="read committed (2)" xactid="5096321128" currentdb="18" currentdbname="Spyder" lockTimeout="4294967295" clientoption1="671088672" clientoption2="128056">
  <process status="suspended" waittime="1086374" spid="1265" sbid="0" ecid="0" priority="0" trancount="1" lastbatchstarted="2019-08-25T13:29:42.290" lastbatchcompleted="2019-08-25T13:29:42.290" lastattention="1900-01-01T00:00:00.290" clientapp="Nest" hostname="BDC5619" hostpid="63476143" loginname="webwriter" isolationlevel="read committed (2)" xactid="5096321128" currentdb="18" currentdbname="Spyder" lockTimeout="4294967295" clientoption1="671088672" clientoption2="128056">
  <process status="suspended" waittime="1867650" spid="1265" sbid="0" ecid="0" priority="0" trancount="1" lastbatchstarted="2019-08-25T13:29:42.290" lastbatchcompleted="2019-08-25T13:29:42.290" lastattention="1900-01-01T00:00:00.290" clientapp="Nest" hostname="BDC5619" hostpid="63476143" loginname="webwriter" isolationlevel="read committed (2)" xactid="5096321128" currentdb="18" currentdbname="Spyder" lockTimeout="4294967295" clientoption1="671088672" clientoption2="128056">
  <process status="suspended" waittime="3210540" spid="1265" sbid="0" ecid="0" priority="0" trancount="1" lastbatchstarted="2019-08-25T13:29:42.290" lastbatchcompleted="2019-08-25T13:29:42.290" lastattention="1900-01-01T00:00:00.290" clientapp="Nest" hostname="BDC5619" hostpid="63476143" loginname="webwriter" isolationlevel="read committed (2)" xactid="5096321128" currentdb="18" currentdbname="Spyder" lockTimeout="4294967295" clientoption1="671088672" clientoption2="128056">

Here is a single full block process XML report. I had to anonymize some of the data. I also had to remove a large select statement that was being blocked. The blocked statement didn't use the purchasing table, but did use several tables that would be locked during SPID 1190's transaction.

<blocked-process-report monitorLoop="220292">
 <blocked-process>
  <process id="process1e398303848" taskpriority="0" logused="0" waitresource="PAGE: 13:1:73935055 " waittime="176854" ownerId="5114199102" transactionname="user_transaction" lasttranstarted="2019-08-30T14:20:03.090" XDES="0x228526d7ba0" lockMode="S" schedulerid="9" kpid="14672" status="suspended" spid="1406" sbid="0" ecid="34" priority="0" trancount="0" lastbatchstarted="2019-08-30T14:20:03.097" lastbatchcompleted="2019-08-30T14:20:03.097" lastattention="1900-01-01T00:00:00.097" clientapp="pymssql=2.1.3" hostname="host2" hostpid="6" isolationlevel="read committed (2)" xactid="5114199102" currentdb="13" currentdbname="adventureworks" lockTimeout="4294967295" clientoption1="671090784" clientoption2="128060">
   <executionStack>
    <frame line="10" stmtstart="548" stmtend="2224" sqlhandle="0x02000000d90ad532f652d16e21402d61b05f9483b61ff1d50000000000000000000000000000000000000000" />
   </executionStack>
   <inputbuf>

        **select statement removed**
        </inputbuf>
  </process>
 </blocked-process>
 <blocking-process>
  <process status="suspended" waittime="3210540" spid="1190" sbid="0" ecid="0" priority="0" trancount="1" lastbatchstarted="2019-08-30T13:29:42.290" lastbatchcompleted="2019-08-30T13:29:42.290" lastattention="1900-01-01T00:00:00.290" clientapp="purchasing " hostname="prodhost1" hostpid="63476143" loginname="webwrtier" isolationlevel="read committed (2)" xactid="5096321128" currentdb="13" currentdbname="adventureworks" lockTimeout="4294967295" clientoption1="671088672" clientoption2="128056">
   <executionStack />
   <inputbuf>
(@Uuids [UniqueUuidList] READONLY)
            select
                PurchasingUuid as Uuid,
                PurchasingId as Id
            from Purchasing p
            where exists (
                select 1
                from @Uuids u
                where u.val = p.PurchasingUuid
            )
           </inputbuf>
  </process>
 </blocking-process>
</blocked-process-report>

  • 1
    What are your top wait types? – nkdbajoe Aug 30 '19 at 21:16
  • By total wait time it's CXPACKET,then LATCH_EX but their averages are low at 13ms and 6ms. I am seeing that LCK_M_X average wait time is 5,406ms! – Deerup Aug 30 '19 at 21:23
  • Are there other processes that are running and runnable that are able to use resources? – nkdbajoe Aug 30 '19 at 21:31
1

We don't have information to say why it is in suspended state. But there are two DMVs that can tell us more.

sys.dm_os_waiting_tasks tell us where SQL Server is waiting at the moment.

sys.dm_exec_session_wait_stats tell us where a session is spending its waits. Be aware that waits might not be reflected here until the wait is over. for instance, if you wait for a lock, this won't accumulate that wait while you are still blocked. Only when that wait is over, the value will be reflected here.

And, of course, your favourite way to see if you are blocked. That part from an XE trace doesn't say me much. If you use the blocked process report, then you have XML with the "bigger picture". I don't know what trace event produced the output in your post.

  • I posted the full XML trace. – Deerup Sep 4 '19 at 14:43
  • Looks like a regular blocking situation to me. What am I missing? – Tibor Karaszi Sep 5 '19 at 10:36
  • The blocking query should have finished instantly, yet it was in this state for 15+ minutes. The Purchasing only has a few thousand rows and that Purchasing query wasn't being blocked. I would have thought that the transaction was sleeping yet it was always in the suspended state. There was normal amounts of IO/CPU usage during this blocking. – Deerup Sep 5 '19 at 14:43
  • I see. All we can see from the blocked process report is that it is waiting (suspended). I.e., executing something but need to wait for some reason. We can't see from this report what it is waiting for. – Tibor Karaszi Sep 5 '19 at 18:45

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.