Ordinary client backup takes 30mins to start

[SteveLaw]

Hi,

I've configured am ordinary client OS backup of a Windows 2003 x32 server and nothing at all happens for 30 mins or so then the backup starts to write - any ideas why this should be? 

We're on NB 7.5.0.5, Master is Win2008R2 and media server is Win2003 R2 x64.

Activity log - nothing at all happened between 12:01:13 and 12:28:36:

24/11/2014 12:00:50 - Info nbjm(pid=7148) starting backup job (jobid=552247) for client ukdcsitas14, policy MBFS_FS_UKDCSITAS14_UAT, schedule Daily_Full  
24/11/2014 12:00:50 - Info nbjm(pid=7148) requesting STANDARD_RESOURCE resources from RB for backup job (jobid=552247, request id:{5E1B1B45-72FE-4B0F-BB83-33151EBA0E1E})  
24/11/2014 12:00:50 - requesting resource MKDD002_MBFS_DD_MK
24/11/2014 12:00:50 - requesting resource swm009.corpadds.net.NBU_CLIENT.MAXJOBS.ukdcsitas14
24/11/2014 12:00:50 - requesting resource swm009.corpadds.net.NBU_POLICY.MAXJOBS.MBFS_FS_UKDCSITAS14_UAT
24/11/2014 12:00:50 - granted resource swm009.corpadds.net.NBU_CLIENT.MAXJOBS.ukdcsitas14
24/11/2014 12:00:50 - granted resource swm009.corpadds.net.NBU_POLICY.MAXJOBS.MBFS_FS_UKDCSITAS14_UAT
24/11/2014 12:00:50 - granted resource MediaID=@aaaab;DiskVolume=MBFS_MK;DiskPool=MBFS_MK;Path=MBFS_MK;StorageServer=mkdd002.dcsit.net;MediaServer=deploy01.corpadds.net
24/11/2014 12:00:50 - granted resource MKDD002_MBFS_DD_MK
24/11/2014 12:00:50 - estimated 0 Kbytes needed
24/11/2014 12:00:50 - Info nbjm(pid=7148) started backup (backupid=ukdcsitas14_1416830450) job for client ukdcsitas14, policy MBFS_FS_UKDCSITAS14_UAT, schedule Daily_Full on storage unit MKDD002_MBFS_DD_MK
24/11/2014 12:00:50 - started
24/11/2014 12:00:51 - started process bpbrm (6828)
24/11/2014 12:00:58 - Info bpbrm(pid=6828) ukdcsitas14 is the host to backup data from     
24/11/2014 12:00:58 - Info bpbrm(pid=6828) reading file list from client        
24/11/2014 12:00:58 - connecting
24/11/2014 12:01:00 - connected; connect time: 00:00:02
24/11/2014 12:01:01 - Info bpbrm(pid=6828) starting bpbkar32 on client         
24/11/2014 12:01:08 - Info bpbkar32(pid=1028) Backup started           
24/11/2014 12:01:08 - Info bptm(pid=5200) start            
24/11/2014 12:01:08 - Info bptm(pid=5200) using 262144 data buffer size        
24/11/2014 12:01:08 - Info bptm(pid=5200) setting receive network buffer to 1049600 bytes      
24/11/2014 12:01:08 - Info bptm(pid=5200) using 30 data buffers         
24/11/2014 12:01:12 - Info bptm(pid=5200) start backup           
24/11/2014 12:01:12 - begin writing
24/11/2014 12:01:13 - Info bptm(pid=5200) backup child process is pid 8004.9016       
24/11/2014 12:01:13 - Info bptm(pid=8004) start            
24/11/2014 12:28:36 - Info bpbkar32(pid=1028) change journal NOT enabled for <C:\>       
24/11/2014 15:40:34 - Info bpbkar32(pid=1028) change journal NOT enabled for <D:\>   

Thanks!

[RamNagalla]

Does the both media server and client are in same netbackup version level?

run the bpbkar null test on C drive to see if there a dealy with the Server responce and Disk I/O 

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

