log backup takes forever

ITSyncForce · August 22, 2012 4:30AM

Since a couple of weeks our hourly logbackup takes at least 10 hours to complete. In the past this was done in less then 10 minutes.

This is a dual hexacore machine with 24GB of RAM with a total of around 40GB of databases running SQL 2008 R2.

The activity monitor shows that the wait type is preemptive_os_getprocaddress.

As this server was not been down since we deployed it (about 250 days ago) I decided to reboot it last night to see if that fixes the problem. Unfortunattely it has not. log backup that started at 1am this night has still not finished and will take at least another half hour.

Is there a fix, we run SQL backup 7.1.0.214

petey · August 22, 2012 11:38AM

Could you please post the contents of the SQL Backup log for a backup that took hours to complete?

The default folder where the logs are stored is 'C:\Documents and Settings\All Users\Application Data\Red Gate\SQL Backup\Log\<instance name>' on Windows 2003 and older, and 'C:\ProgramData\Red Gate\SQL Backup\Log\<instance name>' on Windows Vista and newer.

ITSyncForce · August 23, 2012 10:09AM

Below is the log from the old situation and the new situation.

As you can see is the command not changed only the version. I am not sure when it started but I can see from the logfiles that the duration of the log backups increased over time from the initial 5-10 minutes to around 45 minutes. And now it is around 10 hours.

Old situation:

SQL Backup log file 6.5.1.9

-SQL "BACKUP LOGS [*] TO DISK = 'E:\Program Files\Microsoft SQL Server\MSSQL\Backup\logs\<AUTO>.sqb' WITH ERASEFILES_ATSTART = 2, ERASEFILES_REMOTE = 7, FILEOPTIONS = 4, DISKRETRYINTERVAL = 30, DISKRETRYCOUNT = 10, COPYTO = '\\<NAS>\Backups\db04\logs', INIT, THREADCOUNT = 2 "

PROCESSES COMPLETED SUCCESSFULLY

3/30/2012 8:00:00 PM: Backing up BM_<DB> (transaction log) to:
3/30/2012 8:00:00 PM: E:\Program Files\Microsoft SQL Server\MSSQL\Backup\logs\LOG_BM_<DB>_2012033020.sqb

3/30/2012 8:00:02 PM: Deleting old backup file: E:\Program Files\Microsoft SQL Server\MSSQL\Backup\logs\LOG_BM_<DB>_2012032819.sqb
3/30/2012 8:00:02 PM: Deleting old backup file: \\<NAS>\Backups\db04\logs\LOG_BM_<DB>_2012032319.sqb
3/30/2012 8:00:02 PM: BACKUP LOG [BM_<DB>] TO VIRTUAL_DEVICE = 'SQLBACKUP_D28F91C7-5CA1-4079-A724-EAB52CAD0BE1', VIRTUAL_DEVICE = 'SQLBACKUP_D28F91C7-5CA1-4079-A724-EAB52CAD0BE101' WITH BUFFERCOUNT = 12, BLOCKSIZE = 65536, MAXTRANSFERSIZE = 1048576, NAME = N'Database (BM_<DB>), 3/30/2012 8:00:00 PM', DESCRIPTION = N'Backup on 3/30/2012 8:00:00 PM Server: SFDB04 Database: BM_<DB>', FORMAT

3/30/2012 8:00:03 PM: Backup data size : 1.000 MB
3/30/2012 8:00:03 PM: Compressed data size: 6.000 KB
3/30/2012 8:00:03 PM: Compression rate : 99.41%

3/30/2012 8:00:03 PM: Processed 0 pages for database 'BM_<DB>', file 'BM_<DB>_log' on file 1.
3/30/2012 8:00:03 PM: BACKUP LOG successfully processed 0 pages in 0.002 seconds (0.000 MB/sec).

3/30/2012 8:00:03 PM: Backing up BM_<DB> (transaction log) to:
3/30/2012 8:00:03 PM: E:\Program Files\Microsoft SQL Server\MSSQL\Backup\logs\LOG_BM_<DB>_2012033020.sqb

3/30/2012 8:00:04 PM: Deleting old backup file: E:\Program Files\Microsoft SQL Server\MSSQL\Backup\logs\LOG_BM_<DB>_2012032819.sqb
3/30/2012 8:00:04 PM: Deleting old backup file: \\<NAS>\Backups\db04\logs\LOG_BM_<DB>_2012032319.sqb
3/30/2012 8:00:04 PM: BACKUP LOG [BM_<DB>] TO VIRTUAL_DEVICE = 'SQLBACKUP_8056B020-BC46-4CA6-9144-E45DDBCBC6B2', VIRTUAL_DEVICE = 'SQLBACKUP_8056B020-BC46-4CA6-9144-E45DDBCBC6B201' WITH BUFFERCOUNT = 12, BLOCKSIZE = 65536, MAXTRANSFERSIZE = 1048576, NAME = N'Database (BM_<DB>), 3/30/2012 8:00:03 PM', DESCRIPTION = N'Backup on 3/30/2012 8:00:03 PM Server: SFDB04 Database: BM_<DB>', FORMAT

3/30/2012 8:00:04 PM: Backup data size : 1.000 MB
3/30/2012 8:00:04 PM: Compressed data size: 5.500 KB
3/30/2012 8:00:04 PM: Compression rate : 99.46%

3/30/2012 8:00:04 PM: Processed 0 pages for database 'BM_<DB>', file 'BM_<DB>_log' on file 1.
3/30/2012 8:00:04 PM: BACKUP LOG successfully processed 0 pages in 0.002 seconds (0.000 MB/sec).

3/30/2012 8:00:04 PM: Backing up BM_<DB> (transaction log) to:
3/30/2012 8:00:04 PM: E:\Program Files\Microsoft SQL Server\MSSQL\Backup\logs\LOG_BM_<DB>_2012033020.sqb

