Resolved: Long running log backups because service sits idle

swelshswelsh Posts: 13
edited February 17, 2014 4:05PM in SQL Backup Previous Versions
We are having an issue after upgrading from 6.5 to 7.6 where our transaction log backups are now taking significantly longer because the SQL Backup service just sits idle for anywhere from 20 seconds to around 5 minutes before starting the next backup. This is when there are no other backups running.


Here you can see it sitting for about 20 seconds:
2/13/2014 2:40:02 PM: Backing up ALMIS48_23 (transaction log) to:
2/13/2014 2:40:02 PM: I:\MSSQL\LogShip\Stage\\LOG_SCSQLPVOS0800_ALMIS48_23_20140213_144002.sqb

2/13/2014 2:40:03 PM: BACKUP LOG [ALMIS48_23] TO VIRTUAL_DEVICE = 'SQLBACKUP_DB0A0DE2-B228-40A5-8147-1A031B8805A3', VIRTUAL_DEVICE = 'SQLBACKUP_DB0A0DE2-B228-40A5-8147-1A031B8805A301', VIRTUAL_DEVICE = 'SQLBACKUP_DB0A0DE2-B228-40A5-8147-1A031B8805A302', VIRTUAL_DEVICE = 'SQLBACKUP_DB0A0DE2-B228-40A5-8147-1A031B8805A303', VIRTUAL_DEVICE = 'SQLBACKUP_DB0A0DE2-B228-40A5-8147-1A031B8805A304', VIRTUAL_DEVICE = 'SQLBACKUP_DB0A0DE2-B228-40A5-8147-1A031B8805A305', VIRTUAL_DEVICE = 'SQLBACKUP_DB0A0DE2-B228-40A5-8147-1A031B8805A306', VIRTUAL_DEVICE = 'SQLBACKUP_DB0A0DE2-B228-40A5-8147-1A031B8805A307' WITH BUFFERCOUNT = 32, BLOCKSIZE = 65536, MAXTRANSFERSIZE = 1048576, NAME = N'Database (ALMIS48_23), 2/13/2014 2:40:02 PM', DESCRIPTION = N'Backup on 2/13/2014 2:40:02 PM Server: SCSQLPVOS0800 Database: ALMIS48_23', FORMAT

2/13/2014 2:40:03 PM: Backup data size : 8.125 MB
2/13/2014 2:40:03 PM: Compressed data size: 155.000 KB
2/13/2014 2:40:03 PM: Compression rate : 98.14%

2/13/2014 2:40:03 PM: Processed 2 pages for database 'ALMIS48_23', file 'ALMIS48_23_Log' on file 1.
2/13/2014 2:40:03 PM: BACKUP LOG successfully processed 2 pages in 0.171 seconds (0.051 MB/sec).

2/13/2014 2:40:21 PM: Backing up msdb (transaction log) to:
2/13/2014 2:40:21 PM: I:\MSSQL\LogShip\Stage\\LOG_SCSQLPVOS0800_msdb_20140213_144021.sqb

2/13/2014 2:40:21 PM: BACKUP LOG [msdb] TO VIRTUAL_DEVICE = 'SQLBACKUP_395E6B1A-16C5-40C0-B905-E662B75D8619', VIRTUAL_DEVICE = 'SQLBACKUP_395E6B1A-16C5-40C0-B905-E662B75D861901', VIRTUAL_DEVICE = 'SQLBACKUP_395E6B1A-16C5-40C0-B905-E662B75D861902', VIRTUAL_DEVICE = 'SQLBACKUP_395E6B1A-16C5-40C0-B905-E662B75D861903', VIRTUAL_DEVICE = 'SQLBACKUP_395E6B1A-16C5-40C0-B905-E662B75D861904', VIRTUAL_DEVICE = 'SQLBACKUP_395E6B1A-16C5-40C0-B905-E662B75D861905', VIRTUAL_DEVICE = 'SQLBACKUP_395E6B1A-16C5-40C0-B905-E662B75D861906', VIRTUAL_DEVICE = 'SQLBACKUP_395E6B1A-16C5-40C0-B905-E662B75D861907' WITH BUFFERCOUNT = 32, BLOCKSIZE = 65536, MAXTRANSFERSIZE = 1048576, NAME = N'Database (msdb), 2/13/2014 2:40:21 PM', DESCRIPTION = N'Backup on 2/13/2014 2:40:21 PM Server: SCSQLPVOS0800 Database: msdb', FORMAT

