Backup timeouts

mrclodmrclod Posts: 60
edited February 11, 2009 3:10AM in SQL Backup Previous Versions
I am having some issues with backups getting the 1010 and 3201 errors on a couple of my servers, but cannot seem to get them to go away.

The second or third backup attempts appear so far to always be successful.

Not sure where I need to continue to resolve this appropriately.

Thanks

Jon



Here is an example of error email sent to me:

SQL Backup log file 5.3.0.178

-SQL "BACKUP LOG [myDB] TO DISK = 'L:\BACKUPS\<database>\<AUTO>.sqb' WITH COMPRESSION = 3, COPYTO = '\\mybackuplocation\<database>\', ERASEFILES_ATSTART = 7, KEYSIZE = 256, PASSWORD = 'XXXXXXXXXXXX', MAILTO_ONERROR = 'IT@myCompany.com;DBAs@myCompany.com', THREADCOUNT = 3, VERIFY "
ERRORS AND WARNINGS


1/31/2009 4:00:00 AM: Backing up myDB (transaction log) to:
1/31/2009 4:00:00 AM: L:\BACKUPS\myDB\LOG_myDB_20090131_040000.sqb

1/31/2009 4:00:00 AM: Deleting old backup file: L:\BACKUPS\myDB\LOG_myDB_20090123_200000.sqb
1/31/2009 4:00:00 AM: BACKUP LOG [myDB] TO VIRTUAL_DEVICE = 'SQLBACKUP_B4F01510-91D5-4006-90E0-8CDAD6575962', VIRTUAL_DEVICE = 'SQLBACKUP_B4F01510-91D5-4006-90E0-8CDAD657596201', VIRTUAL_DEVICE = 'SQLBACKUP_B4F01510-91D5-4006-90E0-8CDAD657596202' WITH BUFFERCOUNT = 18, BLOCKSIZE = 65536, MAXTRANSFERSIZE = 1048576, NAME = N'Database (myDB), 1/31/2009 4:00:00 AM', DESCRIPTION = N'Backup on 1/31/2009 4:00:00 AM Server: D3DB1 Database: myDB'

1/31/2009 4:00:30 AM: VDI error 1010: Failed to get the configuration from the server because the timeout interval has elapsed. Check that the SQL Server instance is running and that you have the SQL Server System Administrator server role; or try increasing the value of the VDITimeout registry setting in HKEY_LOCAL_MACHINE\SOFTWARE\Red Gate\SQL Backup\BackupSettingsGlobal\[InstanceName]
1/31/2009 4:01:00 AM: SQL error 3013: BACKUP LOG is terminating abnormally.
1/31/2009 4:01:00 AM: SQL error 3201: Cannot open backup device 'SQLBACKUP_B4F01510-91D5-4006-90E0-8CDAD6575962'. Operating system error 0x80070002(The system cannot find the file specified.).
1/31/2009 4:01:00 AM:
1/31/2009 4:01:00 AM: Memory profile
1/31/2009 4:01:00 AM: Type Maximum Minimum Average Blk count Total
1/31/2009 4:01:00 AM:
1/31/2009 4:01:00 AM: Commit 66093056 4096 1223759 2402 2939469824
1/31/2009 4:01:00 AM: Reserve 8253440 4096 227470 634 144216064
1/31/2009 4:01:00 AM: Free 93847552 4096 509163 270 137474048
1/31/2009 4:01:00 AM: Private 66093056 4096 1261417 2343 2955501568
1/31/2009 4:01:00 AM: Mapped 1060864 4096 98304 81 7962624
1/31/2009 4:01:00 AM: Image 24862720 4096 196440 612 120221696
1/31/2009 4:01:00 AM:
1/31/2009 4:01:11 AM:
1/31/2009 4:01:11 AM: Verifying files:
1/31/2009 4:01:11 AM: L:\BACKUPS\myDB\LOG_myDB_20090131_040000.sqb
1/31/2009 4:01:11 AM:
The backup set on file 1 is valid.
1/31/2009 4:01:18 AM: Copied L:\BACKUPS\myDB\LOG_myDB_20090131_040000.sqb to \\mybackuplocation\myDB\LOG_myDB_20090131_040000.sqb.


PROCESSES COMPLETED SUCCESSFULLY

1/31/2009 4:01:00 AM: Warning 300: Backup failed. Retry attempt: 1
1/31/2009 4:01:02 AM: Deleting old backup file: L:\BACKUPS\myDB\LOG_myDB_20090124_040000.sqb
1/31/2009 4:01:02 AM: BACKUP LOG [myDB] TO VIRTUAL_DEVICE = 'SQLBACKUP_9C5BDFD8-21B4-42A7-B01F-9903AEBC08CA', VIRTUAL_DEVICE = 'SQLBACKUP_9C5BDFD8-21B4-42A7-B01F-9903AEBC08CA01', VIRTUAL_DEVICE = 'SQLBACKUP_9C5BDFD8-21B4-42A7-B01F-9903AEBC08CA02' WITH BUFFERCOUNT = 18, BLOCKSIZE = 65536, MAXTRANSFERSIZE = 524288, NAME = N'Database (myDB), 1/31/2009 4:00:00 AM', DESCRIPTION = N'Backup on 1/31/2009 4:00:00 AM Server: D3DB1 Database: myDB'

1/31/2009 4:01:11 AM: Backup data size : 417.438 MB
1/31/2009 4:01:11 AM: Compressed data size: 78.572 MB
1/31/2009 4:01:11 AM: Compression rate : 81.18%

Processed 52883 pages for database 'myDB', file 'myDB_Log' on file 1.
BACKUP LOG successfully processed 52883 pages in 7.855 seconds (55.151 MB/sec).
· Share on Twitter

