Slow Transaction log backup performance

kmadsen@hbham.com · May 9, 2005 10:05AM

I am seeing on one server very slow performance for transaction log backups via the extended stored proc. Looking at the generated log file alone the performance looks good one instance the log shows a start time of 8:40:14 and a finish time of 8:40:17 (3 seconds lapsed time), but the file times on the log file and the backup file are 8 minutes different and they are both located on the same drive in the same folder. Logfile Timestamp = 8:46 and the backup file = 8:38am. Now this is backing up to a remote share (100MB Lan) so I would not expect the times in the log file to match exactly the file times, it looks like an 8 minute period between the create f the backup file and the create of the log file. Note: The backup file size is only 11KB. Also looking that the job that runs the transaction log backups it runs as if it was taking 8+ minutes per database while the backup files total only 4MB.

Any ideas?

petey · May 9, 2005 12:40PM

Are you using version 3.1? 3.0 had a performance issue with regards to backing up to network shares.

Do you experience this delay only for transaction log backups, and only if using the extended stored proc.? Does using the GUI or command line interface give the same problem?

kmadsen@hbham.com · May 9, 2005 1:16PM

We are using version 3.0.0. The delay looks only like it is only involved in transaction log backups. We only perform backups using the XP so I am not sure about the GUI or command line. Where can I get v3.1?

petey · May 9, 2005 1:18PM

From the SQL Backup GUI, select the Help menu item, followed by the 'Check for updates' item.

kmadsen@hbham.com · May 9, 2005 1:30PM

Our procedures do not permit updates performed like this on a production server. Is it available for direct download?

kmadsen@hbham.com · May 16, 2005 10:28AM

Any response?

Brian Donahue · May 16, 2005 12:59PM

Hello,

I've sent the link directly to your email address. Sorry for the delay.

kmadsen@hbham.com · May 16, 2005 1:07PM

It would be very nice as well if the version number was included in the filename so that people knew what version they were installing prior to starting the install. Also do I just install over the existing or do I need to uninstall first to upgrade to the new version?

kmadsen@hbham.com · May 20, 2005 8:01AM

Still no response on the installation instructions. Do I just install over the existing to upgrade or do I need to uninstall first.

Brian Donahue · May 20, 2005 9:28AM

Hello,

The link that I had sent is always the newest version. Older versions are available from a *different* URL. When a new version comes out, we simply append a bit on the end with the old version number.

All that you need to do is run the new install and it should detect the old version and upgrade it. You probably also want to run the 'install stored procedure' utility when it comes up, otherwise, you'll still have the older stored procedure installed on the SQL Server.

kmadsen@hbham.com · June 6, 2005 5:29PM

I have upgraded to v5.2.0 and still see about a two minute pause between finishing backup file and writting the log file. For instance

Contents of the log file
6/6/2005 5:20:43 PM: SQL Backup 3.2.0, (c) Red Gate Software Ltd 2004 - 2005
6/6/2005 5:20:43 PM:
6/6/2005 5:20:43 PM: Backing up Admin (transaction log) to \\hbhscorp4\sqlbak\sqlcmsbk\Admin_TLog_20050606_172007.TRN ...
6/6/2005 5:20:43 PM:
6/6/2005 5:20:43 PM: BACKUP LOG [Admin] TO DISK = '\\hbhscorp4\sqlbak\sqlcmsbk\Admin_TLog_20050606_172007.TRN' WITH NAME = '', DESCRIPTION = '', ERASEFILES = 3, LOGTO = '\\hbhscorp4\sqlbak\sqlcmsbk\Admin_TLog_20050606_172007.Log', COMPRESSION = 1
6/6/2005 5:20:43 PM:
6/6/2005 5:20:43 PM:
6/6/2005 5:20:44 PM: Backup data size : 896.000 KB
6/6/2005 5:20:44 PM: Compressed data size: 11.500 KB
6/6/2005 5:20:44 PM: Compression rate : 98.72%
6/6/2005 5:20:50 PM: Process completed successfully.
6/6/2005 5:20:50 PM:

Processed 1 pages for database 'Admin', file 'Admin_Log' on file 1.
BACKUP LOG successfully processed 1 pages in 0.082 seconds (0.099 MB/sec).
(1 row affected)

