100% completion in 8 minutes, recovery takes 2 hours

Brian K

SQL Virtual Restore 5.2.1.7

I have a 20gb database backup in Redgate SQL Backup 6.5 format, non-encrypted, single-stream, compression level 3, SQL 2005 server.

I'm trying to restore the database onto what SHOULD be a blindingly fast 64-bit SQL 2008 server.

I've enabled stats reporting to message window, and it reaches 100% in about 8 minutes, but recovery took around two hours.

I enabled the verbose restore logging traceflag and most of the time seems to be spent on "Restore-Redo begins on database Attendance_Virtual".

Any ideas what's going on?

Matthew Flatt

Hi Brian,

It sounds like it's the upgrade process which is taking the time. As the backup source is SQL Server 2005 and the destination is SQL 2008, SQL Server will upgrade the database before it can be recovered. The output of the RESTORE DATABASE [dbname] WITH RECOVERY should include lots of upgrade steps, is this the case?

Thanks,

Brian K

Matthew Flatt wrote:

Hi Brian,

It sounds like it's the upgrade process which is taking the time. As the backup source is SQL Server 2005 and the destination is SQL 2008, SQL Server will upgrade the database before it can be recovered. The output of the RESTORE DATABASE [dbname] WITH RECOVERY should include lots of upgrade steps, is this the case?

Thanks,

A straight restore with SQL Backup takes around 10 minutes, and the Virtual Restore task was with no recovery.

Another database full restore of a DB about 3/4 the size took only 7.5 minutes for restore and recovery.

Matthew Flatt

Hi Brian,

I'm a little confused, in your original post you stated that the recovery took 2 hours. If the restore was to NORECOVERY, what recovery process is it that took 2 hours?

Thanks,

Brian K

Matthew Flatt wrote:

Hi Brian,

I'm a little confused, in your original post you stated that the recovery took 2 hours. If the restore was to NORECOVERY, what recovery process is it that took 2 hours?

Thanks,

I'm sorry, that was a mistake on my part. It was 2 hours before the TSQL restore command completed with no recovery and the database was finally ready for a differential restore.

Does that make sense?

Brian K

I started a new restore a few minutes ago, this time WITH RECOVERY:

-- Script generated by Red Gate SQL Virtual Restore v2.3.0.96
-- Multi-threaded SQL Backup backups are handled by repeating the DISK parameter in the RESTORE command, once for each thread used during the backup process.
RESTORE DATABASE [attendance_Virtual] FROM
DISK=N'E:\TempForRefresh\FULL_attendance.sqb'
WITH MOVE N'attendance' TO N'F:\DATA\attendance_attendance_Virtual.vmdf',
MOVE N'attendance_log' TO N'F:\DATA\attendance_log_attendance_Virtual.vldf',
NORECOVERY, STATS=1, REPLACE
GO
RESTORE DATABASE [attendance_Virtual] WITH RECOVERY
GO

The SQL log so far:

Date,Source,Severity,Message
07/20/2011 10:43:38,spid86,Unknown,Restore-Redo begins on database attendance_Virtual
07/20/2011 10:43:38,spid86,Unknown,The database 'attendance_Virtual' is marked RESTORING and is in a state that does not allow recovery to be run.
07/20/2011 10:43:30,spid86,Unknown,Starting up database 'attendance_Virtual'.
07/20/2011 10:43:26,spid86,Unknown,Restore: Backup set restored
07/20/2011 10:43:26,spid86,Unknown,Restore: Data transfer complete on attendance_Virtual
07/20/2011 10:43:26,spid86,Unknown,FileHandleCache: 0 files opened. CacheSize: 12
07/20/2011 10:42:10,spid86,Unknown,Restore: LogZero complete
07/20/2011 10:42:10,spid86,Unknown,Zeroing completed on F:\DATA\attendance_log_attendance_Virtual.vldf
07/20/2011 10:42:00,spid86,Unknown,Restore: Waiting for log zero on attendance_Virtual
07/20/2011 10:30:23,spid86,Unknown,Restore: Transferring data to attendance_Virtual
07/20/2011 10:30:23,spid86,Unknown,Restore: Restoring backup set
07/20/2011 10:30:23,spid86,Unknown,Restore: Containers are ready
07/20/2011 10:30:23,spid86,Unknown,Zeroing F:\DATA\attendance_log_attendance_Virtual.vldf from page 1 to 1310912 (0x2000 to 0x280180000)
07/20/2011 10:30:23,spid86,Unknown,Restore: PreparingContainers
07/20/2011 10:30:23,spid86,Unknown,Restore: Attached database attendance_Virtual as DBID=43
07/20/2011 10:30:23,spid86,Unknown,Restore: BeginRestore (offline) on attendance_Virtual
07/20/2011 10:30:23,spid86,Unknown,Restore: Planning complete
07/20/2011 10:30:22,spid86,Unknown,Restore: Planning begins
07/20/2011 10:30:22,spid86,Unknown,Restore: Backup set is open
07/20/2011 10:30:22,spid86,Unknown,Restore: Configuration section loaded
07/20/2011 10:30:22,spid86,Unknown,Opening backup set
07/20/2011 10:30:22,spid86,Unknown,RestoreDatabase: Database attendance_Virtual
07/20/2011 10:30:16,spid63,Unknown,DBCC TRACEON 3605<c/> server process ID (SPID) 63. This is an informational message only; no user action is required.

