The Senior Escalation Engineers do various training and mentoring activities.  As I do this I thought I would try to propagate some of this information on the blog.

A customer asked: "Why does it take me 7 hours to backup my database but 21 hours to restore?"

The answer could be many things.   For example, if you have a 1TB database with only 100GB of data the backup would only have to take 100GB but the restore has to build the 1TB database could take longer. Another scenario would be if you are not using instant file initialization, zeroing of the files results in many more writes.

The following is the error log output for a restore.   This is generally enough to determine what phase of backup/restore is taking the time.

2008-01-23 08:38:40.42 spid52      Starting up database 'dbPerf_MAIN'.

2008-01-23 08:38:40.52 spid52      The database 'dbPerf_MAIN' is marked RESTORING and is in a state that does not allow recovery to be run.

2008-01-23 08:38:43.71 spid52      Starting up database 'dbPerf_MAIN'.

2008-01-23 08:38:46.82 Backup      Restore is complete on database 'dbPerf_MAIN'.  The database is now available.

2008-01-23 08:38:46.82 Backup      Database was restored: Database: dbPerf_MAIN, creation date(time): 2008/01/16(14:04:58), first LSN: 647:4889:66, last LSN: 647:4918:1, number of dump devices: 1, device information: (FILE=1, TYPE=DISK: {'c:\temp\dbperf_main.bak'}). Informational message. No user action required.

As mentioned (https://forums.microsoft.com/MSDN/ShowPost.aspx?PostID=930079&SiteID=1) SQL Server does have a trace flag that provides more details about a backup or restore activity.  

WARNING: This trace flags should be used under the guidance of Microsoft SQL Server support.  They are used in this post for discussion purposes only and may not be supported in future versions.

The following is SQL Server error log output using trace flag 3004 to collect extended information.   Trace flag 3605 is also required to force the output into the error log.

I highlighted the normal messages to help show the phase breakdowns better.   Looking at the detailed messages you can see what is doing on.   For example halting the full text crawls happens before you see the starting up database message.  Using the timings and the associated message here you can take a standard restore sequence and determine the areas of performance to focus on.

dbcc traceon(3004, 3605, -1)

restore database dbPerf_MAIN from disk = 'c:\perf.bak' with replace, stats=1 

2008-01-23 08:59:56.26 spid52      RestoreDatabase: Database dbPerf_MAIN

2008-01-23 08:59:56.26 spid52      Opening backup set

2008-01-23 08:59:56.31 spid52      Restore: Configuration section loaded

2008-01-23 08:59:56.31 spid52      Restore: Backup set is open

2008-01-23 08:59:56.31 spid52      Restore: Planning begins

2008-01-23 08:59:56.32 spid52      Halting FullText crawls on database dbPerf_MAIN

2008-01-23 08:59:56.32 spid52      Dismounting FullText catalogs

2008-01-23 08:59:56.32 spid52      X-locking database: dbPerf_MAIN

2008-01-23 08:59:56.32 spid52      Restore: Planning complete

2008-01-23 08:59:56.32 spid52      Restore: BeginRestore (offline) on dbPerf_MAIN

2008-01-23 08:59:56.40 spid52      Restore: PreparingContainers

2008-01-23 08:59:56.43 spid52      Restore: Containers are ready

2008-01-23 08:59:56.43 spid52      Zeroing C:\Program Files\Microsoft SQL Server\MSSQL10.SQL2008\MSSQL\DATA\dbPerf_MAIN_log.LDF from page 1 to 17312 (0x2000 to 0x8740000)

2008-01-23 08:59:56.43 spid52      Restore: Restoring backup set

2008-01-23 08:59:56.43 spid52      Restore: Transferring data to dbPerf_MAIN

2008-01-23 08:59:58.55 spid52      Restore: Waiting for log zero on dbPerf_MAIN

2008-01-23 09:00:00.64 spid52      Zeroing completed on C:\Program Files\Microsoft SQL Server\MSSQL10.SQL2008\MSSQL\DATA\dbPerf_MAIN_log.LDF

2008-01-23 09:00:00.70 spid52      Restore: LogZero complete

2008-01-23 09:00:00.97 spid52      FileHandleCache: 0 files opened. CacheSize: 12

2008-01-23 09:00:00.97 spid52      Restore: Data transfer complete on dbPerf_MAIN

2008-01-23 09:00:00.97 spid52      Restore: Backup set restored

2008-01-23 09:00:01.11 spid52      Starting up database 'dbPerf_MAIN'.

2008-01-23 09:00:01.15 spid52      The database 'dbPerf_MAIN' is marked RESTORING and is in a state that does not allow recovery to be run.

2008-01-23 09:00:01.15 spid52      Restore-Redo begins on database dbPerf_MAIN

2008-01-23 09:00:04.06 spid52      Rollforward complete on database dbPerf_MAIN

2008-01-23 09:00:04.09 spid52      Restore: Done with fixups

2008-01-23 09:00:04.09 spid52      Restore: Transitioning database to ONLINE

2008-01-23 09:00:04.09 spid52      Restore: Restarting database for ONLINE

2008-01-23 09:00:04.31 spid52      Starting up database 'dbPerf_MAIN'.

2008-01-23 09:00:05.32 spid52      FixupLogTail(progress) zeroing C:\Program Files\Microsoft SQL Server\MSSQL10.SQL2008\MSSQL\DATA\dbPerf_MAIN_log.LDF from 0x6cf6c00 to 0x6cf8000.

2008-01-23 09:00:05.32 spid52      Zeroing C:\Program Files\Microsoft SQL Server\MSSQL10.SQL2008\MSSQL\DATA\dbPerf_MAIN_log.LDF from page 13948 to 13960 (0x6cf8000 to 0x6d10000)

2008-01-23 09:00:05.32 spid52      Zeroing completed on C:\Program Files\Microsoft SQL Server\MSSQL10.SQL2008\MSSQL\DATA\dbPerf_MAIN_log.LDF

2008-01-23 09:00:05.38 spid52      PostRestoreContainerFixups: running fixups on dbPerf_MAIN

2008-01-23 09:00:05.38 spid52      PostRestoreContainerFixups: fixups complete

2008-01-23 09:00:05.41 spid52      PostRestoreReplicationFixup for dbPerf_MAIN starts

2008-01-23 09:00:06.04 spid52      PostRestoreReplicationFixup for dbPerf_MAIN complete

2008-01-23 09:00:06.08 spid52      Restore: Database is restarted

2008-01-23 09:00:06.08 Backup      Restore is complete on database 'dbPerf_MAIN'.  The database is now available.

2008-01-23 09:00:06.08 spid52      Resuming any halted fulltext crawls

2008-01-23 09:00:06.08 spid52      Restore: Writing history records

2008-01-23 09:00:06.08 Backup      Database was restored: Database: dbPerf_MAIN, creation date(time): 2008/01/16(14:04:58), first LSN: 647:4889:66, last LSN: 647:4918:1, number of dump devices: 1, device information: (FILE=1, TYPE=DISK: {'c:\temp\dbperf_main.bak'}). Informational message. No user action required.

2008-01-23 09:00:06.10 spid52      Writing backup history records

2008-01-23 09:00:06.18 spid52      Restore: Done with MSDB maintenance

2008-01-23 09:00:06.18 spid52      RestoreDatabase: Finished

 

Bob Dorr
SQL Server Senior Escalation Engineer