Oct
28
2015

Daylight Savings end affects not only you, but your SQL Server too

The last weekend of October is a common date for the daylight savings (or summer time) to get to its end in the north hemisphere.

According to Wikipedia:

Daylight saving time (DST) or summer time is the practice of advancing clocks during summer months by one hour so that in the evening daylight is experienced an hour longer, while sacrificing normal sunrise times. Typically, users in regions with summer time adjust clocks forward one hour close to the start of spring and adjust them backward in the autumn to standard time.

So last Sunday we moved the clock backwards one hour at 3am, so we have our clocks pointing 2am twice.

And how that affects me as DBA? Well, long story short… Your backup log chain can be broken, but please keep reading to see why.

 
Transaction Log Architecture
 

SQL Server in order to make transactions durable and recoverable in the event of a crash uses the transaction log, which is one of the database files and any database in SQL Server must have one.

This file contains a description of any change that has happened to the database, that allows transactions to be rolled back, Availability Group replicas and Mirror databases to be synchronized and so on.

Each record within the log file has its own LSN (log sequence number) which is an ever increasing identifier, that way each change is perfectly identified in the order that it occurred.

When your databases use the full or bulk logged recovery model, you have to take care of the transaction log by doing often enough transaction log backups which will [eventually] truncate the log file and allow you to restoring the database to a specific point in time.

Restoring to a point is time is the reason why most of the shops out there use the full recovery model for their databases and DBA’s run SQL Agent jobs or Maintenance plans to perform transaction log backups periodically.

 
BACKUP LOG
 

According to BOL, BACKUP LOG does:

Under the full recovery model or bulk-logged recovery model, backs up the transaction log of the database to create a log backup

Depending on your RPO those transaction log backups happen more o less frequent, a common pattern can be every hour.

One of the many arguments for the BACKUP T-SQL statement is [INIT|NOINIT] which “Controls whether the backup operation appends to or overwrites the existing backup sets on the backup media. The default is to append to the most recent backup set on the media (NOINIT).”.

That’s it if you take your backups specifying WITH INIT the backup media will be overwritten in case it does exist.

So if you have taken a backup at 2am using the pattern DBName_yyyymmdd_hhmm.trn WITH INIT, and you do it twice because of the DST, the second backup will overwrite the first and break the log chain

Let’s see how it happens.

IF DB_ID('LogChain') IS NOT NULL DROP DATABASE [LogChain]
GO
 
CREATE DATABASE [LogChain]
GO
 
ALTER DATABASE [LogChain] SET RECOVERY FULL
GO
 
-- Full backup taken on October 25th at midnight 
BACKUP DATABASE [LogChain] TO DISK = 'LogChain_Full_backup_INIT_20151025.bak' WITH INIT
GO
 
-- Log backup taken on October 25th at 1am
BACKUP LOG [LogChain] TO DISK = 'LogChain_Log_backup_INIT_20151025_010000.trn' WITH INIT
GO
 
-- Log backup taken on October 25th at 2am
BACKUP LOG [LogChain] TO DISK = 'LogChain_Log_backup_INIT_20151025_020000.trn' WITH INIT
GO
 
-----------------------------------------------------------------------------------
-- DST Applies here, so after 02:59, it is again 02:00
-----------------------------------------------------------------------------------
 
-- Log backup taken on October 25th at 2am (second time)
BACKUP LOG [LogChain] TO DISK = 'LogChain_Log_backup_INIT_20151025_020000.trn' WITH INIT
GO
 
-- Log backup taken on October 25th at 3am
BACKUP LOG [LogChain] TO DISK = 'LogChain_Log_backup_INIT_20151025_030000.trn' WITH INIT
GO
 
-- Log backup taken on October 25th at 4am
BACKUP LOG [LogChain] TO DISK = 'LogChain_Log_backup_INIT_20151025_040000.trn' WITH INIT
GO
 
-----------------------------------------------------------------------------------
-- Now we have to restore to some point between 3am and 4am, say 03:30
-----------------------------------------------------------------------------------
 
-- Full Backup
RESTORE DATABASE [LogChain]
    FROM DISK = 'LogChain_Full_backup_INIT_20151025.bak'
    WITH REPLACE, NORECOVERY
GO
 
-- Transaction Log backup (1am)
RESTORE LOG [LogChain]
    FROM DISK = 'LogChain_Log_backup_INIT_20151025_010000.trn'
    WITH NORECOVERY
GO
 
-- Transaction Log backup (2am)
RESTORE LOG [LogChain]
    FROM DISK = 'LogChain_Log_backup_INIT_20151025_020000.trn'
    WITH NORECOVERY
GO
--Msg 4305, Level 16, State 1, Line 48
--The log in this backup set begins at LSN 37000000020800001, which is too recent to apply to the database. An earlier log backup that includes LSN 37000000019200001 can be restored.
--Msg 3013, Level 16, State 1, Line 48
--RESTORE DATABASE is terminating abnormally.
 
RESTORE HEADERONLY FROM DISK = 'LogChain_Log_backup_INIT_20151025_020000.trn'
-- Just one line, the first log backup is lost 
 
-- Transaction Log backup (3am)
RESTORE LOG [LogChain]
    FROM DISK = 'LogChain_Log_backup_INIT_20151025_030000.trn'
    WITH NORECOVERY