2/13/2014 2:40:22 PM: Backup data size : 17.625 MB
2/13/2014 2:40:22 PM: Compressed data size: 2.990 MB
2/13/2014 2:40:22 PM: Compression rate : 83.03%

2/13/2014 2:40:22 PM: Processed 1279 pages for database 'msdb', file 'MSDBLog' on file 1.
2/13/2014 2:40:22 PM: BACKUP LOG successfully processed 1279 pages in 0.113 seconds (88.383 MB/sec).

2/13/2014 2:40:40 PM: Backing up VLMI08000000 (transaction log) to:
2/13/2014 2:40:40 PM: I:\MSSQL\LogShip\Stage\\LOG_SCSQLPVOS0800_VLMI08000000_20140213_144040.sqb

2/13/2014 2:40:40 PM: BACKUP LOG [VLMI08000000] TO VIRTUAL_DEVICE = 'SQLBACKUP_6BDA1579-0E22-4343-9EE5-E35F9227CD25', VIRTUAL_DEVICE = 'SQLBACKUP_6BDA1579-0E22-4343-9EE5-E35F9227CD2501', VIRTUAL_DEVICE = 'SQLBACKUP_6BDA1579-0E22-4343-9EE5-E35F9227CD2502', VIRTUAL_DEVICE = 'SQLBACKUP_6BDA1579-0E22-4343-9EE5-E35F9227CD2503', VIRTUAL_DEVICE = 'SQLBACKUP_6BDA1579-0E22-4343-9EE5-E35F9227CD2504', VIRTUAL_DEVICE = 'SQLBACKUP_6BDA1579-0E22-4343-9EE5-E35F9227CD2505', VIRTUAL_DEVICE = 'SQLBACKUP_6BDA1579-0E22-4343-9EE5-E35F9227CD2506', VIRTUAL_DEVICE = 'SQLBACKUP_6BDA1579-0E22-4343-9EE5-E35F9227CD2507' WITH BUFFERCOUNT = 32, BLOCKSIZE = 65536, MAXTRANSFERSIZE = 1048576, NAME = N'Database (VLMI08000000), 2/13/2014 2:40:40 PM', DESCRIPTION = N'Backup on 2/13/2014 2:40:40 PM Server: SCSQLPVOS0800 Database: VLMI08000000', FORMAT

2/13/2014 2:40:42 PM: Backup data size : 8.938 MB
2/13/2014 2:40:42 PM: Compressed data size: 796.500 KB
2/13/2014 2:40:42 PM: Compression rate : 91.30%

2/13/2014 2:40:42 PM: Processed 310 pages for database 'VLMI08000000', file 'VLMI08000000_Log' on file 1.
2/13/2014 2:40:42 PM: BACKUP LOG successfully processed 310 pages in 0.147 seconds (16.425 MB/sec).

2/13/2014 2:41:06 PM: Backing up VLMI08000000_objects (transaction log) to:
2/13/2014 2:41:06 PM: I:\MSSQL\LogShip\Stage\\LOG_SCSQLPVOS0800_VLMI08000000_objects_20140213_144106.sqb

