3

I have an application that must delete and insert registries from a table, the table is storing the historic registries for an access control and is stored with the datetime for the check in the system.

Now this is the issue. I have a threadpool in which each thread works over one day in a time period (normally a month). When the process start, it's giving me some deadlocks. I made a lock trace and in the deadlock graph only says that a process was blocked but no which sentence or transaction was made, and in the deadlock log it say Parallel query worker thread was involved in a deadlock. How can I make a more detailed trace or query in order to know what is making my app and DB blocking?

Thanks

EDIT

here is the XML for the trace I already made in the past days:

<deadlock victim="process45f9fb048">
  <process-list>
   <process id="process45f9fb048" taskpriority="0" logused="0" waitresource="PAGE: 4:1:98644" waittime="5369" ownerId="1282041063" transactionname="DELETE" lasttranstarted="2014-06-27T03:15:01.157" XDES="0xbeb91620" lockMode="U" schedulerid="7" kpid="1984" status="suspended" spid="204" sbid="0" ecid="4" priority="0" trancount="0" lastbatchstarted="2014-06-27T03:15:00.620" lastbatchcompleted="2014-06-27T03:15:00.620" clientapp="SQLAgent - TSQL JobStep (Job 0xF408BE64B781AB40B05180C1B2EB9DC8 : Step 1)" hostname="REPORTESCRYSTAL" hostpid="28848" isolationlevel="read committed (2)" xactid="1282041063" currentdb="4" lockTimeout="4294967295" clientoption1="673185824" clientoption2="128056">
    <executionStack>
     <frame procname="msdb.dbo.sp_syscollector_purge_collection_logs" line="31" stmtstart="2152" stmtend="2720" sqlhandle="0x03000400af551732fc7ab30044a000000100000000000000">
DELETE FROM dbo.sysssislog
        FROM dbo.sysssislog AS s
        INNER JOIN dbo.syscollector_execution_log_internal AS l ON (l.package_execution_id = s.executionid)
        INNER JOIN #purged_log_ids AS i ON i.log_id = l.log_id

    -- Then delete the actual logs     </frame>
     <frame procname="adhoc" line="2" stmtstart="28" sqlhandle="0x0100040034b4980c80c0a260030000000000000000000000">
EXEC [dbo].[sp_syscollector_purge_collection_logs]     </frame>
    </executionStack>
    <inputbuf>
    </inputbuf>
   </process>
   <process id="process961c988" taskpriority="0" logused="0" waitresource="PAGE: 4:1:98644" waittime="5324" ownerId="1282041063" transactionname="DELETE" lasttranstarted="2014-06-27T03:15:01.157" XDES="0xaece7620" lockMode="U" schedulerid="3" kpid="27920" status="suspended" spid="204" sbid="0" ecid="2" priority="0" trancount="0" lastbatchstarted="2014-06-27T03:15:00.620" lastbatchcompleted="2014-06-27T03:15:00.620" clientapp="SQLAgent - TSQL JobStep (Job 0xF408BE64B781AB40B05180C1B2EB9DC8 : Step 1)" hostname="REPORTESCRYSTAL" hostpid="28848" isolationlevel="read committed (2)" xactid="1282041063" currentdb="4" lockTimeout="4294967295" clientoption1="673185824" clientoption2="128056">
    <executionStack>
     <frame procname="msdb.dbo.sp_syscollector_purge_collection_logs" line="31" stmtstart="2152" stmtend="2720" sqlhandle="0x03000400af551732fc7ab30044a000000100000000000000">
DELETE FROM dbo.sysssislog
        FROM dbo.sysssislog AS s
        INNER JOIN dbo.syscollector_execution_log_internal AS l ON (l.package_execution_id = s.executionid)
        INNER JOIN #purged_log_ids AS i ON i.log_id = l.log_id

    -- Then delete the actual logs     </frame>
     <frame procname="adhoc" line="2" stmtstart="28" sqlhandle="0x0100040034b4980c80c0a260030000000000000000000000">