which shows a time stamp of 5:23pm and the backup file shows a time of 5:19. Note: This is obviously backing up to a network share and the file times are not in sync with the SQL server's time.

Daniel Handley · June 7, 2005 7:09AM

Hi

I think your right about this being related to backing up over the network. I have not been able to confirm this yet but i would assume that once the last part of the data file is written some verification, not file verification, is occurring and then the file is time stamped.

I would not recommend backing up directly to a network device, unless you have to. My preferred method would be to backup locally and then use the "copyto" option to get the file to the remote drive. Local files can be kept to a minimum by using the "erasefiles" and "erasefiles_atstart" options, and the remote files can be dealt with locally by using robocopy and delete.
This method should also increase the backup time (no network bottle neck), and increase the writing across the network (no backup bottleneck).

Regards
Dan

kmadsen@hbham.com · June 7, 2005 7:25AM

So what is the next step for solving this? Native backups to network shares don't have this issue. In fact native transaction log backups currently complete 2x-3x faster than compressed ones.

FYI - Server is a quad 1.4Ghz with an average CPU utilization while backups are occuring of 15-30%.

Daniel Handley · June 7, 2005 7:32AM

Hi

Sorry I misunderstand. I thought you were saying that the backup takes about 3 seconds to complete, but the timestamp on the remote is different because the remote computer clock is not synced with SQL Server?

Please try my suggested method, but i will attempt to replicate you situation here.

Regards
Dan

kmadsen@hbham.com · June 7, 2005 7:37AM

The log states the backup takes 3 seconds, while actually timing the backup it takes 2-3 minutes. I am willing to try backing up localy, but that is not a fix for this issue.

fhanlon · June 9, 2005 1:40PM

I too have noticed the same thing. I will run some backup in QA. The informational message will say the backup took 1-2 seconds, but the query actually took 30 or so seconds. Here's an actual example:

1. EXEC master..sqlbackup '-SQL "BACKUP DATABASE CME_TRAIN_GLL TO DISK = ''C:\BACKUPS\DB\<AUTO>'' WITH ERASEFILES=2,COMPRESSION=1, VERIFY" -E"'

the output from this command says: BACKUP DATABASE successfully processed 21009 pages in 2.490 seconds (69.115 MB/sec). But in QA it actually took 10 seconds to execute.

2. backup database CME_TRAIN_GLL to DISK='c:\BACKUPS\DB\CME_TRAIN_GLL_FULL_20050609.BAK' with init

The output from this command says BACKUP DATABASE successfully processed 21009 pages in 5.664 seconds. (30.384 MB/sec) QA says it actually took 6 seconds to execute which is about right.

The SQL Backup version is smaller but it doesn't seem to execute in less time despite what it says.

petey · June 10, 2005 2:00PM

The 'BACKUP DATABASE successfully processed

pages ...' message originates from the SQL Server engine. SQL Backup simply displays this message and is the actual time taken to write the compressed file.

However, SQL Backup also writes some header data to the file after it has been generated, and some delays are introduced to ensure that the backup file has been fully flushed to disk before the header data is written. To write part of the header, it also needs to login to SQL Server to retrieve the data.

Also, using the ERASEFILES option requires SQL Backup to iterate through all files in the folder, check if it's a SQL Backup file, read it's header, and decide if the file should be deleted. If you have a lot of files in the folder, this might take some time.

To gain a better insight of what's happening when, you could start Profiler and measure each stage of the backup process. You should see an entry for 'BACKUP

TO VIRTUAL DEVICE =

..' , which is the actual backup process being performed. After that, you should see a query to the backup history table to retrieve the backup details, which is the point when the header data is written.

kmadsen@hbham.com · June 10, 2005 2:13PM

In my case I am seeing approx a 2 minute difference between the log reported time and the actual amount of time. My currently group of regular transaction log backups is taking 20-25 minutes using SQLBackup while native it is in the 2-5 minute range.

What is the next step for correcting this?

petey · June 11, 2005 8:19AM

We'll need to measure exactly how long each of the following task takes:

1. creation of the backup file
2. connecting to SQL Server to retrieve the header data, update the backup history tables and writing the file header
3. deletion of the old backup files
4. writing of the log file

1 and 2 can be measured by looking at profiler, and the writing of the file header is recorded by the date modified attribute of the backup file.

4 can be measured by taking the difference between the date created attribute of the log file and the actual time the entire backup process completes.

