2

I have a really weird problem with a deadlock between a business process and a monitoring job. The both were involved on a deadlock that lasted around 5.5 hours. I don't know why SQL Server took so long in identifying that deadlock. Here is the fragment of the errorlog file:

Process ID 103 was killed by hostname Server1, host process ID 9908.
2013-03-11 07:38:11.33 spid16s     deadlock-list
2013-03-11 07:38:11.33 spid16s      deadlock victim=process3c1dc18
2013-03-11 07:38:11.33 spid16s       process-list
2013-03-11 07:38:11.33 spid16s        process id=process3c1dc18 taskpriority=0 logused=0 waitresource=OBJECT: 10:2073058421:2  waittime=19049468 ownerId=484658244 transactionname=WstrObjnameI4I4 lasttranstarted=2013-03-11T02:20:37.643 XDES=0x2a2ac81c8 lockMode=Sch-S schedulerid=3 kpid=11148 status=suspended spid=62 sbid=0 ecid=0 priority=0 transcount=1 lastbatchstarted=2013-03-11T02:20:02.900 lastbatchcompleted=2013-03-11T02:20:02.897 clientapp=SQLAgent - TSQL JobStep (Job 0x05BCA8DF1ECB76448CAB7B7FBBDCF12C : Step 1) hostname=CHQSQL10 hostpid=3180 loginname=Domain\SQLUser isolationlevel=read committed (2) xactid=484655352 currentdb=10 lockTimeout=4294967295 clientoption1=673185824 clientoption2=128056
2013-03-11 07:38:11.33 spid16s         executionStack
2013-03-11 07:38:11.33 spid16s          frame procname=adhoc line=4 stmtstart=78 sqlhandle=0x020000002e6f9032eba1a214586a5ff0b388fbf56e7c1535
2013-03-11 07:38:11.33 spid16s     SELECT 'Mar 11 2013  2:20:02:900AM',
2013-03-11 07:38:11.33 spid16s         DB_NAME() DBName,
2013-03-11 07:38:11.33 spid16s         OBJECT_NAME(p.OBJECT_ID) BlockedObjectName,
2013-03-11 07:38:11.33 spid16s         tl.resource_type,
2013-03-11 07:38:11.33 spid16s         tl.request_mode,
2013-03-11 07:38:11.33 spid16s         cast(wt.wait_duration_ms / 60000.00 as decimal(10,2)) as [LockDuration],
2013-03-11 07:38:11.33 spid16s         tl.request_session_id,
2013-03-11 07:38:11.33 spid16s         se1.host_name as [request_Host],
2013-03-11 07:38:11.33 spid16s         se1.program_name as [request_Program],
2013-03-11 07:38:11.33 spid16s         se1.login_name as [request_Login],
2013-03-11 07:38:11.33 spid16s         h1.TEXT AS RequestingText,
2013-03-11 07:38:11.33 spid16s         wt.blocking_session_id,
2013-03-11 07:38:11.33 spid16s         se2.host_name as [blocking_Host],
2013-03-11 07:38:11.33 spid16s         se2.program_name as [blocking_Program],
2013-03-11 07:38:11.33 spid16s         se2.login_name as [blocking_Login],
2013-03-11 07:38:11.33 spid16s         h2.TEXT AS BlockingTest
2013-03-11 07:38:11.33 spid16s         FROM sys.dm_tran_locks AS tl
2013-03-11 07:38:11.33 spid16s         INNER JOIN sys.databases db ON db.database_id = tl.resource_database_id
2013-03-11 07:38:11.33 spid16s         INNER JOIN sys.dm_os_waiting_tasks AS wt ON tl.lock_owner_address = wt.resource_address
2013-03-11 07:38:11.33 spid16s         INNER JOIN sys.partitions AS p ON p.hobt_id = tl.resource_associated_entity_id
2013-03-11 07:38:11.33 spid16s         INNER JOIN sys.dm_exec_connections ec1 ON ec1.session_id = tl.request_session_id
2013-03-11 07:38:11.33 spid16s         INNER JOIN sys.dm_exec_connections ec2 ON ec2.se     
2013-03-11 07:38:11.33 spid16s          frame procname=mssqlsystemresource.sys.sp_executesql line=1 sqlhandle=0x0400ff7fbe80662601000000000000000000000000000000
2013-03-11 07:38:11.33 spid16s     sp_executesql     
2013-03-11 07:38:11.33 spid16s          frame procname=DBATools.dbo.sp_foreachdb line=72 stmtstart=5630 stmtend=5694 sqlhandle=0x03001e0020c96c7eba4db70070a100000100000000000000
2013-03-11 07:38:11.33 spid16s     EXEC sp_executesql @sql;     
2013-03-11 07:38:11.33 spid16s          frame procname=DBATools.dbo.usp_CheckBlockingSessions line=62 stmtstart=5850 stmtend=6840 sqlhandle=0x03001e00ae80847cbc31b80070a100000100000000000000
2013-03-11 07:38:11.33 spid16s     INSERT INTO dbo.BlockingSessions
2013-03-11 07:38:11.33 spid16s         (GatherTime
2013-03-11 07:38:11.33 spid16s         ,DBName
2013-03-11 07:38:11.33 spid16s         ,BlockedObjectName
2013-03-11 07:38:11.33 spid16s         ,resource_type
2013-03-11 07:38:11.33 spid16s         ,request_mode
2013-03-11 07:38:11.33 spid16s         ,LockDuration
2013-03-11 07:38:11.33 spid16s         ,request_session_id
2013-03-11 07:38:11.33 spid16s         ,request_Host
2013-03-11 07:38:11.33 spid16s         ,request_Program
2013-03-11 07:38:11.33 spid16s         ,request_Login
2013-03-11 07:38:11.33 spid16s         ,RequestingText
2013-03-11 07:38:11.33 spid16s         ,blocking_session_id
2013-03-11 07:38:11.33 spid16s         ,blocking_Host
2013-03-11 07:38:11.33 spid16s         ,blocking_Program
2013-03-11 07:38:11.33 spid16s         ,blocking_Login
2013-03-11 07:38:11.33 spid16s         ,BlockingText)
2013-03-11 07:38:11.33 spid16s       EXEC dbo.sp_foreachdb  @command=@v_SQLCommand, @user_only=1, @compatibility_level=90
2013-03-11 07:38:11.33 spid16s       --EXEC sp_MSForEachDB @v_SQLCommand     
2013-03-11 07:38:11.33 spid16s          frame procname=adhoc line=1 sqlhandle=0x01001e006da0d429b0e25a9e040000000000000000000000
2013-03-11 07:38:11.33 spid16s     EXEC dbo.usp_CheckBlockingSessions     
2013-03-11 07:38:11.33 spid16s         inputbuf
2013-03-11 07:38:11.33 spid16s     EXEC dbo.usp_CheckBlockingSessions    
2013-03-11 07:38:11.33 spid16s        process id=process3c769b8 taskpriority=0 logused=1088 waitresource=KEY: 10:327680 (00001df3833b) waittime=4656 ownerId=484617865 transactionname=TRUNCATE TABLE lasttranstarted=2013-03-11T02:05:07.180 XDES=0x4c89b55b0 lockMode=X schedulerid=12 kpid=13200 status=suspended spid=64 sbid=0 ecid=0 priority=0 transcount=1 lastbatchstarted=2013-03-11T02:05:07.180 lastbatchcompleted=2013-03-11T02:05:07.163 clientapp=Microsoft SQL Server hostname=Server1 hostpid=9248 loginname=Domain\SQLUser isolationlevel=read committed (2) xactid=484617865 currentdb=10 lockTimeout=4294967295 clientoption1=671088672 clientoption2=128056
2013-03-11 07:38:11.33 spid16s         executionStack
2013-03-11 07:38:11.33 spid16s          frame procname=adhoc line=1 stmtend=58 sqlhandle=0x01000a0037917905903bd7c8010000000000000000000000
2013-03-11 07:38:11.33 spid16s     truncate table dbo.Table1     
2013-03-11 07:38:11.33 spid16s         inputbuf
2013-03-11 07:38:11.33 spid16s     truncate table dbo.Table1
truncate table dbo.Table2
truncate table dbo.Table3
truncate table dbo.Table4
truncate table d    
2013-03-11 07:38:11.33 spid16s       resource-list
2013-03-11 07:38:11.33 spid16s        objectlock lockPartition=2 objid=2073058421 subresource=FULL dbid=10 objectname=DBStore.dbo.Table1 id=lock4a2309200 mode=Sch-M associatedObjectId=2073058421
2013-03-11 07:38:11.33 spid16s         owner-list
2013-03-11 07:38:11.33 spid16s          owner id=process3c769b8 mode=Sch-M
2013-03-11 07:38:11.33 spid16s         waiter-list
2013-03-11 07:38:11.33 spid16s          waiter id=process3c1dc18 mode=Sch-S requestType=wait
2013-03-11 07:38:11.33 spid16s        keylock hobtid=327680 dbid=10 objectname=UKStoreReporting .sys.sysrowsets indexname=clust id=lock4ad68f980 mode=U associatedObjectId=327680
2013-03-11 07:38:11.33 spid16s         owner-list
2013-03-11 07:38:11.33 spid16s          owner id=process3c1dc18 mode=S
2013-03-11 07:38:11.33 spid16s         waiter-list
2013-03-11 07:38:11.33 spid16s          waiter id=process3c769b8 mode=X requestType=convert