3/30/2012 8:00:05 PM: Deleting old backup file: E:\Program Files\Microsoft SQL Server\MSSQL\Backup\logs\LOG_BM_<DB>_2012032819.sqb
3/30/2012 8:00:05 PM: Deleting old backup file: \\<NAS>\Backups\db04\logs\LOG_BM_<DB>_2012032319.sqb
3/30/2012 8:00:05 PM: BACKUP LOG [BM_<DB>] TO VIRTUAL_DEVICE = 'SQLBACKUP_66016508-C170-4F3F-96E0-3FDD1DAF671E', VIRTUAL_DEVICE = 'SQLBACKUP_66016508-C170-4F3F-96E0-3FDD1DAF671E01' WITH BUFFERCOUNT = 12, BLOCKSIZE = 65536, MAXTRANSFERSIZE = 1048576, NAME = N'Database (BM_<DB>), 3/30/2012 8:00:04 PM', DESCRIPTION = N'Backup on 3/30/2012 8:00:04 PM Server: SFDB04 Database: BM_<DB>', FORMAT

3/30/2012 8:00:05 PM: Backup data size : 1.000 MB
3/30/2012 8:00:05 PM: Compressed data size: 6.000 KB
3/30/2012 8:00:05 PM: Compression rate : 99.41%

3/30/2012 8:00:05 PM: Processed 0 pages for database 'BM_<DB>', file 'BM_<DB>_log' on file 1.
3/30/2012 8:00:05 PM: BACKUP LOG successfully processed 0 pages in 0.003 seconds (0.000 MB/sec).

3/30/2012 8:00:05 PM: Backing up BM_<DB> (transaction log) to:
3/30/2012 8:00:05 PM: E:\Program Files\Microsoft SQL Server\MSSQL\Backup\logs\LOG_BM_<DB>_2012033020.sqb

3/30/2012 8:00:06 PM: Deleting old backup file: E:\Program Files\Microsoft SQL Server\MSSQL\Backup\logs\LOG_BM_<DB>_2012032819.sqb
3/30/2012 8:00:06 PM: Deleting old backup file: \\<NAS>\Backups\db04\logs\LOG_BM_<DB>_2012032319.sqb
3/30/2012 8:00:06 PM: BACKUP LOG [BM_<DB>] TO VIRTUAL_DEVICE = 'SQLBACKUP_CDBC3AC3-8615-4EDF-A2FF-AA9A29704E82', VIRTUAL_DEVICE = 'SQLBACKUP_CDBC3AC3-8615-4EDF-A2FF-AA9A29704E8201' WITH BUFFERCOUNT = 12, BLOCKSIZE = 65536, MAXTRANSFERSIZE = 1048576, NAME = N'Database (BM_<DB>), 3/30/2012 8:00:05 PM', DESCRIPTION = N'Backup on 3/30/2012 8:00:05 PM Server: SFDB04 Database: BM_<DB>', FORMAT

3/30/2012 8:00:06 PM: Backup data size : 1.000 MB
3/30/2012 8:00:06 PM: Compressed data size: 7.500 KB
3/30/2012 8:00:06 PM: Compression rate : 99.27%

3/30/2012 8:00:06 PM: Processed 0 pages for database 'BM_<DB>', file 'BM_<DB>_log' on file 1.
3/30/2012 8:00:06 PM: BACKUP LOG successfully processed 0 pages in 0.004 seconds (0.000 MB/sec).

3/30/2012 8:00:07 PM: Backing up cms_<DB> (transaction log) to:
3/30/2012 8:00:07 PM: E:\Program Files\Microsoft SQL Server\MSSQL\Backup\logs\LOG_cms_<DB>_2012033020.sqb

3/30/2012 8:00:07 PM: Deleting old backup file: E:\Program Files\Microsoft SQL Server\MSSQL\Backup\logs\LOG_cms_<DB>_2012032819.sqb
3/30/2012 8:00:07 PM: Deleting old backup file: \\<NAS>\Backups\db04\logs\LOG_cms_<DB>_2012032319.sqb
3/30/2012 8:00:07 PM: BACKUP LOG [cms_<DB>] TO VIRTUAL_DEVICE = 'SQLBACKUP_44322AA8-D065-4D04-A2D5-7720FA974C3A', VIRTUAL_DEVICE = 'SQLBACKUP_44322AA8-D065-4D04-A2D5-7720FA974C3A01' WITH BUFFERCOUNT = 12, BLOCKSIZE = 65536, MAXTRANSFERSIZE = 1048576, NAME = N'Database (cms_<DB>), 3/30/2012 8:00:07 PM', DESCRIPTION = N'Backup on 3/30/2012 8:00:07 PM Server: SFDB04 Database: cms_<DB>', FORMAT

3/30/2012 8:00:08 PM: Backup data size : 1.125 MB
3/30/2012 8:00:08 PM: Compressed data size: 14.000 KB
3/30/2012 8:00:08 PM: Compression rate : 98.78%

3/30/2012 8:00:08 PM: Processed 3 pages for database 'cms_<DB>', file 'cms_<DB>_log' on file 1.
3/30/2012 8:00:08 PM: BACKUP LOG successfully processed 3 pages in 0.002 seconds (10.498 MB/sec).

3/30/2012 8:00:08 PM: Backing up cms_<DB> (transaction log) to:
3/30/2012 8:00:08 PM: E:\Program Files\Microsoft SQL Server\MSSQL\Backup\logs\LOG_cms_<DB>_2012033020.sqb

3/30/2012 8:00:09 PM: Deleting old backup file: E:\Program Files\Microsoft SQL Server\MSSQL\Backup\logs\LOG_cms_<DB>_2012032819.sqb
3/30/2012 8:00:09 PM: Deleting old backup file: \\<NAS>\Backups\db04\logs\LOG_cms_<DB>_2012032319.sqb
3/30/2012 8:00:09 PM: BACKUP LOG [cms_<DB>] TO VIRTUAL_DEVICE = 'SQLBACKUP_5E924274-9F08-42F6-BE06-49ED54E27E7E', VIRTUAL_DEVICE = 'SQLBACKUP_5E924274-9F08-42F6-BE06-49ED54E27E7E01' WITH BUFFERCOUNT = 12, BLOCKSIZE = 65536, MAXTRANSFERSIZE = 1048576, NAME = N'Database (cms_<DB>), 3/30/2012 8:00:08 PM', DESCRIPTION = N'Backup on 3/30/2012 8:00:08 PM Server: SFDB04 Database: cms_<DB>', FORMAT

