Long Running Backup Jobs

DowdianDowdian Posts: 8
edited February 9, 2007 8:25AM in SQL Backup Previous Versions
I installed SQL Backup on 01/09/07 on a server named SQLDATA. From that time until 01/23/07 the average run time for the full nightly backup on SQLDATA was about 48 minutes (Fantastic!!!). The job's run time jumped up on the 23rd, however, and has been averaging 135 minutes since then.

There were two significant changes that I am aware of on SQLDATA on the 23rd. I created a new database, but that database was, and remains empty. Also, Microsoft patches were applied that day.

Based on the logs, it looks like the actual work of backing up the databases took a total of about 15 minutes last night, but there are significant time gaps between the backups of each database with a total run time of 116 minutes. This seems similar to the issue described in the Slow Copying? post I read today so I have moved the SQL Backup log files from the C: drive and set the configuration to delete them after two weeks. However, the log files on SQLDATA were not significant in number or in size, so I don't believe this is the cause of my issue.

Does anyone have any idea as to why these jobs suddenly began taking so long?
Dowdian
I write the code that makes the young girls cry.
· Share on Twitter

Comments

  • peteypetey Posts: 2,358 New member
    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.
    Peter Yeoh
    SQL Backup Consultant Developer
    Associate, Yohz Software
    Beyond compression - SQL Backup goodies under the hood, updated for version 8
    · Share on Twitter
  • DowdianDowdian Posts: 8
    Here's the command I'm using:
    DECLARE @exitcode int
DECLARE @sqlerrorcode int
exec master..sqlbackup N'-SQL "BACKUP DATABASES EXCLUDE &#91;master, msdb, model&#93;  TO DISK = ''\\sqldata\data\SQLBackups\hprhsdata\backup\&lt;AUTO&gt;'' WITH NAME = ''&lt;AUTO&gt;'', DESCRIPTION = ''&lt;AUTO&gt;'', ERASEFILES = 7, COMPRESSION = 2, THREADS = 1"', @exitcode OUTPUT, @sqlerrorcode OUTPUT
IF &#40;@exitcode &lt;&gt;0&#41; OR &#40;@sqlerrorcode &lt;&gt; 0&#41;
BEGIN
  RAISERROR &#40;'SQL Backup job failed with exitcode: %d  SQL error code: %d', 16, 1, @exitcode, @sqlerrorcode&#41;
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 &#40;full database&#41; to: 
  \\hprhsdata\Data\SQLBackups\HPRHSDATA\Backup\FULL_&#40;local&#41;_TelAll_20070123_025317.sqb

1/23/2007 2:53:17 AM: BACKUP DATABASE &#91;TelAll&#93;  TO DISK = '\\hprhsdata\Data\SQLBackups\HPRHSDATA\Backup\FULL_&#40;local&#41;_TelAll_20070123_025317.sqb' WITH NAME = '&lt;AUTO&gt;', DESCRIPTION = '&lt;AUTO&gt;', ERASEFILES_ATSTART = 6, COMPRESSION = 2, THREADS = 1

1/23/2007 2:53:25 AM: Deleting old backup file: \\hprhsdata\Data\SQLBackups\HPRHSDATA\Backup\FULL_&#40;local&#41;_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 &#40;23.826 MB/sec&#41;.
--------------------------------------------------------------------------------
...

    ...

1/24/2007 3:13:24 AM: Backing up TelAll &#40;full database&#41; to: 
  \\hprhsdata\Data\SQLBackups\HPRHSDATA\Backup\FULL_&#40;local&#41;_TelAll_20070124_031318.sqb

1/24/2007 3:13:24 AM: BACKUP DATABASE &#91;TelAll&#93;  TO DISK = '\\hprhsdata\Data\SQLBackups\HPRHSDATA\Backup\FULL_&#40;local&#41;_TelAll_20070124_031318.sqb' WITH NAME = '&lt;AUTO&gt;', DESCRIPTION = '&lt;AUTO&gt;', 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 &#40;23.691 MB/sec&#41;.
--------------------------------------------------------------------------------
...
    Dowdian
    I write the code that makes the young girls cry.
    · Share on Twitter
  • peteypetey Posts: 2,358 New member
    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?
    Peter Yeoh
    SQL Backup Consultant Developer
    Associate, Yohz Software
    Beyond compression - SQL Backup goodies under the hood, updated for version 8
    · Share on Twitter
  • DowdianDowdian Posts: 8
    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
    I write the code that makes the young girls cry.
    · Share on Twitter
  • peteypetey Posts: 2,358 New member
    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.
    Peter Yeoh
    SQL Backup Consultant Developer
    Associate, Yohz Software
    Beyond compression - SQL Backup goodies under the hood, updated for version 8
    · Share on Twitter
  • DowdianDowdian Posts: 8
    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
    I write the code that makes the young girls cry.
    · Share on Twitter
  • DowdianDowdian Posts: 8
    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
    I write the code that makes the young girls cry.
    · Share on Twitter
  • peteypetey Posts: 2,358 New member
    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.
    Peter Yeoh
    SQL Backup Consultant Developer
    Associate, Yohz Software
    Beyond compression - SQL Backup goodies under the hood, updated for version 8
    · Share on Twitter
  • DowdianDowdian Posts: 8
    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 :D, but I'll post the final results tomorrow.

    Thanks again.
    Dowdian
    I write the code that makes the young girls cry.
    · Share on Twitter
  • DowdianDowdian Posts: 8
    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
    I write the code that makes the young girls cry.
    · Share on Twitter
Sign In or Register to comment.