One DBA's Ongoing Search for Clarity in the Middle of Nowhere


*or*

Yet Another Andy Writing About SQL Server

Tuesday, December 22, 2015

The transaction log for database 'ABC' is full due to 'ACTIVE_BACKUP_OR_RESTORE'

I have recently had a client with a problem each morning where they were having processes fail with this message in their SQL Server Error Log:
Date 12/01/2015 5:58:48 AM
Log SQL Server (Current - 12/01/2015 1:00:00 PM)
Source spid118
Message Error: 9002, Severity: 17, State: 3.
--
Date 12/01/2015 5:58:48 AM
Log SQL Server (Current - 12/01/2015 1:00:00 PM)
Source spid118
Message The transaction log for database 'ABC' is full due to 'ACTIVE_BACKUP_OR_RESTORE'.
Their question was how their log could be full since their database is in SIMPLE recovery.   

Their particular situation is that database ABC is a 650GB OLTP database, and the backup to the remote location was taking 7-8 hours each night over the time in question:

server_name
database_name
backup_start_date
backup_finish_date
physical_device_name
type
BackupSizeGB
Server1
ABC
12/4/2015 23:30
12/5/2015 7:11
VNBU0-29756-4248-1450758615
D
630
Server1
ABC
12/3/2015 0:00
12/3/2015 7:46
VNBU0-33644-31396-1450499421
D
630
Server1
ABC
12/1/2015 23:30
12/2/2015 6:22
VNBU0-30500-35052-1450413013
D
424
Server1
ABC
11/30/2015 23:30
12/1/2015 6:37
VNBU0-18236-33032-1450326613
D
468
Server1
ABC
10/30/2015 23:30
10/31/2015 4:51
VNBU0-5696-14276-1447734610
D
386
Server1
ABC
10/29/2015 0:05
10/29/2015 5:27
VNBU0-14976-21580-1447475427
D
378
Server1
ABC
10/27/2015 23:31
10/28/2015 4:59
VNBU0-18040-27960-1447389025
D
367
Server1
ABC
10/26/2015 23:31
10/27/2015 4:34
VNBU0-20180-26980-1447302625
D
356
Server1
ABC
10/25/2015 23:31
10/26/2015 5:00
VNBU0-22808-28180-1447216223
D
372
Server1
ABC
10/24/2015 23:31
10/25/2015 5:21
VNBU0-6160-15336-1447129821
D
372
Server1
ABC
10/23/2015 23:31
10/24/2015 5:01
VNBU0-5396-24044-1447043425
D
359
Server1
ABC
10/22/2015 23:31
10/23/2015 7:47
VNBU0-8796-18884-1446957027
D
375
Server1
ABC
10/21/2015 23:37
10/22/2015 5:29
VNBU0-18032-28004-1446870623
D
364
Server1
ABC
10/20/2015 23:31
10/21/2015 5:00
VNBU0-8692-19836-1446784216
D
371


The way FULL backups work in SQL Server, the transaction log is not released for re-use during a FULL backup, even if regular LOG backups are occurring or the database is in SIMPLE recovery.  This is due to the fact that the portion of the LOG that is used during the FULL has to be persisted during the FULL in order to be backed up at the end of the FULL – that is, the FULL backup includes the data at the start of the FULL (23:30) *plus* the LOG used until the end of the FULL (in the case of the 12/04-12/05 backup, the LOG used from 23:30 to 07:11).  This is the meaning of the ACTIVE_BACKUP_OR_RESTORE message – the LOG is waiting for the end of the active FULL backup before it can be released for re-use, which in this case was causing the LOG/LDF file to grow to fill its mount point.

What this means is that the LOG file has to be large enough (or be able to auto-grow large enough) to hold all of the work done during the FULL backup.  In this system (like many others) there is maintenance done overnight (the largest on this system being a purge job which runs for 7-8 hours each night against database ABC almost exactly during this same time window).  This maintenance was generating hundreds of GB of LOG each night during the FULL backup, resulting in the errors shown above.

For this client, the problem turned out to be that the NetBackup process performing these particular backups had been replaced by a snapshot style backup and disabled at the end of October but had recently been accidentally re-enabled.  Shutting off this NetBackup schedule killed these backups, directly resolving the issue.

The alternative would be to have a sufficiently large LOG/LDF file to hold the work done during the FULL backup - even in SIMPLE recovery this is required.  Another option would be to examine the nightly maintenance and schedule it to a different window, away from the FULL backup to minimize the amount of LOG/LDF that needs to persist during the FULL.

Many people don't consider this situation, and it doesn't come up frequently - usually only in this specific situation of a relatively large database that is also high traffic to fill the LOG during the FULL.

Hope this helps!

--

NOTE: as I was finishing polishing this for release I noticed that Erik Darling (blog/@dumb_chauffeur) released a similar post earlier today "What happens to transaction log backups during full backups?" on the Brent Ozar Unlimited blog.  His post has good detail on proving the situation's existence via the Log Sequence Numbers (LSNs) stored in the FULL and LOG backups.




5 comments:

  1. Brent is awesome, but this article you have written was also very good and explained the exact issue that happened for myself, thank you!

    ReplyDelete
  2. Hi Andy,
    I m facing similar issue, the Trn log grows as much as 150Gb during the nightly Diff backup, we do NOT have any maintenance or any big updates running during Diff backup. Diff backup runs after major ETL job is done. What could be the reason for the bulge in trn log even though we don't have any big updates on DB? Db size 1Tb, Diff backup size about 250Gb.


    ReplyDelete
    Replies
    1. Is there anything long running (long running transactions) that would persist in the log and have to be retained? After the DIFF is completed does the space in the LDF immediately clear?

      Delete
  3. ETL jobs run before the Diff backup until then Trn log use remains low, as soon as Diff backup starts, Trn log starts growing and drop immediately after backup is complete (backup runs about 3 hours).

    ReplyDelete