3/30/2012 8:00:09 PM: Backup data size : 1.125 MB
3/30/2012 8:00:09 PM: Compressed data size: 28.000 KB
3/30/2012 8:00:09 PM: Compression rate : 97.57%

3/30/2012 8:00:09 PM: Processed 8 pages for database 'cms_<DB>', file 'cms_<DB>_log' on file 1.
3/30/2012 8:00:09 PM: BACKUP LOG successfully processed 8 pages in 0.003 seconds (19.368 MB/sec).

3/30/2012 8:00:09 PM: Backing up cms_<DB> (transaction log) to:
3/30/2012 8:00:09 PM: E:\Program Files\Microsoft SQL Server\MSSQL\Backup\logs\LOG_cms_<DB>_2012033020.sqb

3/30/2012 8:00:10 PM: Deleting old backup file: E:\Program Files\Microsoft SQL Server\MSSQL\Backup\logs\LOG_cms_<DB>_2012032819.sqb
3/30/2012 8:00:10 PM: Deleting old backup file: \\<NAS>\Backups\db04\logs\LOG_cms_<DB>_2012032319.sqb
3/30/2012 8:00:10 PM: BACKUP LOG [cms_<DB>] TO VIRTUAL_DEVICE = 'SQLBACKUP_91DD4246-D835-4AE2-B810-4D46280380C6', VIRTUAL_DEVICE = 'SQLBACKUP_91DD4246-D835-4AE2-B810-4D46280380C601' WITH BUFFERCOUNT = 12, BLOCKSIZE = 65536, MAXTRANSFERSIZE = 1048576, NAME = N'Database (cms_<DB>), 3/30/2012 8:00:09 PM', DESCRIPTION = N'Backup on 3/30/2012 8:00:09 PM Server: SFDB04 Database: cms_<DB>', FORMAT

3/30/2012 8:00:10 PM: Backup data size : 1.125 MB
3/30/2012 8:00:10 PM: Compressed data size: 15.000 KB
3/30/2012 8:00:10 PM: Compression rate : 98.70%

3/30/2012 8:00:10 PM: Processed 2 pages for database 'cms_<DB>', file 'cms_<DB>_log' on file 1.
3/30/2012 8:00:10 PM: BACKUP LOG successfully processed 2 pages in 0.019 seconds (0.796 MB/sec).

3/30/2012 8:00:11 PM: Backing up cms_<DB> (transaction log) to:
3/30/2012 8:00:11 PM: E:\Program Files\Microsoft SQL Server\MSSQL\Backup\logs\LOG_cms_<DB>_2012033020.sqb

3/30/2012 8:00:11 PM: Deleting old backup file: E:\Program Files\Microsoft SQL Server\MSSQL\Backup\logs\LOG_cms_<DB>_2012032819.sqb
3/30/2012 8:00:11 PM: Deleting old backup file: \\<NAS>\Backups\db04\logs\LOG_cms_<DB>_2012032319.sqb
3/30/2012 8:00:11 PM: BACKUP LOG [cms_<DB>] TO VIRTUAL_DEVICE = 'SQLBACKUP_1877A281-395B-426D-8250-FF706C262776', VIRTUAL_DEVICE = 'SQLBACKUP_1877A281-395B-426D-8250-FF706C26277601' WITH BUFFERCOUNT = 12, BLOCKSIZE = 65536, MAXTRANSFERSIZE = 1048576, NAME = N'Database (cms_<DB>), 3/30/2012 8:00:11 PM', DESCRIPTION = N'Backup on 3/30/2012 8:00:11 PM Server: SFDB04 Database: cms_<DB>', FORMAT

3/30/2012 8:00:12 PM: Backup data size : 1.000 MB
3/30/2012 8:00:12 PM: Compressed data size: 8.500 KB
3/30/2012 8:00:12 PM: Compression rate : 99.17%

3/30/2012 8:00:12 PM: Processed 0 pages for database 'cms_<DB>', file 'cms_<DB>_log' on file 1.
3/30/2012 8:00:12 PM: BACKUP LOG successfully processed 0 pages in 0.002 seconds (0.000 MB/sec).

3/30/2012 8:00:12 PM: Backing up cms_<DB> (transaction log) to:
3/30/2012 8:00:12 PM: E:\Program Files\Microsoft SQL Server\MSSQL\Backup\logs\LOG_cms_<DB>_2012033020.sqb

3/30/2012 8:00:13 PM: Deleting old backup file: E:\Program Files\Microsoft SQL Server\MSSQL\Backup\logs\LOG_cms_<DB>_2012032819.sqb
3/30/2012 8:00:13 PM: Deleting old backup file: \\<NAS>\Backups\db04\logs\LOG_cms_<DB>_2012032319.sqb
3/30/2012 8:00:13 PM: BACKUP LOG [cms_<DB>] TO VIRTUAL_DEVICE = 'SQLBACKUP_A6EEB9F6-2315-4B2B-8438-3995B495B917', VIRTUAL_DEVICE = 'SQLBACKUP_A6EEB9F6-2315-4B2B-8438-3995B495B91701' WITH BUFFERCOUNT = 12, BLOCKSIZE = 65536, MAXTRANSFERSIZE = 1048576, NAME = N'Database (cms_<DB>), 3/30/2012 8:00:12 PM', DESCRIPTION = N'Backup on 3/30/2012 8:00:12 PM Server: SFDB04 Database: cms_<DB>', FORMAT

3/30/2012 8:00:13 PM: Backup data size : 1.000 MB
3/30/2012 8:00:13 PM: Compressed data size: 6.000 KB
3/30/2012 8:00:13 PM: Compression rate : 99.41%

3/30/2012 8:00:13 PM: Processed 0 pages for database 'cms_<DB>', file 'cms_<DB>_log' on file 1.
3/30/2012 8:00:13 PM: BACKUP LOG successfully processed 0 pages in 0.001 seconds (0.000 MB/sec).

3/30/2012 8:00:13 PM: Backing up cms_<DB> (transaction log) to:
3/30/2012 8:00:13 PM: E:\Program Files\Microsoft SQL Server\MSSQL\Backup\logs\LOG_cms_<DB>_2012033020.sqb

