The Curious Case Of The Phantom Last Log Backup!

I was extremely "busy" at work the other day. So much so, I was sat reading Paul Randal's Blog, when I came across an interesting article on how to tell if your database is really in Full Recovery, see here.

The general premise is that when you switch from Simple to Full recovery model, the model does not change until the log backup chain has been established, with a backup. This is called pseudo-simple mode, and can be recognised by a database that is in Full recovery model showing a NULL value for last_log_backup_lsn in sys.database_recovery_staus

I was a little board, so I though that I would have a look and make sure that our OLTP databases were really in Full Recovery Model, and they were, but much to my surprise I found that some of our VLDs that were in Simple Recovery Model were showing a non-NULL value in the last_log_backup_lsn column in sys.database_recovery_status catalogue view.

This confused me and I ask Paul Randal if there was a pseudo-full mode, but there is not, so why was there a last_log_backup_lsn? Well, intrigued, I kept an eye on the transaction logs of the databases involved, buy using SELECT * FROM sys.fn_dblog(NULL,NULL) which shows all log records in the active VLFs.

Day 1 - 7436 entries, day 2 - 762 entries.

This was good news! It meant that the log had been truncated, so the databases were behaving as if the were in Simple recovery model. This was a relief, as my initial fear was that they were behaving as though they were in Full, and of course, we were not taking Transaction Log backups, as we thought they were in Simple!

So the next test - Was this record of a last LSN only in the sys.database_recovery_status catalogue view or was it embedded more internally? To check this, I ran DBCC PAGE on the boot page of the database. The database ID happened to be 8, so the syntax was

DBCC TRACEON(3604)
DBCC PAGE(8,1,9,3)

Here, I turned on trace flag 3604, so that the DBCC output would be to the messages window, rather than the event log. The parameters for DBCC Page represent the Database ID, The file number, the page number and then the level of detail. The database boot page is always at page 9 of file 1 see here for more info on system pages.

The results showed that the boot page also contained the lsn and time stamp of the last log backup, so the mystery continued. Where did it come from? Unfortunately, it was a production system that I was looking at, so I was not able to play around with it too much, but after a few hours of trying different things, that I new had occurred on the production system, I managed to reproduce the symptom, with the following script:


CREATE DATABASE [lsn_test] ON  PRIMARY
USE [master]
GO
ALTER DATABASE [lsn_test] SET RECOVERY FULL WITH NO_WAIT
GO

The results were as expected...

name recovery_model_desc last_log_backup_lsn
lsn_test FULL NULL

So now...

BACKUP DATABASE [lsn_test]
TO  DISK = N'C:\Program Files\Microsoft SQL Server\MSSQL10.MSSQLSERVER=MSSQL\Backup\lsn_test.bak'
WITH NOFORMAT, NOINIT,  NAME = N'lsn_test-Full Database Backup',
SKIP, NOREWIND, NOUNLOAD,  STATS = 10
GO

Again, results as expected...

name recovery_model_desc last_log_backup_lsn
lsn_test FULL 25000000006200064

Next, was to switch the Database to Simple...

USE [master]
GO
ALTER DATABASE [lsn_test] SET RECOVERY SIMPLE WITH NO_WAIT
GO

Once more, predictable results...

name recovery_model_desc last_log_backup_lsn
lsn_test SIMPLE NULL

So now lets backup the database again...

BACKUP DATABASE [lsn_test] TO  DISK = N'C:\Program Files\Microsoft SQL=erver\MSSQL10.MSSQLSERVER\MSSQL\Backup\lsn_test.bak'
WITH NOFORMAT, NOINIT, 
NAME = N'lsn_test-Full Database Backup', SKIP, NOREWIND, NOUNLOAD,  ST=TS = 10
GO

Once more, the correct results...

name recovery_model_desc last_log_backup_lsn
lsn_test SIMPLE NULL

So finally, what happens if we restore the database...?

RESTORE DATABASE [lsn_test] FROM  DISK = N'C:\Program Files\Microsoft =QL Server\MSSQL10.MSSQLSERVER\MSSQL\Backup\lsn_test.bak'
WITH  FILE = 2,  NOUNLOAD,  STATS = 10
GO

Ah, this doesn't look so straight forward...!

name recovery_model_desc last_log_backup_lsn
lsn_test SIMPLE 25000000011900001
So basically, SQL has picked up the last log backup LSN from the restore, but it is meaningless, and essentially a bug. So in the end, it turned out not to be a major issue, but it was certainly interesting, tracking it down, and a big thanks to Paul Randal for helping me get my head around it!


Find my book, Pro SQL Server Administration on Amazon -

America

United Kingdom