Lazy Log Truncation – Clearing of SQL transaction log VLF status deferred

I came across an oddity in the transaction log when I was testing Availability Group backup scenarios which really had me confused.  It required some help from my colleague Denzil and a few others to figure out what was going on.  This adventure taught us about Lazy Log Truncation.  This is not new to SQL 2012 as it also exists in SQL 2008R2 (and possibly prior), but only when a database is being mirrored or participating in an Availability Group.

For more on VLF’s and transaction log architecture: Transaction Log Physical Architecture

Before getting into the oddity that Lazy Log Truncation brings into play, let’s first look at what you normally see in the transaction log as it is filled and truncated.

I started off creating a database with a fixed log file size of 100MB in full recovery model.  I have this all in the attached script for you to try on your own as well. Once that is set up, take a full database backup to get full recovery model going.  Then run DBCC LOGINFO to show you the current VLFs in the database.

 

USE [LLTTest]

GO

DBCC LOGINFO --you see here that there are 8 VLFs with 1 that has a status of 2

GO

clip_image002

The status value of 2 means that it is the active portion of the log, meaning that it contains data that needs to be backed up in order for that VLF to be able to be used again.

Next we will do some work in the database that will generate a little log activity.

CREATE TABLE test1 ( myvarchar varchar(5000))

GO

INSERT INTO test1 VALUES( replicate('*',5000))

GO 5000

DELETE FROM test1

Now take a look at DBCC LOFINGO again and you can see that more of the VLFs contain active transaction log data.

clip_image004

Next, we take a backup of the transaction log in order to clear out all the full VLFs and run DBCC LOGINFO again. Note that FSeqNo 35 is still marked as active.  This is because only full VLFs that do not contain log records for active transactions or records needed for replication (mirroring, CDC, replication, etc) are truncated. Also note that there must always be at least 1 active VLF.

BACKUP LOG [LLTTest] TO DISK = N'C:\Program Files\Microsoft SQL Server\MSSQL11.MSSQLSERVER\MSSQL\Backup\LLTTest.bak' WITH NOFORMAT, NOINIT, NAME = N'LLTTest-Transaction Log Backup', SKIP, NOREWIND, NOUNLOAD, STATS = 10

GO

DBCC LOGINFO --after the tlog backup all but one of the VLFs are inactive (status 0)

GO

 

clip_image006

 

This is exactly what you would expect to see, no surprises here.    When it becomes interesting is when you do this same test against a database participating in an Availability Group.  For the sake of keeping this blog entry from being too long, I am not showing you how to add this db to an availability group, but you can do so on your own using the GUI tools.

After adding this database to an availability group, there was no change to the output of DBCC LOGINFO, but one interesting thing to note is that the DBCC LOGINFO output will be identical across all the replicas when everything is synchronized.

Now, we are doing to do the same work we did before to put some activity in the transaction log.

INSERT INTO test1 VALUES( replicate('*',5000))

GO 5000

GO

DELETE FROM test1

GO

DBCC LOGINFO --Nothing special here, you can see more active VLFs

GO

This looks similar to what we saw before, it is just that different VLFs are being used and the activity rolled over to the beginning of the log file since I have the file set to a fixed size (to make this easier to demo).

clip_image008

Now we will backup the transaction log to truncate the VLFs, right? 

BACKUP LOG [LLTTest] TO DISK = N'C:\Program Files\Microsoft SQL Server\MSSQL11.MSSQLSERVER\MSSQL\Backup\LLTTest.bak' WITH NOFORMAT, NOINIT, NAME = N'LLTTest-Transaction Log Backup', SKIP, NOREWIND, NOUNLOAD, STATS = 10

GO

DBCC LOGINFO

GO

ACK! The status didn't clear to 0 on any of the VLFs?! The DBCC LOGINFO output did not change at all. The replica is fully synchronized, so we know it is not due to data not being at all the replicas. The transaction log backup file does contain data, so are those VLFs cleared out or not?

clip_image010

 

If we do work again, what will happen? We think the transaction log was just backed up so there should be plenty of free space right? Running DBCC SQLPERF ('LOGSPACE') confirms that. So what will happen? Will the transaction log fill and return an error? This seems very confusing. Well let's give it a shot!

INSERT INTO test1 VALUES( replicate('*',5000))

GO 5000

DELETE FROM test1

--Spoiler Alert: IT WORKS!!

GO

DBCC LOGINFO

GO

 

You can see that FSeqNo 32-35 have been replaced with 40-43.  Even though the VLFs were still considered active, they were able to be reused since they were part of the previous transaction log backup.

clip_image012

We noticed that in a mirroring or Availability Group scenario, Lazy Log Truncation marks the VLFs for truncation, but it does not actually truncate the log unless those VLFs are necessary.  Why is this done?  Well, the primary log truncation has to retain log which may be in use at any of the secondaries. When adding a replica, this aids in minimizing the number of transaction log backups that must be restored in order to get the replica transaction log at the same point as the primary. 

Is this something that you need to be aware of?  Not really, but we thought it was an interesting tidbit about how Availability Groups and mirroring have had so much thought put into them.  We also didn’t want you to be concerned if you happened to notice that a lot of your VLFs are marked as active when you think they have been backed up and should be truncated.

Lisa Gardner – Premier Field Engineer