Extended stored procedure taking long time to finish

jfeldman

Hello,
We just loaded some normal NT hotfixes our production server. Now our backups(For log and full DB) are running for an extremely long time. I just ran a full backup thru the SQLbackup GUI on a 3GB database with compression level = 2, the backup window indicated a total time of 29min. However the Activity History shows the backup file created in 1min 31sec- which is what I'd expect for the whole process to run. Task manager showed SQBCoreServices using 82,000K of memory, SqlBackup.exe using 8,000k - DOnt know if that is normal, they're both down to < 10,000 and 3,000 k.

Normal Tlog backups jobs our taking multiple minutes when the History shows they took less than 10 secs - this causes the jobs to run beyond the next scheduled run....

I have tried reinstalling SQLbackup, but no improvement.



Specs:
NT server 5.2(2003) build 3790 SP1 8GB ram, QUAD Blade
SQL server 2005 Enterprise build 3050, 6.9 GB dedicated RAM
SQLBackp 4.6.0.815

jfeldman

Here is my command -SQL "BACKUP LOG [GMS] TO DISK = 'R:\GMS\<AUTO>' WITH NAME = '<AUTO>', DESCRIPTION = '<AUTO>', MAXTRANSFERSIZE = 262144,INIT, ERASEFILES =26h, COMPRESSION = 2,FILEOPTIONS = 1"

THis job took 3:48. the actual backup took 0.154. The job isn't doing anything other than the backup.

Here is the SQL back log

SQL Backup log file
12/22/2007 10:30:00 AM: Backing up GMS (transaction log) to:
R:\GMS\GMS_LOG_20071222_103000.sqb

12/22/2007 10:30:00 AM: BACKUP LOG [GMS] TO DISK = 'R:\GMS\GMS_LOG_20071222_103000.sqb' WITH NAME = '<AUTO>', DESCRIPTION = '<AUTO>', INIT, ERASEFILES = 26h, FILEOPTIONS = 1, COMPRESSION = 2

12/22/2007 10:30:00 AM: Backup data size : 21.188 MB
12/22/2007 10:30:00 AM: Compressed data size: 307.500 KB
12/22/2007 10:30:00 AM: Compression rate : 98.58%

Processed 2594 pages for database 'GMS', file 'GMS_Log' on file 1.
BACKUP LOG successfully processed 2594 pages in 0.154 seconds (137.940 MB/sec).
12/22/2007 10:30:02 AM: Deleting old backup file: R:\GMS\GMS_LOG_20071221_081800.sqb
12/22/2007 10:30:02 AM: Deleting old backup file: R:\GMS\GMS_LOG_20071221_082100.sqb
12/22/2007 10:30:02 AM: Deleting old backup file: R:\GMS\GMS_LOG_20071221_082400.sqb
12/22/2007 10:30:02 AM: Deleting old backup file: R:\GMS\GMS_LOG_20071221_082700.sqb
12/22/2007 10:30:03 AM: SQL Backup process ended.

12/22/2007 10:30:03 AM: Deleting log file: C:\Documents and Settings\All Users\Application Data\Red Gate\SQL Backup\Log\(LOCAL)\20070923 111631 01 {0181F5D0-82D8-4920-AA52-C6DAB13C5BF2}.log
12/22/2007 10:30:03 AM: Deleting log file: C:\Documents and Settings\All Users\Application Data\Red Gate\SQL Backup\Log\(LOCAL)\20070923 111631 01 {8560942C-6327-4B9D-BBF8-274B96141B61}.log
12/22/2007 10:30:03 AM: Deleting log file: C:\Documents and Settings\All Users\Application Data\Red Gate\SQL Backup\Log\(LOCAL)\20070923 111719 01 {11BCCF50-E98E-463C-8447-DFCF9F163418}.log
12/22/2007 10:30:03 AM: Deleting log file: C:\Documents and Settings\All Users\Application Data\Red Gate\SQL Backup\Log\(LOCAL)\20070923 111908 01 {A11FEAB0-3947-47F6-AE37-34C6C60F4DA4}.log
12/22/2007 10:30:03 AM: Deleting log file: C:\Documents and Settings\All Users\Application Data\Red Gate\SQL Backup\Log\(LOCAL)\20070923 112121 01 {7B5C30FF-0138-40C9-B77B-36AC651F17A6}.log
12/22/2007 10:30:03 AM: Deleting log file: C:\Documents and Settings\All Users\Application Data\Red Gate\SQL Backup\Log\(LOCAL)\20070923 112121 01 {F409B38B-CFD3-4E5D-B87A-9FD1C32C78A7}.log
12/22/2007 10:30:03 AM: Deleting log file: C:\Documents and Settings\All Users\Application Data\Red Gate\SQL Backup\Log\(LOCAL)\20070923 112307 01 {A06FD324-6E6B-425F-8BA6-2C6FE26C54C1}.log
12/22/2007 10:30:03 AM: Deleting log file: C:\Documents and Settings\All Users\Application Data\Red Gate\SQL Backup\Log\(LOCAL)\20070923 112507 01 {EE55BEE3-7120-411A-AE99-8C4EE3A03D8D}.log
12/22/2007 10:30:03 AM: Deleting log file: C:\Documents and Settings\All Users\Application Data\Red Gate\SQL Backup\Log\(LOCAL)\20070923 112621 01 {B9CF14A0-6D14-4F81-AD01-3C83238B442B}.log
12/22/2007 10:30:03 AM: Deleting log file: C:\Documents and Settings\All Users\Application Data\Red Gate\SQL Backup\Log\(LOCAL)\20070923 112712 01 {439B6D6B-8E5D-4BE7-B22F-69A945CE6DA5}.log
12/22/2007 10:30:03 AM: Deleting log file: C:\Documents and Settings\All Users\Application Data\Red Gate\SQL Backup\Log\(LOCAL)\20070923 112909 01 {DE789AB6-87FB-4DD7-9B34-7A4727BEEE63}.log
12/22/2007 10:33:48 AM: Deleted msdb entries older than 9/23/2007 10:33:48 AM

petey

It appears that the deletion of the old msdb entries is what's causing the backup to take excessively long.

Could you please set up SQL Backup such that it does not delete the old entries in the msdb tables? You can do this via the GUI. Then run a backup to confirm that without the cleanup, the backup completes faster.

If it is confirmed to be so, then you can either:
- turn that option off permanently and periodically perform the cleanup manually using the sp_delete_backuphistory stored procedure

- look for alternatives to sp_delete_backuphistory, or add some indexes to the relevant tables. On SQL Server 2000, this stored procedure is cursor based, hence the performance hit. Google for alternatives and suggestions on what indexes to add. The usual caveats about modifying system tables apply.