Netbackup 7.5 - iSCSI - Large VMDK - Job slow at start

[soadotjpa]

Good Evening,

I'm hoping someone can help me determine if there is a fix for the problem I am experiencing.  I have had several recent environment changes but 90% of my backups are working flawlessly at great speeds.  Here are the details for the last 10%:

When backing up smaller VMs of a size less than 100GB my backups are quick and progress smoothly.  My bpbkar32 job will start usually a minute or two after position the tape to the proper location.  Speeds typically around 55 - 65 MB/sec on an LTO4 tape drive.

When backing up large VMs of a size greater than 100GB my backups are initially crawling.

Here is a snipet from a job backing up a 600GB server:
 

11/30/2012 7:03:20 PM - started process bpbrm (5260)

11/30/2012 7:03:20 PM - connecting

11/30/2012 7:03:21 PM - Info bpbrm(pid=5260) starting bpbkar32 on client         

11/30/2012 7:03:21 PM - connected; connect time: 00:00:01

11/30/2012 7:03:24 PM - Info bpbkar32(pid=5128) Backup started           

11/30/2012 7:03:24 PM - Info bptm(pid=3984) start            

11/30/2012 7:03:24 PM - Info bptm(pid=3984) using 65536 data buffer size        

11/30/2012 7:03:24 PM - Info bptm(pid=3984) setting receive network buffer to 263168 bytes      

11/30/2012 7:03:24 PM - Info bptm(pid=3984) using 30 data buffers         

11/30/2012 7:03:25 PM - Info bptm(pid=3984) start backup           

11/30/2012 7:03:25 PM - Info bptm(pid=3984) Waiting for mount of media id 000406 (copy 1) on server xxxxx

11/30/2012 7:03:25 PM - mounting 000406

11/30/2012 7:04:02 PM - Info bptm(pid=3984) media id 000406 mounted on drive index 0, drivepath {2,0,3,0}, drivename IBM.ULT3580-HH4.000, copy 1

11/30/2012 7:04:02 PM - mounted; mount time: 00:00:37

11/30/2012 7:04:02 PM - positioning 000406 to file 11

11/30/2012 7:04:55 PM - positioned 000406; position time: 00:00:53

11/30/2012 7:04:55 PM - begin writing

11/30/2012 8:03:59 PM - Info bpbkar32(pid=5128) INF - Transport Type = san 

As you can see the bpbkar32 job doesn't kick of for about an hour.  After this job kicks off, I see about 200 KB/sec transfer speeds for another hour.  My network connection shows no real traffic.  My storage device shows no contention for resources.  After this second hour of waiting, my speeds just pick up out of nowhere and I start streaming at around 55-65 MB/sec again.

I'm not sure why it takes approximately 2 hours for NetBackup to really start sending data over my storage fabric on large VMDK files.  Here is a snipet from a 90GB server job details to show the contrast:

11/30/2012 6:00:15 PM - Info bpbrm(pid=4196) reading file list from client        

11/30/2012 6:00:15 PM - Info bpbrm(pid=4196) starting bpbkar32 on client         

11/30/2012 6:00:15 PM - connecting

11/30/2012 6:00:15 PM - connected; connect time: 00:00:00

11/30/2012 6:00:44 PM - Info bpbkar32(pid=4544) Backup started           

11/30/2012 6:00:44 PM - Info bptm(pid=5488) start            

11/30/2012 6:00:44 PM - Info bptm(pid=5488) using 65536 data buffer size        

11/30/2012 6:00:44 PM - Info bptm(pid=5488) setting receive network buffer to 263168 bytes      

11/30/2012 6:00:44 PM - Info bptm(pid=5488) using 30 data buffers         

11/30/2012 6:00:44 PM - Info bptm(pid=5488) start backup           

11/30/2012 6:00:44 PM - Info bptm(pid=5488) Waiting for mount of media id 000406 (copy 1) on server xxxxxxx. 

11/30/2012 6:00:44 PM - mounting 000406

11/30/2012 6:01:23 PM - Info bptm(pid=5488) media id 000406 mounted on drive index 0, drivepath {2,0,3,0}, drivename IBM.ULT3580-HH4.000, copy 1

11/30/2012 6:01:23 PM - mounted; mount time: 00:00:39

11/30/2012 6:01:23 PM - positioning 000406 to file 5

11/30/2012 6:03:43 PM - positioned 000406; position time: 00:02:20

11/30/2012 6:03:43 PM - begin writing

11/30/2012 6:04:21 PM - Info bpbkar32(pid=4544) INF - Transport Type = san       

11/30/2012 6:18:11 PM - Info bptm(pid=5488) waited for full buffer 23591 times, delayed 25269 times    

11/30/2012 6:18:11 PM - Info bpbkar32(pid=4544) bpbkar waited 677 times for empty buffer, delayed 3689 times.   

11/30/2012 6:18:21 PM - Info bptm(pid=5488) EXITING with status 0 <----------        

11/30/2012 6:18:21 PM - Info bpbrm(pid=4196) validating image for client xxxxxxx        

11/30/2012 6:18:21 PM - Info bpbkar32(pid=4544) done. status: 0: the requested operation was successfully completed    

11/30/2012 6:18:21 PM - end writing; write time: 00:14:38

Thank you for your time!

[soadotjpa]

I just realized another bit of information that may be important.  This is the first time this client has been backed up using this new policy.  It is performaing a Full backup.  I'm wondering now if it is scanning the large file to determine what needs to be backed up and this is what is taking the 2 hours.

