cancel
Showing results for 
Search instead for 
Did you mean: 

Suddenly Differential copies of server files are extremately slow or hang

Angel_Fontana
Level 4

Hi there,

 

I'm doing backups of my server file (Windows 2008 Enterprise) with Netbackup Appliance 5230. This server is a vmachine but the data disks are mapped as RAW so I've to use MS-Windows policy type. I've got 2 schedules, Full backup on weekend and Differential the rest of the week. These are the backup selections, each New stream are different vdisks in 2 SANs:

buselections.jpg

Since yesterday, Monday, I'm having problems with the Differential backups in two ways:

The first problem is, suddenly the backup task hangs in a folders with no errors or any message. I cancelled the task, it started again and several hours after hangs again in other folder of the same unit (N:\IT). these are the logs:

first hang:

01/04/2014 0:02:00 - Info nbjm(pid=91943) starting backup job (jobid=2477) for client omgesfiles.global.com, policy Copia_Ficheros, schedule Diferencial 
01/04/2014 0:02:00 - Info nbjm(pid=91943) requesting STANDARD_RESOURCE resources from RB for backup job (jobid=2477, request id:{15CE6746-B920-11E3-A05A-CC922E45814B}) 
01/04/2014 0:02:00 - requesting resource stu_disk_omgesnetbu
01/04/2014 0:02:00 - requesting resource omgesnetbu.global.com.NBU_CLIENT.MAXJOBS.omgesfiles.global.com
01/04/2014 0:02:00 - requesting resource omgesnetbu.global.com.NBU_POLICY.MAXJOBS.Copia_Ficheros
01/04/2014 0:02:01 - granted resource omgesnetbu.global.com.NBU_CLIENT.MAXJOBS.omgesfiles.global.com
01/04/2014 0:02:01 - granted resource omgesnetbu.global.com.NBU_POLICY.MAXJOBS.Copia_Ficheros
01/04/2014 0:02:01 - granted resource MediaID=@aaaac;DiskVolume=PureDiskVolume;DiskPool=dp_disk_omgesnetbu;Path=PureDiskVolume;StorageServ...
01/04/2014 0:02:01 - granted resource stu_disk_omgesnetbu
01/04/2014 0:02:02 - estimated 35059196 Kbytes needed
01/04/2014 0:02:02 - Info nbjm(pid=91943) started backup (backupid=omgesfiles.global.com_1396303322) job for client omgesfiles.global.com, policy Copia_Ficheros, schedule Diferencial on storage unit stu_disk_omgesnetbu
01/04/2014 0:02:02 - started process bpbrm (101231)
01/04/2014 0:02:03 - Info bpbrm(pid=101231) omgesfiles.global.com is the host to backup data from    
01/04/2014 0:02:03 - Info bpbrm(pid=101231) reading file list for client       
01/04/2014 0:02:04 - Info bpbrm(pid=101231) accelerator enabled          
01/04/2014 0:02:10 - connecting
01/04/2014 0:02:11 - Info bpbrm(pid=101231) starting bpbkar on client        
01/04/2014 0:02:11 - connected; connect time: 0:00:01
01/04/2014 0:02:15 - Info bpbkar(pid=4048) Backup started          
01/04/2014 0:02:15 - Info bpbrm(pid=101231) bptm pid: 101270         
01/04/2014 0:02:15 - Info bptm(pid=101270) start           
01/04/2014 0:02:15 - Info bpbkar(pid=4048) change time comparison:<enabled>         
01/04/2014 0:02:15 - Info bpbkar(pid=4048) accelerator enabled backup, archive bit processing:<disabled>      
01/04/2014 0:02:16 - Info bptm(pid=101270) using 262144 data buffer size       
01/04/2014 0:02:16 - Info bptm(pid=101270) using 30 data buffers        
01/04/2014 0:02:16 - Info bptm(pid=101270) start backup          
01/04/2014 0:02:16 - Info bpbkar(pid=4048) will attempt to use change journal data for <Q:\Datos HP>  
01/04/2014 0:02:16 - Info bpbkar(pid=4048) will attempt to use change journal data for <Q:\Datos PHD>  
01/04/2014 0:02:16 - Info bpbkar(pid=4048) will attempt to use change journal data for <N:\IT>   
01/04/2014 0:02:16 - Info bpbkar(pid=4048) will attempt to use change journal data for <N:\OMDKB>   
01/04/2014 0:02:16 - Info bpbkar(pid=4048) will attempt to use change journal data for <N:\SQLDATAOUT>   
01/04/2014 0:02:16 - Info bpbkar(pid=4048) will attempt to use change journal data for <N:\Admon>   
01/04/2014 0:02:16 - Info bpbkar(pid=4048) will attempt to use change journal data for <F:\Ignition>   
01/04/2014 0:02:16 - Info bpbkar(pid=4048) will attempt to use change journal data for <G:\Insight>   
01/04/2014 0:02:16 - Info bpbkar(pid=4048) will attempt to use change journal data for <R:\Datos>   
01/04/2014 0:02:17 - Info bptm(pid=101270) backup child process is pid 101297      
01/04/2014 0:02:17 - begin writing
01/04/2014 0:02:29 - Info bpbkar(pid=4048) not using change journal data for <Q:\Datos HP>: not configured for use
01/04/2014 0:02:29 - Info bpbkar(pid=4048) not using change journal data for enumeration for <Q:\Datos HP> but will use it for change detection
01/04/2014 0:15:57 - Info bpbkar(pid=4048) not using change journal data for <Q:\Datos PHD>: not configured for use
01/04/2014 0:15:57 - Info bpbkar(pid=4048) not using change journal data for enumeration for <Q:\Datos PHD> but will use it for change detection
01/04/2014 0:21:25 - Info bpbkar(pid=4048) 4999 entries sent to bpdbm       
01/04/2014 0:47:28 - Info bpbkar(pid=4048) 9999 entries sent to bpdbm       
01/04/2014 1:24:14 - Info bpbkar(pid=4048) 14999 entries sent to bpdbm       
01/04/2014 1:43:57 - Info bpbkar(pid=4048) 19999 entries sent to bpdbm       
01/04/2014 2:08:44 - Info bpbkar(pid=4048) not using change journal data for <N:\IT>: not configured for use 
01/04/2014 2:08:44 - Info bpbkar(pid=4048) not using change journal data for enumeration for <N:\IT> but will use it for change detection
01/04/2014 2:12:53 - Info bpbkar(pid=4048) 24998 entries sent to bpdbm       
01/04/2014 2:23:07 - Info bpbkar(pid=4048) 29998 entries sent to bpdbm       
01/04/2014 2:31:11 - Info bpbkar(pid=4048) 34998 entries sent to bpdbm       
01/04/2014 2:40:25 - Info bpbkar(pid=4048) 39998 entries sent to bpdbm       
01/04/2014 17:31:18 - Error bptm(pid=101270) media manager terminated by parent process      
01/04/2014 17:31:27 - Info omgesnetbu(pid=101270) StorageServer=PureDisk:omgesnetbu; Report=PDDO Stats for (omgesnetbu): scanned: 610712 KB, CR sent: 204697 KB, CR sent over FC: 0 KB, dedup: 66.5%, cache disabled
01/04/2014 17:31:28 - Info bpbkar(pid=4048) done. status: 150: termination requested by administrator     
01/04/2014 17:31:28 - end writing; write time: 17:29:11
termination requested by administrator(150)