[SteveLaw]

Hi, thanks for your input!
Both client and media server are v 7.5.0.6. Now running bpbkar test.....

[SteveLaw]

Ran bpbkar32 against a 168mb folder on the d: drive. Tokk maybe 10 secs to complete, watched the bpbkar32.exe appear in Task manager, read the data then disappear again. Logs are below. So it doesn't show any signs of pausing to think for 30mins about reading and writing the data. 

17:53:00.246: [3252.2524] <4> ov_log::OVInit: INF - Starting log file: C:\Program Files\Veritas\NetBackup\logs\BPBKAR\112414.log

17:53:00.246: [3252.2524] <4> ov_log::OVInit: GENERAL Log Level: 0
17:53:00.246: [3252.2524] <4> ov_log::OVInit: TCP Log Level: 0
17:53:00.246: [3252.2524] <4> ov_log::OVInit: INF - the log mutex: 1688
BPBKAR  NetBackup Backup/Archive  7.5GA  [Jun 10 2013]
Copyright © 1993 - 2013 Symantec Corporation, All Rights Reserved.
All Rights Reserved.

17:53:00.246: [3252.2524] <2> WinMain: DAT - _pgmptr = 'C:\Program Files\VERITAS\NetBackup\bin\bpbkar32.exe'
17:53:00.246: [3252.2524] <2> WinMain: DAT - lpCmdLine = '-nocont d:\CDL_TestData\ '
17:53:00.246: [3252.2524] <2> date_debug: DAT - timezone: GMT Standard Time, offset=0, dst: GMT Daylight Time
17:53:00.246: [3252.2524] <2> date_debug: DAT - current time: 1416851580, 24/11/2014 17:53:00
17:53:00.246: [3252.2524] <2> date_debug: DAT - 01/01/94 UCT:  757382400, 01/01/1994 00:00:00
17:53:00.246: [3252.2524] <2> date_debug: DAT - 07/01/94 UCT:  773020800, 01/07/1994 00:00:00
17:53:00.246: [3252.2524] <2> WinMain: DAT - standard input handle = -2
17:53:00.261: [3252.2524] <4> WinMain: INF - not using socket for standard input handle
17:53:00.261: [3252.2524] <2> WinMain: DAT - standard output handle = 140
17:53:00.261: [3252.2524] <4> WinMain: INF - not using socket for standard output handle
17:53:00.261: [3252.2524] <2> WinMain: DAT - standard error handle = 136
17:53:00.261: [3252.2524] <4> WinMain: INF - not using socket for standard error handle
17:53:00.261: [3252.2524] <4> tar_backup_tfi::create: INF - change time comparison:<disabled>
17:53:00.261: [3252.2524] <4> tar_backup::V_SetupJobData: INF - dwJobData: ffffffff
17:53:00.261: [3252.2524] <4> tar_backup::V_SetupJobData: INF -     dwJob: ffffffff
17:53:00.308: [3252.2524] <4> ncfLogConfiguration: INF - Module: libncf, Release: 7.5.0.6 , Build: 06/10/2013 19:55:39 CDT (20130610)
17:53:00.308: [3252.2524] <4> ncfLogConfiguration: INF - Windows version: 5.2.3790, Platform: 2 (Service Pack 2), Service pack: 2.0, Suite: 274, Product type: 3
17:53:00.324: [3252.2524] <4> ncfLogConfiguration: INF - Process architecture: 0, Page size: 4096, Process type: 4, Process level: 586, Processor revision: 15
17:53:00.339: [3252.2524] <4> NcfString::logLocale: INF - Current code page: WINDOWS: 1252  (ANSI - Latin I), Max. character width: 1, Substitution character: 0x3F [?], Unicode substitution character: 0x003f [?.]
17:53:00.339: [3252.2524] <4> dos_backup::V_PreProcessing: INF - backup privileges enabled, previous = 0
17:53:00.339: [3252.2524] <4> dos_backup::V_PreProcessing: INF - restore privileges enabled, previous = 0
17:53:00.339: [3252.2524] <4> dos_backup::V_PreProcessing: INF - security privileges enabled, previous = 0
17:53:00.339: [3252.2524] <4> dos_backup::V_PreProcessing: INF - tcb privileges enabled, previous = 0
17:53:00.339: [3252.2524] <4> dos_backup::V_PreProcessing: INF - create token privileges enabled, previous = 0
17:53:00.339: [3252.2524] <4> dos_backup::V_PreProcessing: INF - user name: 
17:53:00.339: [3252.2524] <4> dos_backup::V_PreProcessing: INF - no access token: scheduled backup
17:53:00.339: [3252.2524] <2> ov_log::V_GlobalLog: WRN - ubsVerifyMIS():Microsoft Exchange Information Store is not installed.
17:53:00.339: [3252.2524] <2> ov_log::V_GlobalLog: INF - BEDS_Init() Enter InitFlags:0x0
17:53:00.449: [3252.2524] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: C:
17:53:00.449: [3252.2524] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: D:
17:53:00.449: [3252.2524] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: EFI>System>Partition
17:53:00.449: [3252.2524] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: Microsoft Terminal Services
17:53:00.449: [3252.2524] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: Microsoft Windows Network
17:53:00.449: [3252.2524] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: Web Client Network
17:53:00.449: [3252.2524] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: UKDCSITAS14\Microsoft SQL Server Instances
17:53:00.449: [3252.2524] <2> ov_log::V_GlobalLog: INF - DumpChildDleInfo() Child DLE Device Name: UKDCSITAS14\MSSQLSERVER
17:53:00.449: [3252.2524] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: System?State
17:53:00.449: [3252.2524] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: Active Directory Application Mode
17:53:00.464: [3252.2524] <2> tar_base::V_vTarMsgW: INF - BACKUP START 3252
17:53:00.464: [3252.2524] <2> tar_backup_tfi::setupFileDirectives: TAR - backup filename = d:\CDL_TestData\
17:53:00.464: [3252.5032] <4> tar_base::keepaliveThread: INF - keepalive thread is active with an interval of 30 seconds
17:53:00.464: [3252.2524] <2> NBJournalDataCollection::NBJournalDataCollection: INF - volume guid:<\\?\Volume{358d5940-0cda-11d9-8b1d-806e6f6e6963}\>
17:53:00.464: [3252.2524] <2> NBJournalDataCollection::NBJournalDataCollection: INF - mounted at:<C:\>:<\\?\Volume{358d5940-0cda-11d9-8b1d-806e6f6e6963}\>
17:53:00.464: [3252.2524] <2> NBJournalDataCollection::NBJournalDataCollection: INF - not adding to collection, volume:<\\?\Volume{358d5940-0cda-11d9-8b1d-806e6f6e6963}\>:<C:\> is configured to not use the change journal
17:53:00.464: [3252.2524] <2> NBJournalDataCollection::NBJournalDataCollection: INF - volume guid:<\\?\Volume{0c5cce09-9221-11d9-b0a8-505054503030}\>
17:53:00.464: [3252.2524] <2> NBJournalDataCollection::NBJournalDataCollection: INF - mounted at:<D:\>:<\\?\Volume{0c5cce09-9221-11d9-b0a8-505054503030}\>
17:53:00.464: [3252.2524] <2> NBJournalDataCollection::NBJournalDataCollection: INF - not adding to collection, volume:<\\?\Volume{0c5cce09-9221-11d9-b0a8-505054503030}\>:<D:\> is configured to not use the change journal
17:53:00.464: [3252.2524] <4> dos_backup::V_Initialize: INF - created change journal collection
17:53:00.464: [3252.2524] <2> tar_base::V_vTarMsgW: INF - Open File Backup license is not installed on the server.  Open File Backup usage will be disabled.
17:53:00.464: [3252.2524] <2> tar_backup_vxbsa::add: INF - called with 'd:\CDL_TestData\'
17:53:00.464: [3252.2524] <2> _expand_root: INF - checking for root expansion:<d:\CDL_TestData\>
17:53:00.464: [3252.2524] <2> _fix_registry: INF - checking for registry expansion:<d:\CDL_TestData\>
17:53:00.464: [3252.2524] <4> dos_backup::V_VerifyFileSystem: INF - corrected name:<D:\CDL_TestData\>
17:53:00.464: [3252.2524] <4> dos_backup::V_VerifyFileList: INF - UBS Local Type for 'D:\CDL_TestData\' --> 10020002
17:53:03.152: [3252.2524] <4> backup_create: INF - NetBackup Temp Directory: 'C:\Program Files\Veritas\\NetBackup\Temp'
17:53:03.152: [3252.2524] <4> tar_backup_tfi::backup_arg_state: INF - remember start error count: 0
17:53:03.152: [3252.2524] <4> tar_backup_tfi::backup_arg_state: INF - remember start fatal count: 0
17:53:03.152: [3252.2524] <4> dos_backup::tfs_scanstart: INF - starting scan for file directive:<D:\CDL_TestData\>
17:53:03.152: [3252.2524] <4> dos_backup::tfs_scanstart: INF - starting scan using name:<D:\CDL_TestData\>
17:53:03.152: [3252.2524] <4> dos_backup::tfs_scanstart: INF - in 'backup' mode
17:53:03.152: [3252.2524] <4> dos_backup::_change_journal_prepare: INF - waiting to prepare change journal
17:53:03.167: [3252.2524] <4> dos_backup::_tfs_handle_search_state: INF - Calling V_OpenTIRInfoFile <pstrNameCurr = D:\CDL_TestData>
17:53:03.167: [3252.2524] <2> tar_base::V_vTarMsgW: JBD - change journal NOT enabled for <D:\CDL_TestData\>
17:53:03.167: [3252.2524] <2> ov_log::V_GlobalLogEx: INF - file_access (constructor): 0 non-NTFS volumes
17:53:06.979: [3252.2524] <4> dos_backup::tfs_scannext: INF - no more path list entries
17:53:06.979: [3252.2524] <4> tar_backup::backup_endarg_state: INF - finish error count: 0
17:53:06.979: [3252.2524] <4> tar_backup::backup_endarg_state: INF - finish fatal count: 0
17:53:06.979: [3252.2524] <2> tar_base::backup_finish: TAR - backup:                     40 files
17:53:06.979: [3252.2524] <2> tar_base::backup_finish: TAR - backup:          file data:  176325948 bytes
17:53:06.979: [3252.2524] <2> tar_base::backup_finish: TAR - backup:         image data:  176429056 bytes
17:53:06.979: [3252.2524] <2> tar_base::backup_finish: TAR - backup:       elapsed time:          3 secs     58809685 bps
17:53:07.011: [3252.2524] <4> tar_backup::backup_done_state: INF - number of file directives not found: 0
17:53:07.011: [3252.2524] <4> tar_backup::backup_done_state: INF -     number of file directives found: 1
17:53:07.011: [3252.5032] <4> tar_base::keepaliveThread: INF - keepalive thread terminating (reason: WAIT_OBJECT_0)
17:53:07.011: [3252.2524] <4> tar_base::stopKeepaliveThread: INF - keepalive thread has exited. (reason: WAIT_OBJECT_0)
17:53:07.011: [3252.2524] <8> tar_backup_tfi::cleanupTemp: WRN - will not cleanup 'temp' directory, backup id or 'temp' directory is not set
17:53:07.011: [3252.2524] <2> tar_base::V_vTarMsgW: INF - EXIT STATUS 0: the requested operation was successfully completed
17:53:07.011: [3252.2524] <4> dos_backup::tfs_reset: INF - Snapshot deletion start
17:53:07.011: [3252.2524] <4> OVStopCmd: INF - EXIT - status = 0
17:53:07.011: [3252.2524] <2> tar_base::V_Close: closing...
17:53:07.011: [3252.2524] <4> dos_backup::tfs_reset: INF - Snapshot deletion start
17:53:07.011: [3252.2524] <2> ov_log::V_GlobalLog: INF - BEDS_Term(): enter - InitFlags:0x00000101
17:53:07.011: [3252.2524] <2> ov_log::V_GlobalLog: INF - BEDS_Term(): ubs specifics: 0x001d0000
17:53:07.026: [3252.2524] <4> OVShutdown: INF - Finished process
17:53:07.042: [3252.2524] <4> WinMain: INF - Exiting C:\Program Files\VERITAS\NetBackup\bin\bpbkar32.exe
17:53:09.042: [3252.2524] <4> ov_log::OVClose: INF - Closing log file: C:\Program Files\Veritas\NetBackup\logs\BPBKAR\112414.log

