100% completion in 8 minutes, recovery takes 2 hours

SQL Virtual Restore: Rapidly mount live, fully functional databases direct from backups

Moderators: eddie davis, Colin Millerchip, fionag

100% completion in 8 minutes, recovery takes 2 hours

Postby Brian K » Wed Jul 20, 2011 3:00 pm

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?
Brian K
 
Posts: 11
Joined: Wed Jul 20, 2011 2:49 pm

Postby Matthew Flatt » Wed Jul 20, 2011 3:10 pm

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,
Matthew Flatt
Test Engineer, HyperBac
Matthew Flatt
 
Posts: 253
Joined: Tue Jan 15, 2008 4:45 pm

Re:

Postby Brian K » Wed Jul 20, 2011 3:14 pm

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.
Last edited by Brian K on Wed Jul 20, 2011 3:19 pm, edited 1 time in total.
Brian K
 
Posts: 11
Joined: Wed Jul 20, 2011 2:49 pm

Postby Matthew Flatt » Wed Jul 20, 2011 3:19 pm

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,
Matthew Flatt
Test Engineer, HyperBac
Matthew Flatt
 
Posts: 253
Joined: Tue Jan 15, 2008 4:45 pm

Re:

Postby Brian K » Wed Jul 20, 2011 3:20 pm

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
 
Posts: 11
Joined: Wed Jul 20, 2011 2:49 pm

Re:

Postby Brian K » Wed Jul 20, 2011 3:56 pm

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

Code: Select all
-- 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:

Code: Select all
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.
Brian K
 
Posts: 11
Joined: Wed Jul 20, 2011 2:49 pm

Postby Matthew Flatt » Wed Jul 20, 2011 4:41 pm

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,
Matthew Flatt
Test Engineer, HyperBac
Matthew Flatt
 
Posts: 253
Joined: Tue Jan 15, 2008 4:45 pm

Re:

Postby Brian K » Wed Jul 20, 2011 4:44 pm

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.
Brian K
 
Posts: 11
Joined: Wed Jul 20, 2011 2:49 pm

Postby Matthew Flatt » Wed Jul 20, 2011 4:48 pm

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,
Matthew Flatt
Test Engineer, HyperBac
Matthew Flatt
 
Posts: 253
Joined: Tue Jan 15, 2008 4:45 pm

Re:

Postby Brian K » Wed Jul 20, 2011 4:54 pm

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
 
Posts: 11
Joined: Wed Jul 20, 2011 2:49 pm

Re:

Postby Brian K » Wed Jul 20, 2011 5:00 pm

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.
Brian K
 
Posts: 11
Joined: Wed Jul 20, 2011 2:49 pm

Postby Matthew Flatt » Wed Jul 20, 2011 5:05 pm

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,
Matthew Flatt
Test Engineer, HyperBac
Matthew Flatt
 
Posts: 253
Joined: Tue Jan 15, 2008 4:45 pm

Re:

Postby Brian K » Wed Jul 20, 2011 5:09 pm

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
 
Posts: 11
Joined: Wed Jul 20, 2011 2:49 pm

Re:

Postby Brian K » Wed Jul 20, 2011 5:58 pm

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.
Brian K
 
Posts: 11
Joined: Wed Jul 20, 2011 2:49 pm

Postby Matthew Flatt » Wed Jul 20, 2011 6:15 pm

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,
Matthew Flatt
Test Engineer, HyperBac
Matthew Flatt
 
Posts: 253
Joined: Tue Jan 15, 2008 4:45 pm

Next

Return to SQL Virtual Restore 2

Who is online

Users browsing this forum: No registered users and 2 guests