Instant File Initialization and restores

SQLServer has been able to take advantage of using Instant File Initialization (IFI) for quite some time. The SQL Server instance service account can use Instant File Initialization if it has been granted the “Perform volume maintenance tasks” at the Windows level, via a Local Group Policy.

To grant this right, use this process:

Start secpol.msc
Navigate to Security Settings / Local Policies / User Rights Assignment and add the service account (or even better, the Windows group in use for that instance’s service accounts) the “Perform volume maintenance tasks” right (aka SeManageVolumePrivilege).
Restart your SQLServer instance.

In many posts, Instant File Initialisation is highlighted as a database creation and (automatic) file growth time saver.

However, Instant file initilization also helps at recovery time.

When you restore a database, SQLServer will zero-out all associated database files if the service account has not been granted the “Perform volume maintenance tasks” privilege, just as it does during a create database command.

I recently needed to restore a 100GB database on a new server was surprised my restore needed so much time. I reviewed my install checklist and noticed I didn’t check the “Perform volume maintenance tasks” authority.

Trace flags 3004 + 3605 show more in detail what the engine does for your database during restore, so I started them and re-launched the restore. I performed this restore on two different servers ( D008 and CL008 ) to see its impact on an older server and on our new clustered instance.

Below you’ll find the results I found in the errorlog files. Check for mentions of .mdf file actions (or whatever you name your data files at restore time).

I have clipped the content and highlighted the meant zero-out operations for your convenience.

Here is the result in the errorlog with INITIAL FILE INITIALIZATION NOT ENABLED

--- ( Instance D008) -----------

2012-03-06 15:21:54.67 Server Microsoft SQL Server 2008 R2 (SP1) - 10.50.2500.0 (Intel X86) Jun 17 2011 00:57:23 Copyright (c) Microsoft Corporation Enterprise Edition on Windows NT 6.0 <X86> (Build 6002: Service Pack 2)

2012-03-06 15:22:23.16 spid54 DBCC TRACEON 3004, server process ID (SPID) 54. This is an informational message only; no user action is required.

2012-03-06 15:22:23.16 spid54 DBCC TRACEON 3605, server process ID (SPID) 54. This is an informational message only; no user action is required.

2012-03-06 15:22:45.72 spid57 RestoreDatabase: Database MyDb

2012-03-06 15:22:45.80 spid57 Opening backup set

...

2012-03-06 15:23:40.35 spid57 Restore: BeginRestore (offline) on MyDb

2012-03-06 15:23:40.35 spid57 Restore: Attached database MyDb as DBID=24

2012-03-06 15:23:40.35 spid57 Restore: PreparingContainers

2012-03-06 15:23:40.51 spid57 Zeroing E:\MSSQL10_50.DV008\MSSQL\DataUserDb\MyDb.mdf from page 1 to 12763568 (0x2000 to 0x1858360000)

2012-03-06 15:23:40.51 spid57 Zeroing D:\MSSQL10_50.DV008\MSSQL\DataUserLog\MyDb_log.ldf from page 1 to 1344000 (0x2000 to 0x290400000)

2012-03-06 15:24:08.36 spid52 Attempting to load library 'xpstar.dll' into memory. This is an informational message only. No user action is required.

2012-03-06 15:24:08.40 spid52 Using 'xpstar.dll' version '2009.100.1600' to execute extended stored procedure 'xp_instance_regread'. This is an informational message only; no user action is required.

2012-03-06 15:25:27.93 spid57 RestoreDatabase: Database MyDb

2012-03-06 15:25:27.99 spid57 Opening backup set

2012-03-06 15:25:28.06 spid57 Restore: Configuration section loaded

2012-03-06 15:25:28.06 spid57 Restore: Backup set is open

2012-03-06 15:25:28.06 spid57 Restore: Planning begins

2012-03-06 15:25:28.09 spid57 Restore: Planning complete

2012-03-06 15:25:28.09 spid57 Restore: BeginRestore (offline) on MyDb

2012-03-06 15:25:28.09 spid57 Restore: Attached database MyDb as DBID=24

2012-03-06 15:25:28.09 spid57 Restore: PreparingContainers

2012-03-06 15:25:28.24 spid57 Zeroing D:\MSSQL10_50.DV008\MSSQL\DataUserLog\MyDb_log.ldf from page 1 to 1344000 (0x2000 to 0x290400000)

2012-03-06 15:25:28.24 spid57 Zeroing E:\MSSQL10_50.DV008\MSSQL\DataUserDb\MyDb.mdf from page 1 to 12763568 (0x2000 to 0x1858360000)

2012-03-06 15:29:43.01 spid57 Zeroing completed on D:\MSSQL10_50.DV008\MSSQL\DataUserLog\MyDb_log.ldf

