Thursday, March 17, 2016

Log Backup, Checkpoint, and Log_Reuse_Wait Status


Testing Environment: SQL 2014

Recently, I encountered an issue of log_reuse_wait column not changing even after taking log backup. The database was not replicated or mirrored.

So, I decided to do some testing to understand when and how this value changes.

Testing database: RajeevSub

I created a table in the database.

USE RajeevSub
GO

CREATE TABLE testbl (NAME CHAR(1000))
GO

Let’s look at the tranlog of this database.

DBCC loginfo


Currently, VLF 307 is in use and none else have data in them.
Let’s look at the log_reuse_wait column for this DB.
SELECT name, log_reuse_wait_desc FROM sys.databases WHERE name = 'RajeevSub'
As of now, it shows NOTHING. Now, I insert 20000 rows into this table.
INSERT INTO testbltbl
SELECT 'AAAAAAAAAAAAAAAAAAAAA'
GO 20000
 
Let's look at log info now.
The VLF 308 has filled up completely and log has rolled over into 309. So, 308 can be reused if it is truncated. Let’s look at log_reuse_wait column for this DB.
SELECT name, log_reuse_wait_desc FROM sys.databases WHERE name = 'RajeevSub'
It still shows NOTHING. Now, let’s run checkpoint and check log_reuse_wait again.
CHECKPOINT
SELECT name, log_reuse_wait_desc FROM sys.databases WHERE name = 'RajeevSub'
This time, it changes to “Log_Backup”. Tranlog VLF can only be truncated after pages have been checkpointed to disk. Until then it cannot be truncated. Actually, the log_reuse_wait_desc should have shown CHECKPOINT as the reason instead of NOTHING earlier.
Now, let us take a tranlog backup and check log_reuse_wait.
BACKUP LOG rajeevsub TO DISK ='null'
 
SELECT name, log_reuse_wait_desc FROM sys.databases WHERE name = 'RajeevSub'
It still shows Log_Backup. Let’s check loginfo.
It shows that 308 is not active anymore. 309 is the only active VLF. So, log backup cleared tran log but still, log_reuse_wait keeps showing log_backup as the reason log cannot be truncated. In fact, tranlog did get truncated as 308 is ready to be reused if needed. Let’s run checkpoint and check this column again.
CHECKPOINT
SELECT name, log_reuse_wait_desc FROM sys.databases WHERE name = 'RajeevSub'
Now, it changed to NOTHING. It appears that the status in log_reuse_wait_desc is not always correct. This time, it was just waiting for CHECKPOINT to occur.
Now, let’s run log backup without doing any transactions and check this column again.
BACKUP LOG rajeevsub TO DISK ='null'
GO
SELECT name, log_reuse_wait_desc FROM sys.databases WHERE name = 'RajeevSub'
Whaaatt!! I did not do any transaction, there was no log to truncate and still it changed log_reuse_wait status to Log_Backup after taking log backup.
Let’s run checkpoint and check status.
CHECKPOINT
SELECT name, log_reuse_wait_desc FROM sys.databases WHERE name = 'RajeevSub'
It changed back to “Nothing”. Actually, it was waiting for Checkpoint to occur.
Let’s look at the tranlog content and try to figure it out.
Using below command, here is the output from log.
SELECT * FROM fn_dblog(null,null)

Please ignore the first part of numbers in Current LSN column. It shows 13b which is VLF number 315 as there was long gap between the first half and second half of this article. In the first half, we were working with files 308 and 309.
Now, I will take a backup and look at tran log entries again. Note that tran log backup itself is a transaction as shown by highlighted tran log entries.
Log_reuse_wait_desc shows LOG_BACKUP.
Running Checkpoint again and looking at tran log entries.
This shows that log_reuse_wait_desc does not change to NOTHING until the last transaction after log backup is checkpointed to the disk. After log_reuse_wait_desc changes to NOTHING, it will wait for the current VLF to fill up or a tranlog backup to happen before it changes the log_reuse_wait_desc to LOG_BACKUP.
I am not sure if I confused you or clarified things to you. May be, it will make more sense when you test it out yourself. ☺