Slow Transaction log backup performance

kmadsen@hbham.comkmadsen@hbham.com Posts: 23
edited June 16, 2005 11:46PM in SQL Backup Previous Versions
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?

Comments

  • peteypetey Posts: 2,358 New member
    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?
    Peter Yeoh
    SQL Backup Consultant Developer
    Associate, Yohz Software
    Beyond compression - SQL Backup goodies under the hood, updated for version 8
  • 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?
  • peteypetey Posts: 2,358 New member
    From the SQL Backup GUI, select the Help menu item, followed by the 'Check for updates' item.
    Peter Yeoh
    SQL Backup Consultant Developer
    Associate, Yohz Software
    Beyond compression - SQL Backup goodies under the hood, updated for version 8
  • Our procedures do not permit updates performed like this on a production server. Is it available for direct download?
  • Brian DonahueBrian Donahue Posts: 6,590 Bronze 1
    Hello,

    I've sent the link directly to your email address. Sorry for the delay.
  • 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?
  • Still no response on the installation instructions. Do I just install over the existing to upgrade or do I need to uninstall first.
  • Brian DonahueBrian Donahue Posts: 6,590 Bronze 1
    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.
  • 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.
  • 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
    Daniel Handley
    Red Gate Software Ltd
  • 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%.
  • 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
    Daniel Handley
    Red Gate Software Ltd
  • 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.
  • fhanlonfhanlon Posts: 17 Bronze 2
    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.
    Francis
  • peteypetey Posts: 2,358 New member
    The 'BACKUP DATABASE successfully processed xx 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 xx TO VIRTUAL DEVICE = xx ..' , 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.
    Peter Yeoh
    SQL Backup Consultant Developer
    Associate, Yohz Software
    Beyond compression - SQL Backup goodies under the hood, updated for version 8
  • 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?
  • peteypetey Posts: 2,358 New member
    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.
    Peter Yeoh
    SQL Backup Consultant Developer
    Associate, Yohz Software
    Beyond compression - SQL Backup goodies under the hood, updated for version 8
  • peteypetey Posts: 2,358 New member
    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.
    Peter Yeoh
    SQL Backup Consultant Developer
    Associate, Yohz Software
    Beyond compression - SQL Backup goodies under the hood, updated for version 8
  • 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)
  • peteypetey Posts: 2,358 New member
    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?
    Peter Yeoh
    SQL Backup Consultant Developer
    Associate, Yohz Software
    Beyond compression - SQL Backup goodies under the hood, updated for version 8
  • 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.
  • 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)
  • peteypetey Posts: 2,358 New member
    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.
    Peter Yeoh
    SQL Backup Consultant Developer
    Associate, Yohz Software
    Beyond compression - SQL Backup goodies under the hood, updated for version 8
  • 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)
  • peteypetey Posts: 2,358 New member
    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?
    Peter Yeoh
    SQL Backup Consultant Developer
    Associate, Yohz Software
    Beyond compression - SQL Backup goodies under the hood, updated for version 8
  • 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?
  • peteypetey Posts: 2,358 New member
    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?
    Peter Yeoh
    SQL Backup Consultant Developer
    Associate, Yohz Software
    Beyond compression - SQL Backup goodies under the hood, updated for version 8
  • peteypetey Posts: 2,358 New member
    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.
    Peter Yeoh
    SQL Backup Consultant Developer
    Associate, Yohz Software
    Beyond compression - SQL Backup goodies under the hood, updated for version 8
Sign In or Register to comment.