GO
 
-- Transaction Log backup (4am)
RESTORE LOG [LogChain]
    FROM DISK = 'LogChain_Log_backup_INIT_20151025_040000.trn'
    WITH NORECOVERY, STOPAT = '20151025 03:30:00'
GO

You can see how all transactions after the 1am LOG BACKUP are lost and nothing can be done except taking a new full backup to restart the chain, not really nice situation to be.

If instead of using INIT, we use NOINIT, the behavior is different as it will not overwrite the media

IF DB_ID('LogChain') IS NOT NULL DROP DATABASE [LogChain]
GO
  
CREATE DATABASE [LogChain]
GO
  
ALTER DATABASE [LogChain] SET RECOVERY FULL
GO
  
-- Full backup taken on October 25th at midnight 
BACKUP DATABASE [LogChain] TO DISK = 'LogChain_Full_backup_NOINIT_20151025.bak' WITH NOINIT
GO
  
-- Log backup taken on October 25th at 1am
BACKUP LOG [LogChain] TO DISK = 'LogChain_Log_backup_NOINIT_20151025_010000.trn' WITH NOINIT
GO
  
-- Log backup taken on October 25th at 2am
BACKUP LOG [LogChain] TO DISK = 'LogChain_Log_backup_NOINIT_20151025_020000.trn' WITH NOINIT
GO
  
-----------------------------------------------------------------------------------
-- DST Applies here, so after 02:59, it is again 02:00
-----------------------------------------------------------------------------------
  
-- Log backup taken on October 25th at 2am (second time)
BACKUP LOG [LogChain] TO DISK = 'LogChain_Log_backup_NOINIT_20151025_020000.trn' WITH NOINIT
GO
  
-- Log backup taken on October 25th at 3am
BACKUP LOG [LogChain] TO DISK = 'LogChain_Log_backup_NOINIT_20151025_030000.trn' WITH NOINIT
GO
  
-- Log backup taken on October 25th at 4am
BACKUP LOG [LogChain] TO DISK = 'LogChain_Log_backup_NOINIT_20151025_040000.trn' WITH NOINIT
GO
  
-----------------------------------------------------------------------------------
-- Now we have to restore to some point between 3am and 4am, say 03:30
-----------------------------------------------------------------------------------
  
-- Full Backup
RESTORE DATABASE [LogChain]
    FROM DISK = 'LogChain_Full_backup_NOINIT_20151025.bak'
    WITH REPLACE, NORECOVERY
GO
  
-- Transaction Log backup (1am)
RESTORE LOG [LogChain]
    FROM DISK = 'LogChain_Log_backup_NOINIT_20151025_010000.trn'
    WITH NORECOVERY
GO
 
--=================================================== 
RESTORE HEADERONLY FROM DISK = 'LogChain_Log_backup_NOINIT_20151025_020000.trn'
-- We have 2 lines, so the 1st backup can be restored and so can be the 2nd
--===================================================
 
-- Transaction Log backup (2am)
RESTORE LOG [LogChain]
    FROM DISK = 'LogChain_Log_backup_NOINIT_20151025_020000.trn'
    WITH FILE = 1, NORECOVERY
GO
  
RESTORE LOG [LogChain]
    FROM DISK = 'LogChain_Log_backup_NOINIT_20151025_020000.trn'
    WITH FILE = 2, NORECOVERY
GO
  
-- Transaction Log backup (3am)
RESTORE LOG [LogChain]
    FROM DISK = 'LogChain_Log_backup_NOINIT_20151025_030000.trn'
    WITH NORECOVERY
GO
  
-- Transaction Log backup (4am)
RESTORE LOG [LogChain]
    FROM DISK = 'LogChain_Log_backup_NOINIT_20151025_040000.trn'
    WITH NORECOVERY, STOPAT = '20151025 03:30:00'
GO
 
 

Our backup log chain is intact and any point in time restore is possible.

Just for clarification, the backup media generated twice at 2am contains 2 different backups, which can be seen by doing RESTORE HEADERONLY and can be restored individually one after another.

 
Useful Links

Just a bit of wrap up, further reading for the concepts involved:

2 comments
  1. Abe Newton says:

    With the NOINIT method is there still 2 hours worth of transaction between the no 1 and 2am, and how or can we access the first set over the other?

    • Raul says:

      Hi Abe,

      you can access each backup individually within the media using [fileNumber], so the 2am log backup can be split into these 2 commands

      RESTORE DATABASE [LogChain]
      FROM DISK = ‘LogChain_Log_backup_NOINIT_20151025_020000.bak’
      WITH FILE = 1, REPLACE, NORECOVERY
      GO
      RESTORE DATABASE [LogChain]
      FROM DISK = ‘LogChain_Log_backup_NOINIT_20151025_020000.bak’
      WITH FILE = 2, REPLACE, NORECOVERY
      GO

      To see the order of the files within the media you can use

      RESTORE HEADERONLY
      FROM DISK = ‘LogChain_Log_backup_NOINIT_20151025_020000.bak’
      GO

      Thanks for commenting, I’ll probably update the post to clarify this point

Leave a Reply

Your email address will not be published. Required fields are marked *