2/13/2014 2:41:06 PM: BACKUP LOG [VLMI08000000_objects] TO VIRTUAL_DEVICE = 'SQLBACKUP_EA6092B6-F7B5-453B-891B-7682AFC87D4C', VIRTUAL_DEVICE = 'SQLBACKUP_EA6092B6-F7B5-453B-891B-7682AFC87D4C01', VIRTUAL_DEVICE = 'SQLBACKUP_EA6092B6-F7B5-453B-891B-7682AFC87D4C02', VIRTUAL_DEVICE = 'SQLBACKUP_EA6092B6-F7B5-453B-891B-7682AFC87D4C03', VIRTUAL_DEVICE = 'SQLBACKUP_EA6092B6-F7B5-453B-891B-7682AFC87D4C04', VIRTUAL_DEVICE = 'SQLBACKUP_EA6092B6-F7B5-453B-891B-7682AFC87D4C05', VIRTUAL_DEVICE = 'SQLBACKUP_EA6092B6-F7B5-453B-891B-7682AFC87D4C06', VIRTUAL_DEVICE = 'SQLBACKUP_EA6092B6-F7B5-453B-891B-7682AFC87D4C07' WITH BUFFERCOUNT = 32, BLOCKSIZE = 65536, MAXTRANSFERSIZE = 1048576, NAME = N'Database (VLMI08000000_objects), 2/13/2014 2:41:06 PM', DESCRIPTION = N'Backup on 2/13/2014 2:41:06 PM Server: SCSQLPVOS0800 Database: VLMI08000000_objects', FORMAT

2/13/2014 2:41:06 PM: Backup data size : 4.000 MB
2/13/2014 2:41:06 PM: Compressed data size: 18.500 KB
2/13/2014 2:41:06 PM: Compression rate : 99.55%

2/13/2014 2:41:06 PM: Processed 0 pages for database 'VLMI08000000_objects', file 'VLMI08000000_objects_Log' on file 1.
2/13/2014 2:41:06 PM: BACKUP LOG successfully processed 0 pages in 0.013 seconds (0.000 MB/sec).

2/13/2014 2:41:26 PM: Backing up VLMI15000000 (transaction log) to:
2/13/2014 2:41:26 PM: I:\MSSQL\LogShip\Stage\\LOG_SCSQLPVOS0800_VLMI15000000_20140213_144126.sqb

2/13/2014 2:41:26 PM: BACKUP LOG [VLMI15000000] TO VIRTUAL_DEVICE = 'SQLBACKUP_5597AA3F-284D-4BE7-A456-51F5478C5ADC', VIRTUAL_DEVICE = 'SQLBACKUP_5597AA3F-284D-4BE7-A456-51F5478C5ADC01', VIRTUAL_DEVICE = 'SQLBACKUP_5597AA3F-284D-4BE7-A456-51F5478C5ADC02', VIRTUAL_DEVICE = 'SQLBACKUP_5597AA3F-284D-4BE7-A456-51F5478C5ADC03', VIRTUAL_DEVICE = 'SQLBACKUP_5597AA3F-284D-4BE7-A456-51F5478C5ADC04', VIRTUAL_DEVICE = 'SQLBACKUP_5597AA3F-284D-4BE7-A456-51F5478C5ADC05', VIRTUAL_DEVICE = 'SQLBACKUP_5597AA3F-284D-4BE7-A456-51F5478C5ADC06', VIRTUAL_DEVICE = 'SQLBACKUP_5597AA3F-284D-4BE7-A456-51F5478C5ADC07' WITH BUFFERCOUNT = 32, BLOCKSIZE = 65536, MAXTRANSFERSIZE = 1048576, NAME = N'Database (VLMI15000000), 2/13/2014 2:41:26 PM', DESCRIPTION = N'Backup on 2/13/2014 2:41:26 PM Server: SCSQLPVOS0800 Database: VLMI15000000', FORMAT

2/13/2014 2:41:26 PM: Backup data size : 4.375 MB
2/13/2014 2:41:26 PM: Compressed data size: 65.000 KB
2/13/2014 2:41:26 PM: Compression rate : 98.55%

