cancel
Showing results for 
Search instead for 
Did you mean: 

vmware backup takes to start writing data

Fernando_Sampai
Level 3

After migrating to NetBackup 7.6.0.4, backup jobs with vmware Accelerator takes about 20 minutes to start the writing of the data:

Job Details:

3/27/2015 2:17:46 PM - Info nbjm(pid=12192) starting backup job (jobid=1324665) for client SRV10551, policy D-VMware-SO-DC-ClusterDev, schedule Diff  
3/27/2015 2:17:46 PM - estimated 73614966 Kbytes needed
3/27/2015 2:17:46 PM - Info nbjm(pid=12192) started backup (backupid=SRV10551_1427476666) job for client SRV10551, policy D-VMware-SO-DC-ClusterDev, schedule Diff on storage unit SRV10422_DEDUP
3/27/2015 2:17:48 PM - started process bpbrm (137568)
3/27/2015 2:17:49 PM - Info bpbrm(pid=137568) SRV10551 is the host to backup data from     
3/27/2015 2:17:49 PM - Info bpbrm(pid=137568) reading file list for client        
3/27/2015 2:17:50 PM - Info bpbrm(pid=137568) accelerator enabled           
3/27/2015 2:17:52 PM - Info bpbrm(pid=137568) starting bpbkar32 on client         
3/27/2015 2:17:52 PM - connecting
3/27/2015 2:17:52 PM - connected; connect time: 0:00:00
3/27/2015 2:17:53 PM - Info bpbkar32(pid=139976) Backup started           
3/27/2015 2:17:53 PM - Info bpbkar32(pid=139976) accelerator enabled backup, archive bit processing:<disabled>       
3/27/2015 2:17:53 PM - Info bptm(pid=132660) start            
3/27/2015 2:17:53 PM - Info bptm(pid=132660) using 262144 data buffer size        
3/27/2015 2:17:53 PM - Info bptm(pid=132660) setting receive network buffer to 1049600 bytes      
3/27/2015 2:17:53 PM - Info bptm(pid=132660) using 30 data buffers         
3/27/2015 2:17:54 PM - Info bptm(pid=132660) start backup           
3/27/2015 2:17:55 PM - begin writing
3/27/2015 2:38:58 PM - Info bpbkar32(pid=139976) INF - Transport Type =  san      
3/27/2015 2:40:19 PM - Info bpbkar32(pid=139976) accelerator sent 186496512 bytes out of 64444267520 bytes to server, optimization 99.7% 
3/27/2015 2:40:20 PM - Info bpbkar32(pid=139976) bpbkar waited 136 times for empty buffer, delayed 1822 times.   
3/27/2015 2:40:58 PM - Info bptm(pid=132660) waited for full buffer 7 times, delayed 80857 times    
3/27/2015 2:41:15 PM - Info bptm(pid=132660) EXITING with status 0 <----------        

3/27/2015 2:41:15 PM - Info srv10422(pid=132660) StorageServer=PureDisk:srv10422; Report=PDDO Stats for (srv10422): scanned: 62937049 KB, CR sent: 373026 KB, CR sent over FC: 0 KB, dedup: 99.4%, cache disabled
3/27/2015 2:41:16 PM - Info bpbrm(pid=137568) validating image for client SRV10551        
3/27/2015 2:41:16 PM - Info bpbkar32(pid=139976) done. status: 0: the requested operation was successfully completed    
3/27/2015 2:41:17 PM - end writing; write time: 0:23:22
the requested operation was successfully completed(0)

8 REPLIES 8

sdo
Moderator
Moderator
Partner    VIP    Certified

1) Do all Diff accelerated VM SAN backups now take 20 minutes longer, or just some?

2) Was this the first ever occurence of the Diff schedules in v7.6.0.4?

3) Do Full accerelated VM SAN backups of the same clients also take 20 minutes longer?

4) If you run a Full accelerated VM SAN backup and then a Diff accelerated VM SAN backup, does the Diff still take 20 minutes longer than it used to?

Fernando_Sampai
Level 3

Hi, sdo

