Error on Production server - VDITimeout

meklembl · November 27, 2012 7:02AM

For years, I've been backing up our Production server to replace the databases on a reporting server. Now, intermittently, when I go to restore I've been getting this error. This morning, I cannot resolve the issue.

SQL Backup v7.2.0.78

Restoring IntelliCorpProd (database) from:
F:\Backups\Hercules\IntelliCorpProd_2.sqb
F:\Backups\Hercules\IntelliCorpProd_1.sqb

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, that you have the SQL Server System Administrator server role; and that no other processes are
blocking the backup or restore process; or try increasing the value of the VDITimeout registry setting in HKEY_LOCAL_MACHINE\SOFTWARE\Red Gate\SQL Backup\BackupSettingsGlobal\[InstanceName]
Also check that the database is not currently in use.

petey · November 28, 2012 3:44AM

Could you please post the contents of the SQL Backup log file for the failed restore? The default folder where the logs are stored is C:\Documents and Settings\All Users\Application Data\Red Gate\SQL Backup\Log\<instance name> on Windows 2003 and older, and C:\ProgramData\Red Gate\SQL Backup\Log\<instance name> on Windows Vista and newer.

meklembl · November 28, 2012 8:30AM

SQL Backup log file 7.2.0.78

-SQL "RESTORE DATABASE [IntelliCorpProd]
FROM DISK = 'F:\Backups\Hercules\IntelliCorpProd_2.sqb',
DISK = 'F:\Backups\Hercules\IntelliCorpProd_1.sqb'
WITH RECOVERY, DISCONNECT_EXISTING, REPLACE "

ERRORS AND WARNINGS

11/27/2012 3:21:28 AM: Restoring IntelliCorpProd (database) from:
11/27/2012 3:21:28 AM: F:\Backups\Hercules\IntelliCorpProd_2.sqb
11/27/2012 3:21:28 AM: F:\Backups\Hercules\IntelliCorpProd_1.sqb

11/27/2012 3:21:36 AM: ALTER DATABASE [IntelliCorpProd] SET ONLINE RESTORE DATABASE [IntelliCorpProd] FROM VIRTUAL_DEVICE = 'SQLBACKUP_4F620AF8-8842-4E79-A139-110D5755890C', VIRTUAL_DEVICE = 'SQLBACKUP_4F620AF8-8842-4E79-A139-110D5755890C01' WITH BUFFERCOUNT = 12, BLOCKSIZE = 65536, MAXTRANSFERSIZE = 1048576 , RECOVERY, REPLACE

11/27/2012 3:22:06 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, that you have the SQL Server System Administrator server role; and that no other processes are blocking the backup or restore process; or try increasing the value of the VDITimeout registry setting in HKEY_LOCAL_MACHINE\SOFTWARE\Red Gate\SQL Backup\BackupSettingsGlobal\[InstanceName]
11/27/2012 3:22:06 AM: Also check that the database is not currently in use.
11/27/2012 3:22:06 AM:
11/27/2012 3:22:07 AM: SPID Status Login HostName BlkBy DBName Command CPUTime DiskIO LastBatch ProgramName SPID_1 REQUESTID
11/27/2012 3:22:07 AM:

