Long Running Backup Jobs

• 
  Could you pls post the backup command you are using, and also the contents of a log (default folder C:\Documents and Settings\All Users\Application Data\Red Gate\SQL Backup\Log\<instance name>) that recorded an exceptionally long backup?
  
  Thanks.

  petey February 01, 2007 22:33

  - 0 +
• 
  Here's the command I'm using:
  

  DECLARE @exitcode int
  DECLARE @sqlerrorcode int
  exec master..sqlbackup N'-SQL "BACKUP DATABASES EXCLUDE [master, msdb, model]  TO DISK = ''\\sqldata\data\SQLBackups\hprhsdata\backup\<AUTO>'' WITH NAME = ''<AUTO>'', DESCRIPTION = ''<AUTO>'', ERASEFILES = 7, COMPRESSION = 2, THREADS = 1"', @exitcode OUTPUT, @sqlerrorcode OUTPUT
  IF (@exitcode <>0) OR (@sqlerrorcode <> 0)
  BEGIN
    RAISERROR ('SQL Backup job failed with exitcode: %d  SQL error code: %d', 16, 1, @exitcode, @sqlerrorcode)
  END
  

  
  It looks like the log files are too large to include in the post. I've included sections of two log files below. The first is from 01/23 and is typical of the performance I had seen up till then. The second is from 01/24 and shows the performance I've seen since then. If you 'd like to see the logs in their entirety, let me know and I can email them to you.
  

  ...
  
  1/23/2007 2:53:17 AM: Backing up TelAll (full database) to: 
    \\hprhsdata\Data\SQLBackups\HPRHSDATA\Backup\FULL_(local)_TelAll_20070123_025317.sqb
  
  1/23/2007 2:53:17 AM: BACKUP DATABASE [TelAll]  TO DISK = '\\hprhsdata\Data\SQLBackups\HPRHSDATA\Backup\FULL_(local)_TelAll_20070123_025317.sqb' WITH NAME = '<AUTO>', DESCRIPTION = '<AUTO>', ERASEFILES_ATSTART = 6, COMPRESSION = 2, THREADS = 1
  
  1/23/2007 2:53:25 AM: Deleting old backup file: \\hprhsdata\Data\SQLBackups\HPRHSDATA\Backup\FULL_(local)_TelAll_20070117_024549.sqb
  1/23/2007 2:55:32 AM: Backup data size    : 77.938 MB
  1/23/2007 2:55:32 AM: Compressed data size: 36.464 MB
  1/23/2007 2:55:32 AM: Compression rate    : 53.21%
  
  Processed 9880 pages for database 'TelAll', file 'TelAll_dat' on file 1.
  Processed 1 pages for database 'TelAll', file 'TelAll_log' on file 1.
  BACKUP DATABASE successfully processed 9881 pages in 3.397 seconds (23.826 MB/sec).
  --------------------------------------------------------------------------------
  ...
  

  ...
  
  1/24/2007 3:13:24 AM: Backing up TelAll (full database) to: 
    \\hprhsdata\Data\SQLBackups\HPRHSDATA\Backup\FULL_(local)_TelAll_20070124_031318.sqb
  
  1/24/2007 3:13:24 AM: BACKUP DATABASE [TelAll]  TO DISK = '\\hprhsdata\Data\SQLBackups\HPRHSDATA\Backup\FULL_(local)_TelAll_20070124_031318.sqb' WITH NAME = '<AUTO>', DESCRIPTION = '<AUTO>', ERASEFILES_ATSTART = 6, COMPRESSION = 2, THREADS = 1
  
  1/24/2007 3:44:07 AM: Backup data size    : 75.625 MB
  1/24/2007 3:44:07 AM: Compressed data size: 34.652 MB
  1/24/2007 3:44:07 AM: Compression rate    : 54.18%
  
  Processed 9584 pages for database 'TelAll', file 'TelAll_dat' on file 1.
  Processed 1 pages for database 'TelAll', file 'TelAll_log' on file 1.
  BACKUP DATABASE successfully processed 9585 pages in 3.314 seconds (23.691 MB/sec).
  --------------------------------------------------------------------------------
  ...
  

  Dowdian February 05, 2007 09:35

  - 0 +
• 
  If you were to create a backup to that same location manually, using the exact same command, does it take as long? Will removing the ERASEFILES_ATSTART = 6 option shorten the duration?

  petey February 05, 2007 11:30

  - 0 +
• 
  I removed ERASEFILES_ATSTART = 6 and replaced it with ERASEFILES = 7 on 02/01 and have not seen any change in the job's run-time.
  
  I ran the command from Query Analyzer. It completed successfully in about 24 minutes. Two differences that might account for this is that there were no files old enough to delete (they were deleted early this morning), and backup jobs run much faster outside my normal backup window because there's no contention from all the other backup jobs.
  
  After looking over last nights log, it looks like the delay is still occurring just after the file deletion step, so I modified the statement to delete files that were six days old rather that seven. This modified statement ran in Query Analyzer in about 25 minutes.
  
  If it's contention for resources, why then the sudden change on the 23rd?

  Dowdian February 05, 2007 13:39

  - 0 +
• 
  From the log, the actual backup takes under 4 seconds. However, the entire SQL Backup process took over 30 minutes. It would appear that some pre or post processing tasks are taking longer than usual. Usual suspects would be the deletion of logs, or the deletion of old backup files via ERASEFILES/ERASEFILES_ATSTART.
  
  If you can, try scheduling a backup without the ERASEFILES/ERASEFILES_ATSTART options for a day, to see if it is the cause of the problem.

  petey February 05, 2007 21:33

  - 0 +
• 
  I agree with you about the pre or post processing tasks being the probable culprit. I ran the statement manually this morning having removed the ERASEFILES option and found that the job finished in 16 minutes (40% improvement over yesterday). I've modified the scheduled job and will post the results tomorrow.
  
  Thanks for your help on this.

  Dowdian February 06, 2007 09:06

  - 0 +
• 
  Removing the ERASEFILES option brought the job run time right back down to normal, about 35 minutes. Any thoughts on where to go from here?

  Dowdian February 07, 2007 14:49

  - 0 +
• 
  Are there a lot of files (backup and non-backups) in the \sqldata\data\SQLBackups\hprhsdata\backup folder? SQL Backup needs to read each file, determine if it is a SQL Backup file, check if it is for the current server/database, before deciding if the file should be deleted.

  petey February 07, 2007 21:37

  - 0 +
• 
  Yes, there are a lot. The server hosts 26 databases. I do full's nightly and TLog's hourly on each. I keep the files for seven days on disk.
  
  I've updated the job to segregate the different database's backups into seperate folders and reset the ERASEFILES = 7 option.
  
  I believe we've got it , but I'll post the final results tomorrow.
  
  Thanks again.

  Dowdian February 08, 2007 13:05

  - 0 +
• 
  The job ran last night in 45 minutes, right back where it aught to be. Thanks very much for your help with this issue.

  Dowdian February 09, 2007 08:25

  - 0 +

Add comment

Please sign in to leave a comment.