2012-03-06 15:57:24.38 spid57 Zeroing completed on E:\MSSQL10_50.DV008\MSSQL\DataUserDb\MyDb.mdf

2012-03-06 15:57:24.38 spid57 Restore: Containers are ready

2012-03-06 15:57:24.40 spid57 Restore: Restoring backup set

...

2012-03-06 17:28:17.36 spid57 RestoreDatabase: Finished

...

Errorlog with INITIAL FILE INITIALIZATION ENABLED

--- ( Instance D008) ---- complete list -------

2012-03-06 10:34:38.360,Server,Microsoft SQL Server 2008 R2 (SP1) - 10.50.2500.0 (Intel X86) Jun 17 2011 00:57:23 Copyright (c) Microsoft Corporation Enterprise Edition on Windows NT 6.0 <X86> (Build 6002: Service Pack 2)

2012-03-06 18:46:00.330 spid55 DBCC TRACEON 3004, server process ID (SPID) 55. This is an informational message only; no user action is required.

2012-03-06 18:46:00.330 spid55 DBCC TRACEON 3605, server process ID (SPID) 55. This is an informational message only; no user action is required.

2012-03-06 18:46:20.250 spid53 RestoreDatabase: Database MyDb

2012-03-06 18:46:20.310 spid53 Starting up database 'MyDb'.

2012-03-06 18:46:20.360 spid53 The database 'MyDb' is marked RESTORING and is in a state that does not allow recovery to be run.

2012-03-06 18:46:20.360 spid53 X-locking database: MyDb

2012-03-06 18:46:20.360 spid53 Opening backup set

2012-03-06 18:46:20.440 spid53 Restore: Configuration section loaded

2012-03-06 18:46:20.440 spid53 Restore: Backup set is open

2012-03-06 18:46:20.440 spid53 Restore: Planning begins

2012-03-06 18:46:20.460 spid53 Dismounting FullText catalogs

2012-03-06 18:46:20.460 spid53 Restore: Planning complete

2012-03-06 18:46:20.460 spid53 Restore: BeginRestore (offline) on MyDb

2012-03-06 18:46:20.480 spid53 Restore: PreparingContainers

2012-03-06 18:46:20.520 spid53 Restore: Containers are ready

2012-03-06 18:46:20.520 spid53 Zeroing D:\MSSQL10_50.DV008\MSSQL\DataUserLog\MyDb_log.ldf from page 1 to 1344000 (0x2000 to 0x290400000)

2012-03-06 18:46:20.810 spid53 Restore: Restoring backup set

2012-03-06 18:46:20.810 spid53 Restore: Transferring data to MyDb

2012-03-06 18:49:46.580 spid53 Zeroing completed on D:\MSSQL10_50.DV008\MSSQL\DataUserLog\MyDb_log.ldf

2012-03-06 20:17:42.850 spid53 Restore: Waiting for log zero on MyDb

2012-03-06 20:17:42.850 spid53 Restore: LogZero complete

2012-03-06 20:17:43.390 spid53 FileHandleCache: 0 files opened. CacheSize: 12

2012-03-06 20:17:43.390 spid53 Restore: Data transfer complete on MyDb

2012-03-06 20:17:43.430 spid53 Restore: Backup set restored

2012-03-06 20:17:43.440 spid53 Starting up database 'MyDb'.

2012-03-06 20:17:43.470 spid53 The database 'MyDb' is marked RESTORING and is in a state that does not allow recovery to be run.

2012-03-06 20:17:43.490 spid53 Restore-Redo begins on database MyDb

2012-03-06 20:17:45.380 spid53 Rollforward complete on database MyDb

2012-03-06 20:17:45.420 spid53 Restore: Done with fixups

2012-03-06 20:17:45.460 spid53 Restore: Writing history records

2012-03-06 20:17:45.460 Backup Database was restored: Database: MyDb, creation date(time): 2012/02/08(22:55:21), first LSN: 18456:144700:290, last LSN: 18456:144876:1, number of dump devices: 1, device information: (FILE=1, TYPE=DISK: {'\\mysafezone\SQLBackupCL008$\MyDbFull.bak'}). Informational message. No user action required.

2012-03-06 20:17:45.470 spid53 Writing backup history records

2012-03-06 20:17:45.520 spid53 Restore: Done with MSDB maintenance

2012-03-06 20:17:45.520 spid53 RestoreDatabase: Finished

--- result in errorlog --- INITIAL FILE INITIALIZATION NOT ENABLED -------

--- ( Instance CL008) -----------

02/20/2012 00:00:00 spid57 Microsoft SQL Server 2008 R2 (SP1) - 10.50.2500.0 (X64) <nl/> Jun 17 2011 00:54:03 <nl/> Copyright (c) Microsoft Corporation<nl/> Enterprise Edition (64-bit) on Windows NT 6.1 <X64> (Build 7601: Service Pack 1)

