Log Copy Queue Pending

mp · July 21, 2009 11:29AM

Hello,
I just installed SQL Backup 6 and ran a full backup w/network copy last night and everything worked perfectly. I tried to setup transaction log backups this morning and the dumps ran fine, however, the logs are stuck in the Log Copy Queue and the "Last Attempt to Copy" column is empty. The log file for an individual database says:

"No attempts have been made to copy this file."

I am running backups every 15 minutes now and they are stacking up in the queue. Any thoughts/assistance is greatly appreciated. The server is an 64-bit cluster in case that helps any.

-Mike

Chris.Allen · July 21, 2009 1:41PM

We'd better check out the logs which are, by default, here:

C:\Documents and Settings\All Users\Application Data\Red Gate\SQL Backup\Log\<instance>

Also- could you send the script used that causes the problem?

mp · July 21, 2009 1:47PM

Here is a sample log...

7/21/2009 1:30:24 PM: Backing up TestDatabase (transaction log) to:
7/21/2009 1:30:24 PM: X:\Backups\LOG_(local)_TestDatabase_20090721_133024.sqb

7/21/2009 1:30:24 PM: BACKUP LOG [TestDatabase] TO VIRTUAL_DEVICE = 'SQLBACKUP_A905F3BC-11EA-4ED5-A3BC-8910C5F68D3B', VIRTUAL_DEVICE = 'SQLBACKUP_A905F3BC-11EA-4ED5-A3BC-8910C5F68D3B01', VIRTUAL_DEVICE = 'SQLBACKUP_A905F3BC-11EA-4ED5-A3BC-8910C5F68D3B02', VIRTUAL_DEVICE = 'SQLBACKUP_A905F3BC-11EA-4ED5-A3BC-8910C5F68D3B03', VIRTUAL_DEVICE = 'SQLBACKUP_A905F3BC-11EA-4ED5-A3BC-8910C5F68D3B04', VIRTUAL_DEVICE = 'SQLBACKUP_A905F3BC-11EA-4ED5-A3BC-8910C5F68D3B05', VIRTUAL_DEVICE = 'SQLBACKUP_A905F3BC-11EA-4ED5-A3BC-8910C5F68D3B06' WITH BUFFERCOUNT = 28, BLOCKSIZE = 65536, MAXTRANSFERSIZE = 1048576, NAME = N'Database (TestDatabase), 7/21/2009 1:30:24 PM', DESCRIPTION = N'Backup on 7/21/2009 1:30:24 PM Server: sqlcluster Database: TestDatabase', FORMAT

7/21/2009 1:30:24 PM: Backup data size : 4.625 MB
7/21/2009 1:30:24 PM: Compressed data size: 38.500 KB
7/21/2009 1:30:24 PM: Compression rate : 99.19%

7/21/2009 1:30:24 PM: Processed 12 pages for database 'TestDatabase', file 'TestDatabase_log' on file 1.
7/21/2009 1:30:24 PM: BACKUP LOG successfully processed 12 pages in 0.152 seconds (0.606 MB/sec).
7/21/2009 1:30:24 PM:
7/21/2009 1:30:24 PM: Verifying files:
7/21/2009 1:30:24 PM: C:\Backups\LOG_(local)_TestDatabase_20090721_133024.sqb
7/21/2009 1:30:24 PM:
7/21/2009 1:30:25 PM: The backup set on file 1 is valid.

Chris.Allen · July 21, 2009 1:58PM

To reset the status, run these to delete the backed-up copies:

run this first:
EXEC MASTER..sqbdata 'select * from backupfiles_copylist'

see what the stauts of the jobs is (we think its going to be 'A') then run:

EXEC MASTER..sqbdata 'delete from backupfiles_copylist where status = 'A''

(if necessary, change 'A' to the correct status)

Chris.Allen · July 21, 2009 1:59PM

Also, you can use this to make sure there no copy errors:

EXEC MASTER..sqbdata 'select * from backupfiles_copylist_log'

mp · July 21, 2009 1:59PM

I ran that command and all of the records have 'P' for the status column.

mp · July 21, 2009 3:03PM

I seem to be able to reproduce the issue only for 'backup log' commands. I have verified that the SQL command in the agent job has the copyto command in it, however, that value does not seem to show up in the Red Gate logs. The "backup database" commands work fine.

petey · July 22, 2009 8:35AM