3 can only be assumed by taking the difference between 2 and 4, or by creating the backup file to an empty network folder (remember to copy it later to the standard location if you need it), and measuring the time this takes to the time it takes when created in the standard backup folder which contains other backup files.

petey · June 15, 2005 12:57PM

To fhanlon:

For small backups, the time taken by SQL Backup is indeed larger than that taken by native backups due to process overheads (between 2 to 6 seconds). The actual time spent on the backup is as reported. The rest of the time is spent updating the header and backup history, allowing for some intentional delays to ensure the backup file is fully written to disk.

kmadsen@hbham.com · June 15, 2005 3:34PM

First Profiler trace containing the backup commands...

Event Class Application Name Text Data SPID Start Time
Audit Logout SQLAgent - Job Manager 68 6/15/05 3:20 PM
Audit Login OSQL-32 #NAME?
SQL:BatchStarting OSQL-32 set quoted_identifier off 68 6/15/05 3:20 PM
SQL:BatchStarting OSQL-32 BACKUP LOG [Admin] TO VIRTUAL_DEVICE = 'SQLBACKUP_49282749' WITH BLOCKSIZE = 65536, MAXTRANSFERSIZE = 1048576, NAME = '', DESCRIPTION = '', FORMAT
Audit Logout OSQL-32 68 6/15/05 3:20 PM
Audit Login OSQL-32 #NAME?
SQL:BatchStarting OSQL-32 set quoted_identifier off 83 6/15/05 3:20 PM
SQL:BatchStarting OSQL-32 SELECT TOP 1 a.first_lsn, a.last_lsn, a.checkpoint_lsn, a.database_backup_lsn FROM msdb..backupset a INNER JOIN msdb..backupmediafamily b ON a.media_set_id = b.media_set_id WHERE b.physical_device_name = 'SQLBACKUP_49282749' ORDER BY a.media_set_id DESC
Audit Logout OSQL-32 83 6/15/05 3:20 PM
Audit Login OSQL-32 #NAME?
SQL:BatchStarting OSQL-32 set quoted_identifier off 79 6/15/05 3:20 PM
SQL:BatchStarting OSQL-32 UPDATE msdb..backupmediafamily SET physical_device_name = '\\hbhscorp4\sqlbak\sqlcmsbk\Admin_TLog_20050615_152007.TRN' WHERE physical_device_name = 'SQLBACKUP_49282749' AND device_type = 7
SQL:BatchStarting OSQL-32 set quoted_identifier off 82 6/15/05 3:25 PM
SQL:BatchStarting OSQL-32 BACKUP LOG [CMS2000] TO VIRTUAL_DEVICE = 'SQLBACKUP_166256317' WITH BLOCKSIZE = 65536, MAXTRANSFERSIZE = 1048576, NAME = '', DESCRIPTION = '', FORMAT
Audit Logout OSQL-32 82 6/15/05 3:25 PM
Audit Login OSQL-32 #NAME?
SQL:BatchStarting OSQL-32 set quoted_identifier off 60 6/15/05 3:26 PM
SQL:BatchStarting OSQL-32 SELECT TOP 1 a.first_lsn, a.last_lsn, a.checkpoint_lsn, a.database_backup_lsn FROM msdb..backupset a INNER JOIN msdb..backupmediafamily b ON a.media_set_id = b.media_set_id WHERE b.physical_device_name = 'SQLBACKUP_166256317' ORDER BY a.media_set_id DESC
Audit Logout OSQL-32 60 6/15/05 3:26 PM
Audit Login OSQL-32 #NAME?
SQL:BatchStarting OSQL-32 set quoted_identifier off 78 6/15/05 3:26 PM
SQL:BatchStarting OSQL-32 UPDATE msdb..backupmediafamily SET physical_device_name = '\\hbhscorp4\sqlbak\sqlcmsbk\CMS2000_TLog_20050615_152433.TRN' WHERE physical_device_name = 'SQLBACKUP_166256317' AND device_type = 7
Audit Logout OSQL-32 78 6/15/05 3:26 PM

Second the file date/time of the backup files and the logs

Admin DB - TRN File = 3:20pm Log file = 3:24pm
CMS2000 db - TRN File = 3:26pm log file = 3:28pm

Third Log files

Admin.log