2nd hang:

01/04/2014 17:43:14 - Info nbjm(pid=91943) starting backup job (jobid=2559) for client omgesfiles.global.com, policy Copia_Ficheros, schedule Diferencial 
01/04/2014 17:43:14 - estimated 35059196 Kbytes needed
01/04/2014 17:43:14 - Info nbjm(pid=91943) started backup (backupid=omgesfiles.global.com_1396366994) job for client omgesfiles.global.com, policy Copia_Ficheros, schedule Diferencial on storage unit stu_disk_omgesnetbu
01/04/2014 17:43:14 - started process bpbrm (39045)
01/04/2014 17:43:15 - Info bpbrm(pid=39045) omgesfiles.global.com is the host to backup data from    
01/04/2014 17:43:15 - Info bpbrm(pid=39045) reading file list for client       
01/04/2014 17:43:16 - Info bpbrm(pid=39045) accelerator enabled          
01/04/2014 17:43:21 - connecting
01/04/2014 17:43:22 - Info bpbrm(pid=39045) starting bpbkar on client        
01/04/2014 17:43:22 - connected; connect time: 0:00:01
01/04/2014 17:43:26 - Info bpbkar(pid=3868) Backup started          
01/04/2014 17:43:26 - Info bpbrm(pid=39045) bptm pid: 39139         
01/04/2014 17:43:26 - Info bpbkar(pid=3868) change time comparison:<enabled>         
01/04/2014 17:43:26 - Info bpbkar(pid=3868) accelerator enabled backup, archive bit processing:<disabled>      
01/04/2014 17:43:27 - Info bptm(pid=39139) start           
01/04/2014 17:43:27 - Info bptm(pid=39139) using 262144 data buffer size       
01/04/2014 17:43:27 - Info bptm(pid=39139) using 30 data buffers        
01/04/2014 17:43:27 - Info bpbkar(pid=3868) will attempt to use change journal data for <Q:\Datos HP>  
01/04/2014 17:43:27 - Info bpbkar(pid=3868) will attempt to use change journal data for <Q:\Datos PHD>  
01/04/2014 17:43:27 - Info bpbkar(pid=3868) will attempt to use change journal data for <N:\IT>   
01/04/2014 17:43:27 - Info bpbkar(pid=3868) will attempt to use change journal data for <N:\OMDKB>   
01/04/2014 17:43:27 - Info bpbkar(pid=3868) will attempt to use change journal data for <N:\SQLDATAOUT>   
01/04/2014 17:43:27 - Info bpbkar(pid=3868) will attempt to use change journal data for <N:\Admon>   
01/04/2014 17:43:27 - Info bpbkar(pid=3868) will attempt to use change journal data for <F:\Ignition>   
01/04/2014 17:43:27 - Info bpbkar(pid=3868) will attempt to use change journal data for <G:\Insight>   
01/04/2014 17:43:27 - Info bpbkar(pid=3868) will attempt to use change journal data for <R:\Datos>   
01/04/2014 17:43:28 - Info bptm(pid=39139) start backup          
01/04/2014 17:43:29 - Info bptm(pid=39139) backup child process is pid 39147      
01/04/2014 17:43:29 - begin writing
01/04/2014 17:43:40 - Info bpbkar(pid=3868) not using change journal data for <Q:\Datos HP>: not configured for use
01/04/2014 17:43:40 - Info bpbkar(pid=3868) not using change journal data for enumeration for <Q:\Datos HP> but will use it for change detection
01/04/2014 17:52:17 - Info bpbkar(pid=3868) not using change journal data for <Q:\Datos PHD>: not configured for use
01/04/2014 17:52:17 - Info bpbkar(pid=3868) not using change journal data for enumeration for <Q:\Datos PHD> but will use it for change detection
01/04/2014 17:56:24 - Info bpbkar(pid=3868) 4999 entries sent to bpdbm       
01/04/2014 18:17:38 - Info bpbkar(pid=3868) 9999 entries sent to bpdbm       
01/04/2014 18:48:16 - Info bpbkar(pid=3868) 14999 entries sent to bpdbm       
01/04/2014 19:07:43 - Info bpbkar(pid=3868) 19999 entries sent to bpdbm       
01/04/2014 19:28:36 - Info bpbkar(pid=3868) not using change journal data for <N:\IT>: not configured for use 
01/04/2014 19:28:36 - Info bpbkar(pid=3868) not using change journal data for enumeration for <N:\IT> but will use it for change detection
01/04/2014 19:31:20 - Info bpbkar(pid=3868) 24998 entries sent to bpdbm       
01/04/2014 19:41:12 - Info bpbkar(pid=3868) 29998 entries sent to bpdbm       
01/04/2014 19:49:37 - Info bpbkar(pid=3868) 34998 entries sent to bpdbm       
01/04/2014 19:58:56 - Info bpbkar(pid=3868) 39998 entries sent to bpdbm       
01/04/2014 22:52:05 - Error bptm(pid=39139) media manager terminated by parent process      
01/04/2014 22:52:16 - Info omgesnetbu(pid=39139) StorageServer=PureDisk:omgesnetbu; Report=PDDO Stats for (omgesnetbu): scanned: 1407408 KB, CR sent: 209592 KB, CR sent over FC: 0 KB, dedup: 85.1%, cache disabled
01/04/2014 22:52:21 - Info bpbkar(pid=3868) done. status: 150: termination requested by administrator     
01/04/2014 22:52:21 - end writing; write time: 5:08:52
termination requested by administrator(150)