3/30/2012 8:00:14 PM: Deleting old backup file: E:\Program Files\Microsoft SQL Server\MSSQL\Backup\logs\LOG_cms_<DB>_2012032819.sqb
3/30/2012 8:00:14 PM: Deleting old backup file: \\<NAS>\Backups\db04\logs\LOG_cms_<DB>_2012032319.sqb
3/30/2012 8:00:14 PM: BACKUP LOG [cms_<DB>] TO VIRTUAL_DEVICE = 'SQLBACKUP_8FE59F1D-1954-4237-9B35-491688A6A260', VIRTUAL_DEVICE = 'SQLBACKUP_8FE59F1D-1954-4237-9B35-491688A6A26001' WITH BUFFERCOUNT = 12, BLOCKSIZE = 65536, MAXTRANSFERSIZE = 1048576, NAME = N'Database (cms_<DB>), 3/30/2012 8:00:13 PM', DESCRIPTION = N'Backup on 3/30/2012 8:00:13 PM Server: SFDB04 Database: cms_<DB>', FORMAT

3/30/2012 8:00:14 PM: Backup data size : 1.125 MB
3/30/2012 8:00:14 PM: Compressed data size: 11.000 KB
3/30/2012 8:00:14 PM: Compression rate : 99.05%

3/30/2012 8:00:14 PM: Processed 1 pages for database 'cms_<DB>', file 'cms_<DB>_log' on file 1.
3/30/2012 8:00:14 PM: BACKUP LOG successfully processed 1 pages in 0.005 seconds (1.269 MB/sec).

3/30/2012 8:00:14 PM: Backing up cms_<DB> (transaction log) to:
3/30/2012 8:00:14 PM: E:\Program Files\Microsoft SQL Server\MSSQL\Backup\logs\LOG_cms_<DB>_2012033020.sqb

3/30/2012 8:00:15 PM: Deleting old backup file: E:\Program Files\Microsoft SQL Server\MSSQL\Backup\logs\LOG_cms_<DB>_2012032819.sqb
3/30/2012 8:00:15 PM: Deleting old backup file: \\<NAS>\Backups\db04\logs\LOG_cms_<DB>_2012032318.sqb
3/30/2012 8:00:15 PM: BACKUP LOG [cms_<DB>] TO VIRTUAL_DEVICE = 'SQLBACKUP_BB788625-E5BA-4F52-88CE-EB3685A88F71', VIRTUAL_DEVICE = 'SQLBACKUP_BB788625-E5BA-4F52-88CE-EB3685A88F7101' WITH BUFFERCOUNT = 12, BLOCKSIZE = 65536, MAXTRANSFERSIZE = 1048576, NAME = N'Database (cms_<DB>), 3/30/2012 8:00:14 PM', DESCRIPTION = N'Backup on 3/30/2012 8:00:14 PM Server: SFDB04 Database: cms_<DB>', FORMAT

3/30/2012 8:00:15 PM: Backup data size : 1.375 MB
3/30/2012 8:00:15 PM: Compressed data size: 40.500 KB
3/30/2012 8:00:15 PM: Compression rate : 97.12%

3/30/2012 8:00:15 PM: Processed 10 pages for database 'cms_<DB>', file 'cms_<DB>_log' on file 1.
3/30/2012 8:00:15 PM: BACKUP LOG successfully processed 10 pages in 0.031 seconds (2.488 MB/sec).

3/30/2012 8:00:16 PM: Backing up cms_<DB> (transaction log) to:
3/30/2012 8:00:16 PM: E:\Program Files\Microsoft SQL Server\MSSQL\Backup\logs\LOG_cms_<DB>_2012033020.sqb

3/30/2012 8:00:16 PM: Deleting old backup file: E:\Program Files\Microsoft SQL Server\MSSQL\Backup\logs\LOG_cms_<DB>_2012032819.sqb
3/30/2012 8:00:16 PM: Deleting old backup file: \\<NAS>\Backups\db04\logs\LOG_cms_<DB>_2012032318.sqb
3/30/2012 8:00:16 PM: Deleting old backup file: \\<NAS>\Backups\db04\logs\LOG_cms_<DB>_2012032319.sqb
3/30/2012 8:00:16 PM: BACKUP LOG [cms_<DB>] TO VIRTUAL_DEVICE = 'SQLBACKUP_8DC13126-81AC-4A9B-9B73-AA51D956A292', VIRTUAL_DEVICE = 'SQLBACKUP_8DC13126-81AC-4A9B-9B73-AA51D956A29201' WITH BUFFERCOUNT = 12, BLOCKSIZE = 65536, MAXTRANSFERSIZE = 1048576, NAME = N'Database (cms_<DB>), 3/30/2012 8:00:16 PM', DESCRIPTION = N'Backup on 3/30/2012 8:00:16 PM Server: SFDB04 Database: cms_<DB>', FORMAT

3/30/2012 8:00:17 PM: Backup data size : 1.938 MB
3/30/2012 8:00:17 PM: Compressed data size: 174.500 KB
3/30/2012 8:00:17 PM: Compression rate : 91.20%

3/30/2012 8:00:17 PM: Processed 59 pages for database 'cms_<DB>', file 'cms_<DB>_log' on file 1.
3/30/2012 8:00:17 PM: BACKUP LOG successfully processed 59 pages in 0.020 seconds (22.705 MB/sec).

3/30/2012 8:00:17 PM: Backing up <DB> (transaction log) to:
3/30/2012 8:00:17 PM: E:\Program Files\Microsoft SQL Server\MSSQL\Backup\logs\LOG_<DB>_2012033020.sqb

3/30/2012 8:00:18 PM: Deleting old backup file: E:\Program Files\Microsoft SQL Server\MSSQL\Backup\logs\LOG_<DB>_2012032819.sqb
3/30/2012 8:00:18 PM: Deleting old backup file: \\<NAS>\Backups\db04\logs\LOG_<DB>_2012032318.sqb
3/30/2012 8:00:18 PM: Deleting old backup file: \\<NAS>\Backups\db04\logs\LOG_<DB>_2012032319.sqb
3/30/2012 8:00:18 PM: BACKUP LOG [<DB>] TO VIRTUAL_DEVICE = 'SQLBACKUP_B708275A-AA3E-4A83-A2A1-AEBA0BE3EA22', VIRTUAL_DEVICE = 'SQLBACKUP_B708275A-AA3E-4A83-A2A1-AEBA0BE3EA2201' WITH BUFFERCOUNT = 12, BLOCKSIZE = 65536, MAXTRANSFERSIZE = 1048576, NAME = N'Database (<DB>), 3/30/2012 8:00:17 PM', DESCRIPTION = N'Backup on 3/30/2012 8:00:17 PM Server: SFDB04 Database: <DB>', FORMAT

