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