EXEC [dbo].[sp_syscollector_purge_collection_logs]     </frame>
    </executionStack>
    <inputbuf>
    </inputbuf>
   </process>
   <process id="processb543dc8" taskpriority="0" logused="0" waitresource="PAGE: 4:1:108775" waittime="5367" ownerId="1282041011" transactionname="DELETE" lasttranstarted="2014-06-27T03:15:01.153" XDES="0x6771b32d0" lockMode="U" schedulerid="4" kpid="27392" status="suspended" spid="197" sbid="0" ecid="2" priority="0" trancount="0" lastbatchstarted="2014-06-27T03:15:00.617" lastbatchcompleted="2014-06-27T03:15:00.617" clientapp="SQLAgent - TSQL JobStep (Job 0xE0A214220ED4114D8DD04385F151A9B2 : Step 1)" hostname="REPORTESCRYSTAL" hostpid="28848" isolationlevel="read committed (2)" xactid="1282041011" currentdb="4" lockTimeout="4294967295" clientoption1="673185824" clientoption2="128056">
    <executionStack>
     <frame procname="msdb.dbo.sp_syscollector_purge_collection_logs" line="31" stmtstart="2152" stmtend="2720" sqlhandle="0x03000400af551732fc7ab30044a000000100000000000000">
DELETE FROM dbo.sysssislog
        FROM dbo.sysssislog AS s
        INNER JOIN dbo.syscollector_execution_log_internal AS l ON (l.package_execution_id = s.executionid)
        INNER JOIN #purged_log_ids AS i ON i.log_id = l.log_id

    -- Then delete the actual logs     </frame>
     <frame procname="adhoc" line="2" stmtstart="28" sqlhandle="0x0100040034b4980c80c0a260030000000000000000000000">
EXEC [dbo].[sp_syscollector_purge_collection_logs]     </frame>
    </executionStack>
    <inputbuf>
    </inputbuf>
   </process>
   <process id="process9631948" taskpriority="0" logused="0" waitresource="PAGE: 4:1:108775" waittime="5301" ownerId="1282041011" transactionname="DELETE" lasttranstarted="2014-06-27T03:15:01.153" XDES="0x506b8f300" lockMode="U" schedulerid="5" kpid="23904" status="suspended" spid="197" sbid="0" ecid="1" priority="0" trancount="0" lastbatchstarted="2014-06-27T03:15:00.617" lastbatchcompleted="2014-06-27T03:15:00.617" clientapp="SQLAgent - TSQL JobStep (Job 0xE0A214220ED4114D8DD04385F151A9B2 : Step 1)" hostname="REPORTESCRYSTAL" hostpid="28848" isolationlevel="read committed (2)" xactid="1282041011" currentdb="4" lockTimeout="4294967295" clientoption1="673185824" clientoption2="128056">
    <executionStack>
     <frame procname="msdb.dbo.sp_syscollector_purge_collection_logs" line="31" stmtstart="2152" stmtend="2720" sqlhandle="0x03000400af551732fc7ab30044a000000100000000000000">
DELETE FROM dbo.sysssislog
        FROM dbo.sysssislog AS s
        INNER JOIN dbo.syscollector_execution_log_internal AS l ON (l.package_execution_id = s.executionid)
        INNER JOIN #purged_log_ids AS i ON i.log_id = l.log_id

    -- Then delete the actual logs     </frame>
     <frame procname="adhoc" line="2" stmtstart="28" sqlhandle="0x0100040034b4980c80c0a260030000000000000000000000">
EXEC [dbo].[sp_syscollector_purge_collection_logs]     </frame>
    </executionStack>
    <inputbuf>
    </inputbuf>
   </process>
   <process id="process964fdc8" taskpriority="0" logused="10000" waittime="5745" schedulerid="8" kpid="32756" status="suspended" spid="204" sbid="0" ecid="0" priority="0" trancount="2" lastbatchstarted="2014-06-27T03:15:00.620" lastbatchcompleted="2014-06-27T03:15:00.620" clientapp="SQLAgent - TSQL JobStep (Job 0xF408BE64B781AB40B05180C1B2EB9DC8 : Step 1)" hostname="REPORTESCRYSTAL" hostpid="28848" loginname="SALUDTOTAL\bo_agent" isolationlevel="read committed (2)" xactid="1282041063" currentdb="4" lockTimeout="4294967295" clientoption1="673185824" clientoption2="128056">
    <executionStack>
     <frame procname="msdb.dbo.sp_syscollector_purge_collection_logs" line="31" stmtstart="2152" stmtend="2720" sqlhandle="0x03000400af551732fc7ab30044a000000100000000000000">
DELETE FROM dbo.sysssislog
        FROM dbo.sysssislog AS s
        INNER JOIN dbo.syscollector_execution_log_internal AS l ON (l.package_execution_id = s.executionid)
        INNER JOIN #purged_log_ids AS i ON i.log_id = l.log_id

    -- Then delete the actual logs     </frame>
     <frame procname="adhoc" line="2" stmtstart="28" sqlhandle="0x0100040034b4980c80c0a260030000000000000000000000">
