As a DBA there are numerous times when we restore databases.
While doing so I have asked these questions to myself several times. Here I
will try to answer them as best as I can
So why my database backup takes 1 hour and restore takes 8
hours?
There are multiple reasons for this
- Let’s say I am backing up a database with total size 500 GB but actual data is 100 GB (With 400 GB allocated space available). Backup will have to be only for 100 GB. However while restoring entire 500 GB database has to be rebuilt so restore time is much more than backup time.
- Other
reason could be that you are not using “Instant File Initialization” in
which deleted data on the disk is replaced by zeros while data and log
files are being created. So if your data file total size is 500 GB with
100 GB actual data then after writing 100 GB data all other bytes will be
filled with zeros (instant file Initialization not enabled). This will add
significant time to restore.
BOL reference: http://msdn.microsoft.com/en-us/library/ms175935.aspx
Now to the second question; what is going on with restore?
Usually you can specify STATS while restoring and restore
command will output the status every N %
E.g: Here I am restoring TestDB with STATS set to 10 (every
10% display message)
RESTORE DATABASE [TestDB] FROM DISK = N'D:\TestDB\TestDB_BK.bak'
WITH FILE = 1, NOUNLOAD, REPLACE, STATS =
10
GO
Here is what you will see in message tab of SSMS
10 percent
processed.
20 percent
processed.
30 percent
processed.
40 percent
processed.
50 percent
processed.
60 percent
processed.
70 percent
processed.
80 percent
processed.
90 percent
processed.
100 percent
processed.
Processed
292888 pages for database 'TestDB', file 'TestDB' on file 1.
Processed 6
pages for database 'TestDB', file 'TestDB_log' on file 1.
RESTORE DATABASE successfully processed 292894 pages in
23.265 seconds (98.355 MB/sec).
Along with this there are entries logged in SQL error log
which also tell you what is happening while restore is going on (Run sp_readerrorlog to read the SQL Error logs)
2012-04-24
13:44:51.190 spid64 Starting up
database 'TestDB'.
2012-04-24
13:44:51.230 spid64 The database
'TestDB' is marked RESTORING and is in a state that does not allow recovery to
be run.
2012-04-24
13:44:51.640 spid64 Starting up
database 'TestDB'.
2012-04-24
13:44:52.150 Backup Restore is
complete on database 'TestDB'. The
database is now available.
2012-04-24
13:44:52.160 Backup Database was
restored: Database: TestDB, creation date(time): 2012/04/24(13:27:09), first
LSN: 1417:196:183, last LSN: 1417:289:1, number of dump devices: 1, device
information: (FILE=1, TYPE=DISK: {'D:\TestDB\TestDB_BK.bak'}). Informational
message. No us
But this does not tell you much about exactly what is going
on while restoring
So there are some undocumented trace flags which can be used
to find out exact status of restore.
Trace flag 3004: This
flag turns on information regarding instant file initialization. Enabling this
trace flag will not make this information available to view.
Trace flag 3605: This
flag will send some DBCC output to the error log. This trace flag needs to be
enabled to see the instant file initialization information made available by
trace flag 3004.
Now let’s restore with these 2 trace flags turned on
DBCC TRACEON(3004, 3605,-1)
RESTORE DATABASE [TestDB] FROM DISK = N'D:\TestDB\TestDB_BK.bak'
WITH FILE = 1, NOUNLOAD, REPLACE, STATS = 10
GO
10 percent
processed.
20 percent
processed.
30 percent
processed.
40 percent
processed.
50 percent
processed.
60 percent
processed.
70 percent
processed.
80 percent
processed.
90 percent
processed.
100 percent processed.
Processed
292888 pages for database 'TestDB', file 'TestDB' on file 1.
Processed 6
pages for database 'TestDB', file 'TestDB_log' on file 1.
RESTORE DATABASE successfully processed 292894 pages in
23.265 seconds (98.355 MB/sec).
From SQL Serve error log you can see there are lot of other
messages logged related to the restore which are quite helpful.
2012-04-24
13:45:25.240 spid64
RestoreDatabase: Database TestDB
2012-04-24
13:45:25.240 spid64 Opening backup
set
2012-04-24
13:45:25.260 spid64 Restore:
Configuration section loaded
2012-04-24
13:45:25.260 spid64 Restore: Backup
set is open
2012-04-24
13:45:25.260 spid64 Restore:
Planning begins
2012-04-24
13:45:25.270 spid64 Halting
FullText crawls on database TestDB
2012-04-24
13:45:25.270 spid64 Dismounting
FullText catalogs
2012-04-24
13:45:25.270 spid64 X-locking
database: TestDB
2012-04-24
13:45:25.270 spid64 Restore:
Planning complete
2012-04-24
13:45:25.270 spid64 Restore:
BeginRestore (offline) on TestDB
2012-04-24
13:45:25.300 spid64 Restore:
PreparingContainers
2012-04-24
13:45:25.310 spid64 Restore:
Containers are ready
2012-04-24
13:45:25.310 spid64 Zeroing
E:\TransactionLogs\TestDB_log.ldf from page 1 to 128 (0x2000 to 0x100000)
2012-04-24
13:45:25.310 spid64 Zeroing
completed on E:\TransactionLogs\TestDB_log.ldf
2012-04-24
13:45:25.310 spid64 Restore:
Restoring backup set
2012-04-24
13:45:25.310 spid64 Restore:
Transferring data to TestDB
2012-04-24
13:45:48.420 spid64 Restore:
Waiting for log zero on TestDB
2012-04-24
13:45:48.430 spid64 Restore:
LogZero complete
2012-04-24
13:45:48.580 spid64
FileHandleCache: 0 files opened. CacheSize: 12
2012-04-24
13:45:48.580 spid64 Restore: Data transfer complete on TestDB
2012-04-24
13:45:48.590 spid64 Restore: Backup
set restored
2012-04-24
13:45:48.590 spid64 Starting up
database 'TestDB'.
2012-04-24
13:45:48.640 spid64 The database
'TestDB' is marked RESTORING and is in a state that does not allow recovery to
be run.
2012-04-24
13:45:48.650 spid64 Restore-Redo
begins on database TestDB
2012-04-24
13:45:49.140 spid64 Rollforward
complete on database TestDB
2012-04-24
13:45:49.150 spid64 Restore: Done
with fixups
2012-04-24
13:45:49.160 spid64 Restore:
Transitioning database to ONLINE
2012-04-24
13:45:49.170 spid64 Restore:
Restarting database for ONLINE
2012-04-24
13:45:49.200 spid64 Starting up
database 'TestDB'.
2012-04-24
13:45:49.310 spid64
FixupLogTail(progress) zeroing E:\TransactionLogs\TestDB_log.ldf from
0xa2200 to 0xa4000.
2012-04-24
13:45:49.310 spid64 Zeroing
E:\TransactionLogs\TestDB_log.ldf from page 82 to 94 (0xa4000 to 0xbc000)
2012-04-24
13:45:49.310 spid64 Zeroing
completed on E:\TransactionLogs\TestDB_log.ldf
2012-04-24
13:45:49.420 spid64
PostRestoreContainerFixups: running fixups on TestDB
2012-04-24
13:45:49.440 spid64
PostRestoreContainerFixups: fixups complete
2012-04-24
13:45:49.450 spid64
PostRestoreReplicationFixup for TestDB starts
2012-04-24
13:45:49.640 spid64
PostRestoreReplicationFixup for TestDB complete
2012-04-24
13:45:49.640 spid64 Restore:
Database is restarted
2012-04-24
13:45:49.640 Backup Restore is complete on database 'TestDB'. The database is now available.
2012-04-24
13:45:49.640 spid64 Resuming any
halted fulltext crawls
2012-04-24
13:45:49.650 spid64 Restore:
Writing history records
2012-04-24
13:45:49.650 Backup Database was
restored: Database: TestDB, creation date(time): 2012/04/24(13:27:09), first
LSN: 1417:196:183, last LSN: 1417:289:1, number of dump devices: 1, device
information: (FILE=1, TYPE=DISK: {'D:\TestDB\TestDB_BK.bak'}). Informational
message. No us
2012-04-24
13:45:49.650 spid64 Writing backup
history records
2012-04-24
13:45:49.670 spid64 Restore: Done
with MSDB maintenance
2012-04-24 13:45:49.670 spid64 RestoreDatabase: Finished
Here are some of the other undocumented (or less documented)
trace flag which come handy while checking backup & restore detailed status
Trace flag 3014: Also provides detailed
information on steps during backup and restore.
Trace Flag
3604: Sends DBCC output to screen instead of error log
Caution: These trace flags should be
used only by professional DBAs since there are side effects of using
undocumented trace flags
No comments:
Post a Comment