This month's T-SQL Tuesday event is on the topic of monitoring, and is hosted by Catherine Wilhelmsen (@cathrinew).
If you've ever wondered what is going on after a backup or restore operation reaches 100%, but the database is still not available, you're not alone. When people are running backups interactively, they often add the WITH STATS option, which adds a notification as each specified % of the data movement process is completed. But that doesn't add a whole lot of diagnostics, and it can often represent a very small portion of the overall process (which can include things like undo/redo operations and updates to tables in msdb).
Let's say we have a very simple database like this:
Now, if I want to backup and restore this database, I can run code like this following:
The output will look something like this (the system *tries* to report at exact % intervals, but it will sometimes be off by a bit):
There are a couple of undocumented trace flags you can add to get a lot more diagnostic information, either in the messages pane of Management Studio (using trace flag 3604), or in SQL Server's error log (using trace flag 3605).
Trace Flag 3014
The first trace flag for exposing more diagnostic information about the backup or restore operation is 3014. Let's run the backup again, and see the output in the messages pane:
The output:
For a restore operation:
The output is:
There are no timestamps on the output to the messages pane, so if you're using just 3604, you kind of have to watch the process and pay attention to when it "gets stuck" - and hope that it isn't a typical SSMS output buffer problem. But if you use 3605, you can see the timestamp for each step in the event log, so after the fact it should be easy to analyze and see where the time was spent.
Trace Flag 3004
Trace flag 3004 adds information to the output about file preparation, bitmaps, and instant file initialization (instant file initialization, which avoids the costly operation about zeroing out files, is only relevant for restore operations, and only for restoring data files).
For a backup:
Output:
For a restore, the additional information that is included about instant file initialization under 3004 is only directed to the error log, not to the messages pane. For this operation:
In the messages pane, we see this:
If you go to the error log, though, you'll see this information:
(Microsoft's Bob Dorr has written about TF 3004 before, but notes that it is undocumented and unsupported.)
If instant file initialization is not enabled, you'll see additional zeroing data for the data files (not necessarily in this order):
There are some scenarios that can prevent instant file initialization from helping the restore process, such as:
- the privilege not being granted to the SQL Server service account;
- the use of Transparent Data Encryption (TDE);
- the use of trace flag 1806, which disables instant file initialization;
For more details on instant file initialization, see these posts:
- Instant Initialization – What, Why and How?
- How and Why to Enable Instant File Initialization
- Misconceptions around instant file initialization
- A SQL Server DBA myth a day: (3/30) instant file initialization can be controlled from within SQL Server
- SQL Server Instant File Initialization (PQW)
Summary
If you are trying to monitor a sluggish backup or restore process, these trace flags should be able to help you determine where exactly the slowdown is occurring - it could be processing undo/redo operations, VLFs, Full-text, or writing to msdb. It could be something as simple as the fact that you expected instant file initialization to be enabled, and it wasn't. There could be other things that affect backup or restore performance but that won't become apparent under these trace flags; for example, if you are using backup compression, but trace flag 3042 is enabled, this flag changes the way the backup file is allocated during the process (documented here).
I don't recommend running these trace flags globally. In fact, I highly recommend running 3226 in general, which does something like the opposite - it prevents all of the successful backup message noise from polluting the error log. Note that 3004 and 3014 are not completely trumped by 3226. Having 3226 enabled globally will not prevent you from using these flags for troubleshooting purposes; the output will just be missing these lines:
RESTORE DATABASE successfully processed 290 pages in 0.029 seconds (78.125 MB/sec).
Facebook
Linkedin
Twitter
Comments