SQL Backup

Latest version: 7.2

SQL Backup

Knowledge Base

Troubleshooting slow backup and restore tasks

Category: Troubleshooting & error messages
Date: 19 May 2009
Product: SQL Backup
When backing up or restoring a database using SQL Backup, the process may appear to take longer than it should. SQL Backup's own logs may indicate a high throughput for the restore, but the time taken to execute task itself may seem to go for too long.

Database backups can seem to take longer in SQL Backup due to its' own housekeeping tasks, such as deleting old backup history and erasing backup files that are older than the configured retention time. The remainder of this article, however, concerns only time delays caused by SQL Server tasks that must complete before SQL Backup can begin to backup or restore data.

Restoring a database using SQL Backup can cause time-consuming housekeeping and other SQL Server activity to initiate. For instance, when restoring a large database from a full backup, SQL Server needs to allocate the disk space before the restore can even begin. Some backup and restore activities may trigger a SQL Server checkpoint operation. None of these activities is accounted for by SQL Backup; if a lengthy operation needs to be carried out by SQL Server before the server is ready to accept data from SQL Backup's restore task, SQL Backup's status (exec master..sqbstatus) will report 0 bytes restored until SQL Server can accept the backup data stream from SQL Backup.

Fortunately, it is possible to detailed information about backup and restore operations from SQL Server using a trace flag. If you open a new query window in SQL Server Management Studio or Query Analyzer, and connect to the server's MASTER database using an account with a SYSADMIN role, executing the following query will turn on extra logging for the backup and restore operations of the SQL Server.

DBCC TRACEON (3004, 3605, -1)

When it is no longer necessary to obtain detailed information, the extra logging can be turned off again using

DBCC TRACEOFF (3004, 3605, -1)

Once you have executed the trace command, you may start to see the extra logging in the SQL Server activity logs immediately upon the next backup or restore operation. For instance, in Management->SQL Server Logs->Current in SQL Server Management Studio. In the following example log entry where the trace had been enabled, you will see that the creation of the data files for a new database being restored had taken approximately 34 seconds to initialize.

Date,Source,Severity,Message
06/06/2008 12:11:59,spid58,Unknown,RestoreDatabase: Finished
06/06/2008 12:11:59,spid58,Unknown,Restore: Done with MSDB maintenance
06/06/2008 12:11:59,spid58,Unknown,Writing backup history records
06/06/2008 12:11:59,Backup,Unknown,Database was restored: Database: MyBigDatabase<c/> creation date(time): 2007/03/04
(17:02:14)<c/> first LSN: 69877:8282:1<c/> last LSN: 69877:8383:1<c/> number of dump devices: 1<c/> device information:
(FILE=1<c/> TYPE=VIRTUAL_DEVICE: {'SQLBACKUP_BABB2FB2-2F7A-4E0F-B3DB-66D46CF18587'}). Informational message. No user action
required.
06/06/2008 12:11:59,spid58,Unknown,Restore: Writing history records
06/06/2008 12:11:59,spid58,Unknown,Resuming any halted fulltext crawls
06/06/2008 12:11:59,spid58,Unknown,Restore: Database is restarted
06/06/2008 12:11:59,spid58,Unknown,PostRestoreReplicationFixup for MyBigDatabase complete
06/06/2008 12:11:58,spid58,Unknown,PostRestoreReplicationFixup for MyBigDatabase starts
06/06/2008 12:11:58,spid58,Unknown,PostRestoreContainerFixups: fixups complete
06/06/2008 12:11:58,spid58,Unknown,PostRestoreContainerFixups: running fixups on MyBigDatabase
06/06/2008 12:11:56,spid58,Unknown,Recovery is writing a checkpoint in database 'MyBigDatabase' (10). This is an
informational message only. No user action is required.
06/06/2008 12:11:56,spid58,Unknown,Zeroing completed on D:\sql2005\MSSQL.1\MSSQL\Data\MyBigDatabase_LOG.LDF
06/06/2008 12:11:56,spid58,Unknown,Zeroing D:\sql2005\MSSQL.1\MSSQL\Data\MyBigDatabase_LOG.LDF from page 43788 to 43848
(0x15618000 to 0x15690000)
06/06/2008 12:11:56,spid58,Unknown,FixupLogTail() zeroing D:\sql2005\MSSQL.1\MSSQL\Data\MyBigDatabase_LOG.LDF from 0x15617e00
to 0x15618000.
06/06/2008 12:11:54,spid58,Unknown,Starting up database 'MyBigDatabase'.
06/06/2008 12:11:54,spid58,Unknown,Restore: Restarting database for ONLINE
06/06/2008 12:11:54,spid58,Unknown,Restore: Transitioning database to ONLINE
06/06/2008 12:11:54,spid58,Unknown,Restore: Done with fixups
06/06/2008 12:11:54,spid58,Unknown,Rollforward complete on database MyBigDatabase
06/06/2008 12:11:50,spid58,Unknown,Restore-Redo begins on database MyBigDatabase
06/06/2008 12:11:50,spid58,Unknown,The database 'MyBigDatabase' is marked RESTORING and is in a state that does not allow
recovery to be run.
06/06/2008 12:11:49,spid58,Unknown,Starting up database 'MyBigDatabase'.
06/06/2008 12:11:49,spid58,Unknown,Restore: Backup set restored
06/06/2008 12:11:49,spid58,Unknown,Restore: Data transfer complete on MyBigDatabase
06/06/2008 12:11:49,spid58,Unknown,FileHandleCache: 0 files opened. CacheSize: 12
06/06/2008 12:11:49,spid58,Unknown,Restore: LogZero complete
06/06/2008 12:11:49,spid58,Unknown,Restore: Waiting for log zero on MyBigDatabase
06/06/2008 12:09:45,spid58,Unknown,Zeroing completed on D:\sql2005\MSSQL.1\MSSQL\Data\MyBigDatabase_LOG.LDF
06/06/2008 12:09:11,spid58,Unknown,Restore: Transferring data to MyBigDatabase
06/06/2008 12:09:11,spid58,Unknown,Restore: Restoring backup set
06/06/2008 12:09:11,spid58,Unknown,Restore: Containers are ready
06/06/2008 12:09:11,spid58,Unknown,Zeroing D:\sql2005\MSSQL.1\MSSQL\Data\MyBigDatabase_LOG.LDF from page 1 to 132880 (0x2000
to 0x40e20000)
06/06/2008 12:09:11,spid58,Unknown,Restore: PreparingContainers
06/06/2008 12:09:11,spid58,Unknown,Restore: Attached database MyBigDatabase as DBID=10
06/06/2008 12:09:11,spid58,Unknown,Restore: BeginRestore (offline) on MyBigDatabase
06/06/2008 12:09:11,spid58,Unknown,Restore: Planning complete
06/06/2008 12:09:11,spid58,Unknown,Restore: Planning begins
06/06/2008 12:09:11,spid58,Unknown,Restore: Backup set is open
06/06/2008 12:09:11,spid58,Unknown,Restore: Configuration section loaded
06/06/2008 12:09:11,spid58,Unknown,Opening backup set
06/06/2008 12:09:11,spid58,Unknown,RestoreDatabase: Database MyBigDatabase
06/06/2008 12:08:58,spid58,Unknown,Restore: Configuration section loaded

Document ID: KB200806000267 Keywords: SQL,Backup,TRACEON,restore,slow,troubleshoot,hang

Was this article helpful?

Search support
Forums
Visit the SQL Backup forum.

SQL Backup

all SQL products

all products