3/30/2012 8:00:18 PM: Backup data size : 1.000 MB
3/30/2012 8:00:18 PM: Compressed data size: 8.500 KB
3/30/2012 8:00:18 PM: Compression rate : 99.17%

3/30/2012 8:00:18 PM: Processed 0 pages for database '<DB>', file '<DB>_log' on file 1.
3/30/2012 8:00:18 PM: BACKUP LOG successfully processed 0 pages in 0.017 seconds (0.000 MB/sec).

..........................

3/30/2012 8:05:37 PM: SQL Backup process ended.

Current situation:

SQL Backup log file 7.1.0.72

-SQL "BACKUP LOGS [*] TO DISK = 'E:\Program Files\Microsoft SQL Server\MSSQL\Backup\logs\<AUTO>.sqb' WITH ERASEFILES_ATSTART = 2, ERASEFILES_REMOTE = 7, FILEOPTIONS = 4, PASSWORD = 'XXXXXXXXXX', DISKRETRYINTERVAL = 30, DISKRETRYCOUNT = 10, COPYTO = '\\<NAS>\Backups\db04\logs', INIT, KEYSIZE = 256 "

PROCESSES COMPLETED SUCCESSFULLY

8/22/2012 10:00:00 PM: Backing up BM_<DB> (transaction log) to:
8/22/2012 10:00:00 PM: E:\Program Files\Microsoft SQL Server\MSSQL\Backup\logs\LOG_BM_<DB>_2012082222.sqb

8/22/2012 10:05:09 PM: Deleting old backup file: E:\Program Files\Microsoft SQL Server\MSSQL\Backup\logs\LOG_BM_<DB>_2012082011.sqb
8/22/2012 10:05:34 PM: Deleting old backup file: \\<NAS>\Backups\db04\logs\LOG_BM_<DB>_2012081516.sqb
8/22/2012 10:07:40 PM: BACKUP LOG [BM_<DB>] TO VIRTUAL_DEVICE = 'SQLBACKUP_77D9B27F-C4CB-4ED4-A5E4-5FE8BFDA571B' WITH BUFFERCOUNT = 6, BLOCKSIZE = 65536, MAXTRANSFERSIZE = 1048576, NAME = N'Database (BM_<DB>), 8/22/2012 10:00:00 PM', DESCRIPTION = N'Backup on 8/22/2012 10:00:00 PM Server: SFDB04 Database: BM_<DB>', FORMAT

8/22/2012 10:07:41 PM: Backup data size : 512.000 KB
8/22/2012 10:07:41 PM: Compressed data size: 4.000 KB
8/22/2012 10:07:41 PM: Compression rate : 99.22%

8/22/2012 10:07:41 PM: Processed 0 pages for database 'BM_<DB>', file 'BM_<DB>_log' on file 1.
8/22/2012 10:07:41 PM: BACKUP LOG successfully processed 0 pages in 0.001 seconds (0.000 MB/sec).

8/22/2012 10:07:41 PM: Backing up BM_<DB> (transaction log) to:
8/22/2012 10:07:41 PM: E:\Program Files\Microsoft SQL Server\MSSQL\Backup\logs\LOG_BM_<DB>_2012082222.sqb

8/22/2012 10:08:01 PM: Deleting old backup file: E:\Program Files\Microsoft SQL Server\MSSQL\Backup\logs\LOG_BM_<DB>_2012082012.sqb
8/22/2012 10:08:26 PM: Deleting old backup file: \\<NAS>\Backups\db04\logs\LOG_BM_<DB>_2012081516.sqb
8/22/2012 10:10:46 PM: BACKUP LOG [BM_<DB>] TO VIRTUAL_DEVICE = 'SQLBACKUP_D68C9ECF-11C4-45A9-B9EB-94EEEAA0EBD0' WITH BUFFERCOUNT = 6, BLOCKSIZE = 65536, MAXTRANSFERSIZE = 1048576, NAME = N'Database (BM_<DB>), 8/22/2012 10:07:41 PM', DESCRIPTION = N'Backup on 8/22/2012 10:07:41 PM Server: SFDB04 Database: BM_<DB>', FORMAT

8/22/2012 10:10:46 PM: Backup data size : 512.000 KB
8/22/2012 10:10:46 PM: Compressed data size: 4.000 KB
8/22/2012 10:10:46 PM: Compression rate : 99.22%

8/22/2012 10:10:46 PM: Processed 0 pages for database 'BM_<DB>', file 'BM_<DB>_log' on file 1.
8/22/2012 10:10:46 PM: BACKUP LOG successfully processed 0 pages in 0.001 seconds (0.000 MB/sec).

8/22/2012 10:10:47 PM: Backing up BM_<DB> (transaction log) to:
8/22/2012 10:10:47 PM: E:\Program Files\Microsoft SQL Server\MSSQL\Backup\logs\LOG_BM_<DB>_2012082222.sqb

8/22/2012 10:10:58 PM: Deleting old backup file: E:\Program Files\Microsoft SQL Server\MSSQL\Backup\logs\LOG_BM_<DB>_2012082013.sqb
8/22/2012 10:11:23 PM: Deleting old backup file: \\<NAS>\Backups\db04\logs\LOG_BM_<DB>_2012081516.sqb
8/22/2012 10:13:30 PM: BACKUP LOG [BM_<DB>] TO VIRTUAL_DEVICE = 'SQLBACKUP_59E48257-E0D0-4F61-8988-F2C27B4EFD21' WITH BUFFERCOUNT = 6, BLOCKSIZE = 65536, MAXTRANSFERSIZE = 1048576, NAME = N'Database (BM_<DB>), 8/22/2012 10:10:47 PM', DESCRIPTION = N'Backup on 8/22/2012 10:10:47 PM Server: SFDB04 Database: BM_<DB>', FORMAT