.......

02/23/2012 08:11:01 spid120 RestoreDatabase: Database MyDb

...

02/23/2012 08:11:01 spid120 Zeroing S:\MSSQL10_50.CL008\MSSQL\Data\MyDb.mdf from page 1 to 12763568 (0x2000 to 0x1858360000)

02/23/2012 08:11:01 spid120 Zeroing S:\MSSQL10_50.CL008\MSSQL\DATA\MyDb_Log.ldf from page 1 to 640000 (0x2000 to 0x138800000)

02/23/2012 08:11:35 spid120 Zeroing completed on S:\MSSQL10_50.CL008\MSSQL\DATA\MyDb_Log.ldf

02/23/2012 08:15:53 spid120 Zeroing completed on S:\MSSQL10_50.CL008\MSSQL\Data\MyDb.mdf

02/23/2012 08:15:53 spid120 Restore: Containers are ready

...

02/23/2012 08:23:40 spid120 RestoreDatabase: Finished

--- result in errorlog --- INITIAL FILE INITIALIZATION ENABLED -----------

--- ( Instance CL008) -----------

02/23/2012 12:52:12,Server Microsoft SQL Server 2008 R2 (SP1) - 10.50.2500.0 (X64) <nl/> Jun 17 2011 00:54:03 <nl/> Copyright (c) Microsoft Corporation<nl/> Enterprise Edition (64-bit) on Windows NT 6.1 <X64> (Build 7601: Service Pack 1)

...

02/23/2012 14:08:09 spid116 RestoreDatabase: Database MyDb

...

02/23/2012 14:08:10 spid116 Zeroing S:\MSSQL10_50.CL008\MSSQL\DATA\MyDb_Log.ldf from page 1 to 640000 (0x2000 to 0x138800000)

...

02/23/2012 14:08:41 spid116 Zeroing completed on S:\MSSQL10_50.CL008\MSSQL\DATA\MyDb_Log.ldf

02/23/2012 14:15:49 spid116 Restore: Waiting for log zero on MyDb

02/23/2012 14:15:49 spid116 Restore: LogZero complete

...

02/23/2012 14:15:50 spid116 Starting up database 'MyDb'.

02/23/2012 14:15:50 spid116 FixupLogTail(progress) zeroing S:\MSSQL10_50.CL008\MSSQL\DATA\MyDb_Log.ldf from 0x1b7f5800 to 0x1b7f6000.

02/23/2012 14:15:50 spid116 Zeroing S:\MSSQL10_50.CL008\MSSQL\DATA\MyDb_Log.ldf from page 56315 to 56795 (0x1b7f6000 to 0x1bbb6000)

02/23/2012 14:15:50 spid116 Zeroing completed on S:\MSSQL10_50.CL008\MSSQL\DATA\MyDb_Log.ldf

...

02/23/2012 14:15:51 spid116 RestoreDatabase: Finished

...

As you can observe in the second set, having IFI enabled, there is no mention of the zero-out operation for the MDF, saving me 33 minutes (D008) and 4 minutes (CL008) of restore time. In a crisis situation, every second counts, right ?

If you haven’t granted your service accounts this privilege, maybe now is the time to do so.

Of course these figures don’t mean a thing, if you don’t know the hardware I tested it on, so here it is:

Serverinfo: D008

DELL PE2600 with 2 2-core CPU (32-bit)

OS: Windows Server 2008 Standard SP2

Memory: 3072 MB DDR Speed: 266

Processor: 2 * Intel Xeon CPU 2.40GHz.

GB RPM ultra cacheMB raid

C 36 10000 320 8 1

D 73 10000 320 8 1

E 2*73 10000 320 8 0

Serverinfo: CL008

HP ProLiant DL580 G7

OS: Windows Server 2008 R2 Enterprise (x64) SP1

Memory: 64GB

Processor: 4 * Intel Xeon CPU E7530 @ 1.87GHz.

C-drive 146 GB – 10000RPM- 6Gb/s SAS - 16 – 22

R-drive : SAN luns (+mounted volume Raid5 (data) Raid1(log) )

Hyper-threading turned on

A brand new SAN HP P6300 30TB with a single raid5 pool.

No SAN-mirroring in use

LUN definitions to host the data files : Raid5

LUN definitions to host the Log files: Raid1

Instant File Initialization and restores

Rate

Share

Categories

Share

Rate

Instant File Initialization and restores

Rate

Share

Categories

Share

Rate

Related content

Integrating SQL LiteSpeed in your existing Backup Infrastructure

Squeezing Wasted Full Scans out of SQL Server Agent

Backup and Restore Back to Basics with SQL LiteSpeed

Removing Orphan Users from All Databases on Server

Alternatives to SQL Backups