Yes, all the diff backups are taking 20 minutes.

The full backups also take the same time. Follows the job details of the full backup of the same client sent previously:

3/25/2015 9:04:15 PM - Info nbjm(pid=12192) starting backup job (jobid=1322048) for client SRV10551, policy D-VMware-SO-DC-ClusterDev, schedule Full 
3/25/2015 9:04:15 PM - estimated 74018353 Kbytes needed
3/25/2015 9:04:15 PM - Info nbjm(pid=12192) started backup (backupid=SRV10551_1427328255) job for client SRV10551, policy D-VMware-SO-DC-ClusterDev, schedule Full on storage unit SRV10422_DEDUP
3/25/2015 9:04:17 PM - started process bpbrm (127496)
3/25/2015 9:04:18 PM - Info bpbrm(pid=127496) SRV10551 is the host to backup data from    
3/25/2015 9:04:18 PM - Info bpbrm(pid=127496) reading file list for client       
3/25/2015 9:04:19 PM - Info bpbrm(pid=127496) accelerator enabled          
3/25/2015 9:04:20 PM - Info bpbrm(pid=127496) starting bpbkar32 on client        
3/25/2015 9:04:20 PM - connecting
3/25/2015 9:04:20 PM - connected; connect time: 0:00:00
3/25/2015 9:04:21 PM - Info bpbkar32(pid=128988) Backup started          
3/25/2015 9:04:21 PM - Info bpbkar32(pid=128988) accelerator enabled backup, archive bit processing:<disabled>      
3/25/2015 9:04:21 PM - Info bptm(pid=138232) start           
3/25/2015 9:04:21 PM - Info bptm(pid=138232) using 262144 data buffer size       
3/25/2015 9:04:21 PM - Info bptm(pid=138232) setting receive network buffer to 1049600 bytes     
3/25/2015 9:04:21 PM - Info bptm(pid=138232) using 30 data buffers        
3/25/2015 9:04:22 PM - Info bptm(pid=138232) start backup          
3/25/2015 9:04:23 PM - begin writing
3/25/2015 9:33:27 PM - Info bpbkar32(pid=128988) INF - Transport Type =  san     
3/25/2015 9:40:56 PM - Info bptm(pid=138232) waited for full buffer 1160 times, delayed 111283 times   
3/25/2015 9:40:56 PM - Info bpbkar32(pid=128988) accelerator sent 3446327296 bytes out of 64614076416 bytes to server, optimization 94.7%
3/25/2015 9:40:57 PM - Info bpbkar32(pid=128988) bpbkar waited 516 times for empty buffer, delayed 3524 times.  
3/25/2015 9:41:17 PM - Info bptm(pid=138232) EXITING with status 0 <----------       
3/25/2015 9:41:17 PM - Info srv10422(pid=138232) StorageServer=PureDisk:srv10422; Report=PDDO Stats for (srv10422): scanned: 63127399 KB, CR sent: 1887532 KB, CR sent over FC: 0 KB, dedup: 97.0%, cache disabled
3/25/2015 9:41:17 PM - Info bpbrm(pid=127496) validating image for client SRV10551       
3/25/2015 9:41:18 PM - Info bpbkar32(pid=128988) done. status: 0: the requested operation was successfully completed   
3/25/2015 9:41:18 PM - end writing; write time: 0:36:55
the requested operation was successfully completed(0)

Marianne
Moderator
Moderator
Partner    VIP    Accredited Certified

You will need bptm log on media server and bpbkar log on backup host to see what is happening.

Logging level above 0 will be needed. I normally find sufficient info with level 3.

Fernando_Sampai
Level 3

Hi,


follows the requested logs.


I created a new backup policy vmware only with the client mentioned in previous reviews that the logs would not get very large.


regards.

mnolan
Level 6
Employee Accredited Certified

Do you have the job details for jobid 1339181 that these logs are from?

Fernando_Sampai
Level 3