8/22/2012 10:13:30 PM: Backup data size : 512.000 KB
8/22/2012 10:13:30 PM: Compressed data size: 4.000 KB
8/22/2012 10:13:30 PM: Compression rate : 99.22%

8/22/2012 10:13:30 PM: Processed 0 pages for database 'BM_<DB>', file 'BM_<DB>_log' on file 1.
8/22/2012 10:13:30 PM: BACKUP LOG successfully processed 0 pages in 0.001 seconds (0.000 MB/sec).

8/22/2012 10:13:30 PM: Backing up BM_<DB> (transaction log) to:
8/22/2012 10:13:30 PM: E:\Program Files\Microsoft SQL Server\MSSQL\Backup\logs\LOG_BM_<DB>_2012082222.sqb

8/22/2012 10:13:42 PM: Deleting old backup file: E:\Program Files\Microsoft SQL Server\MSSQL\Backup\logs\LOG_BM_<DB>_2012082013.sqb
8/22/2012 10:14:08 PM: Deleting old backup file: \\<NAS>\Backups\db04\logs\LOG_BM_<DB>_2012081516.sqb
8/22/2012 10:29:54 PM: BACKUP LOG [BM_<DB>] TO VIRTUAL_DEVICE = 'SQLBACKUP_A3CBB810-1439-4360-9FB7-4A25C900C9E5' WITH BUFFERCOUNT = 6, BLOCKSIZE = 65536, MAXTRANSFERSIZE = 1048576, NAME = N'Database (BM_<DB>), 8/22/2012 10:13:30 PM', DESCRIPTION = N'Backup on 8/22/2012 10:13:30 PM Server: SFDB04 Database: BM_<DB>', FORMAT

8/22/2012 10:29:55 PM: Backup data size : 9.500 MB
8/22/2012 10:29:55 PM: Compressed data size: 1.104 MB
8/22/2012 10:29:55 PM: Compression rate : 88.37%

8/22/2012 10:29:55 PM: Processed 880 pages for database 'BM_<DB>', file 'BM_<DB>_log' on file 1.
8/22/2012 10:29:55 PM: BACKUP LOG successfully processed 880 pages in 0.293 seconds (23.444 MB/sec).

8/22/2012 10:29:55 PM: Backing up cms_<DB> (transaction log) to:
8/22/2012 10:29:55 PM: E:\Program Files\Microsoft SQL Server\MSSQL\Backup\logs\LOG_cms_<DB>_2012082222.sqb

8/22/2012 10:32:34 PM: Deleting old backup file: E:\Program Files\Microsoft SQL Server\MSSQL\Backup\logs\LOG_cms_<DB>_2012082013.sqb
8/22/2012 10:32:59 PM: Deleting old backup file: \\<NAS>\Backups\db04\logs\LOG_cms_<DB>_2012081516.sqb
8/22/2012 10:34:50 PM: BACKUP LOG [cms_<DB>] TO VIRTUAL_DEVICE = 'SQLBACKUP_8D9E86C3-C539-4855-874F-06D46B9B7967' WITH BUFFERCOUNT = 6, BLOCKSIZE = 65536, MAXTRANSFERSIZE = 1048576, NAME = N'Database (cms_<DB>), 8/22/2012 10:29:55 PM', DESCRIPTION = N'Backup on 8/22/2012 10:29:55 PM Server: SFDB04 Database: cms_<DB>', FORMAT

8/22/2012 10:34:50 PM: Backup data size : 1.875 MB
8/22/2012 10:34:50 PM: Compressed data size: 312.500 KB
8/22/2012 10:34:50 PM: Compression rate : 83.72%

8/22/2012 10:34:50 PM: Processed 134 pages for database 'cms_<DB>', file 'cms_<DB>_log' on file 1.
8/22/2012 10:34:50 PM: BACKUP LOG successfully processed 134 pages in 0.040 seconds (26.049 MB/sec).

8/22/2012 10:34:51 PM: Backing up cms_<DB> (transaction log) to:
8/22/2012 10:34:51 PM: E:\Program Files\Microsoft SQL Server\MSSQL\Backup\logs\LOG_cms_<DB>_2012082222.sqb

8/22/2012 10:35:02 PM: Deleting old backup file: E:\Program Files\Microsoft SQL Server\MSSQL\Backup\logs\LOG_cms_<DB>_2012082013.sqb
8/22/2012 10:35:26 PM: Deleting old backup file: \\<NAS>\Backups\db04\logs\LOG_cms_<DB>_2012081516.sqb
8/22/2012 10:37:40 PM: BACKUP LOG [cms_<DB>] TO VIRTUAL_DEVICE = 'SQLBACKUP_96CD3BA7-AD3E-491C-8447-77F2C34BC0DA' WITH BUFFERCOUNT = 6, BLOCKSIZE = 65536, MAXTRANSFERSIZE = 1048576, NAME = N'Database (cms_<DB>), 8/22/2012 10:34:51 PM', DESCRIPTION = N'Backup on 8/22/2012 10:34:51 PM Server: SFDB04 Database: cms_<DB>', FORMAT

8/22/2012 10:37:40 PM: Backup data size : 1.250 MB
8/22/2012 10:37:40 PM: Compressed data size: 171.000 KB
8/22/2012 10:37:40 PM: Compression rate : 86.64%

8/22/2012 10:37:40 PM: Processed 76 pages for database 'cms_<DB>', file 'cms_<DB>_log' on file 1.
8/22/2012 10:37:40 PM: BACKUP LOG successfully processed 76 pages in 0.048 seconds (12.237 MB/sec).

8/22/2012 10:37:40 PM: Backing up cms_<DB> (transaction log) to:
8/22/2012 10:37:40 PM: E:\Program Files\Microsoft SQL Server\MSSQL\Backup\logs\LOG_cms_<DB>_2012082222.sqb