EXEC [dbo].[sp_syscollector_purge_collection_logs]     </frame>
    </executionStack>
    <inputbuf>

            EXEC [dbo].[sp_syscollector_purge_collection_logs]
                </inputbuf>
   </process>
   <process id="process5fc0b0508" taskpriority="0" logused="10000" waittime="2896" schedulerid="2" kpid="8248" status="suspended" spid="204" sbid="0" ecid="5" priority="0" trancount="0" lastbatchstarted="2014-06-27T03:15:00.620" lastbatchcompleted="2014-06-27T03:15:00.620" clientapp="SQLAgent - TSQL JobStep (Job 0xF408BE64B781AB40B05180C1B2EB9DC8 : Step 1)" hostname="REPORTESCRYSTAL" hostpid="28848" isolationlevel="read committed (2)" xactid="1282041063" currentdb="4" lockTimeout="4294967295" clientoption1="673185824" clientoption2="128056">
    <executionStack>
     <frame procname="msdb.dbo.sp_syscollector_purge_collection_logs" line="31" stmtstart="2152" stmtend="2720" sqlhandle="0x03000400af551732fc7ab30044a000000100000000000000">
DELETE FROM dbo.sysssislog
        FROM dbo.sysssislog AS s
        INNER JOIN dbo.syscollector_execution_log_internal AS l ON (l.package_execution_id = s.executionid)
        INNER JOIN #purged_log_ids AS i ON i.log_id = l.log_id

    -- Then delete the actual logs     </frame>
     <frame procname="adhoc" line="2" stmtstart="28" sqlhandle="0x0100040034b4980c80c0a260030000000000000000000000">
EXEC [dbo].[sp_syscollector_purge_collection_logs]     </frame>
    </executionStack>
    <inputbuf>
    </inputbuf>
   </process>
  </process-list>
  <resource-list>
   <pagelock fileid="1" pageid="98644" dbid="4" objectname="msdb.dbo.sysssislog" id="lock544471d00" mode="U" associatedObjectId="72057594047037440">
    <owner-list>
     <owner id="process9631948" mode="U"/>
    </owner-list>
    <waiter-list>
     <waiter id="process45f9fb048" mode="U" requestType="wait"/>
    </waiter-list>
   </pagelock>
   <pagelock fileid="1" pageid="98644" dbid="4" objectname="msdb.dbo.sysssislog" id="lock544471d00" mode="U" associatedObjectId="72057594047037440">
    <owner-list/>
    <waiter-list>
     <waiter id="process961c988" mode="U" requestType="wait"/>
    </waiter-list>
   </pagelock>
   <pagelock fileid="1" pageid="108775" dbid="4" objectname="msdb.dbo.sysssislog" id="lock6a3143280" mode="U" associatedObjectId="72057594047037440">
    <owner-list>
     <owner id="process964fdc8" mode="U"/>
    </owner-list>
    <waiter-list>
     <waiter id="processb543dc8" mode="U" requestType="wait"/>
    </waiter-list>
   </pagelock>
   <pagelock fileid="1" pageid="108775" dbid="4" objectname="msdb.dbo.sysssislog" id="lock6a3143280" mode="U" associatedObjectId="72057594047037440">
    <owner-list/>
    <waiter-list>
     <waiter id="process9631948" mode="U" requestType="wait"/>
    </waiter-list>
   </pagelock>
   <exchangeEvent id="Port80185c00" WaitType="e_waitPortOpen" nodeId="2">
    <owner-list>
     <owner id="process5fc0b0508"/>
    </owner-list>
    <waiter-list>
     <waiter id="process964fdc8"/>
    </waiter-list>
   </exchangeEvent>
   <exchangeEvent id="Pipe1937d8680" WaitType="e_waitPipeGetRow" nodeId="4">
    <owner-list>
     <owner id="process45f9fb048"/>
     <owner id="process961c988"/>
    </owner-list>
    <waiter-list>
     <waiter id="process5fc0b0508"/>
    </waiter-list>
   </exchangeEvent>
  </resource-list>
 </deadlock>
</deadlock-list>

EDIT 2

I've already replicated the deadlock in another SQL Instance, here is the graph

