Backup Exec 2010. Duplicate jobs from tape to disk take a very long time

[luggi]

We changed our backup policy to duplicate all backups from tape to disk and came across with the situation that “Duplicate backup set following a job”s  are running for many hours (1-12+ hours) which leads to delays with other backups.
I used Backup Exec Debug Monitor to find out the situation from inside. It turned out that most of the time BENGINE is seeking for the backup set on a media (very long) as if it doesn’t have the catalog of backup sets.
There are no such problems to restore the same data from the media (positioning for the backup set is about 3-8 minutes).
Here is a log file I tried to duplicate about 6gb backup set located on the beginning of the media from tape to disk, it took 1hour 15 min (!):
-------------------------
Task Started : Thursday, July 22, 2010 11:21:05 AM
BENGINE:  [07.22.10 11:22:35] [0000]     [6692] 07/22/10 11:22:35 Updating status for: 'ad-daily-to-disk' (0x0 0xB)
BENGINE:  [07.22.10 11:22:35] [0000]     [6692] 07/22/10 11:22:35 Status for: 'ad-daily-to-disk' updated
BENGINE:  [07.22.10 11:22:37] [0000]     [5856] 07/22/10 11:22:37 RewindDrive mover ret = 0 (0x0)
BENGINE:  [07.22.10 11:22:37] [0000]     [5856] 07/22/10 11:22:37   ret_val = 0
BENGINE:  [07.22.10 11:22:37] [0000]     [5856] 07/22/10 11:22:37 Requested Set: ID = 3cf5b028 Seq = 1 Set = 24
BENGINE:  [07.22.10 11:22:37] [0000]     [5856] 07/22/10 11:22:37 Attempting to VCB storage media
BENGINE:  [07.22.10 11:22:37] [0000]     [5856] 07/22/10 11:22:37   TpRead( :(
BENGINE:  [07.22.10 11:22:37] [0000]     [5856] 07/22/10 11:22:37 Error = 0 Req = 65536 Got = 65536
BENGINE:  [07.22.10 11:22:37] [0000]     [5856] 07/22/10 11:22:37 HARDWARE COMPRESSION ===> Compression is configurable.
BENGINE:  [07.22.10 11:22:37] [0000]     [5856] 07/22/10 11:22:37 HARDWARE ENCRYPTION ===> Encryption is supported.
BENGINE:  [07.22.10 11:22:37] [0000]     [5856] 07/22/10 11:22:37 GET_DRV_INF: bsize = 65536
BENGINE:  [07.22.10 11:22:37] [0000]     [5856] 07/22/10 11:22:37 GET_DRV_INF: preferredBlockSize = 65536
BENGINE:  [07.22.10 11:22:37] [0000]     [5856] 07/22/10 11:22:37 FreeFormatEnv( cur_fmt=65535 )
BENGINE:  [07.22.10 11:22:37] [0000]     [5856] 07/22/10 11:22:37 SetupFormatEnv( fmt=0 )
BENGINE:  [07.22.10 11:22:37] [0000]     [5856] 07/22/10 11:22:37 Current media tape header was written by "Symantec Backup Exec 13.0.2896".
BENGINE:  [07.22.10 11:22:37] [0000]     [5856] 07/22/10 11:22:37   TpRead( :(
BENGINE:  [07.22.10 11:22:37] [0000]     [5856] 07/22/10 11:22:37 Error = 0 Req = 65536 Got = 65536
BENGINE:  [07.22.10 11:22:37] [0000]     [5856] 07/22/10 11:22:37 ReadThisSet( cur_fmt=0 )
BENGINE:  [07.22.10 11:22:37] [0000]     [5856] 07/22/10 11:22:37 Set 1 was written by version 13.0.
BENGINE:  [07.22.10 11:22:37] [0000]     [5856] 07/22/10 11:22:37 ReadThisSet() return=0x00000000
BENGINE:  [07.22.10 11:22:37] [0000]     [5856] 07/22/10 11:22:37 Current VCB: ID = 3cf5b028  Seq = 1  Set = 1
BENGINE:  [07.22.10 11:22:37] [0000]     [5856] 07/22/10 11:22:37 GotoBckUpSet( desired=24, this=1 )
BENGINE:  [07.22.10 11:22:37] [0000]     [5856] 07/22/10 11:22:37   state 0, 23 sets to go
BENGINE:  [07.22.10 11:22:37] [0000]     [5856] 07/22/10 11:22:37   state 1, 23 sets to go
BENGINE:  [07.22.10 11:22:37] [0000]     [5856] 07/22/10 11:22:37 MoveNextSet( cur_fmt=0 )
BENGINE:  [07.22.10 11:22:37] [0000]     [5856] 07/22/10 11:22:37 MoveFileMarks( 1 )
BENGINE:  [07.22.10 11:22:37] [0000]     [5856] 07/22/10 11:22:37   TpReadEndSet( :(
 
….. About 30 minutes of moving from set 0 to set 24
 
BENGINE:  [07.22.10 11:56:39] [0000]     [5856] 07/22/10 11:56:39 Set 23 was written by version 13.0.
BENGINE:  [07.22.10 11:56:39] [0000]     [5856] 07/22/10 11:56:39 ReadThisSet() return=0x00000000
BENGINE:  [07.22.10 11:56:39] [0000]     [5856] 07/22/10 11:56:39   state 1, 1 sets to go
BENGINE:  [07.22.10 11:56:39] [0000]     [5856] 07/22/10 11:56:39 MoveNextSet( cur_fmt=0 )
BENGINE:  [07.22.10 11:56:39] [0000]     [5856] 07/22/10 11:56:39 MoveFileMarks( 1 )
BENGINE:  [07.22.10 11:56:39] [0000]     [5856] 07/22/10 11:56:39   TpReadEndSet( :(
BENGINE:  [07.22.10 11:56:40] [0000]     [5856] 07/22/10 11:56:40 MoveFileMarks( ) return=0x00000000
BENGINE:  [07.22.10 11:56:40] [0000]     [5856] 07/22/10 11:56:40   TpRead( :(
BENGINE:  [07.22.10 11:56:40] [0000]     [5856] 07/22/10 11:56:40 Error = 0 Req = 65536 Got = 65536
BENGINE:  [07.22.10 11:56:40] [0000]     [5856] 07/22/10 11:56:40 MoveNextSet() return=0x00000000
BENGINE:  [07.22.10 11:56:40] [0000]     [5856] 07/22/10 11:56:40 ReadThisSet( cur_fmt=0 )
BENGINE:  [07.22.10 11:56:40] [0000]     [5856] 07/22/10 11:56:40 Set 24 was written by version 13.0.
BENGINE:  [07.22.10 11:56:40] [0000]     [5856] 07/22/10 11:56:40 ReadThisSet() return=0x00000000
BENGINE:  [07.22.10 11:56:40] [0000]     [5856] 07/22/10 11:56:40 GotoBckUpSet( ) return=0x00000000
BENGINE:  [07.22.10 11:56:40] [0000]     [5856] 07/22/10 11:56:40 PositionAtSet( :( TF Msg = 8
BENGINE:  [07.22.10 11:56:40] [0000]     [5856] 07/22/10 11:56:40   UI Msg = 8002
BENGINE:  [07.22.10 11:56:40] [0000]     [5856] 07/22/10 11:56:40 HARDWARE COMPRESSION ===> Compression is configurable.
BENGINE:  [07.22.10 11:56:40] [0000]     [5856] 07/22/10 11:56:40 HARDWARE ENCRYPTION ===> Encryption is supported.
BENGINE:  [07.22.10 11:56:40] [0000]     [5856] 07/22/10 11:56:40 GET_DRV_INF: bsize = 65536
BENGINE:  [07.22.10 11:56:40] [0000]     [5856] 07/22/10 11:56:40 GET_DRV_INF: preferredBlockSize = 65536
BENGINE:  [07.22.10 11:56:40] [0000]     [5856] 07/22/10 11:56:40 End of TF_OpenSet: Ret_val = 0x00000000 Buffs = 2 HiWater = 7
BENGINE:  [07.22.10 11:56:40] [0000]     [5856] 07/22/10 11:56:40 Media Server to initiate connection for data transfer
BENGINE:  [07.22.10 11:56:40] [0000]     [5856] 07/22/10 11:56:40 TF_InitMediaServerReverseConnection : Data Connection information: A connection was established between end-points [::1]:54165 and [::1]:54164.
 
………..duplicating  set 24 to disk (about 15 sec, 1GB)………………..
 
BENGINE:  [07.22.10 11:59:21] [0000]     [6692] 07/22/10 11:59:20 Updating status for: 'ad-daily-to-disk' (0x20 0x0)
BENGINE:  [07.22.10 11:59:21] [0000]     [6692] 07/22/10 11:59:20 Status for: 'ad-daily-to-disk' updated
BENGINE:  [07.22.10 11:59:22] [0000]     [5856] 07/22/10 11:59:21 RewindDrive mover ret = 0 (0x0)
BENGINE:  [07.22.10 11:59:22] [0000]     [5856] 07/22/10 11:59:21   ret_val = 0
BENGINE:  [07.22.10 11:59:22] [0000]     [5856] 07/22/10 11:59:21 Requested Set: ID = 3cf5b028 Seq = 1 Set = 22
BENGINE:  [07.22.10 11:59:22] [0000]     [5856] 07/22/10 11:59:21 Attempting to VCB storage media
BENGINE:  [07.22.10 11:59:22] [0000]     [5856] 07/22/10 11:59:21   TpRead( :(
BENGINE:  [07.22.10 11:59:22] [0000]     [5856] 07/22/10 11:59:21 Error = 0 Req = 65536 Got = 65536
BENGINE:  [07.22.10 11:59:22] [0000]     [5856] 07/22/10 11:59:21 HARDWARE COMPRESSION ===> Compression is configurable.
BENGINE:  [07.22.10 11:59:22] [0000]     [5856] 07/22/10 11:59:21 HARDWARE ENCRYPTION ===> Encryption is supported.
BENGINE:  [07.22.10 11:59:22] [0000]     [5856] 07/22/10 11:59:21 GET_DRV_INF: bsize = 65536
BENGINE:  [07.22.10 11:59:22] [0000]     [5856] 07/22/10 11:59:21 GET_DRV_INF: preferredBlockSize = 65536
BENGINE:  [07.22.10 11:59:22] [0000]     [5856] 07/22/10 11:59:21 FreeFormatEnv( cur_fmt=65535 )
BENGINE:  [07.22.10 11:59:22] [0000]     [5856] 07/22/10 11:59:21 SetupFormatEnv( fmt=0 )
BENGINE:  [07.22.10 11:59:22] [0000]     [5856] 07/22/10 11:59:21 Current media tape header was written by "Symantec Backup Exec 13.0.2896".
BENGINE:  [07.22.10 11:59:22] [0000]     [5856] 07/22/10 11:59:21   TpRead( :(
BENGINE:  [07.22.10 11:59:22] [0000]     [5856] 07/22/10 11:59:21 Error = 0 Req = 65536 Got = 65536
BENGINE:  [07.22.10 11:59:22] [0000]     [5856] 07/22/10 11:59:21 ReadThisSet( cur_fmt=0 )
BENGINE:  [07.22.10 11:59:22] [0000]     [5856] 07/22/10 11:59:21 Set 1 was written by version 13.0.
BENGINE:  [07.22.10 11:59:22] [0000]     [5856] 07/22/10 11:59:21 ReadThisSet() return=0x00000000
BENGINE:  [07.22.10 11:59:22] [0000]     [5856] 07/22/10 11:59:21 Current VCB: ID = 3cf5b028  Seq = 1  Set = 1
BENGINE:  [07.22.10 11:59:22] [0000]     [5856] 07/22/10 11:59:21 GotoBckUpSet( desired=22, this=1 )
BENGINE:  [07.22.10 11:59:22] [0000]     [5856] 07/22/10 11:59:21   state 0, 21 sets to go
BENGINE:  [07.22.10 11:59:22] [0000]     [5856] 07/22/10 11:59:21   state 1, 21 sets to go
BENGINE:  [07.22.10 11:59:22] [0000]     [5856] 07/22/10 11:59:21 MoveNextSet( cur_fmt=0 )
BENGINE:  [07.22.10 11:59:22] [0000]     [5856] 07/22/10 11:59:21 MoveFileMarks( 1 )
BENGINE:  [07.22.10 11:59:22] [0000]     [5856] 07/22/10 11:59:21   TpReadEndSet( :(
 
 
……………… About 30 minutes of moving from set 0 to set 22
 
BENGINE:  [07.22.10 12:31:01] [0000]     [5856] 07/22/10 12:31:01 Set 21 was written by version 13.0.
BENGINE:  [07.22.10 12:31:01] [0000]     [5856] 07/22/10 12:31:01 ReadThisSet() return=0x00000000
BENGINE:  [07.22.10 12:31:01] [0000]     [5856] 07/22/10 12:31:01   state 1, 1 sets to go
BENGINE:  [07.22.10 12:31:01] [0000]     [5856] 07/22/10 12:31:01 MoveNextSet( cur_fmt=0 )
BENGINE:  [07.22.10 12:31:01] [0000]     [5856] 07/22/10 12:31:01 MoveFileMarks( 1 )
BENGINE:  [07.22.10 12:31:01] [0000]     [5856] 07/22/10 12:31:01   TpReadEndSet( :(
BENGINE:  [07.22.10 12:33:24] [0000]     [5856] 07/22/10 12:33:23 MoveFileMarks( ) return=0x00000000
BENGINE:  [07.22.10 12:33:24] [0000]     [5856] 07/22/10 12:33:23   TpRead( :(
BENGINE:  [07.22.10 12:33:24] [0000]     [5856] 07/22/10 12:33:23 Error = 0 Req = 65536 Got = 65536
BENGINE:  [07.22.10 12:33:24] [0000]     [5856] 07/22/10 12:33:23 MoveNextSet() return=0x00000000
BENGINE:  [07.22.10 12:33:24] [0000]     [5856] 07/22/10 12:33:23 ReadThisSet( cur_fmt=0 )
BENGINE:  [07.22.10 12:33:24] [0000]     [5856] 07/22/10 12:33:23 Set 22 was written by version 13.0.
BENGINE:  [07.22.10 12:33:24] [0000]     [5856] 07/22/10 12:33:23 ReadThisSet() return=0x00000000
BENGINE:  [07.22.10 12:33:24] [0000]     [5856] 07/22/10 12:33:23 GotoBckUpSet( ) return=0x00000000
BENGINE:  [07.22.10 12:33:24] [0000]     [5856] 07/22/10 12:33:23 PositionAtSet( :( TF Msg = 8
BENGINE:  [07.22.10 12:33:24] [0000]     [5856] 07/22/10 12:33:23   UI Msg = 8002
BENGINE:  [07.22.10 12:33:24] [0000]     [5856] 07/22/10 12:33:23 HARDWARE COMPRESSION ===> Compression is configurable.
BENGINE:  [07.22.10 12:33:24] [0000]     [5856] 07/22/10 12:33:23 HARDWARE ENCRYPTION ===> Encryption is supported.
BENGINE:  [07.22.10 12:33:24] [0000]     [5856] 07/22/10 12:33:23 GET_DRV_INF: bsize = 65536
BENGINE:  [07.22.10 12:33:24] [0000]     [5856] 07/22/10 12:33:23 GET_DRV_INF: preferredBlockSize = 65536
BENGINE:  [07.22.10 12:33:24] [0000]     [5856] 07/22/10 12:33:23 End of TF_OpenSet: Ret_val = 0x00000000 Buffs = 10 HiWater = 7
BENGINE:  [07.22.10 12:33:24] [0000]     [5856] 07/22/10 12:33:23 TF_OpenSet( )
BENGINE:  [07.22.10 12:33:24] [0000]     [5856] 07/22/10 12:33:23 FreeFormatEnv( cur_fmt=65535 )
BENGINE:  [07.22.10 12:33:24] [0000]     [5856] 07/22/10 12:33:23 RewindDrive mover ret = 0 (0x0)
BENGINE:  [07.22.10 12:33:24] [0000]     [5856] 07/22/10 12:33:23   ret_val = 0
BENGINE:  [07.22.10 12:33:24] [0000]     [5856] 07/22/10 12:33:23 Requested Set: ID = ffffffff Seq = -1 Set = -1
BENGINE:  [07.22.10 12:33:24] [0000]     [5856] 07/22/10 12:33:23 Attempting to VCB storage media
BENGINE:  [07.22.10 12:33:24] [0000]     [5856] 07/22/10 12:33:23   TpRead( :(
BENGINE:  [07.22.10 12:33:24] [0000]     [5856] 07/22/10 12:33:23 Error = 1101 Req = 6144 Got = 1024
BENGINE:  [07.22.10 12:33:24] [0000]     [5856] 07/22/10 12:33:23 HARDWARE COMPRESSION ===> Compression is NOT configurable.
BENGINE:  [07.22.10 12:33:24] [0000]     [5856] 07/22/10 12:33:23 HARDWARE ENCRYPTION ===> Encryption is NOT supported.
 
………..duplicating set 22 to disk (about 1 min, 5GB)………………..
 
Task completed : Thursday, July 22, 2010 12:36:48 PM
Time     : 01:15:43 (!)

I also found this entry in the log file:
 
BENGINE:  [07.22.10 11:56:54] [0000]     [5856] 07/22/10 11:56:54 Setting rewind flag to true for older device.  This will likely degrade the performance of the current job.
 
I’m running BE2010 + latest hotfixes on Windows 2008 x64, Tape library HP 1/8  G2 Autoloader w LTO4 tape drive (firmware is up to date).
 
Could anybody help how to workaround the problem ?
Thanks in advance.

[florin_s]

Hello,

kind of offtopic but i'm just wondering what are the advantages or reason that you'd want to duplicate from tape to disk?
usually it's the other way around:
1.you backup to disk(faster backup and restores then to tape)
2.duplicate to  tape(for safe keeping, also cheaper)

br,
florin

[luggi]

Hi Florin
I have one SAN Storage HP EVA 4400 with a fast storage group (sas 15k RPM) for production data (vraids 1,5,6) and a slow storage group (FATA 1tb vraid5) with B2D backups on it for operative data restore during weekdays.
Backups from disk to disk in my case are quite unpredictable – it depends on many factors like B2D disk fragmentation, current EVA load, etc. Many times BE can slow down the backup speed seemingly with no reason.  I had cases of uncontrolled increase of time during backup large data to disk.
Backups from EVA to tape are quicker – reading data from EVA and writing it to tape are speedy all the time. It is about 200Gb per hour for databases data like Exchange, Oracle.  I can easily plan time for my “big” backups. I do not overload EVA by reading and writing at the same time. Reading from tape and duplicating data to disk is also fast.

[GeoffRose]

Hi Luggi

Did you find a solution to this? I am seeing something similar with my BE2010R2 I have the newest firmware too - when I run a backup it seeks for a long time - im hoping this is because its new tapes but I havent seen BE do this before on other installs.

Thanks
Geoff.