How It Works: What is Restore/Backup Doing?

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