8/22/2012 10:37:52 PM: Deleting old backup file: E:\Program Files\Microsoft SQL Server\MSSQL\Backup\logs\LOG_cms_<DB>_2012082013.sqb
8/22/2012 10:38:17 PM: Deleting old backup file: \\<NAS>\Backups\db04\logs\LOG_cms_<DB>_2012081516.sqb
8/22/2012 10:42:16 PM: BACKUP LOG [cms_<DB>] TO VIRTUAL_DEVICE = 'SQLBACKUP_6B7B8E9C-D980-45B6-8DBB-BAB9A101AA9C' WITH BUFFERCOUNT = 6, BLOCKSIZE = 65536, MAXTRANSFERSIZE = 1048576, NAME = N'Database (cms_<DB>), 8/22/2012 10:37:40 PM', DESCRIPTION = N'Backup on 8/22/2012 10:37:40 PM Server: SFDB04 Database: cms_<DB>', FORMAT

8/22/2012 10:42:16 PM: Backup data size : 512.000 KB
8/22/2012 10:42:16 PM: Compressed data size: 5.000 KB
8/22/2012 10:42:16 PM: Compression rate : 99.02%

8/22/2012 10:42:16 PM: Processed 0 pages for database 'cms_<DB>', file 'cms_<DB>_log' on file 1.
8/22/2012 10:42:16 PM: BACKUP LOG successfully processed 0 pages in 0.001 seconds (0.000 MB/sec).

8/22/2012 10:42:17 PM: Backing up cms_<DB> (transaction log) to:
8/22/2012 10:42:17 PM: E:\Program Files\Microsoft SQL Server\MSSQL\Backup\logs\LOG_cms_<DB>_2012082222.sqb

8/22/2012 10:44:46 PM: Deleting old backup file: E:\Program Files\Microsoft SQL Server\MSSQL\Backup\logs\LOG_cms_<DB>_2012082013.sqb
8/22/2012 10:45:11 PM: Deleting old backup file: \\<NAS>\Backups\db04\logs\LOG_cms_<DB>_2012081516.sqb
8/22/2012 10:47:19 PM: BACKUP LOG [cms_<DB>] TO VIRTUAL_DEVICE = 'SQLBACKUP_098F8A6A-CD49-4963-9A47-D88FE90AF695' WITH BUFFERCOUNT = 6, BLOCKSIZE = 65536, MAXTRANSFERSIZE = 1048576, NAME = N'Database (cms_<DB>), 8/22/2012 10:42:17 PM', DESCRIPTION = N'Backup on 8/22/2012 10:42:17 PM Server: SFDB04 Database: cms_<DB>', FORMAT

8/22/2012 10:47:19 PM: Backup data size : 512.000 KB
8/22/2012 10:47:19 PM: Compressed data size: 5.500 KB
8/22/2012 10:47:19 PM: Compression rate : 98.93%

8/22/2012 10:47:19 PM: Processed 0 pages for database 'cms_<DB>', file 'cms_<DB>_log' on file 1.
8/22/2012 10:47:19 PM: BACKUP LOG successfully processed 0 pages in 0.002 seconds (0.000 MB/sec).

8/22/2012 10:47:20 PM: Backing up cms_<DB> (transaction log) to:
8/22/2012 10:47:20 PM: E:\Program Files\Microsoft SQL Server\MSSQL\Backup\logs\LOG_cms_<DB>_2012082222.sqb

8/22/2012 10:47:31 PM: Deleting old backup file: E:\Program Files\Microsoft SQL Server\MSSQL\Backup\logs\LOG_cms_<DB>_2012082013.sqb
8/22/2012 10:47:56 PM: Deleting old backup file: \\<NAS>\Backups\db04\logs\LOG_cms_<DB>_2012081516.sqb
8/22/2012 10:50:01 PM: BACKUP LOG [cms_<DB>] TO VIRTUAL_DEVICE = 'SQLBACKUP_E50ADC05-0250-4596-92D5-4AFF3018C1E0' WITH BUFFERCOUNT = 6, BLOCKSIZE = 65536, MAXTRANSFERSIZE = 1048576, NAME = N'Database (cms_<DB>), 8/22/2012 10:47:20 PM', DESCRIPTION = N'Backup on 8/22/2012 10:47:20 PM Server: SFDB04 Database: cms_<DB>', FORMAT

8/22/2012 10:50:01 PM: Backup data size : 512.000 KB
8/22/2012 10:50:01 PM: Compressed data size: 4.000 KB
8/22/2012 10:50:01 PM: Compression rate : 99.22%

8/22/2012 10:50:01 PM: Processed 0 pages for database 'cms_<DB>', file 'cms_<DB>_log' on file 1.
8/22/2012 10:50:01 PM: BACKUP LOG successfully processed 0 pages in 0.001 seconds (0.000 MB/sec).

8/22/2012 10:50:02 PM: Backing up cms_<DB> (transaction log) to:
8/22/2012 10:50:02 PM: E:\Program Files\Microsoft SQL Server\MSSQL\Backup\logs\LOG_cms_<DB>_2012082222.sqb

8/22/2012 10:50:14 PM: Deleting old backup file: E:\Program Files\Microsoft SQL Server\MSSQL\Backup\logs\LOG_cms_<DB>_2012082014.sqb
8/22/2012 10:50:39 PM: Deleting old backup file: \\<NAS>\Backups\db04\logs\LOG_cms_<DB>_2012081516.sqb
8/22/2012 10:52:43 PM: BACKUP LOG [cms_<DB>] TO VIRTUAL_DEVICE = 'SQLBACKUP_85BCAC41-14D0-44E1-BFBB-A0CC4E93E3F7' WITH BUFFERCOUNT = 6, BLOCKSIZE = 65536, MAXTRANSFERSIZE = 1048576, NAME = N'Database (cms_<DB>), 8/22/2012 10:50:02 PM', DESCRIPTION = N'Backup on 8/22/2012 10:50:02 PM Server: SFDB04 Database: cms_<DB>', FORMAT

8/22/2012 10:52:44 PM: Backup data size : 832.000 KB
8/22/2012 10:52:44 PM: Compressed data size: 30.000 KB
8/22/2012 10:52:44 PM: Compression rate : 96.39%

8/22/2012 10:52:44 PM: Processed 9 pages for database 'cms_<DB>', file 'cms_<DB>_log' on file 1.
8/22/2012 10:52:44 PM: BACKUP LOG successfully processed 9 pages in 0.021 seconds (3.324 MB/sec).