The rest of the streams finished with no problems.

But in the last night differential copy the second stream (where N:/IT is) didn't even start and the first stream is still running (not hanged) for more than 11 hours! I'm using accelerator and the full backup worked last weekend (and it takes 12 hours)

this is the log for the first stream:

02/04/2014 0:01:46 - Info nbjm(pid=91943) starting backup job (jobid=2569) for client omgesfiles.global.com, policy Copia_Ficheros, schedule Diferencial 
02/04/2014 0:01:46 - estimated 48707354 Kbytes needed
02/04/2014 0:01:46 - Info nbjm(pid=91943) started backup (backupid=omgesfiles.global.com_1396389706) job for client omgesfiles.global.com, policy Copia_Ficheros, schedule Diferencial on storage unit stu_disk_omgesnetbu
02/04/2014 0:01:46 - started process bpbrm (108160)
02/04/2014 0:01:47 - Info bpbrm(pid=108160) omgesfiles.global.com is the host to backup data from    
02/04/2014 0:01:47 - Info bpbrm(pid=108160) reading file list for client       
02/04/2014 0:01:48 - Info bpbrm(pid=108160) accelerator enabled          
02/04/2014 0:01:52 - connecting
02/04/2014 0:01:53 - Info bpbrm(pid=108160) starting bpbkar on client        
02/04/2014 0:01:53 - connected; connect time: 0:00:01
02/04/2014 0:01:55 - Info bpbkar(pid=1944) Backup started          
02/04/2014 0:01:55 - Info bpbrm(pid=108160) bptm pid: 108228         
02/04/2014 0:01:55 - Info bpbkar(pid=1944) change time comparison:<enabled>         
02/04/2014 0:01:55 - Info bpbkar(pid=1944) accelerator enabled backup, archive bit processing:<disabled>      
02/04/2014 0:01:56 - Info bptm(pid=108228) start           
02/04/2014 0:01:56 - Info bptm(pid=108228) using 262144 data buffer size       
02/04/2014 0:01:56 - Info bptm(pid=108228) using 30 data buffers        
02/04/2014 0:01:57 - Info bptm(pid=108228) start backup          
02/04/2014 0:01:57 - Info bpbkar(pid=1944) will attempt to use change journal data for <O:\Digital>   
02/04/2014 0:01:57 - Info bpbkar(pid=1944) will attempt to use change journal data for <P:\Datos>   
02/04/2014 0:01:57 - Info bptm(pid=108228) backup child process is pid 108255      
02/04/2014 0:01:57 - begin writing
02/04/2014 0:02:06 - Info bpbkar(pid=1944) not using change journal data for <O:\Digital>: not configured for use 
02/04/2014 0:02:06 - Info bpbkar(pid=1944) not using change journal data for enumeration for <O:\Digital> but will use it for change detection
02/04/2014 0:12:46 - Info bpbkar(pid=1944) 4999 entries sent to bpdbm       
02/04/2014 0:23:55 - Info bpbkar(pid=1944) 9999 entries sent to bpdbm       
02/04/2014 0:38:19 - Info bpbkar(pid=1944) 14999 entries sent to bpdbm       
02/04/2014 0:50:46 - Info bpbkar(pid=1944) 19999 entries sent to bpdbm       
02/04/2014 1:00:38 - Info bpbkar(pid=1944) 24999 entries sent to bpdbm       
02/04/2014 1:10:44 - Info bpbkar(pid=1944) 29999 entries sent to bpdbm       
02/04/2014 1:16:40 - Info bpbkar(pid=1944) 34999 entries sent to bpdbm       
02/04/2014 1:22:44 - Info bpbkar(pid=1944) 39999 entries sent to bpdbm       
02/04/2014 1:30:32 - Info bpbkar(pid=1944) 44999 entries sent to bpdbm       
02/04/2014 1:40:40 - Info bpbkar(pid=1944) 49999 entries sent to bpdbm       
02/04/2014 1:54:25 - Info bpbkar(pid=1944) 54999 entries sent to bpdbm       
02/04/2014 2:01:07 - Info bpbkar(pid=1944) 59999 entries sent to bpdbm       
02/04/2014 2:05:43 - Info bpbkar(pid=1944) 64999 entries sent to bpdbm       
02/04/2014 2:13:31 - Info bpbkar(pid=1944) 69999 entries sent to bpdbm       
02/04/2014 2:21:24 - Info bpbkar(pid=1944) 74999 entries sent to bpdbm       
02/04/2014 2:28:16 - Info bpbkar(pid=1944) 79999 entries sent to bpdbm       
02/04/2014 2:34:58 - Info bpbkar(pid=1944) 84999 entries sent to bpdbm       
02/04/2014 2:45:14 - Info bpbkar(pid=1944) 89999 entries sent to bpdbm       
02/04/2014 3:03:00 - Info bpbkar(pid=1944) 94999 entries sent to bpdbm       
02/04/2014 3:22:17 - Info bpbkar(pid=1944) 99999 entries sent to bpdbm       
02/04/2014 3:25:57 - Info bpbkar(pid=1944) not using change journal data for <P:\Datos>: not configured for use 
02/04/2014 3:25:57 - Info bpbkar(pid=1944) not using change journal data for enumeration for <P:\Datos> but will use it for change detection
02/04/2014 3:31:40 - Info bpbkar(pid=1944) 104998 entries sent to bpdbm       
02/04/2014 3:47:40 - Info bpbkar(pid=1944) 109998 entries sent to bpdbm       
02/04/2014 4:04:34 - Info bpbkar(pid=1944) 114998 entries sent to bpdbm       
02/04/2014 4:25:56 - Info bpbkar(pid=1944) 119998 entries sent to bpdbm       
02/04/2014 4:39:19 - Info bpbkar(pid=1944) 124998 entries sent to bpdbm       
02/04/2014 4:55:08 - Info bpbkar(pid=1944) 129998 entries sent to bpdbm       
02/04/2014 5:09:18 - Info bpbkar(pid=1944) 134998 entries sent to bpdbm       
02/04/2014 5:18:20 - Info bpbkar(pid=1944) 139998 entries sent to bpdbm       
02/04/2014 5:37:01 - Info bpbkar(pid=1944) 144998 entries sent to bpdbm       
02/04/2014 6:00:47 - Info bpbkar(pid=1944) 149998 entries sent to bpdbm       
02/04/2014 6:15:45 - Info bpbkar(pid=1944) 154998 entries sent to bpdbm       
02/04/2014 6:27:52 - Info bpbkar(pid=1944) 159998 entries sent to bpdbm       
02/04/2014 6:46:54 - Info bpbkar(pid=1944) 164998 entries sent to bpdbm       
02/04/2014 7:06:21 - Info bpbkar(pid=1944) 169998 entries sent to bpdbm       
02/04/2014 7:20:36 - Info bpbkar(pid=1944) 174998 entries sent to bpdbm       
02/04/2014 7:30:10 - Info bpbkar(pid=1944) 179998 entries sent to bpdbm       
02/04/2014 7:43:55 - Info bpbkar(pid=1944) 184998 entries sent to bpdbm       
02/04/2014 8:00:54 - Info bpbkar(pid=1944) 189998 entries sent to bpdbm       
02/04/2014 8:12:40 - Info bpbkar(pid=1944) 194998 entries sent to bpdbm       
02/04/2014 8:35:25 - Info bpbkar(pid=1944) 199998 entries sent to bpdbm       
02/04/2014 8:50:46 - Info bpbkar(pid=1944) 204998 entries sent to bpdbm       
02/04/2014 8:57:50 - Info bpbkar(pid=1944) 209998 entries sent to bpdbm       
02/04/2014 9:08:44 - Info bpbkar(pid=1944) 214998 entries sent to bpdbm       
02/04/2014 9:30:23 - Info bpbkar(pid=1944) 219998 entries sent to bpdbm       
02/04/2014 9:58:50 - Info bpbkar(pid=1944) 224998 entries sent to bpdbm       
02/04/2014 10:25:48 - Info bpbkar(pid=1944) 229998 entries sent to bpdbm       
02/04/2014 10:53:33 - Info bpbkar(pid=1944) 234998 entries sent to bpdbm      


Do you know where the problem could be?

thanks for your help!

 

 

 

 

1 REPLY 1

INT_RND
Level 6
Employee Accredited

If I were a betting man I would place my money on "Netbackup Accelerator".

Go in to the policy and turn accelerator off for a test run. See if the behavior changes.

You can always turn it back on later. In my experience the acclerator is very picky and was buggy when it was released. It's really great for certain use cases but it's not appropriate to turn on in every policy.