August 31, 2010 at 9:51 am
Hi,
We have SQL Server 2005 x64 Enterprise edition with SP3 on Windows 2003.
We are using Log shipping for the databases and noticed below Dead lock which was occurred due to Log shipping jobs and the databases involved are System databases.
Could you please advice why Log shipping jobs causing dead locks? Is anything missing here?
Thanks
Here is the Dead lock graph from Error log:
2010-08-30 06:45:05.76 spid18s deadlock-list
2010-08-30 06:45:05.76 spid18s deadlock victim=process3c27c18
2010-08-30 06:45:05.76 spid18s process-list
2010-08-30 06:45:05.76 spid18s process id=process3c08868 taskpriority=0 logused=20003 waittime=3828 schedulerid=1 kpid=1448 status=suspended spid=81 sbid=0 ecid=3 priority=0 transcount=0 lastbatchstarted=2010-08-31T07:45:01.787 lastbatchcompleted=2010-08-31T07:45:01.783 clientapp=.Net SqlClient Data Provider hostname=SQLVS hostpid=5652 isolationlevel=read committed (2) xactid=28643631 currentdb=1 lockTimeout=4294967295 clientoption1=538968096 clientoption2=390200
2010-08-30 06:45:05.76 spid18s executionStack
2010-08-30 06:45:05.76 spid18s frame procname=mssqlsystemresource.sys.sp_MSprocesslogshippingretentioncleanup line=23 stmtstart=1264 stmtend=1708 sqlhandle=0x0300ff7fcc9b930b740ded005e9b00000100000000000000
2010-08-30 06:45:05.76 spid18s delete from msdb.dbo.log_shipping_monitor_history_detail
2010-08-30 06:45:05.76 spid18s where agent_id = @agent_id
2010-08-30 06:45:05.76 spid18s and agent_type = @agent_type
2010-08-30 06:45:05.76 spid18s and log_time_utc < @cutoff_time_utc
2010-08-30 06:45:05.76 spid18s --
2010-08-30 06:45:05.76 spid18s -- cleanup error_detail
2010-08-30 06:45:05.76 spid18s --
2010-08-30 06:45:05.76 spid18s frame procname=mssqlsystemresource.sys.sp_cleanup_log_shipping_history line=76 stmtstart=5036 stmtend=5880 sqlhandle=0x0300ff7fa2e96d06d964ec005e9b00000100000000000000
2010-08-30 06:45:05.76 spid18s exec @retcode = sys.sp_MSprocesslogshippingretentioncleanup
2010-08-30 06:45:05.76 spid18s @agent_id = @agent_id
2010-08-30 06:45:05.76 spid18s ,@agent_type = @agent_type
2010-08-30 06:45:05.76 spid18s ,@monitor_server = @monitor_server
2010-08-30 06:45:05.76 spid18s ,@monitor_server_security_mode = @monitor_server_security_mode
2010-08-30 06:45:05.76 spid18s ,@history_retention_period = @history_retention_period
2010-08-30 06:45:05.76 spid18s ,@curdate_utc = @curdate_utc
2010-08-30 06:45:05.76 spid18s frame procname=adhoc line=1 sqlhandle=0x010001009db282287019d1ca000000000000000000000000
2010-08-30 06:45:05.76 spid18s exec master.sys.sp_cleanup_log_shipping_history @agent_id = N'435ad820-00c6-4fac-b227-b81db1c5cc6b', @agent_type = 0
2010-08-30 06:45:05.76 spid18s inputbuf
2010-08-30 06:45:05.76 spid18s process id=process3c09ac8 taskpriority=0 logused=10003 waittime=3859 schedulerid=1 kpid=3956 status=suspended spid=81 sbid=0 ecid=0 priority=0 transcount=2 lastbatchstarted=2010-08-31T07:45:01.787 lastbatchcompleted=2010-08-31T07:45:01.783 clientapp=.Net SqlClient Data Provider hostname=SQLVS hostpid=5652 loginname=ABC\mssqlsrv isolationlevel=read committed (2) xactid=28643631 currentdb=1 lockTimeout=4294967295 clientoption1=538968096 clientoption2=390200
2010-08-30 06:45:05.76 spid18s executionStack
2010-08-30 06:45:05.76 spid18s frame procname=mssqlsystemresource.sys.sp_MSprocesslogshippingretentioncleanup line=23 stmtstart=1264 stmtend=1708 sqlhandle=0x0300ff7fcc9b930b740ded005e9b00000100000000000000
2010-08-30 06:45:05.76 spid18s delete from msdb.dbo.log_shipping_monitor_history_detail
2010-08-30 06:45:05.76 spid18s where agent_id = @agent_id
2010-08-30 06:45:05.76 spid18s and agent_type = @agent_type
2010-08-30 06:45:05.76 spid18s and log_time_utc < @cutoff_time_utc
2010-08-30 06:45:05.76 spid18s --
2010-08-30 06:45:05.76 spid18s -- cleanup error_detail
2010-08-30 06:45:05.76 spid18s --
2010-08-30 06:45:05.76 spid18s frame procname=mssqlsystemresource.sys.sp_cleanup_log_shipping_history line=76 stmtstart=5036 stmtend=5880 sqlhandle=0x0300ff7fa2e96d06d964ec005e9b00000100000000000000
2010-08-30 06:45:05.76 spid18s exec @retcode = sys.sp_MSprocesslogshippingretentioncleanup
2010-08-30 06:45:05.76 spid18s @agent_id = @agent_id
2010-08-30 06:45:05.76 spid18s ,@agent_type = @agent_type
2010-08-30 06:45:05.76 spid18s ,@monitor_server = @monitor_server
2010-08-30 06:45:05.76 spid18s ,@monitor_server_security_mode = @monitor_server_security_mode
2010-08-30 06:45:05.76 spid18s ,@history_retention_period = @history_retention_period
2010-08-30 06:45:05.76 spid18s ,@curdate_utc = @curdate_utc
2010-08-30 06:45:05.76 spid18s frame procname=adhoc line=1 sqlhandle=0x010001009db282287019d1ca000000000000000000000000
2010-08-30 06:45:05.76 spid18s exec master.sys.sp_cleanup_log_shipping_history @agent_id = N'435ad820-00c6-4fac-b227-b81db1c5cc6b', @agent_type = 0
2010-08-30 06:45:05.76 spid18s inputbuf
2010-08-30 06:45:05.76 spid18s exec master.sys.sp_cleanup_log_shipping_history @agent_id = N'435ad820-00c6-4fac-b227-b81db1c5cc6b', @agent_type = 0
2010-08-30 06:45:05.76 spid18s process id=process3c132e8 taskpriority=0 logused=20003 waittime=3828 schedulerid=2 kpid=2216 status=suspended spid=81 sbid=0 ecid=4 priority=0 transcount=0 lastbatchstarted=2010-08-31T07:45:01.787 lastbatchcompleted=2010-08-31T07:45:01.783 clientapp=.Net SqlClient Data Provider hostname=SQLVS hostpid=5652 isolationlevel=read committed (2) xactid=28643631 currentdb=1 lockTimeout=4294967295 clientoption1=538968096 clientoption2=390200
2010-08-30 06:45:05.76 spid18s executionStack
2010-08-30 06:45:05.76 spid18s frame procname=mssqlsystemresource.sys.sp_MSprocesslogshippingretentioncleanup line=23 stmtstart=1264 stmtend=1708 sqlhandle=0x0300ff7fcc9b930b740ded005e9b00000100000000000000
2010-08-30 06:45:05.76 spid18s delete from msdb.dbo.log_shipping_monitor_history_detail
2010-08-30 06:45:05.76 spid18s where agent_id = @agent_id
2010-08-30 06:45:05.76 spid18s and agent_type = @agent_type
2010-08-30 06:45:05.76 spid18s and log_time_utc < @cutoff_time_utc
2010-08-30 06:45:05.76 spid18s --
2010-08-30 06:45:05.76 spid18s -- cleanup error_detail
2010-08-30 06:45:05.76 spid18s --
2010-08-30 06:45:05.76 spid18s frame procname=mssqlsystemresource.sys.sp_cleanup_log_shipping_history line=76 stmtstart=5036 stmtend=5880 sqlhandle=0x0300ff7fa2e96d06d964ec005e9b00000100000000000000
2010-08-30 06:45:05.76 spid18s exec @retcode = sys.sp_MSprocesslogshippingretentioncleanup
2010-08-30 06:45:05.76 spid18s @agent_id = @agent_id
2010-08-30 06:45:05.76 spid18s ,@agent_type = @agent_type
2010-08-30 06:45:05.76 spid18s ,@monitor_server = @monitor_server
2010-08-30 06:45:05.76 spid18s ,@monitor_server_security_mode = @monitor_server_security_mode
2010-08-30 06:45:05.76 spid18s ,@history_retention_period = @history_retention_period
2010-08-30 06:45:05.76 spid18s ,@curdate_utc = @curdate_utc
2010-08-30 06:45:05.76 spid18s frame procname=adhoc line=1 sqlhandle=0x010001009db282287019d1ca000000000000000000000000
2010-08-30 06:45:05.76 spid18s exec master.sys.sp_cleanup_log_shipping_history @agent_id = N'435ad820-00c6-4fac-b227-b81db1c5cc6b', @agent_type = 0
2010-08-30 06:45:05.76 spid18s inputbuf
2010-08-30 06:45:05.76 spid18s process id=process3c1d438 taskpriority=0 logused=0 waitresource=PAGE: 4:1:130012 waittime=3828 ownerId=28643631 transactionname=DELETE lasttranstarted=2010-08-31T07:45:01.787 XDES=0xcb11f7c0 lockMode=U schedulerid=3 kpid=6120 status=suspended spid=81 sbid=0 ecid=1 priority=0 transcount=0 lastbatchstarted=2010-08-31T07:45:01.787 lastbatchcompleted=2010-08-31T07:45:01.783 clientapp=.Net SqlClient Data Provider hostname=SQLVS hostpid=5652 isolationlevel=read committed (2) xactid=28643631 currentdb=1 lockTimeout=4294967295 clientoption1=538968096 clientoption2=390200
2010-08-30 06:45:05.76 spid18s executionStack
2010-08-30 06:45:05.76 spid18s frame procname=mssqlsystemresource.sys.sp_MSprocesslogshippingretentioncleanup line=23 stmtstart=1264 stmtend=1708 sqlhandle=0x0300ff7fcc9b930b740ded005e9b00000100000000000000
2010-08-30 06:45:05.76 spid18s delete from msdb.dbo.log_shipping_monitor_history_detail
2010-08-30 06:45:05.76 spid18s where agent_id = @agent_id
2010-08-30 06:45:05.76 spid18s and agent_type = @agent_type
2010-08-30 06:45:05.76 spid18s and log_time_utc < @cutoff_time_utc
2010-08-30 06:45:05.76 spid18s --
2010-08-30 06:45:05.76 spid18s -- cleanup error_detail
2010-08-30 06:45:05.76 spid18s --
2010-08-30 06:45:05.76 spid18s frame procname=mssqlsystemresource.sys.sp_cleanup_log_shipping_history line=76 stmtstart=5036 stmtend=5880 sqlhandle=0x0300ff7fa2e96d06d964ec005e9b00000100000000000000
2010-08-30 06:45:05.76 spid18s exec @retcode = sys.sp_MSprocesslogshippingretentioncleanup
2010-08-30 06:45:05.76 spid18s @agent_id = @agent_id
2010-08-30 06:45:05.76 spid18s ,@agent_type = @agent_type
2010-08-30 06:45:05.76 spid18s ,@monitor_server = @monitor_server
2010-08-30 06:45:05.76 spid18s ,@monitor_server_security_mode = @monitor_server_security_mode
2010-08-30 06:45:05.76 spid18s ,@history_retention_period = @history_retention_period
2010-08-30 06:45:05.76 spid18s ,@curdate_utc = @curdate_utc
2010-08-30 06:45:05.76 spid18s frame procname=adhoc line=1 sqlhandle=0x010001009db282287019d1ca000000000000000000000000
2010-08-30 06:45:05.76 spid18s exec master.sys.sp_cleanup_log_shipping_history @agent_id = N'435ad820-00c6-4fac-b227-b81db1c5cc6b', @agent_type = 0
2010-08-30 06:45:05.76 spid18s inputbuf
2010-08-30 06:45:05.76 spid18s process id=process3c27198 taskpriority=0 logused=20003 waittime=3875 schedulerid=4 kpid=4884 status=suspended spid=81 sbid=0 ecid=2 priority=0 transcount=0 lastbatchstarted=2010-08-31T07:45:01.787 lastbatchcompleted=2010-08-31T07:45:01.783 clientapp=.Net SqlClient Data Provider hostname=SQLVS hostpid=5652 isolationlevel=read committed (2) xactid=28643631 currentdb=1 lockTimeout=4294967295 clientoption1=538968096 clientoption2=390200
2010-08-30 06:45:05.76 spid18s executionStack
2010-08-30 06:45:05.76 spid18s frame procname=mssqlsystemresource.sys.sp_MSprocesslogshippingretentioncleanup line=23 stmtstart=1264 stmtend=1708 sqlhandle=0x0300ff7fcc9b930b740ded005e9b00000100000000000000
2010-08-30 06:45:05.76 spid18s delete from msdb.dbo.log_shipping_monitor_history_detail
2010-08-30 06:45:05.76 spid18s where agent_id = @agent_id
2010-08-30 06:45:05.76 spid18s and agent_type = @agent_type
2010-08-30 06:45:05.76 spid18s and log_time_utc < @cutoff_time_utc
2010-08-30 06:45:05.76 spid18s --
2010-08-30 06:45:05.76 spid18s -- cleanup error_detail
2010-08-30 06:45:05.76 spid18s --
2010-08-30 06:45:05.76 spid18s frame procname=mssqlsystemresource.sys.sp_cleanup_log_shipping_history line=76 stmtstart=5036 stmtend=5880 sqlhandle=0x0300ff7fa2e96d06d964ec005e9b00000100000000000000
2010-08-30 06:45:05.76 spid18s exec @retcode = sys.sp_MSprocesslogshippingretentioncleanup
2010-08-30 06:45:05.76 spid18s @agent_id = @agent_id
2010-08-30 06:45:05.76 spid18s ,@agent_type = @agent_type
2010-08-30 06:45:05.76 spid18s ,@monitor_server = @monitor_server
2010-08-30 06:45:05.76 spid18s ,@monitor_server_security_mode = @monitor_server_security_mode
2010-08-30 06:45:05.76 spid18s ,@history_retention_period = @history_retention_period
2010-08-30 06:45:05.76 spid18s ,@curdate_utc = @curdate_utc
2010-08-30 06:45:05.76 spid18s frame procname=adhoc line=1 sqlhandle=0x010001009db282287019d1ca000000000000000000000000
2010-08-30 06:45:05.77 spid18s exec master.sys.sp_cleanup_log_shipping_history @agent_id = N'435ad820-00c6-4fac-b227-b81db1c5cc6b', @agent_type = 0
2010-08-30 06:45:05.77 spid18s inputbuf
2010-08-30 06:45:05.77 spid18s process id=process3c27c18 taskpriority=0 logused=0 waitresource=PAGE: 4:1:130012 waittime=3890 ownerId=28643729 transactionname=DELETE lasttranstarted=2010-08-31T07:45:01.793 XDES=0x806c5560 lockMode=U schedulerid=4 kpid=2144 status=suspended spid=83 sbid=0 ecid=3 priority=0 transcount=0 lastbatchstarted=2010-08-31T07:45:01.793 lastbatchcompleted=2010-08-31T07:45:01.790 clientapp=.Net SqlClient Data Provider hostname=SQLVS hostpid=2336 isolationlevel=read committed (2) xactid=28643729 currentdb=1 lockTimeout=4294967295 clientoption1=538968096 clientoption2=390200
2010-08-30 06:45:05.77 spid18s executionStack
2010-08-30 06:45:05.77 spid18s frame procname=mssqlsystemresource.sys.sp_MSprocesslogshippingretentioncleanup line=23 stmtstart=1264 stmtend=1708 sqlhandle=0x0300ff7fcc9b930b740ded005e9b00000100000000000000
2010-08-30 06:45:05.77 spid18s delete from msdb.dbo.log_shipping_monitor_history_detail
2010-08-30 06:45:05.77 spid18s where agent_id = @agent_id
2010-08-30 06:45:05.77 spid18s and agent_type = @agent_type
2010-08-30 06:45:05.77 spid18s and log_time_utc < @cutoff_time_utc
2010-08-30 06:45:05.77 spid18s --
2010-08-30 06:45:05.77 spid18s -- cleanup error_detail
2010-08-30 06:45:05.77 spid18s --
2010-08-30 06:45:05.77 spid18s frame procname=mssqlsystemresource.sys.sp_cleanup_log_shipping_history line=76 stmtstart=5036 stmtend=5880 sqlhandle=0x0300ff7fa2e96d06d964ec005e9b00000100000000000000
2010-08-30 06:45:05.77 spid18s exec @retcode = sys.sp_MSprocesslogshippingretentioncleanup
2010-08-30 06:45:05.77 spid18s @agent_id = @agent_id
2010-08-30 06:45:05.77 spid18s ,@agent_type = @agent_type
2010-08-30 06:45:05.77 spid18s ,@monitor_server = @monitor_server
2010-08-30 06:45:05.77 spid18s ,@monitor_server_security_mode = @monitor_server_security_mode
2010-08-30 06:45:05.77 spid18s ,@history_retention_period = @history_retention_period
2010-08-30 06:45:05.77 spid18s ,@curdate_utc = @curdate_utc
2010-08-30 06:45:05.77 spid18s frame procname=adhoc line=1 sqlhandle=0x01000100a54bf20a40fc5aaa000000000000000000000000
2010-08-30 06:45:05.77 spid18s exec master.sys.sp_cleanup_log_shipping_history @agent_id = N'ceb1766d-de23-4c32-b97e-592e46c78ffd', @agent_type = 0
2010-08-30 06:45:05.77 spid18s inputbuf
2010-08-30 06:45:05.77 spid18s resource-list
2010-08-30 06:45:05.77 spid18s pagelock fileid=1 pageid=130012 dbid=4 objectname=msdb.dbo.log_shipping_monitor_history_detail id=lock54dfa00 mode=U associatedObjectId=72057594047299584
2010-08-30 06:45:05.77 spid18s owner-list
2010-08-30 06:45:05.77 spid18s owner id=process3c08868 mode=U
2010-08-30 06:45:05.77 spid18s waiter-list
2010-08-30 06:45:05.77 spid18s waiter id=process3c27c18 mode=U requestType=wait
2010-08-30 06:45:05.77 spid18s waiter id=process3c1d438 mode=U requestType=wait
2010-08-30 06:45:05.77 spid18s exchangeEvent id=port800ae480 nodeId=3
2010-08-30 06:45:05.77 spid18s owner-list
2010-08-30 06:45:05.77 spid18s owner event=e_waitNone type=producer id=process3c1d438
2010-08-30 06:45:05.77 spid18s waiter-list
2010-08-30 06:45:05.77 spid18s waiter event=e_waitPortOpen type=consumer id=process3c09ac8
2010-08-30 06:45:05.77 spid18s waiter event=e_waitPortOpen type=producer id=process3c27198
2010-08-30 06:45:05.77 spid18s waiter event=e_waitPortOpen type=producer id=process3c08868
2010-08-30 06:45:05.77 spid18s waiter event=e_waitPortOpen type=producer id=process3c132e8
August 31, 2010 at 11:03 am
Silly question. Are you log shipping to the same server / instance as you're getting the logs from?
What side of the log shipping is the deadlock happening on? The sender side or the receiver side?
Is the log shipping itself being deadlocked or is it deadlocking another process? What other process? (I can only see SPIDs on the log file, so can't tell what's locking what).
August 31, 2010 at 11:13 am
Hi Brandie,
Silly question. Are you log shipping to the same server / instance as you're getting the logs from?
No. We are logshipping from SQLVS\INS1 to SQLDR\INS1 and there is NO separate Monitoring SQL Instance
What side of the log shipping is the deadlock happening on? The sender side or the receiver side?
The dead lock has occurred on Primary instance SQLVS\INS1
Is the log shipping itself being deadlocked or is it deadlocking another process? What other process? (I can only see SPIDs on the log file, so can't tell what's locking what).
When the dead lock has happened, it's created the Dead lock graph in the error log and that is what I posted above
Please advice
Thanks
August 31, 2010 at 11:25 am
Lemme ask my last question again:
From the second line "2010-08-30 06:45:05.76 spid18s deadlock victim=process3c27c18", what is this process?
EDIT: I see that it's a DELETE statement of some sort, but from what? And what is it hitting? I'm assuming it's hitting the log shipping history table that the other process is hitting, but you should verify that.
August 31, 2010 at 11:28 am
From the second line "2010-08-30 06:45:05.76 spid18s deadlock victim=process3c27c18", what is this process?
May be dumb question.
How to verify what process it is?
August 31, 2010 at 12:13 pm
Next time this is running, run SP_WHO2 a few times to see if you can catch the deadlocked SPID (or watch Activity Monitor & refresh often).
If you can get the SPID, run the below code (changing the SPID in the commented spot) to see what command was trying to run. You can also use this code to find out exactly what the SPID that's doing the blocking is working on.
DECLARE @Handle BINARY(20)
SELECT @Handle = sql_handle
FROM SysProcesses
WHERE SPID = 133 --Change this SPID as appropriate
SELECT *
FROM ::fn_get_sql(@handle)
This is not as effective as running Profiler or a Server Side trace, but it has the virtue of being easier to "set up." Doesn't matter which database you run this against. SPIDs are server wide ids.
Once you know what two pieces of code are competing against each other, we'll have a better idea of how to resolve the process.
Viewing 6 posts - 1 through 5 (of 5 total)
You must be logged in to reply to this topic. Login to reply