cancel
Showing results for 
Search instead for 
Did you mean: 

File server client very slow NBU 7.6.0.4

Verneti_Berny
Level 6

Hi all,

I have NBU 7.6.0.4 making backup to storage disk, many clients windows 2008 R2 and 2012 R2, only one client 2012 R2 is very slow, the other clients speed is about 17000 KB/sec, but this one it no pass of 300 KB/sec.

Can anybody help me?

Thanks.

2 ACCEPTED SOLUTIONS

Accepted Solutions

watsons
Level 6

Delay was found here:

02:32:56.787 [2268.2884] <2> tar_base::V_vTarMsgW: JBD - not using change journal data for <E:\>: not configured for use
02:32:56.787 [2268.2884] <2> tar_base::V_vTarMsgW: JBD - not using change journal data for enumeration for <E:\> but will use it for change detection

(almost 2 hours...)

04:17:56.468 [2268.2884] <4> dos_backup::fscp_change_detection(): INF - file changed: file:<E:\Apps\ERP\sholder\producao\shcorp.b1> is open by some process
04:17:56.468 [2268.2884] <4> dos_backup::fscp_change_detection(): INF - file changed: file:<E:\Apps\ERP\sholder\producao\shcorp.d1> is open by some process

 

then..

04:35:22.543 [2268.2884] <4> dos_backup::fscp_change_detection(): INF - file changed: file:<E:\Dados\AC\rosantos\CUSTOMERS\2014\CLP\Oferta CLP Tabacos 26092014.doc> is open by some process
04:35:25.648 [2268.2884] <4> dos_backup::fscp_change_detection(): INF - file changed: file:<E:\Dados\AC\rosantos\CUSTOMERS\2015\Mac Baren\Solicitação de Inspeção 20032015.xls> is open by some process

(2 hours...)

06:46:39.169 [2268.2884] <4> dos_backup::fscp_change_detection(): INF - file changed: file:<E:\Dados\MAN\Eletrica\Administrativo\Ar Condicionados\PMOC Interno\PMOC 2015\Relatórios Mensais PMOC - Fevereiro.xls> is open by some process

(0.5 hours...)

07:24:05.760 [2268.2884] <4> dos_backup::fscp_change_detection(): INF - file changed: file:<E:\Dados\rh\Beneficios\SOLICITAÇÕES DE PAGAMENTO\CONTRATOS\Cronograma de Pagtos.xlsx> is open by some process

How does your policy look like? Does it have Accelerator enabled? If so, can you test this incremental backup with accelerator off? 

 

View solution in original post

RonCaplinger
Level 6

I guess I wasn't clear.  I believe the problem is in Windows, not NBU.  See this article to enable/reconfigure the Change Journal in Windows:

http://www.symantec.com/docs/TECH197143

View solution in original post

15 REPLIES 15

revarooo
Level 6
Employee

How quickly can bpbkar on the client process the data on disk?

How to benchmark the performance of the bpbkar32 process on a Windows client

Article URL http://www.symantec.com/docs/TECH17541

 

 

Also how fast can you transfer a large file across from the client to the media server with ftp for example?

 

Has this client always been slow? Does it run slowly throughout the backup or does it get slower? Are there millions of files in the filesystem that it is slow backing up?

Nicolai
Moderator
Moderator
Partner    VIP   

300K - Has the client a 100MB/ network connection ?

Then check port and duplex setup on NIC and switch.

Verneti_Berny
Level 6

Hy Revarooo, thanks for your reply, I´d execute bpbkar, and as you can see in attach file, it shows me that "open file backup license is not installed on the server". But I´m check en it is installed.

Just incremental backups are slow, in weekend we hava a full backup and it is normally.

On the attach file you can see bpbkar on the last incremental backup and the bpbkar command executed now

Thanks.

Verneti_Berny
Level 6

Thanks Nicolai, 

I forgot to tell that only incremental backups are slow, the full backups it´s normally.

 

Thanks.

Marianne
Moderator
Moderator
Partner    VIP    Accredited Certified

Also check for filesystem fragmentation on the fileserver.

Low system resources and high fragmentation are some of the normal reasons for slow backup.

As a test, use Windows Explorer on the Fileserver to select the drive letter, right-click and select 'Properties'. 
How long till it comes back with info?
Drop down to cmd and do 'dir/s' on this drive letter.
How long till it comes back to the prompt?

Verneti_Berny
Level 6

Hi Marianne.

Properties of drive letter = 2 seconds

Dir /s of the backup folder = 26 min and 20 secs

total of 1.726.219 files

384.489.524.548 bytes

291.098 directories

The problem is in incremental backups, the full backups it´s normally with speed 19.548 KB/sec.

The last full backup on sunday:

393.556.276 KBytes

1.859.015 files

19.548 KB/sec

