100% completion in 8 minutes, recovery takes 2 hours

Brian KBrian K Posts: 12
edited July 22, 2011 8:16AM in SQL Virtual Restore 2
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?
· Share on Twitter

Comments

  • Matthew FlattMatthew Flatt Posts: 255 Bronze 5
    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
    Redgate Foundry
    · Share on Twitter
  • Brian KBrian K Posts: 12
    edited July 20, 2011 10:19AM
    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.
    · Share on Twitter
  • Matthew FlattMatthew Flatt Posts: 255 Bronze 5
    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
    Redgate Foundry
    · Share on Twitter
  • Brian KBrian K Posts: 12
    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?
    · Share on Twitter
  • Brian KBrian K Posts: 12
    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.
    · Share on Twitter
  • Matthew FlattMatthew Flatt Posts: 255 Bronze 5
    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
    Redgate Foundry
    · Share on Twitter
  • Brian KBrian K Posts: 12
    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.
    · Share on Twitter
  • Matthew FlattMatthew Flatt Posts: 255 Bronze 5
    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
    Redgate Foundry
    · Share on Twitter
  • Brian KBrian K Posts: 12
    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.
    · Share on Twitter
  • Brian KBrian K Posts: 12
    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.
    · Share on Twitter
  • Matthew FlattMatthew Flatt Posts: 255 Bronze 5
    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
    Redgate Foundry
    · Share on Twitter
  • Brian KBrian K Posts: 12
    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...
    · Share on Twitter
  • Brian KBrian K Posts: 12
    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.
    · Share on Twitter
  • Matthew FlattMatthew Flatt Posts: 255 Bronze 5
    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
    Redgate Foundry
    · Share on Twitter
  • Brian KBrian K Posts: 12
    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.
    · Share on Twitter
  • james1248james1248 Posts: 3
    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
    · Share on Twitter
  • Brian KBrian K Posts: 12
    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.
    · Share on Twitter
Sign In or Register to comment.