2/13/2014 2:41:26 PM: Processed 18 pages for database 'VLMI15000000', file 'VLMI15000000_Log' on file 1.
2/13/2014 2:41:26 PM: BACKUP LOG successfully processed 18 pages in 0.021 seconds (6.463 MB/sec).

2/13/2014 2:41:47 PM: Backing up VLMI15000000_objects (transaction log) to:
2/13/2014 2:41:47 PM: I:\MSSQL\LogShip\Stage\\LOG_SCSQLPVOS0800_VLMI15000000_objects_20140213_144147.sqb

2/13/2014 2:41:48 PM: BACKUP LOG [VLMI15000000_objects] TO VIRTUAL_DEVICE = 'SQLBACKUP_60E9C5DE-33A5-4414-99D8-3DDEC109CB39', VIRTUAL_DEVICE = 'SQLBACKUP_60E9C5DE-33A5-4414-99D8-3DDEC109CB3901', VIRTUAL_DEVICE = 'SQLBACKUP_60E9C5DE-33A5-4414-99D8-3DDEC109CB3902', VIRTUAL_DEVICE = 'SQLBACKUP_60E9C5DE-33A5-4414-99D8-3DDEC109CB3903', VIRTUAL_DEVICE = 'SQLBACKUP_60E9C5DE-33A5-4414-99D8-3DDEC109CB3904', VIRTUAL_DEVICE = 'SQLBACKUP_60E9C5DE-33A5-4414-99D8-3DDEC109CB3905', VIRTUAL_DEVICE = 'SQLBACKUP_60E9C5DE-33A5-4414-99D8-3DDEC109CB3906', VIRTUAL_DEVICE = 'SQLBACKUP_60E9C5DE-33A5-4414-99D8-3DDEC109CB3907' WITH BUFFERCOUNT = 32, BLOCKSIZE = 65536, MAXTRANSFERSIZE = 1048576, NAME = N'Database (VLMI15000000_objects), 2/13/2014 2:41:47 PM', DESCRIPTION = N'Backup on 2/13/2014 2:41:47 PM Server: SCSQLPVOS0800 Database: VLMI15000000_objects', FORMAT

2/13/2014 2:41:48 PM: Backup data size : 4.000 MB
2/13/2014 2:41:48 PM: Compressed data size: 20.000 KB
2/13/2014 2:41:48 PM: Compression rate : 99.51%

2/13/2014 2:41:48 PM: Processed 0 pages for database 'VLMI15000000_objects', file 'VLMI15000000_objects_Log' on file 1.
2/13/2014 2:41:48 PM: BACKUP LOG successfully processed 0 pages in 0.012 seconds (0.000 MB/sec).


And then here this one just sat for around 5 minutes.

2/13/2014 2:43:08 PM: Backing up VOS06000037_objects (transaction log) to:
2/13/2014 2:43:08 PM: I:\MSSQL\LogShip\Stage\\LOG_SCSQLPVOS0800_VOS06000037_objects_20140213_144308.sqb

2/13/2014 2:43:08 PM: BACKUP LOG [VOS06000037_objects] TO VIRTUAL_DEVICE = 'SQLBACKUP_5FF6A99E-0A5C-4BC7-AE85-D55C1E686FC9', VIRTUAL_DEVICE = 'SQLBACKUP_5FF6A99E-0A5C-4BC7-AE85-D55C1E686FC901', VIRTUAL_DEVICE = 'SQLBACKUP_5FF6A99E-0A5C-4BC7-AE85-D55C1E686FC902', VIRTUAL_DEVICE = 'SQLBACKUP_5FF6A99E-0A5C-4BC7-AE85-D55C1E686FC903', VIRTUAL_DEVICE = 'SQLBACKUP_5FF6A99E-0A5C-4BC7-AE85-D55C1E686FC904', VIRTUAL_DEVICE = 'SQLBACKUP_5FF6A99E-0A5C-4BC7-AE85-D55C1E686FC905', VIRTUAL_DEVICE = 'SQLBACKUP_5FF6A99E-0A5C-4BC7-AE85-D55C1E686FC906', VIRTUAL_DEVICE = 'SQLBACKUP_5FF6A99E-0A5C-4BC7-AE85-D55C1E686FC907' WITH BUFFERCOUNT = 32, BLOCKSIZE = 65536, MAXTRANSFERSIZE = 1048576, NAME = N'Database (VOS06000037_objects), 2/13/2014 2:43:08 PM', DESCRIPTION = N'Backup on 2/13/2014 2:43:08 PM Server: SCSQLPVOS0800 Database: VOS06000037_objects', FORMAT