<deadlock victim="process9ada4508">
  <process-list>
   <process id="process9ada4508" taskpriority="0" logused="0" waitresource="PAGE: 7:1:595136" waittime="2411" ownerId="391631459" transactionname="DELETE" lasttranstarted="2014-07-08T10:51:37.907" XDES="0x9a5c9b00" lockMode="U" schedulerid="2" kpid="7308" status="suspended" spid="93" sbid="0" ecid="2" priority="0" trancount="0" lastbatchstarted="2014-07-08T10:51:37.907" lastbatchcompleted="2014-07-08T10:51:37.907" clientapp=".Net SqlClient Data Provider" hostname="CENTROCONTROL" hostpid="9016" isolationlevel="read committed (2)" xactid="391631459" currentdb="7" lockTimeout="4294967295" clientoption1="671088672" clientoption2="128056">
    <executionStack>
     <frame procname="adhoc" line="1" stmtstart="54" sqlhandle="0x020000000826022c8d837edd59a697e6b8f2b323fc72898d">
DELETE FROM TBL_ITAS_USER_REGISTRY WHERE (URE_DATE_IN &gt;= @p0 AND URE_DATE_IN &lt; @p1) OR (URE_DATE_OUT &gt;= @p0 AND URE_DATE_OUT &lt; @p1)     </frame>
     <frame procname="unknown" line="1" sqlhandle="0x000000000000000000000000000000000000000000000000">
unknown     </frame>
    </executionStack>
    <inputbuf>
    </inputbuf>
   </process>
   <process id="process43fdc8" taskpriority="0" logused="0" waitresource="PAGE: 7:1:595136" waittime="5046" ownerId="391632197" transactionname="DELETE" lasttranstarted="2014-07-08T10:51:39.943" XDES="0x2388fc080" lockMode="U" schedulerid="1" kpid="7944" status="suspended" spid="84" sbid="0" ecid="3" priority="0" trancount="0" lastbatchstarted="2014-07-08T10:51:39.943" lastbatchcompleted="2014-07-08T10:51:39.943" clientapp=".Net SqlClient Data Provider" hostname="CENTROCONTROL" hostpid="9016" isolationlevel="read committed (2)" xactid="391632197" currentdb="7" lockTimeout="4294967295" clientoption1="671088672" clientoption2="128056">
    <executionStack>
     <frame procname="adhoc" line="1" stmtstart="54" sqlhandle="0x020000000826022c8d837edd59a697e6b8f2b323fc72898d">
DELETE FROM TBL_ITAS_USER_REGISTRY WHERE (URE_DATE_IN &gt;= @p0 AND URE_DATE_IN &lt; @p1) OR (URE_DATE_OUT &gt;= @p0 AND URE_DATE_OUT &lt; @p1)     </frame>
     <frame procname="unknown" line="1" sqlhandle="0x000000000000000000000000000000000000000000000000">
unknown     </frame>
    </executionStack>
    <inputbuf>
    </inputbuf>
   </process>
   <process id="process9ada5288" taskpriority="0" logused="10000" waittime="1946" schedulerid="2" kpid="4680" status="suspended" spid="93" sbid="0" ecid="0" priority="0" trancount="2" lastbatchstarted="2014-07-08T10:51:37.907" lastbatchcompleted="2014-07-08T10:51:37.907" clientapp=".Net SqlClient Data Provider" hostname="CENTROCONTROL" hostpid="9016" loginname="Robotec" isolationlevel="read committed (2)" xactid="391631459" currentdb="7" lockTimeout="4294967295" clientoption1="671088672" clientoption2="128056">
    <executionStack>
     <frame procname="adhoc" line="1" stmtstart="54" sqlhandle="0x020000000826022c8d837edd59a697e6b8f2b323fc72898d">
DELETE FROM TBL_ITAS_USER_REGISTRY WHERE (URE_DATE_IN &gt;= @p0 AND URE_DATE_IN &lt; @p1) OR (URE_DATE_OUT &gt;= @p0 AND URE_DATE_OUT &lt; @p1)     </frame>
     <frame procname="unknown" line="1" sqlhandle="0x000000000000000000000000000000000000000000000000">
unknown     </frame>
    </executionStack>
    <inputbuf>
