Ordinary client backup takes 30mins to start

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

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

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

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.

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)

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 :-)

2.5 million and counting.....

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.

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.