2/13/2014 2:43:08 PM: Backup data size : 4.125 MB
2/13/2014 2:43:08 PM: Compressed data size: 24.000 KB
2/13/2014 2:43:08 PM: Compression rate : 99.43%

2/13/2014 2:43:08 PM: Processed 2 pages for database 'VOS06000037_objects', file 'VOS06000037_objects_Log' on file 1.
2/13/2014 2:43:08 PM: BACKUP LOG successfully processed 2 pages in 0.022 seconds (0.488 MB/sec).

2/13/2014 2:48:47 PM: Backing up VOS06000039_objects (transaction log) to:
2/13/2014 2:48:47 PM: I:\MSSQL\LogShip\Stage\\LOG_SCSQLPVOS0800_VOS06000039_objects_20140213_144847.sqb

2/13/2014 2:48:47 PM: BACKUP LOG [VOS06000039_objects] TO VIRTUAL_DEVICE = 'SQLBACKUP_F9C14C12-06AF-4E17-BE1A-5739B9649162', VIRTUAL_DEVICE = 'SQLBACKUP_F9C14C12-06AF-4E17-BE1A-5739B964916201', VIRTUAL_DEVICE = 'SQLBACKUP_F9C14C12-06AF-4E17-BE1A-5739B964916202', VIRTUAL_DEVICE = 'SQLBACKUP_F9C14C12-06AF-4E17-BE1A-5739B964916203', VIRTUAL_DEVICE = 'SQLBACKUP_F9C14C12-06AF-4E17-BE1A-5739B964916204', VIRTUAL_DEVICE = 'SQLBACKUP_F9C14C12-06AF-4E17-BE1A-5739B964916205', VIRTUAL_DEVICE = 'SQLBACKUP_F9C14C12-06AF-4E17-BE1A-5739B964916206', VIRTUAL_DEVICE = 'SQLBACKUP_F9C14C12-06AF-4E17-BE1A-5739B964916207' WITH BUFFERCOUNT = 32, BLOCKSIZE = 65536, MAXTRANSFERSIZE = 1048576, NAME = N'Database (VOS06000039_objects), 2/13/2014 2:48:47 PM', DESCRIPTION = N'Backup on 2/13/2014 2:48:47 PM Server: SCSQLPVOS0800 Database: VOS06000039_objects', FORMAT

2/13/2014 2:48:47 PM: Backup data size : 4.125 MB
2/13/2014 2:48:47 PM: Compressed data size: 20.500 KB
2/13/2014 2:48:47 PM: Compression rate : 99.51%

2/13/2014 2:48:47 PM: Processed 1 pages for database 'VOS06000039_objects', file 'VOS06000039_objects_Log' on file 1.
2/13/2014 2:48:47 PM: BACKUP LOG successfully processed 1 pages in 0.036 seconds (0.203 MB/sec).

We're backing up around 80 databases, and previously the job would complete in about 15-20 minutes, and now it is taking close to an hour.
· Share on Twitter