I really don't know in the first place why the monitoring process acquire a lock on a user table if the query does not mention it. Another question would be if system tables are involved on a deadlock does sql server ignore it?

Here is full first query:

SELECT 
    DB_NAME() DBName,
    OBJECT_NAME(p.OBJECT_ID) BlockedObjectName,
    tl.resource_type,
    tl.request_mode,
    cast(wt.wait_duration_ms / 60000.00 as decimal(10,2)) as [LockDuration],
    tl.request_session_id,
    se1.host_name as [request_Host],
    se1.program_name as [request_Program],
    se1.login_name as [request_Login],
    h1.TEXT AS RequestingText,
    wt.blocking_session_id,
    se2.host_name as [blocking_Host],
    se2.program_name as [blocking_Program],
    se2.login_name as [blocking_Login],
    h2.TEXT AS BlockingTest
    FROM sys.dm_tran_locks AS tl
    INNER JOIN sys.databases db ON db.database_id = tl.resource_database_id
    INNER JOIN sys.dm_os_waiting_tasks AS wt ON tl.lock_owner_address = wt.resource_address
    INNER JOIN sys.partitions AS p ON p.hobt_id = tl.resource_associated_entity_id
    INNER JOIN sys.dm_exec_connections ec1 ON ec1.session_id = tl.request_session_id
    INNER JOIN sys.dm_exec_connections ec2 ON ec2.session_id = wt.blocking_session_id
    INNER JOIN sys.dm_exec_sessions se1 ON ec1.session_id = se1.session_id
    INNER JOIN sys.dm_exec_sessions se2 ON ec2.session_id = se2.session_id
    CROSS APPLY sys.dm_exec_sql_text(ec1.most_recent_sql_handle) AS h1
    CROSS APPLY sys.dm_exec_sql_text(ec2.most_recent_sql_handle) AS h2
    WHERE db.database_id = DB_ID()
    AND cast(wt.wait_duration_ms / 60000.00 as decimal(10,2)) >= 5

