Troubleshoot backup restore issues with trace flag 3004

I faced an issue during restoration of very large db in our development database server. Issue is restoration takes very long time even though we had latest hardware and recent version of SQL Server (it’s SQL 2008 Ent. Ed). So to troubleshoot it I have used the trace flag 3004 which print all internal things happen during backup and restoration operation.

Note: This trace flag is undocumented and used by support team for troubleshooting hence request you to test it in Development servers. No support will be provided by MS incase if something goes wrong using this undocumented trace flag. FYI

Lets come to the point in our case the issue SQL service account is not able to utilize Instant file initialization. Our environment is restricted hence SQL Service account will not be give admin rights and it will provided minimal privilege. As you know to utilize instant file initialization the service account requires SE_MANAGE_VOLUME_NAME permission (known as Perform Volume Maintenance Tasks in Local security policies of the server) by default only administrators have this right so we granted service account this permission to utilize instant initialization of data files. Log files cant use instant file initialization, wonder why? Refer Pauls blog

Im going to simulate a test to show how we found out this issue. I have a database called Finance with data file size 20GB and log file size 5 GB, when ever I restore without instant file initialization it need to initialize around 25 GB of disk space.

Restoration without Instant file Initialization

My SQL service account has limited permission hence it cant use this permission. Now I’m going to restore the db , it will initialize both data and log file which will take long time to complete. Before proceeding with test enable the trace flag using the T-SQL statement below, 3605 is required to print the output to error log.

DBCC TRACEON(3605,3004,-1)

Now lets restore it

backup_restore_troubleshoot_1

From the image above you can see that it took around 8 minutes and 20 seconds to restore the db, then we checked the errorlog for addition restoration info and the details are below. From this errorlog content you can see that it took around 8 minutes to zeroing both data and log file, this clearly shows that its not using instant file initialization feature and this is the max time in restoration.

2011-04-18 20:44:21.630 spid53 Restore: Attached database Finance_WP as DBID=8
2011-04-18 20:44:21.630 spid53 Restore: PreparingContainers
2011-04-18 20:44:21.820 spid53 Zeroing D:Finance_WP.mdf from page 1 to 2560000 (0x2000 to 0x4e2000000)
2011-04-18 20:44:21.820 spid53 Zeroing D:Finance_WP_log.ldf from page 1 to 640000 (0x2000 to 0x138800000)
2011-04-18 20:48:23.200 spid53 Zeroing completed on D:Finance_WP_log.ldf
2011-04-18 20:52:36.670 spid53 Zeroing completed on D:Finance_WP.mdf
2011-04-18 20:52:36.670 spid53 Restore: Containers are ready
2011-04-18 20:52:36.770 spid53 Restore: Restoring backup set

Now we decided to provide the SE_MANAGE_VOLUME_NAME permission to our sql service. To provide the permission follow the steps below

  • Goto Run
  • Type secpol.msc
  • Expand Local Policies folder and click on User Rights Assignment folder.
  • Open Perform Volume Maintenance Tasks and add your SQL Service account as shown below

backup_restore_troubleshoot_2

  • Restart SQL Services to make the change effective

Now Ive granted permission to SQL Service account to make use of Instant file Initialization, lets restore from the backup with different name.

Restoration with Instant file Initialization

I have started the restoration and now SQL utilized instant file initialization feature

backup_restore_troubleshoot_3

From the image above you could see that backup completed in 1 minute and 53 seconds which taken lesser duration compared to the previous test. Lets see the output from errorlog

2011-04-18 20:41:47.730 spid51 Restore: Attached database Finance_WP as DBID=8
2011-04-18 20:41:47.730 spid51 Restore: PreparingContainers
2011-04-18 20:41:47.920 spid51 Zeroing D:Finance_WP_log.ldf from page 1 to 640000 (0x2000 to 0x138800000)
2011-04-18 20:41:47.940 spid51 Restore: Containers are ready
2011-04-18 20:41:48.250 spid51 Restore: Restoring backup set

As you can see that now SQL is utilized instant file initialization for data file. I have already mentioned that log file cant use this feature hence it took time to zeroing my log file which is around 5 GB. This is one of the case where we used trace flag 3004 to troubleshoot restoration, similarly you can get more information about backup and restoration using this trace flag, analyze the output and troubleshoot your problem. Once you are done with testing use the below T-SQL command to turn off the trace flag

DBCC TRACEOFF(3605,3004,-1)


Posted

in

by

Comments

5 responses to “Troubleshoot backup restore issues with trace flag 3004”

  1. PeterPatrickGo avatar

    I met almost the same problem with u before, while ur means seem easier.

  2. Rajesh Kasturi avatar
    Rajesh Kasturi

    Vidya Sagar, This Article is very useful and thanks for sharing valuable knowledge.

  3. Will avatar
    Will

    great tutorial, keep up the good work 🙂

  4. kishore avatar
    kishore

    In our environment we have restore issue the PRODUCTION server taking 4 hrs to restore 300GB file using litespeed, the same database taking 40min in DEVELOPMENT server using litespeed,I dont know what is the cause when copmaring to DEV the PROD configuration is high but i dont know why is it taking long time,no users were connecting during restore in PROD.If we ue Instant File Initilazion is it useful?

    1. VidhyaSagar avatar

      It depends on other factors too… Compare disk IO, memory and CPU usage between your prod and dev box.
      In the mean time get me the output using the trace flag

Leave a Reply

Your email address will not be published. Required fields are marked *