6/15/2005 3:20:19 PM: SQL Backup 3.2.0, (c) Red Gate Software Ltd 2004 - 2005
6/15/2005 3:20:19 PM:
6/15/2005 3:20:19 PM: Backing up Admin (transaction log) to \\hbhscorp4\sqlbak\sqlcmsbk\Admin_TLog_20050615_152007.TRN ...
6/15/2005 3:20:19 PM:
6/15/2005 3:20:19 PM: BACKUP LOG [Admin] TO DISK = '\\hbhscorp4\sqlbak\sqlcmsbk\Admin_TLog_20050615_152007.TRN' WITH NAME = '', DESCRIPTION = '', ERASEFILES = 3, LOGTO = '\\hbhscorp4\sqlbak\sqlcmsbk\Admin_TLog_20050615_152007.Log', COMPRESSION = 1
6/15/2005 3:20:19 PM:
6/15/2005 3:20:19 PM:
6/15/2005 3:20:19 PM: Backup data size : 832.000 KB
6/15/2005 3:20:19 PM: Compressed data size: 12.000 KB
6/15/2005 3:20:19 PM: Compression rate : 98.56%
6/15/2005 3:20:25 PM: Process completed successfully.
6/15/2005 3:20:25 PM:

Processed 1 pages for database 'Admin', file 'Admin_Log' on file 1.
BACKUP LOG successfully processed 1 pages in 0.099 seconds (0.082 MB/sec).
(1 row affected)

CMS2000 Log
6/15/2005 3:25:07 PM: SQL Backup 3.2.0, (c) Red Gate Software Ltd 2004 - 2005
6/15/2005 3:25:07 PM:
6/15/2005 3:25:07 PM: Backing up CMS2000 (transaction log) to \\hbhscorp4\sqlbak\sqlcmsbk\CMS2000_TLog_20050615_152433.TRN ...
6/15/2005 3:25:07 PM:
6/15/2005 3:25:07 PM: BACKUP LOG [CMS2000] TO DISK = '\\hbhscorp4\sqlbak\sqlcmsbk\CMS2000_TLog_20050615_152433.TRN' WITH NAME = '', DESCRIPTION = '', ERASEFILES = 3, LOGTO = '\\hbhscorp4\sqlbak\sqlcmsbk\CMS2000_TLog_20050615_152433.Log', COMPRESSION = 1
6/15/2005 3:25:07 PM:
6/15/2005 3:25:07 PM:
6/15/2005 3:25:11 PM: Backup data size : 38.000 MB
6/15/2005 3:25:11 PM: Compressed data size: 8.317 MB
6/15/2005 3:25:11 PM: Compression rate : 78.11%
6/15/2005 3:26:13 PM: Process completed successfully.
6/15/2005 3:26:13 PM:
6/15/2005 3:26:37 PM: Deleting old backup file: \\hbhscorp4\sqlbak\sqlcmsbk\CMS2000_TLog_20050612_112224.TRN

Processed 4722 pages for database 'CMS2000', file 'CMS2000_Log' on file 1.
BACKUP LOG successfully processed 4722 pages in 3.583 seconds (10.795 MB/sec).
(1 row affected)

petey · June 15, 2005 10:45PM

Thanks very much for the details.

When you stated:

Admin DB - TRN File = 3:20pm Log file = 3:24pm
CMS2000 db - TRN File = 3:26pm log file = 3:28pm

I take it these are the timestamps as recorded on the remote machine? If so, it's indeed a strange situation. Could you pls run the same command without the LOGTO option, so no remote logs are created? Does the backup complete faster?

kmadsen@hbham.com · June 16, 2005 7:36AM

Yes these are the timestamps as recorded on the remote machines. I did sync times on the two machines just before executing the backups to ensure that we were working off a common clock. I will be running without the logto option shortly.

kmadsen@hbham.com · June 16, 2005 10:49AM

No significant change in backup time without the logto option. One thing I have seen while manualy running them is I get the following rowcounts back after the backup log successfull message...

1 row effected
9 rows affected
12829 rows affected (This number keeps increasing)

petey · June 16, 2005 11:12AM

Assuming you are running from within Query Analyzer, a regular completion message looks like this:

Output from SQL Backup (3.2.0)