The truncate is a series of truncates all in a single transaction because it is a task on a SSIS.

Finally how could I avoid this problem? Thanks

Improve this question
  • Can you capture a deadlock graph using a trace, and post the .xdl file? – Aaron Bertrand Mar 11 '13 at 18:06
  • Hi, the lock has already disappeared, and I cannot reproduce it. – mvillegascuellar Mar 11 '13 at 18:11
  • Well without a repro and without a full picture of the queries being issued, the sequence, and the larger scope of each transaction, it's going to be very difficult for anyone to provide specific explanations... – Aaron Bertrand Mar 11 '13 at 18:12
  • I understand but I do not understand why the first query shown on the error log gets blocked by a truncate table. – mvillegascuellar Mar 11 '13 at 18:23
  • 4
    Because maybe it was a livelock for all of that time. Again, without more context, any "answer" would be a guess. – Aaron Bertrand Mar 11 '13 at 18:45
3

I suspect the queries were livelocked for that time (but couldn't possibly speculate as to why, other than that the truncates really took a long time).

Some potential improvements to your query to reduce / eliminate blocking:

  • try joining on sys.dm_db_partition_stats.partition_id instead of sys.partitions.hobt_id
  • try avoiding built-in metadata functions like OBJECT_NAME(), which have been demonstrated to block unnecessarily, when you can easily derive the name from sys.objects instead, which shouldn't block at all.
  • Similarly DB_NAME() could be retrieved before the statement and placed in a variable, or you could grab it from sys.databases instead of using the built-in.
  • sys.dm_tran_locks is a pretty resource-intensive DMV to use; perhaps you should consider not pursuing those granular details until you know you need them. In other words, do that in a second query that is only executed when the first one turned up a session that has been blocked beyond your threshold.
  • And then there's isolation level, which I didn't think would help, and which you have confirmed my suspicion, but leaving here for posterity.

While I've never actually experienced a case where it makes a difference, this may be one of those times where you want to make the isolation level extremely lax for access to DMVs. (I'm not 100% confident it will prevent this situation in the future, but it can't hurt.)

In your blocking-checking stored procedure, place this at the top (or use READ COMMITTED SNAPSHOT if the option is available to you):

SET TRANSACTION ISOLATION LEVEL READ UNCOMMITTED;

If a block doesn't last long enough to survive the implications of that isolation level, it probably wasn't worth tracking anyway.

Improve this answer
  • I tried this, however it always get locked when the truncate table is executed. The sys.partitions is the one that holds the lock. – mvillegascuellar Mar 11 '13 at 19:36
  • Yeah I wasn't convinced that NOLOCK would help at all, just thought I'd throw it out as something to try, and it was too involved for a comment. – Aaron Bertrand Mar 11 '13 at 19:40
1

Could be a problem with the query going after data from syspartitions, while also truncating since syspartitions keeps rows. May be some lock escalation problem there. Maybe try using something more basic to track locking:

select 
    t1.request_session_id as spid, 
    t1.resource_type as type,  
    t1.resource_database_id as dbid, 
    t1.resource_description as description,  
    t1.request_mode as mode, 
    t1.request_status as status
from sys.dm_tran_locks as t1
where t1.request_session_id = @@SPID
Improve this answer
  • You are right the sys.partitions was the one blocked by the truncate table. Now I only have pending the reason why SQL Server did not killed the deadlock process after 5.5 hours??? – mvillegascuellar Mar 11 '13 at 18:37
  • Was it blocking for 5.5 hours, and finally became deadlocked? – Richard Schweiger Mar 13 '13 at 20:37
  • yes, it finally became deadlocked – mvillegascuellar Mar 25 '13 at 15:54

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