[Marianne]

Is this the same folder specified in Backup Selection of the policy (d:\CDL_TestData\)?

We now need all of these logs for a normal backup:

On the media server: bptm and bpbrm 

On the client: bpfis and bpbkar

Please copy the logs to .txt files (e.g. bpfis.txt) and upload as File attachments.

[RonCaplinger · Accepted solution]

By any chance, does this client's file system have over a million files?  it looks like a fulle backup according to the schedule name, but it also shows the Change Journal is not being used.

[watsons]

I would check the bptm on media server, bpbkar on the client to see what could be the delay. Chances are more likely on the client side where some processing is in progressj.

Btw, is there any CLIENT_CONNECT_TIMEOUT value set too high?  (Not the cause, but may cause job to wait rather than failing first)

[SteveLaw]

Hi Ron,

Yes, it does! Just checked the two drives C: and D: and I'm up to 1.5 million and counting   :o

Interestingly, the count on both regularly pauses for a minute or so, presumably the load on the system of counting them all is quite high. 

Can you explain why this might cause the backup to take 30mins or so to start - does Netbackup scan the disk before beginning a backup? 

How will enabling Change Journal help? The Netbackup admin guide for Windows mentions it but doesn't give a 'what is change journal and how does it work' section. 

This is a UAT server that only require one weekly full backup, but it has a twin in production that might need daily backups. 

