Unexplained log ship slow down

Question

I have a number of SQL 2008 instances all running Microsoft SQL Server 2008 (SP4) (confirmed with select @@VERSION on the servers in question). They run on either Windows Server 2008 or Windows Server 2008 R2.

Two of them exist solely to log ship with Red Gate SQL Backup 7.4.0.23, and I'm having issues with one of them. (It's one of the 2008 R2 servers, if that makes a difference.) I'm using a t-sql job that scrolls through a very long list of databases (dynamically pulled from the other servers) and restores them.

Previously, this job took less than 10 minutes. It's now taking an hour and a half to two and a half hours. There have been no code changes and no radical increases in the number of databases to restore. Its sibling server, with almost identical code, is running this job in under 4 minutes. (The sibling server is one of the non-R2 servers, if that makes a difference.)

The Event Log and SQL Error log show an error of:

Operating system error 0x80770006 (failed to retrieve text for this error. Reason: 317)."

I don't know if this is the cause of the problem or not; Google suggests that this occurs when different versions of SQL Server coexist, or Red Gate SQL Backup 6.x needs a special patch. I don't think either of these are the issue because the error is intermittent, the SQL Server versions are identical, and I'm running Red Gate SQL Backup 7.x, but I could certainly be wrong. Red Gate forums suggested running a query to see if VAS memory was low, since that could cause similar issues.

VAS Total avail mem, KB      Max free size, KB
8320072080                   8314974784

Other things I've tried to resolve the issue include:

• Cleaning old log files out of "C:\ProgramData\Red Gate\SQL Backup\Log[instancename]", because the last time the job slowed down it was because there were too many log files in that directory.
• Checking for and resolving any memory issues on the server.
• Making sure that antivirus has exclusions for .sqb files (SQL Backup).
• Running CHKDSK on the volumes involved.
• Watching the job run with sp_WhoIsActive.
• Checking msdb to make sure that the purge job was running properly. The oldest entry is four weeks old, but it still seems overlarge.
• Running DBCC CheckDB on msdb.
• Asking those with visibility into the storage utilities to check for any failures there. They say my storage is "optimal."

Things I plan to do:

• Purge msdb's history to be only a week. It's a blocking query so I want to wait until after hours, even though customers don't actively query this instance.

Watching the job run with sp_whoisactive seems to show a lot of PAGEIOLATCH (both SH and EX) on msdb, but the waits are usually less than a second. (The query is the updating backupset procedure.)

The only error I can find is intermittent variants of (from the SQL Error log):

2016-05-25 14:12:39.18 Backup      Error: 3201, Severity: 16, State: 7.
2016-05-25 14:12:39.18 Backup      Cannot open backup device 'SQLBACKUP_D99ABDE1-42E6-4617-B1EB-BDA30BF8113B'. Operating system error 0x80770006(failed to retrieve text for this error. Reason: 317).

(followed immediately by "Log was restored.") and (from Event Viewer application log):

SQLVDI: Loc=SVDS::Open. Desc=Bad State. ErrorCode=(-1). Process=8056. Thread=10512. Server. Instance=DR. VD=Global\SQLBACKUP_D99ABDE1-42E6-4617-B1EB-BDA30BF8113B_SQLVDIMemoryName_0. 
Cannot open backup device 'SQLBACKUP_D99ABDE1-42E6-4617-B1EB-BDA30BF8113B'. Operating system error 0x80770006(failed to retrieve text for this error. Reason: 317).

What am I missing? Where else can I look?

Things I did after hours:

