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.