Does Instant File Initialization work for manual log file growths?

Question

SQL Server 2022 introduced Instant File Initialization for transaction log file growth events. In the What's New in 2022 page, Microsoft notes:

In general, transaction log files cannot benefit from instant file initialization (IFI). Starting with SQL Server 2022 (16.x) (all editions) and in Azure SQL Database, instant file initialization can benefit transaction log growth events up to 64 MB. The default auto growth size increment for new databases is 64 MB. Transaction log file autogrowth events larger than 64 MB cannot benefit from instant file initialization.

In order to test that, I tried repeatedly growing the log file at different sizes (say, 50 and 70MB), but ... none of them were instantaneous.

DROP DATABASE LogGrowthTest;
GO
CREATE DATABASE [LogGrowthTest]
 CONTAINMENT = NONE
 ON  PRIMARY 
( NAME = N'LogGrowthTest', FILENAME = N'Z:\MSSQL\Data\LogGrowthTest.mdf', 
    SIZE = 8192KB , FILEGROWTH = 60000KB )
 LOG ON 
( NAME = N'LogGrowthTest_log', FILENAME = N'Z:\MSSQL\Data\LogGrowthTest_log.ldf' , 
    SIZE = 8192KB , FILEGROWTH = 60000KB )
GO
DECLARE @TestStartTime DATETIME2 = GETDATE(), @i INT = 1,
    @StringStarter NVARCHAR(4000) = N'ALTER DATABASE [LogGrowthTest] MODIFY FILE ( NAME = N''LogGrowthTest_log'', SIZE = ',
    @StringToExec NVARCHAR(4000);   
WHILE @i < 101
    BEGIN
    /* CHANGE THE 63 IN THE BELOW LINE TO CHANGE FILE GROWTH SIZE: */
    SET @StringToExec = @StringStarter + CAST((@i * 63) AS NVARCHAR(10)) + N'MB );';
    PRINT(@StringToExec)
    EXEC(@StringToExec);
    SET @i = @i + 1;
    END
SELECT DATEDIFF(millisecond,@TestStartTime, GETDATE()) AS TestDurationSeconds
GO

I tried 63MB, 65MB, and it didn't seem to make much difference - the tests took around 15-16 seconds for 100 growth events.