11/27/2012 3:22:07 AM: 1 BACKGROUND sa . . RESOURCE MONITOR 1281 0 11/24 05:11:16 1 0
11/27/2012 3:22:07 AM: 2 BACKGROUND sa . . LAZY WRITER 21578 0 11/24 05:11:16 2 0
11/27/2012 3:22:07 AM: 3 SUSPENDED sa . . LOG WRITER 1078 0 11/24 05:11:16 3 0
11/27/2012 3:22:07 AM: 4 BACKGROUND sa . . LOCK MONITOR 203 0 11/24 05:11:16 4 0
11/27/2012 3:22:07 AM: 5 BACKGROUND sa . . master SIGNAL HANDLER 0 0 11/24 05:11:16 5 0
11/27/2012 3:22:07 AM: 6 sleeping sa . . master TASK MANAGER 0 0 11/24 05:11:16 6 0
11/27/2012 3:22:07 AM: 7 BACKGROUND sa . . master TRACE QUEUE TASK 93 0 11/24 05:11:16 7 0
11/27/2012 3:22:07 AM: 8 sleeping sa . . UNKNOWN TOKEN 0 0 11/24 05:11:16 8 0
11/27/2012 3:22:07 AM: 9 BACKGROUND sa . . master BRKR TASK 0 0 11/24 05:11:16 9 0
11/27/2012 3:22:07 AM: 10 BACKGROUND sa . . master CHECKPOINT 3937 1180 11/24 05:11:16 10 0
11/27/2012 3:22:07 AM: 11 BACKGROUND sa . . master TASK MANAGER 15 0 11/24 05:11:16 11 0
11/27/2012 3:22:07 AM: 12 BACKGROUND sa . . master BRKR EVENT HNDLR 15 69 11/24 05:11:16 12 0
11/27/2012 3:22:07 AM: 13 BACKGROUND sa . . master BRKR TASK 0 0 11/24 05:11:16 13 0
11/27/2012 3:22:07 AM: 14 sleeping sa . . master TASK MANAGER 0 0 11/24 05:11:16 14 0
11/27/2012 3:22:07 AM: 15 sleeping sa . . master TASK MANAGER 0 0 11/24 05:11:16 15 0
11/27/2012 3:22:07 AM: 16 sleeping sa . . master TASK MANAGER 0 0 11/24 05:11:16 16 0
11/27/2012 3:22:07 AM: 17 sleeping sa . . master TASK MANAGER 0 0 11/24 05:11:16 17 0
11/27/2012 3:22:07 AM: 19 sleeping sa . . master TASK MANAGER 0 0 11/24 05:11:16 19 0
11/27/2012 3:22:07 AM: 20 sleeping sa . . master TASK MANAGER 0 13 11/24 05:11:16 20 0
11/27/2012 3:22:07 AM: 51 sleeping INTELLINET\SQLAdmin SQLRPTG . msdb AWAITING COMMAND 329 210 11/27 03:10:02 SQLAgent - Job invocation engine 51 0
11/27/2012 3:22:07 AM: 54 RUNNABLE INTELLINET\SQLAdmin SQLRPTG . master EXECUTE 0 0 11/27 03:21:27 SQLAgent - TSQL JobStep (Job 0x38FA9AE3FCF79148B6ABF0CAEBE3AED9 : Step 6) 54 0
11/27/2012 3:22:07 AM: 55 sleeping INTELLINET\SQLAdmin SQLRPTG . ReportServer AWAITING COMMAND 0 0 11/27 03:21:13 Report Server 55 0
11/27/2012 3:22:07 AM: 56 sleeping searcher3 I51339DIOA . ReportingStoredProcedures_DEV AWAITING COMMAND 0 0 11/26 13:31:43 Microsoft SQL Server Management Studio - Query 56 0
11/27/2012 3:22:07 AM: 57 sleeping INTELLINET\SQLAdmin SQLRPTG . msdb AWAITING COMMAND 156 172 11/25 06:43:10 SQLAgent - Generic Refresher 57 0
11/27/2012 3:22:07 AM: 58 RUNNABLE INTELLINET\SQLAdmin SQLRPTG . master SELECT INTO 468 76 11/27 03:21:29 SQBCoreService.exe 58 0
11/27/2012 3:22:07 AM: 59 sleeping searcher3 I51339DIOA . ReportingStoredProcedures_DEV AWAITING COMMAND 65203 465510 11/26 13:20:16 Microsoft SQL Server Management Studio - Query 59 0
11/27/2012 3:22:07 AM: 60 sleeping INTELLINET\SQLAdmin SQLRPTG . ReportServer AWAITING COMMAND 0 0 11/27 03:21:13 Report Server 60 0
11/27/2012 3:22:07 AM: 62 SUSPENDED INTELLINET\SQLAdmin SQLRPTG . master ALTER DATABASE 93 10 11/27 03:21:36 SQBCoreService.exe 62 0
11/27/2012 3:22:07 AM: 64 sleeping INTELLINET\SQLAdmin SQLRPTG . ReportServer AWAITING COMMAND 0 0 11/27 03:22:02 Report Server 64 0
11/27/2012 3:22:07 AM: 66 sleeping NT AUTHORITY\NETWORK SERVICE SQLRPTG . ReportServer AWAITING COMMAND 0 0 11/27 03:21:40 Report Server 66 0
11/27/2012 3:22:07 AM:
11/27/2012 3:22:17 AM: SQL error 3013: RESTORE DATABASE is terminating abnormally.
11/27/2012 3:22:17 AM: SQL error 3201: Cannot open backup device 'SQLBACKUP_4F620AF8-8842-4E79-A139-110D5755890C'. Operating system error 0x80070002(The system cannot find the file specified.).
11/27/2012 3:22:17 AM:
11/27/2012 3:22:18 AM: Memory profile
11/27/2012 3:22:18 AM: Type Maximum Minimum Average Blk count Total
11/27/2012 3:22:18 AM:

