Video Screencast Help
Symantec to Separate Into Two Focused, Industry-Leading Technology Companies. Learn more.

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

Created: 30 Nov 2012 | 3 comments

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!

Discussion Filed Under:

Comments 3 CommentsJump to latest comment

soadotjpa's picture

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's picture

Check bpfis and bpbkar log on backup host for clues.

Maybe some sort of issue with snapshot?

Supporting Storage Foundation and VCS on Unix and Windows as well as NetBackup on Unix and Windows
Handy NBU Links

soadotjpa's picture

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