SQL Trace Flag 3004 and BACKUP database
Quick one today � Someone asked me if there\’s a starting equivalent of this message:
04/23/2014 11:46:53,Backup,Unknown,Database backed up. Database: foo creation date(time): 2013/11/07(12:19:59) pages dumped: 363 first LSN: 44:888:37 last LSN: 44:928:1 number of dump devices: 1 device information: (FILE=1 TYPE=DISK: {\’C:\\Temp\\foo.bak\’}). This is an informational message only. No user action is required.
You know, so we can track when a database backup starts, and what it\’s doing while backing up… and stuff…
There\’s plenty on trace flag 3004 for RESTORE operations from a backup file so you can identify which areas of your restore operations are taking a while, such as zeroing out and creating devices, etc, but not much on the BACKUP side of things. All I could see was that the trace flag would output detail to the error log if invoked thusly:
DBCC TRACEON (3004,3605,-1)
Take a look at http://blogs.msdn.com/b/psssql/archive/2008/01/23/how-it-works-what-is-restore-backup-doing.aspx for further reading on that. And there\’s plenty others as well, like http://jamessql.blogspot.co.uk/2013/07/trace-flag-for-backup-and-restore.html
I was a bit stumped for the BACKUP bit, so I asked the #sqlhelp tag on twitter if there was another flag for backup. Thanks to @SQLKiwi, turns out it\’s the same one.
So, with that trace flag turned on as above, the output you get in the SQL error log is far more detailed (I\’ve turned the list so it reads in the correct event order):
Date Source Severity Message
04/23/2014 11:47:51 spid52 Unknown BackupDatabase: Database foo
04/23/2014 11:47:51 spid52 Unknown Backup: Media open
04/23/2014 11:47:51 spid52 Unknown Backup: Media ready to backup
04/23/2014 11:47:51 spid52 Unknown Backup: Clearing differential bitmaps
04/23/2014 11:47:51 spid52 Unknown Backup: Bitmaps cleared
04/23/2014 11:47:51 spid52 Unknown BackupDatabase: Checkpoint done
04/23/2014 11:47:51 spid52 Unknown Backup: Scanning allocation bitmaps
04/23/2014 11:47:51 spid52 Unknown Backup: Done with allocation bitmaps
04/23/2014 11:47:51 spid52 Unknown BackupDatabase: Work estimates done
04/23/2014 11:47:51 spid52 Unknown Backup: Leading metadata section done
04/23/2014 11:47:51 spid52 Unknown Backup:Copying data
04/23/2014 11:47:51 spid52 Unknown Backup: DBReaderCount = 1
04/23/2014 11:47:51 spid52 Unknown Started file C:\\Program Files\\Microsoft SQL Server\\MSSQL11.TEST1\\MSSQL\\DATA\\foo.mdf
04/23/2014 11:47:51 spid52 Unknown Completed file C:\\Program Files\\Microsoft SQL Server\\MSSQL11.TEST1\\MSSQL\\DATA\\foo.mdf
04/23/2014 11:47:51 spid52 Unknown BackupDatabase: Database files done
04/23/2014 11:47:51 spid52 Unknown �正灵��慢�退%s : Log files done : Log files done
04/23/2014 11:47:51 spid52 Unknown Backup: Trailing config done
04/23/2014 11:47:51 spid52 Unknown Backup: MBC done
04/23/2014 11:47:51 spid52 Unknown BackupDatabase: Writing history records
04/23/2014 11:47:51 Backup Unknown Database backed up. Database: foo creation date(time): 2013/11/07(12:19:59) pages dumped: 362 first LSN: 44:1040:37 last LSN: 44:1072:1 number of dump devices: 1 device information: (FILE=1 TYPE=DISK: {\’C:\\ Temp\\foo.bak\’}). This is an informational message only. No user action is required.
04/23/2014 11:47:51 spid52 Unknown Writing backup history records
04/23/2014 11:47:51 spid52 Unknown BackupDatabase: Finished
With this detail, it\’s relatively simple to alert on when a BACKUP event starts, or any part of that backup event, and you could also use it for identifying which parts of your database backup are taking a long time.
Just though I should write something up for BACKUP as well as RESTORE…
Back soon….
The Modern Dataist 