Thanks :)

[SteveLaw]

2.5 million and counting.....

[RamNagalla]

2.5 million and counting...... big enough to take long time...

in simple way... i would split the backup into mulitple streams and schedule them in different times..

and the mulitple streams are based on the size and file count... out of these 2.5 million+ files may be located on a few folders/directoreis.. they needs to get sperated and trigger as special backups with few min interval to see the behiaver.

[RonCaplinger]

Yes, NetBackup does scan the file system to determine all of the file names that need to be backed up before it begins backing up anything.  This could be based on the archive bit, or on timestamps, of each file, depending on what you have configured for that client.

This is in addition to the time it takes to do a Volume Shadow Copy snapshot, if configured on the client.

The more files it has to scan through, the longer this takes.  On a client with a slow disk system that is also performing batch processing/database crunching/other non-backup related activity (like a UAT client might be doing!), this can take a really long time.  If the CLIENT_READ_TIMEOUT (or other configurable timeout values) are set too low, the connection between the media server and the client could be closed before the backup has begun.

The Windows Change Journal is a feature that was introduced in Windows 2003 (I think) that tracks (or "journals") all the new or changed file names on each drive on the clients.  NetBackup can read this journal instead of traversing the entire filesystem structure to build the list of files to be backed up.  This can save considerable time, particularly on a busy client.

The only negatives of using the Change Journal feature:

• It is not enabled by default on Windows 2003, and requires some calculations to configure the space for the Journal file. 
• It also requires a FULL backup to be performed first before any future backups can make use of it.
• It is enabled by default on Windows 2008, but I have learned that it may still require the Windows Admin to delete an existing juornal before NetBackup will work with it.  I don't know what the reason for this is.

[SteveLaw]

They are tiny log files dating right back to 2005. I'm just going to delete them. Thanks for your help!