8/22/2012 10:52:44 PM: Backing up cms_<DB> (transaction log) to:
8/22/2012 10:52:44 PM: E:\Program Files\Microsoft SQL Server\MSSQL\Backup\logs\LOG_cms_<DB>_2012082222.sqb

8/22/2012 10:52:54 PM: Deleting old backup file: E:\Program Files\Microsoft SQL Server\MSSQL\Backup\logs\LOG_cms_<DB>_2012082014.sqb
8/22/2012 10:53:19 PM: Deleting old backup file: \\<NAS>\Backups\db04\logs\LOG_cms_<DB>_2012081516.sqb
8/22/2012 10:55:26 PM: BACKUP LOG [cms_<DB>] TO VIRTUAL_DEVICE = 'SQLBACKUP_B2B59394-B0BF-4725-9764-9085A42F1AC7' WITH BUFFERCOUNT = 6, BLOCKSIZE = 65536, MAXTRANSFERSIZE = 1048576, NAME = N'Database (cms_<DB>), 8/22/2012 10:52:44 PM', DESCRIPTION = N'Backup on 8/22/2012 10:52:44 PM Server: SFDB04 Database: cms_<DB>', FORMAT

8/22/2012 10:55:27 PM: Backup data size : 1.438 MB
8/22/2012 10:55:27 PM: Compressed data size: 191.000 KB
8/22/2012 10:55:27 PM: Compression rate : 87.02%

8/22/2012 10:55:27 PM: Processed 81 pages for database 'cms_<DB>', file 'cms_<DB>_log' on file 1.
8/22/2012 10:55:27 PM: BACKUP LOG successfully processed 81 pages in 0.035 seconds (17.898 MB/sec).

8/22/2012 10:55:27 PM: Backing up cms_<DB> (transaction log) to:
8/22/2012 10:55:27 PM: E:\Program Files\Microsoft SQL Server\MSSQL\Backup\logs\LOG_cms_<DB>_2012082222.sqb

8/22/2012 10:55:39 PM: Deleting old backup file: E:\Program Files\Microsoft SQL Server\MSSQL\Backup\logs\LOG_cms_<DB>_2012082014.sqb
8/22/2012 10:56:04 PM: Deleting old backup file: \\<NAS>\Backups\db04\logs\LOG_cms_<DB>_2012081516.sqb
8/22/2012 10:58:11 PM: BACKUP LOG [cms_<DB>] TO VIRTUAL_DEVICE = 'SQLBACKUP_F77CC840-7FE8-4D0A-96DC-80D607A25B73' WITH BUFFERCOUNT = 6, BLOCKSIZE = 65536, MAXTRANSFERSIZE = 1048576, NAME = N'Database (cms_<DB>), 8/22/2012 10:55:27 PM', DESCRIPTION = N'Backup on 8/22/2012 10:55:27 PM Server: SFDB04 Database: cms_<DB>', FORMAT

8/22/2012 10:58:12 PM: Backup data size : 9.438 MB
8/22/2012 10:58:12 PM: Compressed data size: 2.100 MB
8/22/2012 10:58:12 PM: Compression rate : 77.75%

8/22/2012 10:58:12 PM: Processed 940 pages for database 'cms_<DB>', file 'cms_<DB>_log' on file 1.
8/22/2012 10:58:12 PM: BACKUP LOG successfully processed 940 pages in 0.195 seconds (37.647 MB/sec).

.......................

8/23/2012 8:33:10 AM: SQL Backup process ended.

petey · August 23, 2012 11:42AM

A lot of time is spent searching through the 2 folders to determine which files need to be deleted. How many files are there in 'E:\Program Files\Microsoft SQL Server\MSSQL\Backup\logs\' and ' \\<NAS>\Backups\db04\logs\'?

ChrisAVWood · August 23, 2012 1:45PM

Not sure if this makes any difference but the OLD job started at 8.00pm and the NEW one starts at 10.00pm. Could network and server workload be different at 10pm than 8pm?

Just a thought.

Chris

ITSyncForce · August 27, 2012 4:41AM

The logback should run every hour. That would asure us of a maximum lost of data of 1 hour in case of a disaster. In the past it made almost no difference if a log backup run at 3am or 3pm, the one from 3pm ran only a couple of minutes longer due to a higher load of the server.

On the server there are 211 databases. We normally keep the logs of 2 days on the DB server (so a maximum of 10000 logbackupfiles, 23 hourly log backups), however at this moment there are no more then a 1000 files. On the remote server there should be files of the last 7 days (about 35000 files) but now we do not get past the 3500 files.

I do not think it is a problem of searching the directory. To test this I just removed the copy to the NAS and all the files in the current log backup directory. It makes no diffence.

petey · August 27, 2012 4:56AM

Could you please try removing the ERASEFILES_ATSTART and ERASEFILES_REMOTE options, reinstate the COPYTO option, and let the backup run for a couple of days, assuming you have enough space to store the extra files? Do the backups then run faster? Could you also then post the contents of a SQL Backup log for a backup that ran without the ERASEFILES_x options?

Thanks.

ITSyncForce · August 27, 2012 5:02AM

Hi Peter,

I already can tell you that did it. Now it is quick again.

Guess I create a small cleanupscript that will remove the logfiles after 2 days on the server and after 7 days on the NAS.

I am happy again

(just for the stats... 208 logbackups in under 4 minutes

)

petey · August 27, 2012 11:44AM

Glad to hear it's working. It looks like SQL Backup is taking almost 5 minutes to process all the old files in the backup folder and the network share. This process is repeated for every log backup that is ran.

You could resolve this using SQL Backup by storing the backup files in their own sub-folders named after the database e.g. all backups for the DB1 database goes to the 'E:\Program Files\Microsoft SQL Server\MSSQL\Backup\logs\DB1\' folder, and to the '\\<NAS>\Backups\db04\logs\DB1\' network share. In this way, only files belonging to the same database will reside in each folder, and the deletion process then needs to only inspect those files each time it runs. Thus, instead of spending 5 minutes every time it backs up a transaction log, it should now only take 5 minutes in total to perform the deletion process for all the databases it is backing up.

log backup takes forever

Comments

Product Learning

Community Forums

Events & Friends

Simple Talk