Comments

  • peteypetey Posts: 2,358 New member
    Could you please post the backup command you are using to run the backups?
    Peter Yeoh
    SQL Backup Consultant Developer
    Associate, Yohz Software
    Beyond compression - SQL Backup goodies under the hood, updated for version 8
    · Share on Twitter
  • swelshswelsh Posts: 13
    This is what I am using now.
    EXEC [master].[dbo].[sqlbackup] '-SQL "BACKUP LOGS [Databaste, List, Goes, Here] TO DISK = ''I:\MSSQL\Backup\Logs\<AUTO>.sqb'' WITH COMPRESSION = 1, NO_CHECKSUM, THREADCOUNT = 8, MAILTO_ONERRORONLY = ''removed''"';

    It was running the command above in a cursor for one database at a time instead of a list, it doesn't change the long running behavior.

    We are running the same thing on 4 other servers and it is functioning just fine. This is the only server with such a large number databases receiving log backups though (83 databases), the next closest server is 54 databases and finishes in less than 2 minutes for most runs, even during heavy load.
    · Share on Twitter
  • swelshswelsh Posts: 13
    The server is a Windows Failover Cluster of 2 Dell R900s, 4 quad-core processors and 256GB RAM in each.

    Windows Server 2008 R2 SP1 x64
    Clustered install of SQL Server 2008 R2 SP1 x64
    · Share on Twitter
  • peteypetey Posts: 2,358 New member
    Could you please turn on some SQL Server trace flags that will log additional information re. the backup process in the SQL Server error log i.e.

    DBCC TRACEON(3605, 3004, 3014, 3213, -1)

    Once the next backup job has completed after you turned on the trace flags, could you please send me the SQL Server error log, together with the SQL Backup backup log, so that I can check the sequence of events on both sides of the backup process? Please send the files to peter.yeoh@red-gate.com.

    You can then turn off the trace flags i.e.

    DBCC TRACEOFF(3605, 3004, 3014, 3213, -1)
    Peter Yeoh
    SQL Backup Consultant Developer
    Associate, Yohz Software
    Beyond compression - SQL Backup goodies under the hood, updated for version 8
    · Share on Twitter
  • swelshswelsh Posts: 13
    Peter and I resolved this via email.

    In case anyone else has a similar issue, this is how we resolved it:

    We'll need to turn on a trace flag in SQL Backup then. To do this, you need to add a -sqbdebug option to the SQL Backup Agent service.

    Stop the SQL Backup Agent service.

    In the registry, look for

    HKEY_LOCAL_MACHINE\SYSTEM\CurrentControlSet\services\SQLBackupAgent_<your instace name>

    In the ImagePath value, add the -sqbdebug option e.g.

    C:\Program Files (x86)\Red Gate\SQL Backup 7\SQL2005\SQBCoreService.exe -i SQL2005 -sqbdebug

    Start the service. You should see a file named SQBCoreService_log.txt created in the folder where the SQL Backup Agent service executable is located e.g. C:\Program Files (x86)\Red Gate\SQL Backup 7\<your instance name>

    Let the job run once, preferably without the GUI running (as it'll add a lot of noise to the log).

    Investigated the debug log output and found this long running query:
    SELECT TOP 1 a.type, a.backup_set_uuid, a.first_lsn, a.last_lsn, a.checkpoint_lsn, a.database_backup_lsn, a.media_set_id, c.name, a.has_backup_checksums, a.is_damaged FROM msdb..backupset a INNER JOIN msdb..backupmediafamily b ON a.media_set_id = b.media_set_id INNER JOIN master..sysdatabases c ON a.database_name COLLATE DATABASE_DEFAULT = c.name COLLATE DATABASE_DEFAULT WHERE b.physical_device_name = 'x' ORDER BY a.media_set_id DESC

    To resolve the long running query, I had to cleanup the backup history tables in msdb. backupmediafamily was over 18 million records which is what was causing the slowdown.

    Take away: Make sure you either enable the msdb history cleanup in SQL Backup, or run your own maintenance job to prevent the tables from growing too large.
    · Share on Twitter
Sign In or Register to comment.