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.

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.