The top step, restore/redo, takes around a minute when restoring from native SQL Backup file for the same database. Historically, this step should take at least an hour to run with Virtual Restore, I'll update when it does finally complete.

Matthew Flatt

Brian,

Out of interest, how big are the vmdf and vldf files at the moment? Can you also tell me if they are growing during this part of the restore?

Thanks,

Brian K

Matthew Flatt wrote:

Brian,

Out of interest, how big are the vmdf and vldf files at the moment? Can you also tell me if they are growing during this part of the restore?

Thanks,

vmdf 603mb and growing quickly
vldf 809mb and no observed change in size.

Still at same "redo" step.

Matthew Flatt

How is the HyperBacSrv CPU/memory usage and also the SQL Server CPU/memory usage?

If you open the HyperBac Configuration Manager and choose Advanced, what is the value for Index Path?

Could you also give me a few details on the spec of the SQL 2008 box?

Thanks,

Brian K

Matthew Flatt wrote:

How is the HyperBacSrv CPU/memory usage and also the SQL Server CPU/memory usage?

If you open the HyperBac Configuration Manager and choose Advanced, what is the value for Index Path?

Could you also give me a few details on the spec of the SQL 2008 box?

Thanks,

Overall CPU usage is 30%, sql/hyperbac both around 10% on average.

Hyperbac memory usage 600mb, sql 15gb +-.

Index path: C:\Program Files (x86)\Red Gate\HyperBac\indexes

Virtualized (Vsphere 4.1) SQL Server 2008 R2 64-bit, WIndows 2008 datacenter 64-bit, 32gb memory, 16gb allocated to SQL instance.

Running on Dell R900 vsphere host, connected to CX-240 SAN.

1.3tb data drive, 250mb log drive, miscellaneous other drives.

4 CPUs.

Brian K

We are having success with other databases on this box, and seeing small improvements in refresh times over standard SQL Backup 6.5 restores.

I wonder if we're just grabbing this database backup int he middle of some maintenance task or bulk import and a gigantic transaction is being rolled forwards.

Matthew Flatt

It definitely seems that something major was going on when the backup was taken.

Basically all the roll forward is getting pumped into those virtual files and being indexed at the same time which is both affecting your performance and giving you large virtual files.

Even so it does seem particularly slow, are there any logs other than Service.log in the HyperBac logs directory?

Thanks,

Brian K

There are two fiels with strange names dating back to July 8th:

1a100000000003D and C000000000219D

I may have the wrong number of "0"s, but you get the general idea.

The attendance vmdf is now 2.5 gb, the compressed sql backup file itself is only 4.2gb...

Brian K

Brian K wrote:

Matthew Flatt wrote:

Brian,

Out of interest, how big are the vmdf and vldf files at the moment? Can you also tell me if they are growing during this part of the restore?

Thanks,

vmdf 603mb and growing quickly
vldf 809mb and no observed change in size.

Still at same "redo" step.

The restore completed at 2 hours 1 minute. Restore-Redo began at 10:43, rollforward completed at 12:27, database was available 12:32. SQL 2005 to 2008 upgrade scripts ran from 12:27 to 12:32 approximately.

The vmdf ended up being 3.9gb.

Matthew Flatt

Hi Brian,

Those log files are definitely too old to worry about then.

It does sound like the backup may have been taken at an inconvenient time, would you be able to try another backup for that database and compare results?

Thanks,

Brian K

Matthew Flatt wrote:

Hi Brian,

Those log files are definitely too old to worry about then.

It does sound like the backup may have been taken at an inconvenient time, would you be able to try another backup for that database and compare results?

Thanks,

We have seen this with two different backups, both scheduled at 1am on Saturday. I'll check out maintenance plans and other jobs and see what's going on then.

james1248

Hi,

I'm seeing the same thing. Virtual Restore takes much longer than normal restores. The log files are also very large, growing by a few lines every millisecond!! - so I think that is why it's slow for me. Haven't been able to fix it yet. But make sure your log files aren't as busy as mine.

Cheers.
James

Brian K

We have done some more exhaustive testing.

About a third of our database backups we're restoring onto a reporting server have this same problem.

The backups typically take four to eight times longer than a normal SQB restore.

I really can't find a common cause for this issue, redo/recovery takes less than a minute with Redgate SQL Backup, and two hours + with Virtual Restore.