5:38:06 elapsed time

The last incremental backup on monday:

11.842.813 KBytes

113.366 files

584 KB/sec

5:38:36 elapsed time.

 

 

 

 

 

Marianne
Moderator
Moderator
Partner    VIP    Accredited Certified
Heavily fragmented filesystem perhaps? I cannot open zip files on mobile device - will have a look when back at work tomorrow ( if time permits ). Have you remembered to change client logging level to 1 before doing bpbkar null test?

watsons
Level 6

Delay was found here:

02:32:56.787 [2268.2884] <2> tar_base::V_vTarMsgW: JBD - not using change journal data for <E:\>: not configured for use
02:32:56.787 [2268.2884] <2> tar_base::V_vTarMsgW: JBD - not using change journal data for enumeration for <E:\> but will use it for change detection

(almost 2 hours...)

04:17:56.468 [2268.2884] <4> dos_backup::fscp_change_detection(): INF - file changed: file:<E:\Apps\ERP\sholder\producao\shcorp.b1> is open by some process
04:17:56.468 [2268.2884] <4> dos_backup::fscp_change_detection(): INF - file changed: file:<E:\Apps\ERP\sholder\producao\shcorp.d1> is open by some process

 

then..

04:35:22.543 [2268.2884] <4> dos_backup::fscp_change_detection(): INF - file changed: file:<E:\Dados\AC\rosantos\CUSTOMERS\2014\CLP\Oferta CLP Tabacos 26092014.doc> is open by some process
04:35:25.648 [2268.2884] <4> dos_backup::fscp_change_detection(): INF - file changed: file:<E:\Dados\AC\rosantos\CUSTOMERS\2015\Mac Baren\Solicitação de Inspeção 20032015.xls> is open by some process

(2 hours...)

06:46:39.169 [2268.2884] <4> dos_backup::fscp_change_detection(): INF - file changed: file:<E:\Dados\MAN\Eletrica\Administrativo\Ar Condicionados\PMOC Interno\PMOC 2015\Relatórios Mensais PMOC - Fevereiro.xls> is open by some process

(0.5 hours...)

07:24:05.760 [2268.2884] <4> dos_backup::fscp_change_detection(): INF - file changed: file:<E:\Dados\rh\Beneficios\SOLICITAÇÕES DE PAGAMENTO\CONTRATOS\Cronograma de Pagtos.xlsx> is open by some process

How does your policy look like? Does it have Accelerator enabled? If so, can you test this incremental backup with accelerator off? 

 

Verneti_Berny
Level 6

Hi Watsons,

Yes, my policy have accelerator enabled, but in this policy I have 20 clients and only this client appear with this situation. I don´t know why?

 

RonCaplinger
Level 6

As Watsons shows, there is a gap of time right after Netbackup is starting to enumerate the E: drive (build the list of files to back up).  Your client doesn't seem to have the Windows Change Journal enabled for the E: drive.  It has to traverse the entire directory structure on the E: drive to determine what files have to be backed up, which is why it is taking so long.  The Windows Change Journal should be checked to make sure it is set up correctly in Windows, then run a full backup of the client.

I thought it was now standard for this to be enabled since Windows 2008.  There *might* be a reason someone disabled it; you might want to verify that with the owner of that client before you turn it back on.

Verneti_Berny
Level 6

Today I checked my full and incremental backups, and the journal option is the same in both cases, but only in incremental backups the problem occurs.

As we can see bellow, in job details.

Thanks.