(@p0 datetime,@p1 datetime)DELETE FROM TBL_ITAS_USER_REGISTRY WHERE (URE_DATE_IN &gt;= @p0 AND URE_DATE_IN &lt; @p1) OR (URE_DATE_OUT &gt;= @p0 AND URE_DATE_OUT &lt; @p1)    </inputbuf>
   </process>
  </process-list>
  <resource-list>
   <pagelock fileid="1" pageid="595136" dbid="7" objectname="MFEnterprise_v2.dbo.TBL_ITAS_USER_REGISTRY" id="lock800f1200" mode="U" associatedObjectId="72057594063224832">
    <owner-list/>
    <waiter-list>
     <waiter id="process9ada4508" mode="U" requestType="wait"/>
    </waiter-list>
   </pagelock>
   <pagelock fileid="1" pageid="595136" dbid="7" objectname="MFEnterprise_v2.dbo.TBL_ITAS_USER_REGISTRY" id="lock800f1200" mode="U" associatedObjectId="72057594063224832">
    <owner-list>
     <owner id="process9ada5288" mode="U"/>
    </owner-list>
    <waiter-list>
     <waiter id="process43fdc8" mode="U" requestType="wait"/>
    </waiter-list>
   </pagelock>
   <exchangeEvent id="Pipe188f61be0" WaitType="e_waitPipeGetRow" nodeId="2">
    <owner-list>
     <owner id="process9ada4508"/>
    </owner-list>
    <waiter-list>
     <waiter id="process9ada5288"/>
    </waiter-list>
   </exchangeEvent>
  </resource-list>
 </deadlock>
</deadlock-list>
Improve this question
1
  • Once you have an .xdl, post a link to it here. SQL Sentry Plan Explorer Pro can visualize a deadlock much better than the native tools (or reading the XML yourself shudder).
    – Aaron Bertrand
    Jul 3, 2014 at 15:38

2 Answers 2

Reset to default
5

Based on what I see in SQL Sentry Plan Explorer PRO*, looks like two different jobs are fighting over who is going to get to delete some rows (click to enlarge):

click to enlarge

Maybe there is some overlap because Microsoft does some not-so-optimal things in msdb.dbo.sp_syscollector_purge_collection_logs, for instance letting each invocation of the procedure grab TOP (@delete_batch_size) rows with no ORDER BY or exclusion techniques, meaning two people calling the stored procedure could certainly end up trying to delete rows on the same page, or maybe even the same rows.

So the easiest solution:

Don't have two jobs running the same cleanup procedure.

If you need to run both jobs (again, please explain why?), my first thought would be to set MAXDOP to 1 for the delete queries in that stored procedure (yes, you can modify it, just keep that in source control because your change could be undone by service packs, upgrades, etc).

DELETE ... OPTION (MAXDOP 1);

I don't know for sure that this is the cause; would be interesting to see an actual plan from calling the procedure manually outside the context of the job.

If you don't want to modify the stored procedure, you have at least one other option if you are running Enterprise Edition: Resource Governor. Just have the login the job executes as belong to a workload group with max_dop set to 1. I have instructions for doing so (framed in the context of maintenance jobs, but same concept) in my white paper, Using the Resource Governor.

* Disclaimer: I work for SQL Sentry.

Improve this answer
8
  • Actually we don't call the procedure. The transact that we use is for delete N rows from a table, each delete with a date range of one day over the registries in the table. Then one day the deadlocks come in. And this is happening in only one of our clients.
    – Ruben Gomez
    Jul 3, 2014 at 20:10
  • @Ruben I didn't find any statement in the deadlock except those that originated from that stored procedure (and it seems the procedure is called independently from multiple jobs). Are you deleting rows manually from sysssislogs? Why? Why not just let the purge job (and only one of them) do that? Could you provide a deadlock that actually demonstrates the deadlock you're talking about, because the one you've shown us doesn't seem to do that at all.
    – Aaron Bertrand
    Jul 3, 2014 at 21:45
  • thats what is confusing me, I'm executing this query DELETE FROM TBL_USER_REGISTRY WHERE (DATE_IN >= {0} AND DATE_IN < {1}) OR (DATE_OUT >= {0} AND DATE_OUT < {1}) where {0} is one day and {1} is the same day plus one. When we run the trace the only deadlock that apears is the one I show you. And in the event log of the application we only see deadlocks triggered from db.
    – Ruben Gomez
    Jul 3, 2014 at 22:07
  • This deadlock seems completely unrelated to TBL_USER_REGISTRY. Sorry, in order to help, you need to provide the right deadlock.
    – Aaron Bertrand
    Jul 3, 2014 at 23:02
  • Thanks for all the help, I'll try to replicate the deadlock once again and will come back.
    – Ruben Gomez
    Jul 4, 2014 at 2:51
0

Rather than re-write an already great blog post, please see this PFE post about logging deadlocks: Deadlock Logging

Once you have the XML, graph, or TF1222 output you should be able to see all of the players involved and what happened. From there it would be possible to take corrective action, which will depends on what is all involved.

If you would like extra help with this, please attach the XML, graph, or TF output here.

Improve this answer

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.

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