When you ran the following from Query Analyzer/Management Studio:

EXEC MASTER..sqbdata 'select * from backupfiles_copylist'

were the 'name' and 'copyto' values correct? Also, were there any results returned when you ran the following:

EXEC MASTER..sqbdata 'select * from backupfiles_copylist_log'

Thanks.

mp · July 22, 2009 9:22AM

Yes, the name and copyto were correct.

This returned nothing:
EXEC MASTER..sqbdata 'select * from backupfiles_copylist_log'

Any ideas?

petey · July 22, 2009 9:40AM

Could you please run the following query and let me know if any rows were returned?

EXEC master..sqbdata 'SELECT id, name, copyto, overwrite, count, diskretryinterval, diskretrycount, mailto, mailto_onerror, created, lastattempt FROM backupfiles_copylist WHERE status = ''P'' ORDER BY count DESC, created'

This is the query used by SQL Backup to pick up files to copy.

I should have answered your other question re copied files. In SQL Backup version 6, transaction log files that need to be copied to one or more other locations are put into a queue. The copying process is thus done in a separate process, and not as part of the backup process. This serves 2 purposes:

- in the event that the copying process takes longer than expected, the current and subsequent backup processes are not blocked
- a queued copy task can be re-attempted multiple times in the event of a failure

Note that only transaction log backups are queued for copying. Other types of backups are copied immediately i.e. as part of the backup task.

mp · July 22, 2009 9:53AM

I currently have no results for that query. I turned off the "with copy" feature and dumped the records from the backupfiles_copylist table yesterday.

I tried several times to create a new transaction log w/copy (and both with and without 'verify') and always resulted in the log files being queued but with no attempts to deliver as indicated by the 'Last Attempt to Copy' column.

petey · July 22, 2009 11:13AM

Assuming that you are starting with an empty backupfiles_copylist table, could you run the following:

EXEC master..sqlbackup '-sql "BACKUP LOG &#91;TestDatabase&#93; TO DISK = &#91;C:\Backups\&lt;AUTO&gt;&#93; WITH COPYTO = &#91;&lt;your destination folder&gt;&#93;"'

Then run the following to check if the copy task has been queued:

EXEC MASTER..sqbdata 'select * from backupfiles_copylist'

and run the following to check if SQL Backup will pick up that task:

EXEC master..sqbdata 'SELECT id, name, copyto, overwrite, count, diskretryinterval, diskretrycount, mailto, mailto_onerror, created, lastattempt FROM backupfiles_copylist WHERE status = ''P'' ORDER BY count DESC, created'

I should also have mentioned that if you don't want the copy task to be queued, you can use the USESIMPLECOPY option so that the backup file is copied immediately following the backup, and not placed in a queue.

Thanks.

mp · July 22, 2009 1:07PM

I have executed the commands as requested and pasted the results below.

EXEC master..sqlbackup '-sql "BACKUP LOG [TestDatabase] TO DISK = [C:\Backups\<AUTO>] WITH COPYTO = [\\myserver\myshare]"'

Backing up TestDatabase (transaction log) to:
C:\Backups\LOG_(local)_TestDatabase_20090722_112057.sqb

Backup data size : 512.000 KB
Compressed data size: 3.500 KB
Compression rate : 99.32%

Processed 0 pages for database 'TestDatabase', file 'TestDatabase_log' on file 1.
BACKUP LOG successfully processed 0 pages in 0.002 seconds (0.000 MB/sec).
SQL Backup process ended.

name value
exitcode 0
sqlerrorcode 0
filename001 C:\Backups\LOG_(local)_TestDatabase_20090722_112057.sqb

EXEC MASTER..sqbdata 'select * from backupfiles_copylist'
id backup_id name copyto overwrite status count retrycount diskretrycount diskretryinterval mailto mailto_onerror created lastattempt lastupdated
420 3082 C:\Backups\LOG_(local)_TestDatabase_20090722_112057.sqb \\myserver\myshare\LOG_(local)_TestDatabase_20090722_112057.sqb 0 P 0 0 10 30 2009-07-22 11:20:58.790 NULL 2009-07-22 15:20:58.000

EXEC master..sqbdata 'SELECT id, name, copyto, overwrite, count, diskretryinterval, diskretrycount, mailto, mailto_onerror, created, lastattempt FROM backupfiles_copylist WHERE status = ''P'' ORDER BY count DESC, created'

