Diagnosing Database Restores – Trace Flag 3004

Recently one of my fellow DBA had an issue with a Database Restore, where he was restoring a database using a full backup(from GUI) and the wizard was progressed upto 100% and it stayed there for more than 30 Minutes and he pinged me to see what’s going on!! Well, The actual issue was the database which he took the backup had 16000+ VLF’s!!(Very Very Bad sign of Log file sizing) and the log file size was close to 78 GB and there was a hugeeee open transaction(which SQL will Undo while restoring the Backup). Note he was creating a brand new database, So SQL will be creating brand new files and remember transaction log file will be Zero Initialized always as apposed to Data files(If Instant File Initialization is enabled on your Instance).

Our focus in this post is not regarding VLF’s and how Log file should be managed, but to identify what’s happening behind the scenes with your Database Restore and kind of identifying current Phase of restore process. For this you can make use of Undocumented trace flag 3004 along with 3605 to get the events logged in our Error Log. You can enable this trace flag either globally or at session level. (No need of touching your start up parameters for these trace flags) Please see the below Screenshot.

For demo purpose, Let’s restore a Full Backup of a database(it has an Open Transaction) and let’s see how our Error Log looks like with this trace flag being enabled.

I’ve restored the DB, see the Error Log in the below Screenshot.

Focus on these steps where you can note the actual time SQL Server took for Zeroing your Log File, Redo,Undo and all other required Information.

1.Zeroing C:\Program Files\Microsoft SQL Server\MSSQL10_50.PROD\MSSQL\DATA\3005_Demo_1.ldf
from page 1 to 20584 (0x2000 to 0xa0d0000)
2.Restore: Waiting for log zero on 3005_Demo
3.Zeroing completed on
C:\Program Files\Microsoft SQL Server\MSSQL10_50.PROD\MSSQL\DATA\3005_Demo_1.ldf
4.Restore: LogZero complete
5.Starting up database ‘3005_Demo’.
6.The database ‘3005_Demo’ is marked RESTORING and is in a state that does not allow recovery to be run.
7.Starting up database ‘3005_Demo’.
8.Recovery is writing a checkpoint in database ‘3005_Demo’ (19).
9.Recovery completed for database 3005_Demo (database ID 19) in 9 second(s)
(analysis 20 ms, redo 1801 ms, undo 7690 ms.)
10.Restore is complete on database ‘3005_Demo’. The database is now available.
Database was restored: Database: 3005_Demo, creation date(time): 2011/08/23(23:16:47), first LSN: 38:19:1 blabla