22/03/2015 02:30:00 - Info nbjm(pid=3692) starting backup job (jobid=2415) for client uscfs1, policy Windows01, schedule Semanal-LAN  
22/03/2015 02:30:00 - Info nbjm(pid=3692) requesting STANDARD_RESOURCE resources from RB for backup job (jobid=2415, request id:{ECB43218-C718-4768-83D7-827F1DEAD2A6})  
22/03/2015 02:30:00 - requesting resource stu_disk_scsnb3
22/03/2015 02:30:00 - requesting resource scsnb2.NBU_CLIENT.MAXJOBS.uscfs1
22/03/2015 02:30:00 - requesting resource scsnb2.NBU_POLICY.MAXJOBS.Windows01
22/03/2015 02:30:01 - granted resource scsnb2.NBU_CLIENT.MAXJOBS.uscfs1
22/03/2015 02:30:01 - granted resource scsnb2.NBU_POLICY.MAXJOBS.Windows01
22/03/2015 02:30:01 - granted resource MediaID=@aaaae;DiskVolume=PureDiskVolume;DiskPool=slp_disk_scsnb3;Path=PureDiskVolume;StorageServer=scsnb3;MediaServer=scsnb3
22/03/2015 02:30:01 - granted resource stu_disk_scsnb3
22/03/2015 02:30:19 - started
22/03/2015 02:30:20 - estimated 470821514 Kbytes needed
22/03/2015 02:30:20 - Info nbjm(pid=3692) started backup (backupid=uscfs1_1427002219) job for client uscfs1, policy Windows01, schedule Semanal-LAN on storage unit stu_disk_scsnb3
22/03/2015 02:30:21 - started process bpbrm (5480)
22/03/2015 02:30:28 - Info bpbrm(pid=5480) uscfs1 is the host to backup data from     
22/03/2015 02:30:28 - Info bpbrm(pid=5480) reading file list for client        
22/03/2015 02:30:30 - Info bpbrm(pid=5480) accelerator enabled           
22/03/2015 02:30:36 - connecting
22/03/2015 02:30:39 - Info bpbrm(pid=5480) starting bpbkar32 on client         
22/03/2015 02:30:39 - connected; connect time: 0:00:03
22/03/2015 02:30:44 - Info bpbkar32(pid=1916) Backup started           
22/03/2015 02:30:44 - Info bpbkar32(pid=1916) change time comparison:<enabled>          
22/03/2015 02:30:44 - Info bpbkar32(pid=1916) accelerator enabled backup, archive bit processing:<disabled>       
22/03/2015 02:30:44 - Info bptm(pid=1824) start            
22/03/2015 02:30:44 - Info bptm(pid=1824) using 262144 data buffer size        
22/03/2015 02:30:44 - Info bptm(pid=1824) setting receive network buffer to 1049600 bytes      
22/03/2015 02:30:44 - Info bptm(pid=1824) using 30 data buffers         
22/03/2015 02:30:45 - Info bptm(pid=1824) start backup           
22/03/2015 02:30:46 - Info bptm(pid=1824) backup child process is pid 5244.5056       
22/03/2015 02:30:46 - Info bptm(pid=5244) start            
22/03/2015 02:30:46 - begin writing
22/03/2015 02:30:51 - Info bpbkar32(pid=1916) will attempt to use change journal data for <C:\>    
22/03/2015 02:30:52 - Info bpbkar32(pid=1916) will attempt to use change journal data for <E:\>    
22/03/2015 02:30:52 - Info bpbkar32(pid=1916) not using change journal data for <System State:\>: not supported for non-local volumes / file systems
22/03/2015 02:30:52 - Info bpbkar32(pid=1916) not using change journal data for <_BACKUP_SPECIAL_OBJECTS AFTER System State:>: not supported for non-local volumes / file systems
22/03/2015 02:31:46 - Info bpbkar32(pid=1916) not using change journal data for <C:\>: not configured for use  
22/03/2015 02:31:46 - Info bpbkar32(pid=1916) not using change journal data for enumeration for <C:\> but will use it for change detection
22/03/2015 02:32:45 - Info bpbkar32(pid=1916) not using change journal data for <E:\>: not configured for use  
22/03/2015 02:32:45 - Info bpbkar32(pid=1916) not using change journal data for enumeration for <E:\> but will use it for change detection
22/03/2015 02:43:19 - Info bpbkar32(pid=1916) 68219 entries sent to bpdbm        
22/03/2015 02:54:07 - Info bpbkar32(pid=1916) 161432 entries sent to bpdbm        
22/03/2015 03:05:12 - Info bpbkar32(pid=1916) 254394 entries sent to bpdbm        
22/03/2015 03:12:15 - Info bpbkar32(pid=1916) 347358 entries sent to bpdbm        
22/03/2015 03:22:10 - Info bpbkar32(pid=1916) 440309 entries sent to bpdbm        
22/03/2015 03:29:49 - Info bpbkar32(pid=1916) 479094 entries sent to bpdbm        
22/03/2015 03:41:36 - Info bpbkar32(pid=1916) 567443 entries sent to bpdbm        
22/03/2015 03:50:10 - Info bpbkar32(pid=1916) 660666 entries sent to bpdbm        
22/03/2015 03:58:01 - Info bpbkar32(pid=1916) 753709 entries sent to bpdbm        
22/03/2015 04:08:21 - Info bpbkar32(pid=1916) 847134 entries sent to bpdbm        
22/03/2015 04:16:02 - Info bpbkar32(pid=1916) 940947 entries sent to bpdbm        
22/03/2015 04:26:03 - Info bpbkar32(pid=1916) 1035528 entries sent to bpdbm        
22/03/2015 04:39:46 - Info bpbkar32(pid=1916) 1128513 entries sent to bpdbm        
22/03/2015 04:46:59 - Info bpbkar32(pid=1916) 1160056 entries sent to bpdbm        
22/03/2015 04:55:17 - Info bpbkar32(pid=1916) 1190148 entries sent to bpdbm        
22/03/2015 05:05:46 - Info bpbkar32(pid=1916) 1230061 entries sent to bpdbm        
22/03/2015 05:13:37 - Info bpbkar32(pid=1916) 1257234 entries sent to bpdbm        
22/03/2015 05:22:46 - Info bpbkar32(pid=1916) 1281421 entries sent to bpdbm        
22/03/2015 05:32:43 - Info bpbkar32(pid=1916) 1306345 entries sent to bpdbm        
22/03/2015 05:38:22 - Info bpbkar32(pid=1916) 1331171 entries sent to bpdbm        
22/03/2015 05:45:44 - Info bpbkar32(pid=1916) 1369531 entries sent to bpdbm        
22/03/2015 05:53:14 - Info bpbkar32(pid=1916) 1396313 entries sent to bpdbm        
22/03/2015 06:01:11 - Info bpbkar32(pid=1916) 1436797 entries sent to bpdbm        
22/03/2015 06:03:26 - Info bpbkar32(pid=1916) 1461234 entries sent to bpdbm        
22/03/2015 06:06:47 - Info bpbkar32(pid=1916) 1487751 entries sent to bpdbm        
22/03/2015 06:10:20 - Info bpbkar32(pid=1916) 1509938 entries sent to bpdbm        
22/03/2015 06:18:35 - Info bpbkar32(pid=1916) 1535909 entries sent to bpdbm        
22/03/2015 06:27:41 - Info bpbkar32(pid=1916) 1574067 entries sent to bpdbm        
22/03/2015 06:36:25 - Info bpbkar32(pid=1916) 1596909 entries sent to bpdbm        
22/03/2015 06:49:31 - Info bpbkar32(pid=1916) 1624874 entries sent to bpdbm        
22/03/2015 06:57:19 - Info bpbkar32(pid=1916) 1659008 entries sent to bpdbm        
22/03/2015 07:01:35 - Info bpbkar32(pid=1916) 1680772 entries sent to bpdbm        
22/03/2015 07:10:57 - Info bpbkar32(pid=1916) 1714469 entries sent to bpdbm        
22/03/2015 07:19:04 - Info bpbkar32(pid=1916) 1746226 entries sent to bpdbm        
22/03/2015 07:26:20 - Info bpbkar32(pid=1916) 1784852 entries sent to bpdbm        
22/03/2015 07:43:34 - Info bpbkar32(pid=1916) not using change journal data for <System State:\>: forcing rescan, each file will be read in order to validate checksums
22/03/2015 07:52:25 - Info bpbkar32(pid=1916) not using change journal data for <_BACKUP_SPECIAL_OBJECTS AFTER System State:>: forcing rescan, each file will be read in order to validate checksums
22/03/2015 07:52:33 - Info bpbkar32(pid=1916) 1840880 entries sent to bpdbm        
22/03/2015 07:53:12 - Info bpbkar32(pid=1916) 1845880 entries sent to bpdbm        
22/03/2015 07:53:36 - Info bpbkar32(pid=1916) 1850880 entries sent to bpdbm        
22/03/2015 07:54:28 - Info bpbkar32(pid=1916) 1855880 entries sent to bpdbm        
22/03/2015 07:54:58 - Info bpbkar32(pid=1916) accelerator sent 11743809024 bytes out of 403938098176 bytes to server, optimization 97.1% 
22/03/2015 07:55:06 - Info bptm(pid=1824) waited for full buffer 4473 times, delayed 1186909 times    
22/03/2015 07:55:32 - Info bptm(pid=1824) EXITING with status 0 <----------        
22/03/2015 07:55:32 - Info scsnb3(pid=1824) StorageServer=PureDisk:scsnb3; Report=PDDO Stats for (scsnb3): scanned: 394527234 KB, CR sent: 565404 KB, CR sent over FC: 0 KB, dedup: 99.9%, cache disabled
22/03/2015 07:55:33 - Info bpbrm(pid=5480) validating image for client uscfs1        
22/03/2015 07:55:36 - Info bpbkar32(pid=1916) done. status: 0: the requested operation was successfully completed    
22/03/2015 07:55:37 - end writing; write time: 5:24:51
the requested operation was successfully completed(0)

RonCaplinger
Level 6

I guess I wasn't clear.  I believe the problem is in Windows, not NBU.  See this article to enable/reconfigure the Change Journal in Windows:

http://www.symantec.com/docs/TECH197143

Verneti_Berny
Level 6

Thank you Ron, I will do this test tonight, and return tomorrow with, I hope, good news.

 

thanks.

Verneti_Berny
Level 6

Hi Ron,

I cannot make a full backup during week, I need to wait for weekend full backup to run change journal.

The next monday I think we have good news.

Thanks you very much.

Verneti_Berny
Level 6

After the full backup on last weekend, is´t the same situation, my incremental backups are slow.

Thanks.

I will setup every backups to full.