id name copyto overwrite count diskretryinterval diskretrycount mailto mailto_onerror created lastattempt
420 C:\Backups\LOG_(local)_TestDatabase_20090722_112057.sqb \\myserver\myshare\LOG_(local)_TestDatabase_20090722_112057.sqb 0 0 30 10 2009-07-22 11:20:58.790 NULL

petey · July 22, 2009 10:23PM

Could you please post the results of the last query if you ran it now? I would like to see if any of the values have changed.

Thanks.

mp · July 23, 2009 9:43AM

Here are the results.

id name copyto overwrite count diskretryinterval diskretrycount mailto mailto_onerror created lastattempt
420 C:\Backups\LOG_(local)_TestDatabase_20090722_112057.sqb \\myserver\myshare\LOG_(local)_TestDatabase_20090722_112057.sqb 0 0 30 10 2009-07-22 11:20:58.790 NULL

mp · July 24, 2009 10:44AM

Hi Pete,
Are we out of ideas on this one?

petey · July 27, 2009 4:03AM

Could you please download a debug copy of the SQL Backup service executable (SQBCoreService.exe) from here:

ftp://support.red-gate.com/patches/SQL_ ... 0_1001.zip

Stop the SQL Backup Agent service using the Windows Service manager, after ensuring that no SQL Backup processes are running. Rename the existing SQL Backup Agent service file (SQBCoreService.exe). Extract the debug version of the executable from the above archive, and place it in the folder where the original SQBCoreService.exe file was located.

Open the registry, and look for the SQL Backup Agent service definition. For the default instance, this would be

HKEY_LOCAL_MACHINE\System\CurrentControlSet\Services\SQLBackupAgent

For a named instance, this would be

HKEY_LOCAL_MACHINE\System\CurrentControlSet\Services\SQLBackupAgent_<instance name>

Look for the ImagePath value, and edit its data. Add -sqbdebug to the end of the startup parameter e.g.

C:\Program Files\Red Gate\SQL Backup\(LOCAL)\SQBCoreService.exe -sqbdebug

Start the SQL Backup Agent service. Let it run for a minute. This should generate a log file named SQBCoreService_log.txt in the folder where SQBCoreService.exe is located. Please send me that file.

Stop the SQL Backup Agent service after that, remove the -sqbdebug parameter from the startup parameter, and restart the service. This is done because the log file (SQBCoreService_log.txt) can grow very fast, and if you are not debugging, just adds unnecessary overhead.

Thanks.

mat.raftree · December 30, 2009 11:17AM

I am getting the exact same problem with SQLBackup 6.3 running on a number of clusters. TLog backups set to copy to a network share

From reading the previous back and forth on this, I ran this:

EXEC master..sqbdata 'SELECT id, name, copyto, overwrite, count, diskretryinterval, diskretrycount, mailto, mailto_onerror, created, lastattempt FROM backupfiles_copylist WHERE status = ''P'' ORDER BY count DESC, created'

And I have a lot of rows returned, the paths are correct, but the "lastattempt" column is null. It is like something is not running to even attempt to perform the copy.

I can confirm that the Diff and Full backups are not impacted by this issue in our environment (Fulls and Diffs copy over to our network share after a local backup is performed with no issue, and I assume this is using the network resiliency features). Our current interim solution is to change all tlog backup jobs to use the "USESIMPLECOPY" param which basically disables network resiliency, but does work most of the time.

Is there anything in the works to resolve this issue or is there anything i should be looking at to further diagnose the problem?

mp · January 4, 2010 9:36AM

I ended up talking to support a couple of times on this issue. They seemed to be genuinely stumped and I kept getting emails from different techs asking me to do the same thing and hoping for different results. I ended up going with another backup compression vendor. Good luck.

Brian Donahue · January 4, 2010 12:34PM

Hello,

I'm sure that whatever problem you're having does not have one signular, uniquely identifyable cause. Network resiliency itself only appeared because so much support time was spent troubleshooting unreliable networks, misconfigured routers, NETBIOS sessions timing out, and the like.

mp · January 4, 2010 1:44PM

Nobody spent any time trying to diagnose any networking issue. The software itself was unable to even attempt to send out the logs due to the queue being "jammed" by itself. Packet captures showed that your software quit attempting to send out data. Nice try though.

Brian Donahue · January 5, 2010 4:59AM