SQL Backup 3.2.0, (c) Red Gate Software Ltd 2004 - 2005
Backing up test001 (transaction log) to c:\temp\test001.sqb ...
Backup data size : 512.000 KB
Compressed data size: 2.500 KB
Compression rate : 99.51%
Process completed successfully.
BACKUP LOG successfully processed 20 pages ....
(1 row affected)

(8 row(s) affected)

The (1 row affected) message comes from the SQL Server backup engine, while the (8 row(s) affected) message appears because there were 8 lines of output.

You mean to say that you have a 3rd line that displays an even larger number of rows affected? Are there any output between the '9 rows affected' and the '12829 rows affected' lines? Strange, because the profiler output you provided does not seem to suggest another query was ran after the history tables were updated.

Could you post the command that you ran from within QA? Thanks.

kmadsen@hbham.com · June 16, 2005 12:06PM

Command ran from QA =
exec spLogDBBackup '\\hbhscorp4\sqlbak\sqlcmsbk\',3,'CatalogTraining','distribution'

Definition of spLogDBBackup
CREATE procedure spLogDBBackup
@BackupPath sysname,
@RetentionDays tinyint,
@Skip1 sysname = NULL,
@Skip2 sysname = NULL,
@Skip3 sysname = NULL,
@Skip4 sysname = NULL,
@Skip5 sysname = NULL,
@Skip6 sysname = NULL,
@Skip7 sysname = NULL,
@Skip8 sysname = NULL,
@Skip9 sysname = NULL,
@Skip10 sysname = NULL
as
--Intialize the database to be skipped list
create table #SkipDBs (DBName sysname null)
insert into #SkipDBs select @Skip1
insert into #SkipDBs select @Skip2
insert into #SkipDBs select @Skip3
insert into #SkipDBs select @Skip4
insert into #SkipDBs select @Skip5
insert into #SkipDBs select @Skip6
insert into #SkipDBs select @Skip7
insert into #SkipDBs select @Skip8
insert into #SkipDBs select @Skip9
insert into #SkipDBs select @Skip10