• Purge msdb to a week.
• Add a registry key for the VDI timeout for Red Gate SQL Backup. (I'd changed this value previously and then deleted the key. The default is 30 seconds and I thought one database seemed hung up a lot longer than 30 seconds, so I put in a key with the default value to be sure.)

No difference, but I did find this query and it seems to have given me a lead. One database in particular that I thought I noticed in sp_WhoIsActive taking a long time, well. It wasn't my imagination. Approximate restore times include 5068100, 4252443, 4408026, 2184080, 2786363 (in addition to things like 330, 373, etc.). (Those are Milliseconds.) I checked the number of VLFs in this database, and there are only 46 so something else is up with it.

I'm going to load up a full list of log ship DBs and run it again.

The secondary databases are in restoring, not standby. We're using Red Gate for the log shipping for the compression, because we have copies of the encrypted backups written to a share on that server already, and because there was concern about possible overhead on the master. There are a lot of databases being shipped. Over 800 on that server. I try to do it as one process to cut down on msdb contention.

The machines are bare metal, not VMs. It's just falling behind, as far as I can tell, and the contention is either the restore or writing information about the restore to MSDB (or both). The most recent restore was within the last minute.

Answer 1

This is bigger than a comment but something to test first and then implement :

You are logshipping 800+ databases. Thats a large amount of databases that you logship every 15 mins.

You should offload some databases to another server. IMHO 800 databases on a single server is a lot!

We had similar problem with logshipping when we logshipped 200+ databases from NY to LD region.

What we did is as below :

• There was blocking writing to msdb.dbo.sysjobhistory with (TABLOCKX). The TABLOCK hint means that access to the sysjobhistory is always serialized. And since you have lot of jobs running every 15mins, there will be contention (blocking).

• We implemented trace flag TF – 1236. It will introduce Database lock partitioning. Partitioning the DATABASE lock keeps the depth of the lock list manageable in each local partition. This significantly optimizes the access path that is used to obtain a DATABASE lock.

• create indexes on sysjobhistory and log_shipping_monitor_history_detail tables as below :

  use msdb
      go
  
      create nonclustered index [nc_DBA_sysjobhistory] on dbo.sysjobhistory (
              ,[job_id] 
              ,[step_id]     
              ,[run_date]
              ) 
      include (
              [instance_id]
              ,[step_name]
              ,[sql_message_id]
              ,[sql_severity]
              ,[message]
              ,[run_status]
              ,[run_time]
              ,[run_duration]
              ,[retries_attempted]
              ,[server]
              )
      go
  
      use [msdb]
      go
      ----- this will help sys.sp_MSprocesslogshippingretentioncleanup proc (delete from msdb.dbo.log_shipping_monitor_history_detail).. that does the cleanup of logshipping.
  
      create nonclustered index [nc_DBA_LogShipping_monitor_history_detail] on [dbo].[log_shipping_monitor_history_detail] (
              [agent_id] asc
              ,[agent_type] asc
              ,[log_time_utc] asc
              )
      go
  

Answer 2

I loaded all the databases being shipped into this query:

DECLARE @path NVARCHAR(260);

SELECT 
   @path = REVERSE(SUBSTRING(REVERSE([path]), 
   CHARINDEX(CHAR(92), REVERSE([path])), 260)) + N'log.trc'
FROM    sys.traces
WHERE   is_default = 1;

SELECT *, rn = ROW_NUMBER() OVER 
  (PARTITION BY DatabaseName ORDER BY StartTime)
INTO #blat
FROM sys.fn_trace_gettable(@path, DEFAULT) 
WHERE DatabaseName IN (
  N'db1', N'db2' -- , ...
)
ORDER BY StartTime DESC; 

SELECT b.DatabaseName, b.TextData, 
  ApproximateRestoreTime = DATEDIFF(MILLISECOND, b.StartTime, b2.StartTime)
FROM #blat AS b 
LEFT OUTER JOIN #blat AS b2
ON b.DatabaseName = b2.DatabaseName
AND b2.rn = b.rn + 1
WHERE b.EventClass = 115 AND b.EventSubClass = 2
ORDER BY b.StartTime DESC;

GO
DROP TABLE #blat;

(But I edited it to give me the start time, just as a sanity check.) This gave me a slew of results like:

DatabaseName    ApproximateRestoreTime  StartTime

DB1             2228166                 5/26/16 12:07 PM
DB1             370                     5/26/16 12:07 PM
DB1             373                     5/26/16 12:07 PM
DB1             366                     5/26/16 12:07 PM
DB1             383                     5/26/16 12:07 PM
DB1             350                     5/26/16 12:07 PM
DB1             350                     5/26/16 12:07 PM
DB1             1730                    5/26/16 12:07 PM
DB1             1726                    5/26/16 12:07 PM
DB1             426                     5/26/16 12:07 PM
DB1             1946                    5/26/16 12:07 PM

DB2             2237880                 5/26/16 12:07 PM
DB2             2420                    5/26/16 12:07 PM
DB2             2933                    5/26/16 12:07 PM
DB2             1723                    5/26/16 12:07 PM
DB2             360                     5/26/16 12:07 PM
DB2             353                     5/26/16 12:07 PM
DB2             1370                    5/26/16 12:07 PM
DB2             5433                    5/26/16 12:07 PM
DB2             400                     5/26/16 12:07 PM
DB2             436                     5/26/16 12:07 PM
DB2             856                     5/26/16 12:07 PM

DB3             2255540                 5/26/16 12:07 PM
DB3             2513                    5/26/16 12:07 PM
DB3             390                     5/26/16 12:07 PM
DB3             360                     5/26/16 12:07 PM
DB3             470                     5/26/16 12:07 PM
DB3             4830                    5/26/16 12:07 PM
DB3             1046                    5/26/16 12:07 PM
DB3             2753                    5/26/16 12:06 PM
DB3             373                     5/26/16 12:06 PM
DB3             933                     5/26/16 12:06 PM
DB3             813                     5/26/16 12:06 PM

DB4             2272020                 5/26/16 12:06 PM
DB4             2290                    5/26/16 12:06 PM
DB4             1936                    5/26/16 12:06 PM
DB4             353                     5/26/16 12:06 PM
DB4             353                     5/26/16 12:06 PM
DB4             360                     5/26/16 12:06 PM
DB4             393                     5/26/16 12:06 PM
DB4             4000                    5/26/16 12:06 PM
DB4             853                     5/26/16 12:06 PM
DB4             2133                    5/26/16 12:06 PM
DB4             346                     5/26/16 12:06 PM

That looks to me like the databases are restoring just fine and the slowdown is in writing this information to msdb. This combined with the fact that sp_WhoIsActive showed a lot of slowish-looking:

<?query --
(@param0 nvarchar(20), @param1 nvarchar(46), @param2 nvarchar(48), @param3 nvarchar(48), @param4 nvarchar(48), @param5 nvarchar(48), @param6 nvarchar(48), @param7 nvarchar(48), @param8 nvarchar(48), @param9 nvarchar(42), @param10 nvarchar(77), @param11 nvarchar(24), @param12 nvarchar(9), @param13 nvarchar(16), @param14 nvarchar(10), @param15 nvarchar(28), @param16 nvarchar(7), @param17 nvarchar(7), @param18 nvarchar(9), @param19 nvarchar(3), @param20 nvarchar(24), @param21 nvarchar(13), @param22 nvarchar(3), @param23 nvarchar(27), @param24 nvarchar(9), @param25 nvarchar(24), @param26 nvarchar(3), @param27 nvarchar(27))
declare @backup_set_id int
declare @restore_history_id int
select @backup_set_id = backup_set_id from msdb.dbo.backupset where backup_set_uuid = N'{4A3BE7C3-AF68-40D8-9261-35C781B6642C}'
if @backup_set_id is null begin
declare @media_set_id int
declare @media_count int
select @media_set_id = media_set_id from msdb.dbo.backupmediaset where media_uuid = N'{D603F5E0-6150-476A-A5B1-E7D2840AB05C}'
(etc., etc.)

made me think that yeah, msdb is my problem.

It only had a week's worth of history in it as of this morning, but there are over 800 databases being restored every 15 minutes, so the MDF was still 5 GB. I disabled the jobs and reduced that number to 3 days and added some indexes. The job is now taking 4 or 5 minutes.

I'm still not sure why a system that's been running for over two years, happily, with four weeks of history now only runs properly with three days, but I suspect that my storage team is wrong and my storage is less than optimal. I've set them on evaluating that.

In the meantime, if one of the servers this instance is protecting bluescreens I won't be two and a half hours out of date!

The hosting provider now says that C: is fragmented. I've moved msdb to faster storage anyway, since it's the hardest working database on the system.