Hi Mike,

I suppose the problem, if anything, is that SQL Backup does not give us much to go on with regards to diagnosing these sorts of problems. I think it's unfair to say we didn't try, though, as you said in your previous post we tried everything we could think of to find the issue.

This will be my last post on this thread.

mp · January 5, 2010 9:07AM

I never said your team didn't try... I was countering your notion that your team grew tired of diagnosing my supposedly "unreliable networks, misconfigured routers, NETBIOS sessions timing out, and the like."

Nobody tried any network troubleshooting on my network as you can see from the forum transcript and the reliability of a simple NIC/ethernet/switch connection was never brought into question.

The problem for me was that your team just stopped trying without any resolution and, to redgate's credit, I was able to obtain a full refund with little issue.

brosato · January 11, 2010 1:28PM

I'm having the same problem.

brosato · January 11, 2010 1:39PM

Here's what I did. It's working again.

EXEC MASTER..sqbdata delete from backupfiles_copylist_log'
EXEC MASTER..sqbdata 'delete from backupfiles_copylist'

brosato · January 19, 2010 12:03PM

Man, this is disaster waiting to happen. I found another server that was doing this. It doesn't copy the log backups to the network for days, but it's been deleting them locally. No errors indicating there are any problems. Good thing I didn't need those logs for anything.

jimclark · June 21, 2011 3:34PM

Our instances have hundreds of databases and we make hourly log backups which are copied to another storage devices. The log copy queue issues were a significant problem for us but we were able to address them just enough to satisfy our needs by adding some registry entries listed in the help on the "Log Copy Queue" page.

The entries are:
COPYTO:CopyIntervalInMinutes
COPYTO:ThreadCount

The max for thread count is 10 so I set that to 10 and set the copy interval to 1 minute. This was just enough to allow our backups to copy over before the next transaction log backup job launched.

In testing this it appeared that the copying used a fairly naÃ¯ve algorithm, basically copying <COPYTO:ThreadCount> files once every <COPYTO:CopyIntervalInMinutes> or something that performs similarly. So copying a large number of files takes a long time, even if the files are very small. Actually, it is a little more sophisticated than that, because it seems to be copying more than <COPYTO:ThreadCount> files at a time, but it appears to copy 20 or so files then do nothing for <COPYTO:CopyIntervalInMinutes>.

At any rate, creating those registry entry seems to have speed things up considerables!

i hope that helps someone.

petey · June 22, 2011 4:20AM

There is indeed a limit of 20 files that SQL Backup can copy in a minute. We'll prepare a patch that should be available in a couple of days time, where you will be able to specify the maximum number of files that SQL Backup should attempt to copy in each run.

Thanks.

petey · June 22, 2011 5:23AM

The main issue was that SQL Backup only processes the number of files equal to 2 x the no. of copy threads. In your case, it was 20 files every minute, as you used 10 threads.

Could you please try a SQL Backup Agent service patch version (6.5.2.3). That patch now recognises a new setting (COPYTO:ThreadMultiplier, DWORD type), that is the multiplier used to determine the number of files to process during each run. So if you used a value of 5 for COPYTO:ThreadMultiplier, and a value of 10 for COPYTO:ThreadCount, SQL Backup will attempt to copy 50 files during each 'copy process' run.

You can download the patch from here:

ftp://support.red-gate.com/Patches/sql_ ... _5_2_3.zip

That archive contains the SQL Backup Agent executable file (SQBCoreService.exe). To replace the existing service executable file, do the following:

- ensure that no SQL Backup processes are running
- stop the SQL Backup Agent service, or disable the cluster resource if on a cluster
- rename the existing executable file (SQBCoreService.exe) in the SQL Backup installation folder
- extract and place the patched executable file into the same folder
- restart the SQL Backup Agent service/cluster resource

Let me know if this works for you.

Thank you.

jimclark · June 23, 2011 8:13AM

Peter,

Thank you for the fast response! I installed the both of the patched files (SQBCoreService.exe and SQLBackupC.exe) since both were in the zip and created the new registry entry and set the value to 10.

The log backup copying process now copies all of my log backups each minute keeping the queue small!

petey · June 23, 2011 8:22AM

Thanks for the update, glad to hear it's working the way you want it to.

Log Copy Queue Pending

Comments

Product Learning

Community Forums

Events & Friends

Simple Talk