--Create the cursor to loop through the databases respecting the skip list
declare @DBName sysname
declare DB_Cursor Cursor for
select name from master.dbo.sysdatabases
where name not in (select DBName from #SkipDBs where DBName is not null)
and name not in ('TempDB','Master','Model','msdb')
open DB_Cursor

fetch next from DB_Cursor into @DBName

@fetch_status = 0
begin
-- print @DBName
-- select getdate()
exec spDBBackupLog @DBName, @BackupPath, @RetentionDays
-- select getdate()
fetch next from DB_Cursor into @DBName
end

close DB_Cursor
deallocate DB_Cursor
GO

Definition of spDBBackupLog
CREATE procedure spDBBackupLog
@DB_Name sysname,
@BackupPath sysname,
@RetentionDays tinyint
as
declare @BKFileName nvarchar(284)
declare @LogFileName nvarchar(284)
declare @CMDString nvarchar(255)
declare @BackupString nvarchar(4000)
declare @Cur_Date datetime

select @Cur_date = getdate()

--Verify the Database Name is valid
if not exists (select name from master.dbo.sysdatabases where name=@DB_Name)
begin
print 'The database name '+@DB_Name+' is not found in Master.dbo.Sysdatabases'
print 'Usage: exec spDBBackupFull ''DatabaseName'', ''PathToBackup'', NumberOfBackupFilesToRetain'
return 1
end

--Verify the Backup Path is valid
select @CMDString='dir '+@BackupPath
create table #DirOutput (Line nvarchar(255))
insert into #DirOutput
exec master.dbo.xp_cmdshell @CMDString
if exists (select line from #DirOutput where line='File Not Found')
begin
print 'The Backup Path '+@BackupPath+' Does not exist'
print 'Usage: exec spDBBackupFull ''DatabaseName'', ''PathToBackup'', NumberOfBackupFilesToRetain'
return 1
end

--Normalize the backup path with an ending if (select right(@BackupPath,1))<>'\'
select @BackupPath=@BackupPath+'\'

--Build the Backup Filename including the path
select @BKFileName=@BackupPath+@DB_Name+'_TLog_'
+(select right('0000'+cast(datepart(yyyy,@Cur_Date) as nvarchar(4)),4))
+(select right('00'+cast(datepart(mm,@Cur_Date) as nvarchar(2)),2))
+(select right('00'+cast(datepart(dd,@Cur_Date) as nvarchar(2))+'_',3))
+(select right('00'+cast(datepart(hh,@Cur_Date) as nvarchar(2)),2))
+(select right('00'+cast(datepart(mi,@Cur_Date) as nvarchar(2)),2))
+(select right('00'+cast(datepart(ss,@Cur_Date) as nvarchar(2)),2))
+'.TRN'

--Build the Log Filename including the path
select @LogFileName=@BackupPath+@DB_Name+'_TLog_'
+(select right('0000'+cast(datepart(yyyy,@Cur_Date) as nvarchar(4)),4))
+(select right('00'+cast(datepart(mm,@Cur_Date) as nvarchar(2)),2))
+(select right('00'+cast(datepart(dd,@Cur_Date) as nvarchar(2))+'_',3))
+(select right('00'+cast(datepart(hh,@Cur_Date) as nvarchar(2)),2))
+(select right('00'+cast(datepart(mi,@Cur_Date) as nvarchar(2)),2))
+(select right('00'+cast(datepart(ss,@Cur_Date) as nvarchar(2)),2))
+'.Log'

--Build the Backup Command String
select @BackupString=
'exec master.dbo.sqlbackup ''-SQL "BACKUP LOG '+@DB_Name+
' TO DISK = ['+@BKFileName+
-- '] WITH LOGTO = , ERASEFILES = '+cast(@RetentionDays as nvarchar(4))+'"'''
'] with ERASEFILES = '+cast(@RetentionDays as nvarchar(4))+'"'''

-- print @BackupString
exec sp_executesql @BackupString
GO

QA Output (Note: The two select getdate() lines were uncommented for this run)

(1 row(s) affected)

(1 row(s) affected)

(1 row(s) affected)

(1 row(s) affected)

(1 row(s) affected)

(1 row(s) affected)

(1 row(s) affected)

(1 row(s) affected)

(1 row(s) affected)

(1 row(s) affected)

2005-06-16 11:35:03.883

(1 row(s) affected)

(12846 row(s) affected)

exec master.dbo.sqlbackup '-SQL "BACKUP LOG Admin TO DISK = [\\hbhscorp4\sqlbak\sqlcmsbk\Admin_TLog_20050616_113503.TRN] with ERASEFILES = 3"'
Output from SQL Backup (3.2.0)

SQL Backup 3.2.0, (c) Red Gate Software Ltd 2004 - 2005
Serial number: 010-005-019079-86FA
Backing up Admin (transaction log) to \\hbhscorp4\sqlbak\sqlcmsbk\Admin_TLog_20050616_113503.TRN ...
Backup data size : 832.000 KB
Compressed data size: 15.500 KB
Compression rate : 98.14%
Process completed successfully.
Processed 3 pages for database 'Admin', file 'Admin_Log' on file 1.
BACKUP LOG successfully processed 3 pages in 0.058 seconds (0.344 MB/sec).
(1 row affected)

(10 row(s) affected)

2005-06-16 11:38:35.630

(1 row(s) affected)

2005-06-16 11:38:35.630

(1 row(s) affected)

(12848 row(s) affected)

exec master.dbo.sqlbackup '-SQL "BACKUP LOG CMS2000 TO DISK = [\\hbhscorp4\sqlbak\sqlcmsbk\CMS2000_TLog_20050616_113835.TRN] with ERASEFILES = 3"'
Output from SQL Backup (3.2.0)

SQL Backup 3.2.0, (c) Red Gate Software Ltd 2004 - 2005
Serial number: 010-005-019079-86FA
Backing up CMS2000 (transaction log) to \\hbhscorp4\sqlbak\sqlcmsbk\CMS2000_TLog_20050616_113835.TRN ...
Backup data size : 4.250 MB
Compressed data size: 709.000 KB
Compression rate : 83.71%
Process completed successfully.
Processed 420 pages for database 'CMS2000', file 'CMS2000_Log' on file 1.
BACKUP LOG successfully processed 420 pages in 0.198 seconds (17.348 MB/sec).
(1 row affected)

(10 row(s) affected)

2005-06-16 11:41:37.317

(1 row(s) affected)

2005-06-16 11:41:37.317

(1 row(s) affected)

(12850 row(s) affected)

exec master.dbo.sqlbackup '-SQL "BACKUP LOG CMSHeavenly TO DISK = [\\hbhscorp4\sqlbak\sqlcmsbk\CMSHeavenly_TLog_20050616_114137.TRN] with ERASEFILES = 3"'
Output from SQL Backup (3.2.0)

SQL Backup 3.2.0, (c) Red Gate Software Ltd 2004 - 2005
Serial number: 010-005-019079-86FA
Backing up CMSHeavenly (transaction log) to \\hbhscorp4\sqlbak\sqlcmsbk\CMSHeavenly_TLog_20050616_114137.TRN ...
Backup data size : 704.000 KB
Compressed data size: 23.500 KB
Compression rate : 96.66%
Process completed successfully.
Processed 9 pages for database 'CMSHeavenly', file 'CMS2000_Log' on file 1.
BACKUP LOG successfully processed 9 pages in 0.089 seconds (0.765 MB/sec).
(1 row affected)

(10 row(s) affected)

2005-06-16 11:44:34.393

(1 row(s) affected)

2005-06-16 11:44:34.393

(1 row(s) affected)

(12852 row(s) affected)

exec master.dbo.sqlbackup '-SQL "BACKUP LOG eConnect TO DISK = [\\hbhscorp4\sqlbak\sqlcmsbk\eConnect_TLog_20050616_114434.TRN] with ERASEFILES = 3"'
Output from SQL Backup (3.2.0)

SQL Backup 3.2.0, (c) Red Gate Software Ltd 2004 - 2005
Serial number: 010-005-019079-86FA
Backing up eConnect (transaction log) to \\hbhscorp4\sqlbak\sqlcmsbk\eConnect_TLog_20050616_114434.TRN ...
Backup data size : 896.000 KB
Compressed data size: 66.500 KB
Compression rate : 92.58%
Process completed successfully.
Processed 28 pages for database 'eConnect', file 'eConnect_Log' on file 1.
BACKUP LOG successfully processed 28 pages in 0.089 seconds (2.531 MB/sec).
(1 row affected)

(10 row(s) affected)

2005-06-16 11:47:26.050

(1 row(s) affected)

2005-06-16 11:47:26.050

(1 row(s) affected)

(12853 row(s) affected)

exec master.dbo.sqlbackup '-SQL "BACKUP LOG eConnectOregon TO DISK = [\\hbhscorp4\sqlbak\sqlcmsbk\eConnectOregon_TLog_20050616_114726.TRN] with ERASEFILES = 3"'
Output from SQL Backup (3.2.0)

SQL Backup 3.2.0, (c) Red Gate Software Ltd 2004 - 2005
Serial number: 010-005-019079-86FA
Backing up eConnectOregon (transaction log) to \\hbhscorp4\sqlbak\sqlcmsbk\eConnectOregon_TLog_20050616_114726.TRN ...
Backup data size : 576.000 KB
Compressed data size: 4.500 KB
Compression rate : 99.22%
Process completed successfully.
BACKUP LOG successfully processed 0 pages in 0.005 seconds (0.000 MB/sec).
(1 row affected)

(9 row(s) affected)

2005-06-16 11:49:52.453

(1 row(s) affected)

2005-06-16 11:49:52.453

(1 row(s) affected)

(12854 row(s) affected)

exec master.dbo.sqlbackup '-SQL "BACKUP LOG HOS TO DISK = [\\hbhscorp4\sqlbak\sqlcmsbk\HOS_TLog_20050616_114952.TRN] with ERASEFILES = 3"'
Output from SQL Backup (3.2.0)

SQL Backup 3.2.0, (c) Red Gate Software Ltd 2004 - 2005
Serial number: 010-005-019079-86FA
Backing up HOS (transaction log) to \\hbhscorp4\sqlbak\sqlcmsbk\HOS_TLog_20050616_114952.TRN ...
Backup data size : 512.000 KB
Compressed data size: 2.000 KB
Compression rate : 99.61%
Process completed successfully.
BACKUP LOG successfully processed 0 pages in 0.046 seconds (0.000 MB/sec).
(1 row affected)

(9 row(s) affected)

2005-06-16 11:52:20.220

(1 row(s) affected)

2005-06-16 11:52:20.220

(1 row(s) affected)

(12855 row(s) affected)

exec master.dbo.sqlbackup '-SQL "BACKUP LOG Northwind TO DISK = [\\hbhscorp4\sqlbak\sqlcmsbk\Northwind_TLog_20050616_115220.TRN] with ERASEFILES = 3"'
Output from SQL Backup (3.2.0)

SQL Backup 3.2.0, (c) Red Gate Software Ltd 2004 - 2005
Serial number: 010-005-019079-86FA
Backing up Northwind (transaction log) to \\hbhscorp4\sqlbak\sqlcmsbk\Northwind_TLog_20050616_115220.TRN ...
Backup data size : 576.000 KB
Compressed data size: 4.000 KB
Compression rate : 99.31%
Process completed successfully.
BACKUP LOG successfully processed 0 pages in 0.009 seconds (0.000 MB/sec).
(1 row affected)

(9 row(s) affected)

2005-06-16 11:55:04.437

(1 row(s) affected)

2005-06-16 11:55:04.437

(1 row(s) affected)

(12856 row(s) affected)

exec master.dbo.sqlbackup '-SQL "BACKUP LOG POrderApp TO DISK = [\\hbhscorp4\sqlbak\sqlcmsbk\POrderApp_TLog_20050616_115504.TRN] with ERASEFILES = 3"'
Output from SQL Backup (3.2.0)

SQL Backup 3.2.0, (c) Red Gate Software Ltd 2004 - 2005
Serial number: 010-005-019079-86FA
Backing up POrderApp (transaction log) to \\hbhscorp4\sqlbak\sqlcmsbk\POrderApp_TLog_20050616_115504.TRN ...
Backup data size : 704.000 KB
Compressed data size: 39.500 KB
Compression rate : 94.39%
Process completed successfully.
Processed 15 pages for database 'POrderApp', file 'POrderApp_Log' on file 1.
BACKUP LOG successfully processed 15 pages in 0.086 seconds (1.422 MB/sec).
(1 row affected)

(10 row(s) affected)

2005-06-16 11:58:07.593

(1 row(s) affected)

2005-06-16 11:58:07.593

(1 row(s) affected)

(12857 row(s) affected)

exec master.dbo.sqlbackup '-SQL "BACKUP LOG pubs TO DISK = [\\hbhscorp4\sqlbak\sqlcmsbk\pubs_TLog_20050616_115807.TRN] with ERASEFILES = 3"'
Output from SQL Backup (3.2.0)

SQL Backup 3.2.0, (c) Red Gate Software Ltd 2004 - 2005
Serial number: 010-005-019079-86FA
Backing up pubs (transaction log) to \\hbhscorp4\sqlbak\sqlcmsbk\pubs_TLog_20050616_115807.TRN ...
Backup data size : 512.000 KB
Compressed data size: 3.000 KB
Compression rate : 99.41%
Process completed successfully.
BACKUP LOG successfully processed 0 pages in 0.014 seconds (0.000 MB/sec).
(1 row affected)

(9 row(s) affected)

2005-06-16 12:01:12.310

(1 row(s) affected)

petey · June 16, 2005 12:55PM

The large number comes from the xp_cmdshell command to list out the files in the backup folder.

select @CMDString='dir '+@BackupPath
create table #DirOutput (Line nvarchar(255))
insert into #DirOutput
exec master.dbo.xp_cmdshell @CMDString

That means you have 12000+ files all in the same folder, which SQL Backup will need to check which to delete, everytime the backup is performed.

Could you try running the stored procedure but backing up the files to an empty folder (remember to copy it back to the \\hbhscorp4\sqlbak\sqlcmsbk folder)? Does the backup complete faster?

kmadsen@hbham.com · June 16, 2005 3:09PM

I deleted 12K+ of the log files and now it runs much faster. Is there ever going to be an option to delete older log files like the erase files option?

petey · June 16, 2005 9:29PM

The ERASEFILES option that you used (ERASEFILES = 3) should have deleted log files older than 3 days in the backup folder. Do you mean to say that this was not the case?

petey · June 16, 2005 11:46PM

Ignore my last post. I just realized (thx to appwright) that the log files you are referring to are the SQL Backup (SQB) log files, not the db trx log files.

Deleting old SQB log files in the standard log folder is a feature planned for a future release. Hopefully, we can fit in the option to delete old SQB log files in user defined log folders too.

Thanks for your effort and patience.

Slow Transaction log backup performance

Comments

Product Learning

Community Forums

Events & Friends

Simple Talk