So the question is, does Instant File Initialization just not work for manual log file growths, even at small sizes? Only autogrowth events? (I haven't been able to prove yet that it works for autogrowth events either.)

Martin Smith · Accepted Answer · 2022-12-26 15:30:10Z

Does Instant File Initialization work for manual log file growths?

Yes it does.

I tried the following on SQL Server 2019 and SQL Server 2022 (with IFI enabled during setup)

CREATE DATABASE [LogGrowthTest]
 CONTAINMENT = NONE
 ON  PRIMARY 
( NAME = N'LogGrowthTest', FILENAME = N'...LogGrowthTest.mdf' , SIZE = 8MB , FILEGROWTH = 60000KB  )
 LOG ON 
( NAME = N'LogGrowthTest_log', FILENAME = N'...LogGrowthTest_log.ldf' , SIZE = 8MB , FILEGROWTH = 60000KB  )
GO

ALTER DATABASE [LogGrowthTest] MODIFY FILE ( NAME = N'LogGrowthTest_log', SIZE = 64MB );

For SQL Server 2019 I can see the entirety of the newly allocated file section being written to in 8MB chunks (from the length and offset)

The stack in ProcMon shows this activity is happening in zeroing out of the file

There is no such corresponding section in 2022

Time elapsed between first and last procmon entry was 46 ms in the 2019 case (21:30:54.8866621 to 21:30:54.9330198) and 7.9 ms in the 2022 case (21:31:54.8078691 to 21:31:54.8157769).

I saw similar time differences reported via the SET STATISTICS TIME ON output too.

both were writing to the same laptop disc (on which the eagle eyed might notice from the above I accidentally named my 2022 instance 20222).

I was interested in why the loop performed so badly though. It seems that only the first entry really benefits from IFI.

When I add the following to my code above...

ALTER DATABASE [LogGrowthTest] MODIFY FILE ( NAME = N'LogGrowthTest_log', SIZE = 127MB );

The second growth takes significantly longer and writes to much more of the file (including the section that previously was not initialised)

This is not due to zeroing out of the file but also is not something I see in my SQL Server 2019 instance so seems to be additional work that may or may not be related to this feature.

Annoyingly for some reason ProcMon just shows me a blank tab instead of the call stacks for the highlighted WriteFile but windows performance recorder would imply this is spent in sqlmin.dll!SQLServerLogMgr::FormatVirtualLogFile (which ties in with Paul's answer)

Paul White · Accepted Answer · 2022-12-26 14:29:10Z

Confirmed on my local 2022 instance using:

SET NOCOUNT ON;

DECLARE 
    @CurrentSize integer,
    @i integer = 1,
    @SQL nvarchar(max);

SELECT @CurrentSize = DF.size * 8 / 1024
FROM sys.database_files AS DF
WHERE DF.[name] = N'Sandpit_log';

WHILE @i <= 10
BEGIN
    SET @SQL = CONCAT
    (
        N'
        ALTER DATABASE Sandpit 
        MODIFY FILE 
        (
            NAME = N''Sandpit_log'', 
            SIZE = ',
            @CurrentSize + (@i * 64),
            N', 
            FILEGROWTH = 64MB
            );'
    )
    EXECUTE (@SQL);
    SET @i += 1;
END;

Output from global trace flags 3004 (show instant file initialisation details) and 1810 (growth event details) with 3604 also enabled to direct output to the SSMS messages tab:

Skip zeroing D:\Databases\MSSQL16.SQL2022\MSSQL\DATA\Sandpit_log.ldf from page 8192 to 16384 (Offset 0x4000000 to 0x8000000) 64 mb
Grow the file D:\Databases\MSSQL16.SQL2022\MSSQL\DATA\Sandpit_log.ldf (file_id = 2, auto_grow = 0, growth = 65536 KB, new_size = 131072 KB).
Skip zeroing D:\Databases\MSSQL16.SQL2022\MSSQL\DATA\Sandpit_log.ldf from page 16384 to 24576 (Offset 0x8000000 to 0xc000000) 64 mb
Grow the file D:\Databases\MSSQL16.SQL2022\MSSQL\DATA\Sandpit_log.ldf (file_id = 2, auto_grow = 0, growth = 65536 KB, new_size = 196608 KB).
Skip zeroing D:\Databases\MSSQL16.SQL2022\MSSQL\DATA\Sandpit_log.ldf from page 24576 to 32768 (Offset 0xc000000 to 0x10000000) 64 mb
Grow the file D:\Databases\MSSQL16.SQL2022\MSSQL\DATA\Sandpit_log.ldf (file_id = 2, auto_grow = 0, growth = 65536 KB, new_size = 262144 KB).
Skip zeroing D:\Databases\MSSQL16.SQL2022\MSSQL\DATA\Sandpit_log.ldf from page 32768 to 40960 (Offset 0x10000000 to 0x14000000) 64 mb
Grow the file D:\Databases\MSSQL16.SQL2022\MSSQL\DATA\Sandpit_log.ldf (file_id = 2, auto_grow = 0, growth = 65536 KB, new_size = 327680 KB).
Skip zeroing D:\Databases\MSSQL16.SQL2022\MSSQL\DATA\Sandpit_log.ldf from page 40960 to 49152 (Offset 0x14000000 to 0x18000000) 64 mb
Grow the file D:\Databases\MSSQL16.SQL2022\MSSQL\DATA\Sandpit_log.ldf (file_id = 2, auto_grow = 0, growth = 65536 KB, new_size = 393216 KB).
Skip zeroing D:\Databases\MSSQL16.SQL2022\MSSQL\DATA\Sandpit_log.ldf from page 49152 to 57344 (Offset 0x18000000 to 0x1c000000) 64 mb
Grow the file D:\Databases\MSSQL16.SQL2022\MSSQL\DATA\Sandpit_log.ldf (file_id = 2, auto_grow = 0, growth = 65536 KB, new_size = 458752 KB).
Skip zeroing D:\Databases\MSSQL16.SQL2022\MSSQL\DATA\Sandpit_log.ldf from page 57344 to 65536 (Offset 0x1c000000 to 0x20000000) 64 mb
Grow the file D:\Databases\MSSQL16.SQL2022\MSSQL\DATA\Sandpit_log.ldf (file_id = 2, auto_grow = 0, growth = 65536 KB, new_size = 524288 KB).
Skip zeroing D:\Databases\MSSQL16.SQL2022\MSSQL\DATA\Sandpit_log.ldf from page 65536 to 73728 (Offset 0x20000000 to 0x24000000) 64 mb
Grow the file D:\Databases\MSSQL16.SQL2022\MSSQL\DATA\Sandpit_log.ldf (file_id = 2, auto_grow = 0, growth = 65536 KB, new_size = 589824 KB).
Skip zeroing D:\Databases\MSSQL16.SQL2022\MSSQL\DATA\Sandpit_log.ldf from page 73728 to 81920 (Offset 0x24000000 to 0x28000000) 64 mb
Grow the file D:\Databases\MSSQL16.SQL2022\MSSQL\DATA\Sandpit_log.ldf (file_id = 2, auto_grow = 0, growth = 65536 KB, new_size = 655360 KB).
Skip zeroing D:\Databases\MSSQL16.SQL2022\MSSQL\DATA\Sandpit_log.ldf from page 81920 to 90112 (Offset 0x28000000 to 0x2c000000) 64 mb
Grow the file D:\Databases\MSSQL16.SQL2022\MSSQL\DATA\Sandpit_log.ldf (file_id = 2, auto_grow = 0, growth = 65536 KB, new_size = 720896 KB).

Trace flag 1810 has a bug in its format string (%l64d instead of %I64d). If you don't fix that yourself, you can monitor growth using the Extended Events database_file_size_change or modify_file_operation instead. There's no event to monitor IFI as far as I know, so you'll need 3004 for that part.

sys.dm_db_log_info before the log growths:

database_id	file_id	vlf_begin_offset	vlf_size_mb	vlf_sequence_number	vlf_active	vlf_status	vlf_parity	vlf_first_lsn	vlf_create_lsn	vlf_encryptor_thumbprint
5	2	8192	1.93	87	0	0	128	00000000:00000000:0000	00000000:00000000:0000	NULL
5	2	2039808	1.93	88	0	0	128	00000000:00000000:0000	00000000:00000000:0000	NULL
5	2	4071424	1.93	89	1	2	128	00000059:00000010:0001	00000000:00000000:0000	NULL
5	2	6103040	2.17	42	0	0	64	00000000:00000000:0000	00000000:00000000:0000	NULL
5	2	8388608	56	43	0	0	64	00000000:00000000:0000	00000027:0000010B:0001	NULL

and afterward:

database_id	file_id	vlf_begin_offset	vlf_size_mb	vlf_sequence_number	vlf_active	vlf_status	vlf_parity	vlf_first_lsn	vlf_create_lsn	vlf_encryptor_thumbprint
5	2	8192	1.93	87	0	0	128	00000000:00000000:0000	00000000:00000000:0000	NULL
5	2	2039808	1.93	88	0	0	128	00000000:00000000:0000	00000000:00000000:0000	NULL
5	2	4071424	1.93	89	1	2	128	00000059:00000010:0001	00000000:00000000:0000	NULL
5	2	6103040	2.17	42	0	0	64	00000000:00000000:0000	00000000:00000000:0000	NULL
5	2	8388608	56	43	0	0	64	00000000:00000000:0000	00000027:0000010B:0001	NULL
5	2	67108864	64	0	0	0	0	00000000:00000000:0000	00000059:0000088F:0002	NULL
5	2	134217728	64	0	0	0	0	00000000:00000000:0000	00000059:00000896:0001	NULL
5	2	201326592	64	0	0	0	0	00000000:00000000:0000	00000059:0000089D:0001	NULL
5	2	268435456	64	0	0	0	0	00000000:00000000:0000	00000059:000008A4:0001	NULL
5	2	335544320	64	0	0	0	0	00000000:00000000:0000	00000059:000008AB:0001	NULL
5	2	402653184	64	0	0	0	0	00000000:00000000:0000	00000059:000008B2:0001	NULL
5	2	469762048	64	0	0	0	0	00000000:00000000:0000	00000059:000008B9:0001	NULL
5	2	536870912	64	0	0	0	0	00000000:00000000:0000	00000059:000008C0:0001	NULL
5	2	603979776	64	0	0	0	0	00000000:00000000:0000	00000059:000008C7:0001	NULL
5	2	671088640	64	0	0	0	0	00000000:00000000:0000	00000059:000008CE:0001	NULL

Noticed each growth added a single virtual log file (VLF).

The new feature can be disabled with global trace flag 1837. With that set, the output changes to:

Zeroing D:\Databases\MSSQL16.SQL2022\MSSQL\DATA\Sandpit_log.ldf from page 8192 to 16384 (Offset 0x4000000 to 0x8000000) 64 mb
Zeroing completed on D:\Databases\MSSQL16.SQL2022\MSSQL\DATA\Sandpit_log.ldf (elapsed = 25 ms) 64 mb
Grow the file D:\Databases\MSSQL16.SQL2022\MSSQL\DATA\Sandpit_log.ldf (file_id = 2, auto_grow = 0, growth = 65536 KB, new_size = 131072 KB).
Zeroing D:\Databases\MSSQL16.SQL2022\MSSQL\DATA\Sandpit_log.ldf from page 16384 to 24576 (Offset 0x8000000 to 0xc000000) 64 mb
Zeroing completed on D:\Databases\MSSQL16.SQL2022\MSSQL\DATA\Sandpit_log.ldf (elapsed = 23 ms) 64 mb
Grow the file D:\Databases\MSSQL16.SQL2022\MSSQL\DATA\Sandpit_log.ldf (file_id = 2, auto_grow = 0, growth = 65536 KB, new_size = 196608 KB).
Zeroing D:\Databases\MSSQL16.SQL2022\MSSQL\DATA\Sandpit_log.ldf from page 24576 to 32768 (Offset 0xc000000 to 0x10000000) 64 mb
Zeroing completed on D:\Databases\MSSQL16.SQL2022\MSSQL\DATA\Sandpit_log.ldf (elapsed = 28 ms) 64 mb
Grow the file D:\Databases\MSSQL16.SQL2022\MSSQL\DATA\Sandpit_log.ldf (file_id = 2, auto_grow = 0, growth = 65536 KB, new_size = 262144 KB).
Zeroing D:\Databases\MSSQL16.SQL2022\MSSQL\DATA\Sandpit_log.ldf from page 32768 to 40960 (Offset 0x10000000 to 0x14000000) 64 mb
Zeroing completed on D:\Databases\MSSQL16.SQL2022\MSSQL\DATA\Sandpit_log.ldf (elapsed = 22 ms) 64 mb
Grow the file D:\Databases\MSSQL16.SQL2022\MSSQL\DATA\Sandpit_log.ldf (file_id = 2, auto_grow = 0, growth = 65536 KB, new_size = 327680 KB).
Zeroing D:\Databases\MSSQL16.SQL2022\MSSQL\DATA\Sandpit_log.ldf from page 40960 to 49152 (Offset 0x14000000 to 0x18000000) 64 mb
Zeroing completed on D:\Databases\MSSQL16.SQL2022\MSSQL\DATA\Sandpit_log.ldf (elapsed = 23 ms) 64 mb
Grow the file D:\Databases\MSSQL16.SQL2022\MSSQL\DATA\Sandpit_log.ldf (file_id = 2, auto_grow = 0, growth = 65536 KB, new_size = 393216 KB).
Zeroing D:\Databases\MSSQL16.SQL2022\MSSQL\DATA\Sandpit_log.ldf from page 49152 to 57344 (Offset 0x18000000 to 0x1c000000) 64 mb
Zeroing completed on D:\Databases\MSSQL16.SQL2022\MSSQL\DATA\Sandpit_log.ldf (elapsed = 28 ms) 64 mb
Grow the file D:\Databases\MSSQL16.SQL2022\MSSQL\DATA\Sandpit_log.ldf (file_id = 2, auto_grow = 0, growth = 65536 KB, new_size = 458752 KB).
Zeroing D:\Databases\MSSQL16.SQL2022\MSSQL\DATA\Sandpit_log.ldf from page 57344 to 65536 (Offset 0x1c000000 to 0x20000000) 64 mb
Zeroing completed on D:\Databases\MSSQL16.SQL2022\MSSQL\DATA\Sandpit_log.ldf (elapsed = 22 ms) 64 mb
Grow the file D:\Databases\MSSQL16.SQL2022\MSSQL\DATA\Sandpit_log.ldf (file_id = 2, auto_grow = 0, growth = 65536 KB, new_size = 524288 KB).
Zeroing D:\Databases\MSSQL16.SQL2022\MSSQL\DATA\Sandpit_log.ldf from page 65536 to 73728 (Offset 0x20000000 to 0x24000000) 64 mb
Zeroing completed on D:\Databases\MSSQL16.SQL2022\MSSQL\DATA\Sandpit_log.ldf (elapsed = 22 ms) 64 mb
Grow the file D:\Databases\MSSQL16.SQL2022\MSSQL\DATA\Sandpit_log.ldf (file_id = 2, auto_grow = 0, growth = 65536 KB, new_size = 589824 KB).
Zeroing D:\Databases\MSSQL16.SQL2022\MSSQL\DATA\Sandpit_log.ldf from page 73728 to 81920 (Offset 0x24000000 to 0x28000000) 64 mb
Zeroing completed on D:\Databases\MSSQL16.SQL2022\MSSQL\DATA\Sandpit_log.ldf (elapsed = 29 ms) 64 mb
Grow the file D:\Databases\MSSQL16.SQL2022\MSSQL\DATA\Sandpit_log.ldf (file_id = 2, auto_grow = 0, growth = 65536 KB, new_size = 655360 KB).
Zeroing D:\Databases\MSSQL16.SQL2022\MSSQL\DATA\Sandpit_log.ldf from page 81920 to 90112 (Offset 0x28000000 to 0x2c000000) 64 mb
Zeroing completed on D:\Databases\MSSQL16.SQL2022\MSSQL\DATA\Sandpit_log.ldf (elapsed = 23 ms) 64 mb
Grow the file D:\Databases\MSSQL16.SQL2022\MSSQL\DATA\Sandpit_log.ldf (file_id = 2, auto_grow = 0, growth = 65536 KB, new_size = 720896 KB).

Resetting to the same starting point and running the ten growth script again, the log DMV shows:

database_id	file_id	vlf_begin_offset	vlf_size_mb	vlf_sequence_number	vlf_active	vlf_status	vlf_parity	vlf_first_lsn	vlf_create_lsn	vlf_encryptor_thumbprint
5	2	8192	1.93	87	0	0	128	00000000:00000000:0000	00000000:00000000:0000	NULL
5	2	2039808	1.93	88	0	0	128	00000000:00000000:0000	00000000:00000000:0000	NULL
5	2	4071424	1.93	89	1	2	128	00000059:00000010:0001	00000000:00000000:0000	NULL
5	2	6103040	2.17	42	0	0	64	00000000:00000000:0000	00000000:00000000:0000	NULL
5	2	8388608	56	43	0	0	64	00000000:00000000:0000	00000027:0000010B:0001	NULL
5	2	67108864	16	0	0	0	0	00000000:00000000:0000	00000059:000008F6:0001	NULL
5	2	83886080	16	0	0	0	0	00000000:00000000:0000	00000059:000008F6:0001	NULL
5	2	100663296	16	0	0	0	0	00000000:00000000:0000	00000059:000008F6:0001	NULL
5	2	117440512	16	0	0	0	0	00000000:00000000:0000	00000059:000008F6:0001	NULL
5	2	134217728	16	0	0	0	0	00000000:00000000:0000	00000059:000008FE:0001	NULL
5	2	150994944	16	0	0	0	0	00000000:00000000:0000	00000059:000008FE:0001	NULL
5	2	167772160	16	0	0	0	0	00000000:00000000:0000	00000059:000008FE:0001	NULL
5	2	184549376	16	0	0	0	0	00000000:00000000:0000	00000059:000008FE:0001	NULL
5	2	201326592	16	0	0	0	0	00000000:00000000:0000	00000059:00000906:0001	NULL
5	2	218103808	16	0	0	0	0	00000000:00000000:0000	00000059:00000906:0001	NULL
5	2	234881024	16	0	0	0	0	00000000:00000000:0000	00000059:00000906:0001	NULL
5	2	251658240	16	0	0	0	0	00000000:00000000:0000	00000059:00000906:0001	NULL
5	2	268435456	16	0	0	0	0	00000000:00000000:0000	00000059:0000090E:0001	NULL
5	2	285212672	16	0	0	0	0	00000000:00000000:0000	00000059:0000090E:0001	NULL
5	2	301989888	16	0	0	0	0	00000000:00000000:0000	00000059:0000090E:0001	NULL
5	2	318767104	16	0	0	0	0	00000000:00000000:0000	00000059:0000090E:0001	NULL
5	2	335544320	16	0	0	0	0	00000000:00000000:0000	00000059:00000916:0001	NULL
5	2	352321536	16	0	0	0	0	00000000:00000000:0000	00000059:00000916:0001	NULL
5	2	369098752	16	0	0	0	0	00000000:00000000:0000	00000059:00000916:0001	NULL
5	2	385875968	16	0	0	0	0	00000000:00000000:0000	00000059:00000916:0001	NULL
5	2	402653184	16	0	0	0	0	00000000:00000000:0000	00000059:0000091E:0001	NULL
5	2	419430400	16	0	0	0	0	00000000:00000000:0000	00000059:0000091E:0001	NULL
5	2	436207616	16	0	0	0	0	00000000:00000000:0000	00000059:0000091E:0001	NULL
5	2	452984832	16	0	0	0	0	00000000:00000000:0000	00000059:0000091E:0001	NULL
5	2	469762048	16	0	0	0	0	00000000:00000000:0000	00000059:00000926:0001	NULL
5	2	486539264	16	0	0	0	0	00000000:00000000:0000	00000059:00000926:0001	NULL
5	2	503316480	16	0	0	0	0	00000000:00000000:0000	00000059:00000926:0001	NULL
5	2	520093696	16	0	0	0	0	00000000:00000000:0000	00000059:00000926:0001	NULL
5	2	536870912	16	0	0	0	0	00000000:00000000:0000	00000059:0000092E:0001	NULL
5	2	553648128	16	0	0	0	0	00000000:00000000:0000	00000059:0000092E:0001	NULL
5	2	570425344	16	0	0	0	0	00000000:00000000:0000	00000059:0000092E:0001	NULL
5	2	587202560	16	0	0	0	0	00000000:00000000:0000	00000059:0000092E:0001	NULL
5	2	603979776	64	0	0	0	0	00000000:00000000:0000	00000059:00000936:0001	NULL
5	2	671088640	64	0	0	0	0	00000000:00000000:0000	00000059:0000093D:0001	NULL

Notice most 64MB growths resulted in 4 x 16MB VLFs.

Stack Exchange Network

Does Instant File Initialization work for manual log file growths?

2 Answers 2

Your Answer

Not the answer you're looking for? Browse other questions tagged
sql-server
transaction-log
sql-server-2022
or ask your own question.

Hot Network Questions

Does Instant File Initialization work for manual log file growths?

2 Answers 2

Your Answer

Sign up or log in

Post as a guest

Not the answer you're looking for? Browse other questions tagged sql-servertransaction-logsql-server-2022 or ask your own question.

Related

Hot Network Questions

Not the answer you're looking for? Browse other questions tagged
sql-server
transaction-log
sql-server-2022
or ask your own question.