The Curious Case of… a truncated log file after a revert from snapshot

(The Curious Case of… used to be part of our bi-weekly newsletter but we decided to make it a regular blog post instead so it can sometimes be more frequent. It covers something interesting one of us encountered when working with a client, doing some testing, or were asked in a random question from the community.)

I had an email question last week from someone who was very concerned to see a truncated log file after a revert from snapshot. They thought they’d come across a SQL Server bug and wanted to know if I’d seen this before.

Well, the answer is ‘yes’, because that’s how SQL Server has behaved since SQL Server 2005 introduced database snapshots. Whenever you perform a revert to snapshot, the log file is discarded and a new one created with two 256KB VLFs.

This behavior is by design, but understandably surprises people. The idea is that the log does have to be reset during a revert, because the database is being wound backwards in time physically, rather than by rolling back transactions. You’d think that SQL Server would recreate the log at the size it was previously, but the thinking was (when we built the feature) that if the previous log size was very large, recreating it would potentially take a long time, as the log must be zero-initialized on first allocation in the file system. So, it just whacks the log down to two small VLFs, which means after a revert you’ll need to manually grow the log again.

Here’s an example using SQL Server 2019:

USE [master];
GO

IF DATABASEPROPERTYEX (N'SalesDB_Snapshot', N'Version') > 0
	DROP DATABASE [SalesDB_Snapshot];
GO

RESTORE DATABASE SalesDB
	FROM DISK = N'D:\SQLskills\DemoBackups\SalesDB2014.bak'
WITH STATS = 10, REPLACE;
GO

-- Create the snapshot
CREATE DATABASE [SalesDB_Snapshot]
ON (
	NAME = N'SalesDBData',
	FILENAME = N'C:\SQLskills\SalesDBData.mdfss')
AS SNAPSHOT OF [SalesDB];
GO

Now, looking at the log file size (using the old DBCC commands instead of the new DMVs so people playing with this on older versions can follow along) and some of the fields removed from the results for clarity:

DBCC LOGINFO (N'SalesDB');
DBCC SQLPERF (LOGSPACE);
GO
RecoveryUnitId FileId      FileSize             
-------------- ----------- -------------------- 
0              2           10420224             
0              2           10420224             
0              2           10420224             
0              2           10674176             

Database Name Log Size (MB) Log Space Used (%) Status
------------- ------------- ------------------ -----------
master        1.992188      43.77451           0
tempdb        7.992188      6.042278           0
model         19.61719      6.586021           0
SalesDB       39.99219      18.78174           0

Four VLFs of about 10MB each in the SalesDB database. Now I’ll revert to the snapshot and check again:

RESTORE DATABASE [SalesDB]
FROM DATABASE_SNAPSHOT = N'SalesDB_Snapshot';
GO

DBCC LOGINFO (N'SalesDB');
DBCC SQLPERF (LOGSPACE);
GO
RecoveryUnitId FileId      FileSize             
-------------- ----------- -------------------- 
0              2           253952
0              2           253952           

Database Name Log Size (MB) Log Space Used (%) Status
------------- ------------- ------------------ -----------
master        1.992188      43.77451           0
tempdb        7.992188      6.042278           0
model         19.61719      6.586021           0
SalesDB       0.484375      60.28226           0

You can see that the log has been reset to two 256KB VLFs.

Bottom line: it’s expected behavior you need to be aware of. It’s also a neat way to reset the VLFs in a log if someone created the initial log to be enormous and you want to resize it to be a lot smaller, as there’s no other way of reducing the size of the first couple of VLFs.

The Curious Case of… why a minimally-logged operation doesn’t make a log backup smaller

(The Curious Case of… used to be part of our bi-weekly newsletter but we decided to make it a regular blog post instead so it can sometimes be more frequent. It covers something interesting one of us encountered when working with a client, doing some testing, or were asked in a random question from the community.)

I had a question in email last week on why a minimally-logged operation doesn’t make a log backup smaller.

The clue to the answer is in the description of the operation: minimally-logged.

When you perform one of a few operations in the bulk-logged or simple recovery models (e.g. offline index build/rebuild, or bulk load where all requirements for minimal logging have been met – see this whitepaper) then SQL Server vastly reduces the amount of transaction log that’s generated. It does this by only logging the allocation of pages and extents for that operation, and not the contents of the pages themselves.

Now imagine that a log backup after such an operation backed up *only* the transaction log produced. On restoration of that database, including that log backup, the result would be a table or index comprised of empty pages – which is not allowed in SQL Server.

Bottom line: a log backup after a minimally-logged operation has to also back up the data file pages that were populated by the operation, so they can also be restored during the restore of the log backup. This is why a minimally-logged operation does not result in the next log backup being a lot smaller (but it may be a little bit smaller, because of difference in size of 8K data pages vs. log records containing pages).

PS As a corollary question, you may wonder how the log backup gets those data pages, because a log backup does not start with a checkpoint, and so surely those dirty pages are still just in memory and not on disk? No – because for minimally-logged operations, data file pages are written to disk immediately. This mechanism is called ‘eager writing’ and guarantees that the results of a minimally-logged operation are persisted on disk when the operation completes.

The Curious Case of… too few log records for an offline index rebuild

(The Curious Case of… used to be part of our bi-weekly newsletter but we decided to make it a regular blog post instead so it can sometimes be more frequent. It covers something interesting one of us encountered when working with a client, doing some testing, or were asked in a random question from the community.)

I had an email question today asking why there were too few log records for an offline index rebuild the person was doing. They were concerned that the index they were rebuilding in the full recovery model wasn’t being rebuilt properly because instead of seeing at least one log record per row, they were seeing far fewer.

There’s a very simple answer: SQL Server will always try to generate as little log volume as possible.

Let’s say you have an index with 100,000 rows, and 100 rows fit on each index leaf page. When doing an offline rebuild in the full recovery model, SQL Server will not log an LOP_INSERT_ROWS log record for each index row, as that’s too inefficient, given the 100+ bytes of overhead in each log record. Instead it will log about 1,000 LOP_FORMAT_PAGE log records, where each log record contains a full page image with 100 rows in it. That saves the overhead of 99 log records for each 100 rows inserted into the new index – for a total saving of 99,900 x log-record-overhead in log volume (as it would still have to log the LOP_FORMAT_PAGE log records for the page header of each of the 1,000 pages created).

And if you think about it carefully, that approach gives just the same ability to recover the transaction in the event of a crash, as the net effect of each approach is the same.

SQL Server does as much as it can to limit what gets logged for efficiency, which is a good thing if you think of all the places that log is used (including backups, restores, log shipping, replication, mirroring, AGs).