While working on a problem today I happened to think about what the impact to startup might be for a really large tempdb transaction log file. Its fairly common knowledge that data files in SQL Server 2005+ on Windows Server 2003+ can be instant initialized, but the transaction log files can not. If this is news to you see the following blog posts:
Kimberly L. Tripp | Instant Initialization – What, Why and How?
In Recovery… | Misconceptions around instant file initialization
In Recovery… | Search Engine Q&A #24: Why can’t the transaction log use instant initialization?
Tibor Karaszi : Do you have Instant File Initialization?
The thought occurred to me today that despite having log files 8GB in size for tempdb, I’ve never really noticed that it takes that long for SQL Server to startup. So I jumped on twitter and shot a tweet out to Paul Randal (Blog | Twitter) and I also included the #sqlhelp hash tag to see what others in the community thought. I got a couple of comments, one linking me to Paul Randal’s blog post, another saying test it, and another saying the transaction log is always zero initialized.
When I got home tonight I was still thinking about this and as I went to go test it, I remembered that I had read a blog post once about a trace flag that would output information about zero file initialization. A quick search and I found the post on the Premier Field Engineers Blog. So I jumped on a test system I have and added the –T3004 and –T3605 trace flags to the startup parameters. Since the PFE blog provided the following disclaimer about using these trace flags so will I.
WARNING: These trace flags should be used under the guidance of Microsoft SQL Server support. They are used in this post for discussion purposes only and may not be supported in future versions.
After setting the flags I checked tempdb and it was currently setup with a 4GB transaction log file. With this information in hand I restarted the instance and once it was online I opened the ErrorLog to look at what –T3004 could tell me about tempdb log file initialization.
2010-05-13 18:42:13.52 spid12s Clearing tempdb database.
<……….skipped content…………>
2010-05-13 18:42:30.93 spid12s Zeroing T:\SQLData\MSSQL10.MSSQLSERVER\MSSQL\Data\templog.ldf from page 2 to 17 (0x4000 to 0x22000)
2010-05-13 18:42:30.93 spid12s Zeroing completed on T:\SQLData\MSSQL10.MSSQLSERVER\MSSQL\Data\templog.ldf
2010-05-13 18:42:30.93 spid12s Starting up database ‘tempdb’.
2010-05-13 18:42:30.96 spid12s FixupLogTail(progress) zeroing T:\SQLData\MSSQL10.MSSQLSERVER\MSSQL\Data\templog.ldf from 0x5000 to 0x6000.
2010-05-13 18:42:30.96 spid12s Zeroing T:\SQLData\MSSQL10.MSSQLSERVER\MSSQL\Data\templog.ldf from page 3 to 483 (0x6000 to 0x3c6000)
2010-05-13 18:42:30.96 spid12s Zeroing completed on T:\SQLData\MSSQL10.MSSQLSERVER\MSSQL\Data\templog.ldf
Hmm, so the log file is zeroed for tempdb, but it doesn’t take a rocket scientist to notice that the page counts being zeroed out (17-2=15 total pages) don’t add up to 4GB of space. To check this, I created a new user database with a 8GB data file, and a 4GB log file to see the output for zeroing out a 4GB transaction log.
2010-05-13 18:45:42.61 spid54 Zeroing L:\SQLData\MSSQL10.MSSQLSERVER\MSSQL\Data\ZeroLog_log.ldf from page 0 to 524288 (0x0 to 0x100000000)
2010-05-13 18:46:20.92 spid54 Zeroing completed on L:\SQLData\MSSQL10.MSSQLSERVER\MSSQL\Data\ZeroLog_log.ldf
2010-05-13 18:46:36.35 spid54 Starting up database ‘ZeroLog’.
2010-05-13 18:46:36.36 spid54 FixupLogTail(progress) zeroing L:\SQLData\MSSQL10.MSSQLSERVER\MSSQL\Data\ZeroLog_log.ldf from 0x5000 to 0x6000.
2010-05-13 18:46:36.36 spid54 Zeroing L:\SQLData\MSSQL10.MSSQLSERVER\MSSQL\Data\ZeroLog_log.ldf from page 3 to 483 (0x6000 to 0x3c6000)
2010-05-13 18:46:36.37 spid54 Zeroing completed on L:\SQLData\MSSQL10.MSSQLSERVER\MSSQL\Data\ZeroLog_log.ldf
So a user database with a 4GB log file will zero out 524288 pages which is 4GB of space. I got a private message on twitter about the topic from Remus Rusanu (Blog | Twitter), telling me that the entire file isn’t initialized at startup, but if you use ALTER DATABASE to grow the size of the tempdb log, the space you grow by will be zero initialized entirely, so to test that I grew the log file out to 8GB in size:
ALTER DATABASE [tempdb] MODIFY FILE ( NAME = N’templog’, SIZE = 8388608KB )
When I ran this, it returned completed immediately, so I jumped over to the ErrorLog to pull the results and was momentarily confused by what I got back.
2010-05-13 19:20:24.02 spid57 Zeroing T:\SQLData\MSSQL10.MSSQLSERVER\MSSQL\Data\templog.ldf from page 524288 to 524319 (0x100000000 to 0x10003e000)
2010-05-13 19:20:24.02 spid57 Zeroing completed on T:\SQLData\MSSQL10.MSSQLSERVER\MSSQL\Data\templog.ldf
It only initialized 31 pages?? Can that be correct? So I went back and checked my log files actual size and I remembered this little problem mentioned by Kimberly Tripp on her blog post Kimberly L. Tripp | Transaction Log VLFs – too many or too few? that occurs when you grow the file in 4GB increments. So I reran the ALTER DATABASE statement and this time it took a minute for the command to complete. Much better, now I know we did some zeroing out of the file, and the ErrorLog output proved it:
2010-05-13 19:21:17.47 spid57 Zeroing T:\SQLData\MSSQL10.MSSQLSERVER\MSSQL\Data\templog.ldf from page 524319 to 1048576 (0x10003e000 to 0x200000000)
2010-05-13 19:21:49.54 spid57 Zeroing completed on T:\SQLData\MSSQL10.MSSQLSERVER\MSSQL\Data\templog.ldf
Much better, so now the begging question is, why isn’t the log file zero initialized in its entirety at startup? I can’t speak with complete certainty on this, but I would guess that it has to do with the fact that the tempdb transaction log is never used for crash recovery, so it doesn’t really matter that the space isn’t zero initialized. Paul Randal explains in his blog post, In Recovery… | Search Engine Q&A #24: Why can’t the transaction log use instant initialization?, how the parity bits are used during crash recovery to identify where recovery should stop processing log records. Perhaps full zero initialization is skipped for the tempdb log at startup because the log is never used for crash recovery, but that doesn’t explain why the log, when grown, does perform full zero initialization, unless it is due to the way that the log can wrap around, for example based on the last image above (VLF Usage After Log Reuse), if the log space continues to be used without truncation when the log gets back to FSeqNo 29, the log will have to grow causing the allocation to become non-sequential since FSeqNo 30-35 are still active. Maybe someone else will explain the reason why the tempdb log has to be zero initialized when grown but not at startup better.
EDIT:
After posting this, I jumped back over to twitter and saw some interesting comments from Brent Ozar (Blog | Twitter) that made me go back and test the impact of deleting the tempdb files from disk and then starting the instance up. When I did this, the entire file was zero initialized
2010-05-13 20:21:06.21 spid12s Clearing tempdb database.
2010-05-13 20:21:06.23 spid12s Zeroing T:\SQLData\MSSQL10.MSSQLSERVER\MSSQL\Data\templog.ldf from page 0 to 1048576 (0x0 to 0x200000000)
<……….skipped content…………>
2010-05-13 20:22:22.81 spid12s Zeroing completed on T:\SQLData\MSSQL10.MSSQLSERVER\MSSQL\Data\templog.ldf
2010-05-13 20:22:22.84 spid12s Starting up database ‘tempdb’.
2010-05-13 20:22:22.85 spid12s FixupLogTail(progress) zeroing T:\SQLData\MSSQL10.MSSQLSERVER\MSSQL\Data\templog.ldf from 0x5000 to 0x6000.
2010-05-13 20:22:22.85 spid12s Zeroing T:\SQLData\MSSQL10.MSSQLSERVER\MSSQL\Data\templog.ldf from page 3 to 483 (0x6000 to 0x3c6000)
2010-05-13 20:22:22.86 spid12s Zeroing completed on T:\SQLData\MSSQL10.MSSQLSERVER\MSSQL\Data\templog.ldf
So the answer is YES the tempdb transaction log is completely initialized when it is first physically created, but after that, its not zero initialized entirely as the instance starts up. There is a definite difference in startup times on my server when I deleted the files.
With Files
2010-05-13 18:42:12.54 Server Microsoft SQL Server 2008 (SP1) – 10.0.2757.0 (X64)
2010-05-13 18:42:31.04 spid8s Recovery is complete. This is an informational message only. No user action is required.
Without Files
2010-05-13 20:21:05.49 Server Microsoft SQL Server 2008 (SP1) – 10.0.2757.0 (X64)
2010-05-13 20:22:22.97 spid9s Recovery is complete. This is an informational message only. No user action is required.
When the files preexist, instance startup only took 19 seconds, without the files it took 1 minute and 17 seconds. This actually makes the zero initialization during log growth make sense. I’d say a fair bit of my misunderstanding of this is the way tempdb is often referred to be as being recreated at restart. Its not actually recreated based on these tests, but it is cleared, as show by the “Clearing tempdb database.” log entries. Interesting stuff.
ANOTHER EDIT:
So after thinking about this some more, curiosity got the best of me and I wanted to know what would happen if the size of the tempdb log file on disk was different from the size configured for tempdb. To test this, I used ALTER DATABASE to change the size of the log file from 8GB to 1GB and restarted SQL Server. This reduced the size of the log file on startup from 8GB to 1GB and the log showed that it didn’t zero initialize the entire file:
2010-05-13 21:20:45.92 spid12s Clearing tempdb database.
<……….skipped content…………>
2010-05-13 21:21:02.59 spid12s Zeroing T:\SQLData\MSSQL10.MSSQLSERVER\MSSQL\Data\templog.ldf from page 2 to 17 (0x4000 to 0x22000)
2010-05-13 21:21:02.59 spid12s Zeroing completed on T:\SQLData\MSSQL10.MSSQLSERVER\MSSQL\Data\templog.ldf
2010-05-13 21:21:02.62 spid12s Starting up database ‘tempdb’.
2010-05-13 21:21:02.63 spid12s FixupLogTail(progress) zeroing T:\SQLData\MSSQL10.MSSQLSERVER\MSSQL\Data\templog.ldf from 0x5000 to 0x6000.
2010-05-13 21:21:02.63 spid12s Zeroing T:\SQLData\MSSQL10.MSSQLSERVER\MSSQL\Data\templog.ldf from page 3 to 483 (0x6000 to 0x3c6000)
2010-05-13 21:21:02.64 spid12s Zeroing completed on T:\SQLData\MSSQL10.MSSQLSERVER\MSSQL\Data\templog.ldf
In addition to this, the startup time was fast, taking only 17 seconds to complete recovery of the instance.
2010-05-13 21:20:45.23 Server Microsoft SQL Server 2008 (SP1) – 10.0.2757.0 (X64)
2010-05-13 21:21:02.78 spid9s Recovery is complete. This is an informational message only. No user action is required.
So I shut down SQL Server and renamed the log file to templog_small.ldf and then restarted SQL. Once recovery completed, I grew the transaction log back to 8GB and once again shutdown SQL Server. Then I renamed the current 8GB log file to templog_big.ldf and renamed templog_small.ldf to templog.ldf, replacing the 8GB log file with a 1GB log file. SQL Server recognized the change during startup, and once again zero initialized the entire log.
2010-05-13 21:25:11.72 spid12s Clearing tempdb database.
2010-05-13 21:25:11.73 spid12s Zeroing T:\SQLData\MSSQL10.MSSQLSERVER\MSSQL\Data\templog.ldf from page 0 to 1048576 (0x0 to 0x200000000)
<……….skipped content…………>
2010-05-13 21:26:17.95 spid12s Zeroing completed on T:\SQLData\MSSQL10.MSSQLSERVER\MSSQL\Data\templog.ldf
2010-05-13 21:26:28.05 spid12s Zeroing T:\SQLData\MSSQL10.MSSQLSERVER\MSSQL\Data\templog.ldf from page 2 to 17 (0x4000 to 0x22000)
2010-05-13 21:26:28.05 spid12s Zeroing completed on T:\SQLData\MSSQL10.MSSQLSERVER\MSSQL\Data\templog.ldf
2010-05-13 21:26:28.07 spid12s Starting up database ‘tempdb’.
2010-05-13 21:26:28.09 spid12s FixupLogTail(progress) zeroing T:\SQLData\MSSQL10.MSSQLSERVER\MSSQL\Data\templog.ldf from 0x5000 to 0x6000.
2010-05-13 21:26:28.09 spid12s Zeroing T:\SQLData\MSSQL10.MSSQLSERVER\MSSQL\Data\templog.ldf from page 3 to 483 (0x6000 to 0x3c6000)
2010-05-13 21:26:28.10 spid12s Zeroing completed on T:\SQLData\MSSQL10.MSSQLSERVER\MSSQL\Data\templog.ldf
This once again impacted the time required to recover the instance.
2010-05-13 21:25:11.01 Server Microsoft SQL Server 2008 (SP1) – 10.0.2757.0 (X64)
2010-05-13 21:26:28.23 spid9s Recovery is complete. This is an informational message only. No user action is required.
So that leaves me asking, does SQL Server really recreate tempdb from the model database every time it starts? According to KB Article 307487 :
“When SQL Server starts, the tempdb is re-created by using a copy of the model database and is reset to its last configured size.”
It would certainly seem as if this statement is wrong based on testing. What I find the most interesting is if I reverse the process and replace a 1GB log file with a previously created 8GB log file, SQL Server doesn’t zero initialize the 8GB file, it just shrinks it back to 1GB. It only performs the zero initialization as a part of having to grow the preexisting log file during instance startup.