4/8/2015 7:29:08 AM - Info nbjm(pid=12192) starting backup job (jobid=1339181) for client SRV10551, policy VMware_Teste_SRV10551, schedule Full 
4/8/2015 7:29:08 AM - estimated 0 Kbytes needed
4/8/2015 7:29:08 AM - Info nbjm(pid=12192) started backup (backupid=SRV10551_1428488948) job for client SRV10551, policy VMware_Teste_SRV10551, schedule Full on storage unit SRV10422_DEDUP
4/8/2015 7:29:10 AM - started process bpbrm (153348)
4/8/2015 7:29:11 AM - Info bpbrm(pid=153348) SRV10551 is the host to backup data from    
4/8/2015 7:29:11 AM - Info bpbrm(pid=153348) reading file list for client       
4/8/2015 7:29:11 AM - Info bpbrm(pid=153348) accelerator enabled          
4/8/2015 7:29:12 AM - Info bpbrm(pid=153348) There is no complete backup image match with track journal, a regular full backup will be performed.
4/8/2015 7:29:12 AM - Info bpbrm(pid=153348) starting bpbkar32 on client        
4/8/2015 7:29:12 AM - Info bpbkar32(pid=142380) Backup started          
4/8/2015 7:29:12 AM - connecting
4/8/2015 7:29:12 AM - connected; connect time: 0:00:00
4/8/2015 7:29:13 AM - Info bpbkar32(pid=142380) accelerator enabled backup, archive bit processing:<disabled>      
4/8/2015 7:29:13 AM - Info bptm(pid=154856) start           
4/8/2015 7:29:13 AM - Info bptm(pid=154856) using 262144 data buffer size       
4/8/2015 7:29:13 AM - Info bptm(pid=154856) setting receive network buffer to 1049600 bytes     
4/8/2015 7:29:13 AM - Info bptm(pid=154856) using 30 data buffers        
4/8/2015 7:29:24 AM - Info bptm(pid=154856) start backup          
4/8/2015 7:29:28 AM - begin writing
4/8/2015 7:34:14 AM - Info bpbkar32(pid=142380) INF - Transport Type =  san     
4/8/2015 7:50:42 AM - Info bptm(pid=154856) waited for full buffer 28351 times, delayed 47230 times   
4/8/2015 7:50:43 AM - Info bpbkar32(pid=142380) accelerator sent 64898290688 bytes out of 64898287616 bytes to server, optimization 0.0%
4/8/2015 7:50:44 AM - Info bpbkar32(pid=142380) bpbkar waited 6 times for empty buffer, delayed 14460 times.  
4/8/2015 7:52:21 AM - Info bptm(pid=154856) EXITING with status 0 <----------       
4/8/2015 7:52:21 AM - Info srv10422(pid=154856) StorageServer=PureDisk:srv10422; Report=PDDO Stats (multi-threaded stream used) for (srv10422): scanned: 63406540 KB, CR sent: 3783316 KB, CR sent over FC: 0 KB, dedup: 94.0%, cache disabled
4/8/2015 7:52:22 AM - Info bpbrm(pid=153348) validating image for client SRV10551       
4/8/2015 7:52:23 AM - Info bpbkar32(pid=142380) done. status: 0: the requested operation was successfully completed   
4/8/2015 7:52:23 AM - end writing; write time: 0:22:55
the requested operation was successfully completed(0)

D_Thomas
Level 4

I am seeing similar behavior. All jobs are going to an MSDP server running 7.6.1.1.

Master and Media are Windows 2008 R2 SP1.

VMware Backup, RMAN, and standard backups are all taking over an hour to start running now - pretty much an hour and 20 minutes today.

MSDP was full this weekend, but lots of space has been cleared up. CRCCheck was running wild, stopped that to see if it helped, it did not. Checked DNS resolution, network connectivity.

It doesn't make much sense. Some VMware and standard backup jobs fly right out of the gate, but a majority have an hour and 20 minutes between begin writing and data being sent.

I will open a ticket on this, but any ideas?

Thanks,

D_Thomas
Level 4

Restarted the services on the media/MSDP server and its back to normal. Can't say I understand why this happens - I have seen this a few times. I will have to go back in my notes and see if it has anything to do with the disk being full.