Comments

  • peteypetey Posts: 2,358 New member
    Are there any other processes running on the database that may be blocking the backup at 4:00:00 AM e.g. another backup, a reindexing process, or a database shrinking operation?

    Thanks.
    Peter Yeoh
    SQL Backup Consultant Developer
    Associate, Yohz Software
    Beyond compression - SQL Backup goodies under the hood, updated for version 8
    · Share on Twitter
  • mrclodmrclod Posts: 60
    No other backup jobs. No shrinking jobs. No reindexing jobs. No other jobs period running at the backup time.

    The backup jobs run throughout the day to ensure point-in-time recovery. Seeing this intermittently for Full, Diff and especially Log backups.
    · Share on Twitter
  • peteypetey Posts: 2,358 New member
    Seeing this intermittently for Full, Diff and especially Log backups.
    Has the failure to back up on the first attempt happenned consistently, perhaps at a specific time of day, or day of the week? Or do you know if perhaps the server was CPU-bound at the time of the failure?

    What's happening is that SQL Backup sends a backup request to SQL Server (4:00:00 AM), and by default, waits 30 seconds for SQL Server to start servicing the request. At the end of the 30 seconds (4:00:30 AM), it stops waiting on SQL Server to start the backup. In your case, SQL Server only responded 1 minute after the initial request (4:01:00 AM).[/quote]
    Peter Yeoh
    SQL Backup Consultant Developer
    Associate, Yohz Software
    Beyond compression - SQL Backup goodies under the hood, updated for version 8
    · Share on Twitter
  • mrclodmrclod Posts: 60
    We take a log backup every 4 hours, except at midnight when either a full or diff are taken.

    This appears to happen at odd intervals through out the day and then can be silent for a day or two until the next event. Sometime multiple events in a day, sometimes only one.

    Can happen during more intensive cpu times as well as slow points.

    The only consistency I have seen would be the servers that have this showing up.
    · Share on Twitter
  • peteypetey Posts: 2,358 New member
    Thanks for providing the details.

    Something is definitely blocking the first backup attempt, either from within SQL Server (e.g. a blocking process), or from the hardware (e.g. CPU-intensive processes). The subsequent backup attempts are succeeding. If you can reproduce this error consistently, and find that the error is not due to either of the above reasons, I'll be happy to assist you in investigating the matter further.

    If you are concerned about the warnings, there is a registry setting you can add, to increase the timeout from the default of 30 seconds. This won't actually solve the issue of what's blocking the backup process, but just allows the backup attempts to wait longer for SQL Server to respond.

    You would need to create a registry value named VDITimeout (DWORD type), in the registry node HKLM\Software\Red Gate\SQL Backup\BackupSettingsGlobal\<instance name>. For the default instance, the instance name is (LOCAL).
    Peter Yeoh
    SQL Backup Consultant Developer
    Associate, Yohz Software
    Beyond compression - SQL Backup goodies under the hood, updated for version 8
    · Share on Twitter
  • mrclodmrclod Posts: 60
    I found something the other day that may be a factor, but not sure.

    It had stated something about the length of time to perform a checkpoint. One suggestion had been the size of the empty portion of a log file, however, this issue is not occurring on systems that have much larger log files.

    The systems in question are very read/write intensive.

    Could this potentially be my issue?
    · Share on Twitter
  • peteypetey Posts: 2,358 New member
    Was the checkpoint error recorded by SQL Backup, or SQL Server? Could you please post the entire error message?

    Thanks.
    Peter Yeoh
    SQL Backup Consultant Developer
    Associate, Yohz Software
    Beyond compression - SQL Backup goodies under the hood, updated for version 8
    · Share on Twitter
  • mrclodmrclod Posts: 60
    No checkpoint error, just saw that in another post as a possibility.

    I upped the requested registry setting to 60, but still happening about the same frequency.

    Any other ideas to check?
    · Share on Twitter
  • peteypetey Posts: 2,358 New member
    You could try setting up a SQL Agent job, that runs 30 seconds after the backup starts, to log any blocked backups e.g. 
    IF NOT EXISTS &#40;SELECT 1 FROM tempdb..sysobjects WHERE name = '##blockedbackups'&#41;
BEGIN
	SELECT GETDATE&#40;&#41; snapshotdate, a.spid blockedspid, b.spid blockingspid, b.last_batch blockinglast_batch,
	b.hostname blockinghostname, b.program_name blockingprogram_name, b.cmd blockingcmd, b.loginame blockingloginame
        INTO ##blockedbackups 
	FROM master..sysprocesses a
	INNER JOIN master..sysprocesses b ON a.blocked = b.spid
	WHERE a.blocked &lt;&gt; 0
 	  AND a.cmd = 'BACKUP LOG'
END
ELSE BEGIN
	INSERT INTO ##blockedbackups
	SELECT GETDATE&#40;&#41; snapshotdate, a.spid blockedspid, b.spid blockingspid, b.last_batch blockinglast_batch,
	b.hostname blockinghostname, b.program_name blockingprogram_name, b.cmd blockingcmd, b.loginame blockingloginame
	FROM master..sysprocesses a
	INNER JOIN master..sysprocesses b ON a.blocked = b.spid
	WHERE a.blocked &lt;&gt; 0
 	  AND a.cmd = 'BACKUP LOG'
END
    and check this log when you next encounter the error.
    Peter Yeoh
    SQL Backup Consultant Developer
    Associate, Yohz Software
    Beyond compression - SQL Backup goodies under the hood, updated for version 8
    · Share on Twitter
Sign In or Register to comment.