Thanks

[Marianne]

Check bpfis and bpbkar log on backup host for clues.

Maybe some sort of issue with snapshot?

[soadotjpa]

Thank you for the response, Marianne.

I looked into the snapshots.  From VMWare's perspective it took approximately 30 seconds to create the snapshots and map the disk regions.

bpfis shows these warnings several times:

03:00:05.557 [884.3504] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2

03:00:05.713 [884.3504] <8> bpfis: WRN - VfMS error 10; see following messages:

03:00:05.713 [884.3504] <8> bpfis: WRN - Non-fatal method error was reported

03:00:05.713 [884.3504] <8> bpfis: WRN - vfm_configure_fi_one: method: FlashSnap, type: FIM, function: FlashSnap_init

03:00:05.713 [884.3504] <8> bpfis: WRN - VfMS method error 3; see following message:

03:00:05.713 [884.3504] <8> bpfis: WRN - FlashSnap_init: Veritas Volume Manager not installed.

03:00:05.713 [884.3504] <8> bpfis: WRN - VfMS error 10; see following messages:

03:00:05.713 [884.3504] <8> bpfis: WRN - Non-fatal method error was reported

03:00:05.713 [884.3504] <8> bpfis: WRN - vfm_configure_fi_one: method: vxvm, type: FIM, function: vxvm_init

03:00:05.713 [884.3504] <8> bpfis: WRN - VfMS method error 3; see following message:

03:00:05.713 [884.3504] <8> bpfis: WRN - vxvm_init: Veritas Volume Manager not installed.

bpbkar shows the following during my 2 hour waiting span:

7:03:26.792 PM: [5128.5064] <4> ncfLogConfiguration: INF - Module: libncf, Release: 7.5.0.4 , Build: 09/16/2012 07:30:00 CDT (20120916)

7:03:26.792 PM: [5128.5064] <4> ncfLogConfiguration: INF - Windows version: 5.2.3790, Platform: 2 (Service Pack 2), Service pack: 2.0, Suite: 272, Product type: 3

7:03:26.808 PM: [5128.5064] <4> ncfLogConfiguration: INF - Process architecture: 0, Page size: 4096, Process type: 4, Process level: 586, Processor revision: 15

7:03:26.824 PM: [5128.5064] <4> NcfString::logLocale: INF - Current code page: WINDOWS: 1252  (ANSI - Latin I), Max. character width: 1, Substitution character: 0x3F [?], Unicode substitution character: 0x003f [?.]

7:03:26.980 PM: [5128.5064] <2> tar_base::V_vTarMsgW: INF - Snapshot mapping type: ON

7:03:26.980 PM: [5128.5064] <2> tar_base::V_vTarMsgW: INF - Snapshot BLIB type: ON

7:47:06.324 PM: [5128.5064] <2> tar_base::V_vTarMsgW: INF - Found 3 virtual volume(s)

7:47:15.292 PM: [5128.5064] <2> tar_base::V_vTarMsgW: INF - File System Name to catalog C:

7:47:15.308 PM: [5128.5064] <2> tar_base::V_vTarMsgW: INF - File System Name to catalog C:

7:47:32.621 PM: [5128.5064] <2> tar_base::V_vTarMsgW: INF - File System Name to catalog C:

7:47:32.636 PM: [5128.5064] <2> tar_base::V_vTarMsgW: INF - File System Name to catalog C:

7:47:32.636 PM: [5128.5064] <2> tar_base::V_vTarMsgW: INF - File System Name to catalog C:

7:47:47.480 PM: [5128.5064] <2> tar_base::V_vTarMsgW: INF - File System Name to catalog D:

7:47:47.480 PM: [5128.5064] <2> tar_base::V_vTarMsgW: INF - File System Name to catalog D:

8:03:56.323 PM: [5128.5064] <2> tar_base::V_vTarMsgW: INF - File System Name to catalog D:

8:03:56.339 PM: [5128.5064] <2> tar_base::V_vTarMsgW: INF - File System Name to catalog D:

8:03:56.354 PM: [5128.5064] <2> tar_base::V_vTarMsgW: INF - File System Name to catalog D:

8:03:56.651 PM: [5128.5064] <2> tar_base::V_vTarMsgW: INF - File System Name to catalog Q:

8:03:56.667 PM: [5128.5064] <2> tar_base::V_vTarMsgW: INF - File System Name to catalog Q:

8:03:58.729 PM: [5128.5064] <2> tar_base::V_vTarMsgW: INF - File System Name to catalog Q:

8:03:58.729 PM: [5128.5064] <2> tar_base::V_vTarMsgW: INF - File System Name to catalog Q:

8:03:58.745 PM: [5128.5064] <2> tar_base::V_vTarMsgW: INF - File System Name to catalog Q:

8:03:58.964 PM: [5128.5064] <2> tar_base::V_vTarMsgW: INF - Transport Type = san

8:03:58.979 PM: [5128.5064] <2> tar_base::V_vTarMsgW: INF - File System Name to catalog VIRTUAL_FILE

8:48:39.080 PM: [5128.5064] <2> tar_base::V_vTarMsgW: INF - File System Name to catalog VIRTUAL_FILE

8:48:39.095 PM: [5128.5064] <2> tar_base::V_vTarMsgW: INF - File System Name to catalog VMFILE0

8:51:06.705 PM: [5128.5064] <2> tar_base::V_vTarMsgW: INF - File System Name to catalog VMFILE1