11/27/2012 3:22:18 AM: Commit 991379456 4096 289601 24643 7136641024
11/27/2012 3:22:18 AM: Reserve 872349696 8192 76883 23633 1816993792
11/27/2012 3:22:18 AM: Free 8780933365760 4096 45766350634 192 8787139321856
11/27/2012 3:22:18 AM: Private 991379456 4096 185227 47616 8819769344
11/27/2012 3:22:18 AM: Mapped 4194304 4096 434817 83 36089856
11/27/2012 3:22:18 AM: Image 33189888 4096 169455 577 97775616
11/27/2012 3:22:18 AM:

petey · November 28, 2012 8:34PM

It looks like the restore process was blocked by SQL Server's checkpoint process, which completed about 11 seconds after SQL Backup's default timeout of 30 seconds.

You could try increasing SQL Backup's timeout value to 60 seconds, by adding/modifying the VDITimeout value in the registry (HKEY_LOCAL_MACHINE\SOFTWARE\Red Gate\SQL Backup\BackupSettingsGlobal\[InstanceName]). The VDITimeout value is a DWORD type.

meklembl · November 29, 2012 10:16AM

First, I would enter into the registry under HKEY_LOCAL_MACHINE\SOFTWARE\Red Gate\SQL Backup\BackupSettingsGlobal\(LOCAL) a new entry for a 32-bit DWORD named VDITimeout with a Decimal value of 60.

Secondly, how could you tell that the checkpoint process completed about 11 seconds after SQL Backup's default timeout of 30 seconds?

petey · November 29, 2012 8:09PM

Secondly, how could you tell that the checkpoint process completed about 11 seconds after SQL Backup's default timeout of 30 seconds?

When you start a backup/restore in SQL Backup, SQL Backup sends a initialization request to SQL Server. It then waits 30 seconds for SQL Server to respond. If a response is received, SQL Backup then proceeds with the backup/restore, as SQL Server is available to provide/receive the backup data. If by 30 seconds no response is received, SQL Backup aborts the request.

Looking at your log, the restore started at 3:21:28 AM. After disconnecting all users and setting the database offline, SQL Backup then sent an initialization request to SQL Server at 3:21:36 AM. 30 seconds later, at 3:22:06 AM, SQL Backup still had not received any response from SQL Server, and aborted the restore process. At 3:22:17 AM, SQL Server wanted to send the initialization response, but could not find the SQL Backup process that sent it (because it had already aborted the process). SQL Server then raised 'SQL error 3013: RESTORE DATABASE is terminating abnormally.'.

Looking at the sp_who output generated by SQL Backup at 3:22:06 AM, you can see that the SQL Backup process (SPID 62) was blocked by SPID 10 at that moment.

Why doesn't SQL Backup wait indefinitely? That's because there can be many reasons why SQL Backup is blocking the backup/restore process, and the block might never end, causing SQL Backup to hang indefinitely.

meklembl · November 30, 2012 7:37AM

Thanks for the explanation.

ChrisAVWood · November 30, 2012 3:26PM

Pete,

You meant that SQLBackup will wait up to 30 seconds for a response to the initialization request as a lot of my backups taken less than that amount of time to run (Logs mostly) and I have a delay of 8 seconds (VERIFYINTERVAL) to make sure that the verify part does not get caught by buffer to disk cache type activity.

Chris

petey · November 30, 2012 7:12PM

Chris, I'm sorry, but I don't understand your question.

Yes, SQL Backup waits up to 30 seconds for SQL Server to respond that it can perform the requested backup/restore. Usually, SQL Server responds immediately if there are no other processes blocking the backup/restore.

With regards to the VERIFYINTERVAL option, yes, this will cause SQL Backup to wait for the specified interval before verifying the backup file(s) that it created. In addition to ensuring that the disk cache gets flushed and all, it also seems to allow time for SQL Server to clear its backup/restore caches so that more is available for the next process.

ChrisAVWood · December 5, 2012 12:34PM

Pete,

Your note had said 'It then waits 30 seconds for SQL Server to respond' when it could wait for up to a maximum of 30 seconds as this is the default for DISKRETRYINTERVAL. I am not trying to be pickey.

Chris

petey · December 5, 2012 6:42PM

My apologies for the confusion. Yes, that sentence should have been 'waits up to 30 seconds for SQL Server to respond'. Thanks for pointing that out.

Error on Production server - VDITimeout

Comments

Product Learning

Community Forums

Events & Friends

Simple Talk