Forum Discussion

Level 6

15 years ago

Question about throughput

I've noticed something about our NBU environment, and I dont know if this is something that can be diagnosed on this forum, as it may be network related, but I thought I would see if anyone had any suggestions.

I noticed that when our backups initially kick off, they are whizzing through the pipe. For example, one backup will start at 30 MB/s. I know that's not the greatest speed, but it isnt bad. The throughput progressively gets worse as time goes by. For testing purposes I've kicked off only one backup to see this happen, to make sure there are no other resouce contentions.

I'm just baffled as to why the throughput would shrink throughout the duration of the backup. It might bottom out a 7 MB/s, or it might bottom out at 3 MB/s.

Any ideas?

7.1.x and Earlier

Backup and Recovery

NetBackup

Marianne
15 years ago
I have always managed to get performance stats with level 0 logs.
I have posted a bpbkar log from a Windows client below. This is the part that tells us read spead on the client:

11:29:01.485 AM: [7660.6584] <2> tar_base::backup_finish: TAR - backup:          file data: 967486464 bytes 86 gigabytes
11:29:01.485 AM: [7660.6584] <2> tar_base::backup_finish: TAR - backup:         image data: 967493632 bytes 86 gigabytes
11:29:01.485 AM: [7660.6584] <2> tar_base::backup_finish: TAR - backup:       elapsed time:       1638 secs     56965375 bps

Test was done using this command on the client:
bpbkar32 -nocont E:\NTBackups > NUL

bptm log on media servers also have the 'waited for full / empty ....' at the end of backups using level 0 logging.

We have recently seen major backup improvements by disabling TCP chimney as per this TechNote:
http://seer.entsupport.symantec.com/docs/304578.htm

bpbkar log:
11:01:41.548 AM: [7660.6584] <4> ov_log::OVInit: INF - Starting log file: C:\Program Files\VERITAS\NetBackup\logs\BPBKAR\112609.LOG

11:01:41.548 AM: [7660.6584] <4> ov_log::OVInit: GENERAL Log Level: 0
11:01:41.548 AM: [7660.6584] <4> ov_log::OVInit: TCP Log Level: 0
....

11:01:41.563 AM: [7660.6584] <2> WinMain: DAT - _pgmptr = 'C:\Program Files\VERITAS\NetBackup\bin\bpbkar32.exe'
11:01:41.563 AM: [7660.6584] <2> WinMain: DAT - lpCmdLine = '-nocont E:\NTBackups '
11:01:41.563 AM: [7660.6584] <2> date_debug: DAT - timezone: South Africa Standard Time, offset=-7200, dst: NONE
11:01:41.563 AM: [7660.6584] <2> date_debug: DAT - current time: 1259226101, 11/26/2009 11:01:41 AM
11:01:41.563 AM: [7660.6584] <2> date_debug: DAT - 01/01/94 UCT: 757382400, 1/1/1994 2:00:00 AM
11:01:41.563 AM: [7660.6584] <2> date_debug: DAT - 07/01/94 UCT: 773020800, 7/1/1994 2:00:00 AM
11:01:41.563 AM: [7660.6584] <2> WinMain: DAT - standard input handle = -1
11:01:41.563 AM: [7660.6584] <4> WinMain: INF - not using socket for standard input handle
11:01:41.563 AM: [7660.6584] <2> WinMain: DAT - standard output handle = 16
11:01:41.563 AM: [7660.6584] <4> WinMain: INF - not using socket for standard output handle
11:01:41.563 AM: [7660.6584] <2> WinMain: DAT - standard error handle = -1
11:01:41.563 AM: [7660.6584] <4> WinMain: INF - not using socket for standard error handle
11:01:41.673 AM: [7660.6584] <4> tar_backup::V_SetupJobData: INF - dwJobData: ffffffff
11:01:41.673 AM: [7660.6584] <4> tar_backup::V_SetupJobData: INF -     dwJob: ffffffff
11:01:41.673 AM: [7660.6584] <4> dos_backup::V_PreProcessing: INF - backup privileges enabled, previous = 0
11:01:41.673 AM: [7660.6584] <4> dos_backup::V_PreProcessing: INF - restore privileges enabled, previous = 0
11:01:41.673 AM: [7660.6584] <4> dos_backup::V_PreProcessing: INF - security privileges enabled, previous = 0
11:01:41.673 AM: [7660.6584] <4> dos_backup::V_PreProcessing: INF - tcb privileges enabled, previous = 0
11:01:41.673 AM: [7660.6584] <4> dos_backup::V_PreProcessing: INF - create token privileges enabled, previous = 0
11:01:41.673 AM: [7660.6584] <4> dos_backup::V_PreProcessing: INF - user name:
11:01:41.673 AM: [7660.6584] <4> dos_backup::V_PreProcessing: INF - no access token: scheduled backup
11:01:41.673 AM: [7660.6584] <2> tar_backup::V_SetupFileDirectives: TAR - backup filename = E:\NTBackups
11:01:41.688 AM: [7660.6584] <2> tar_base::V_vTarMsgW: INF - Open File Backup license is not installed on the server. Open File Backup usage will be disabled.
11:01:41.704 AM: [7660.6584] <2> ov_log::V_GlobalLog: INF - BEDS_Init() Enter InitFlags:0x0
11:01:42.001 AM: [7660.6584] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: C:
11:01:42.001 AM: [7660.6584] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: D:
11:01:42.001 AM: [7660.6584] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: E:
11:01:42.001 AM: [7660.6584] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: Microsoft Terminal Services
11:01:42.001 AM: [7660.6584] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: Microsoft Windows Network
11:01:42.001 AM: [7660.6584] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: Web Client Network
11:01:42.001 AM: [7660.6584] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: Shadow?Copy?Components
11:01:43.938 AM: [7660.6584] <4> backup_create: INF - NetBackup Temp Directory: 'C:\Program Files\VERITAS\\NetBackup\Temp'
11:29:01.485 AM: [7660.6584] <2> tar_base::backup_finish: TAR - backup:                              2 files
11:29:01.485 AM: [7660.6584] <2> tar_base::backup_finish: TAR - backup:          file data: 967486464 bytes 86 gigabytes
11:29:01.485 AM: [7660.6584] <2> tar_base::backup_finish: TAR - backup:         image data: 967493632 bytes 86 gigabytes
11:29:01.485 AM: [7660.6584] <2> tar_base::backup_finish: TAR - backup:       elapsed time:       1638 secs     56965375 bps
11:29:01.501 AM: [7660.6584] <2> tar_base::V_vTarMsgW: INF - EXIT STATUS 0: the requested operation was successfully completed
11:29:01.501 AM: [7660.6584] <4> OVStopCmd: INF - EXIT - status = 0
11:29:01.517 AM: [7660.6584] <2> ov_log::V_GlobalLog: INF - BEDS_Term() Enter InitFlags:0x101
11:29:01.563 AM: [7660.6584] <4> OVShutdown: INF - Finished process
11:29:01.563 AM: [7660.6584] <4> WinMain: INF - Exiting C:\Program Files\VERITAS\NetBackup\bin\bpbkar32.exe
11:29:03.563 AM: [7660.6584] <4> ov_log::OVClose: INF - Closing log file: C:\Program Files\VERITAS\NetBackup\logs\BPBKAR\112609.LOG

Nathan_B
Level 4
15 years ago
Is this for both incremental and full backups? I've noticed that incremental backups can vary a lot in speed as the system is calcuating what to send.
mph999
Level 6
15 years ago
We can probably diagnose this.

First I would use the bpbkar -nocont option to see what speed we can pull data off the disk. This is effectivly making the client run the clients backup process but we send it to /dev/null. Knowing the amount of data and having timed it we can work out the average speed.

Lets assume this is high, I'd then ftp the same data across to the media server, does this speed stay constant ?

If you run the backup with verbose 5 for the logs and gather the bpbkar from the client and bptm from the media we can see (hopefully) where the delay is. After the backup finishes a line is written saying somethinh like "waited for full buffer" or "waited for empty buffer" x times. If there is a high value of x (generally in the 1000's) then it is a potential bottleneck. If waiting for full, this means the data isn't coming from the client quickly, if waiting for empty, it means the data isn't going from the buffer to the tape drive quickly.

Martin
Symontec
Level 5
15 years ago
Hi, All what the guys say is great... In addition, I would also check parameters en NICs. Is always great if you have your NICs configured FULL DUPLEX and at the MAX SUPPORTED SPEED (100Mbps or 1Gbps). Avoiding AUTO parameters is a good practice for NICs on MASTER/MEDIA/CLIENT, LAN Swchts and every Network Component.

Let us know about the progress to keep helping.

Regards,
SAF
rjrumfelt
Level 6
15 years ago
I've cranked the verbosity up to 5. I'll check bpbkar for "waited for full buffer" or "waited for empty buffer". Its quite large.

One of the offending clients had its NIC configured to auto, but when we tried to modify it the broadcom driver barfed and the server ended up needing a reboot. We just got the auth to have it rebooted, so we'll see what happens.
Marianne
Level 6
15 years ago
I have always managed to get performance stats with level 0 logs.
I have posted a bpbkar log from a Windows client below. This is the part that tells us read spead on the client:

11:29:01.485 AM: [7660.6584] <2> tar_base::backup_finish: TAR - backup:          file data: 967486464 bytes 86 gigabytes
11:29:01.485 AM: [7660.6584] <2> tar_base::backup_finish: TAR - backup:         image data: 967493632 bytes 86 gigabytes
11:29:01.485 AM: [7660.6584] <2> tar_base::backup_finish: TAR - backup:       elapsed time:       1638 secs     56965375 bps

Test was done using this command on the client:
bpbkar32 -nocont E:\NTBackups > NUL

bptm log on media servers also have the 'waited for full / empty ....' at the end of backups using level 0 logging.

We have recently seen major backup improvements by disabling TCP chimney as per this TechNote:
http://seer.entsupport.symantec.com/docs/304578.htm

bpbkar log:
11:01:41.548 AM: [7660.6584] <4> ov_log::OVInit: INF - Starting log file: C:\Program Files\VERITAS\NetBackup\logs\BPBKAR\112609.LOG

11:01:41.548 AM: [7660.6584] <4> ov_log::OVInit: GENERAL Log Level: 0
11:01:41.548 AM: [7660.6584] <4> ov_log::OVInit: TCP Log Level: 0
....

11:01:41.563 AM: [7660.6584] <2> WinMain: DAT - _pgmptr = 'C:\Program Files\VERITAS\NetBackup\bin\bpbkar32.exe'
11:01:41.563 AM: [7660.6584] <2> WinMain: DAT - lpCmdLine = '-nocont E:\NTBackups '
11:01:41.563 AM: [7660.6584] <2> date_debug: DAT - timezone: South Africa Standard Time, offset=-7200, dst: NONE
11:01:41.563 AM: [7660.6584] <2> date_debug: DAT - current time: 1259226101, 11/26/2009 11:01:41 AM
11:01:41.563 AM: [7660.6584] <2> date_debug: DAT - 01/01/94 UCT: 757382400, 1/1/1994 2:00:00 AM
11:01:41.563 AM: [7660.6584] <2> date_debug: DAT - 07/01/94 UCT: 773020800, 7/1/1994 2:00:00 AM
11:01:41.563 AM: [7660.6584] <2> WinMain: DAT - standard input handle = -1
11:01:41.563 AM: [7660.6584] <4> WinMain: INF - not using socket for standard input handle
11:01:41.563 AM: [7660.6584] <2> WinMain: DAT - standard output handle = 16
11:01:41.563 AM: [7660.6584] <4> WinMain: INF - not using socket for standard output handle
11:01:41.563 AM: [7660.6584] <2> WinMain: DAT - standard error handle = -1
11:01:41.563 AM: [7660.6584] <4> WinMain: INF - not using socket for standard error handle
11:01:41.673 AM: [7660.6584] <4> tar_backup::V_SetupJobData: INF - dwJobData: ffffffff
11:01:41.673 AM: [7660.6584] <4> tar_backup::V_SetupJobData: INF -     dwJob: ffffffff
11:01:41.673 AM: [7660.6584] <4> dos_backup::V_PreProcessing: INF - backup privileges enabled, previous = 0
11:01:41.673 AM: [7660.6584] <4> dos_backup::V_PreProcessing: INF - restore privileges enabled, previous = 0
11:01:41.673 AM: [7660.6584] <4> dos_backup::V_PreProcessing: INF - security privileges enabled, previous = 0
11:01:41.673 AM: [7660.6584] <4> dos_backup::V_PreProcessing: INF - tcb privileges enabled, previous = 0
11:01:41.673 AM: [7660.6584] <4> dos_backup::V_PreProcessing: INF - create token privileges enabled, previous = 0
11:01:41.673 AM: [7660.6584] <4> dos_backup::V_PreProcessing: INF - user name:
11:01:41.673 AM: [7660.6584] <4> dos_backup::V_PreProcessing: INF - no access token: scheduled backup
11:01:41.673 AM: [7660.6584] <2> tar_backup::V_SetupFileDirectives: TAR - backup filename = E:\NTBackups
11:01:41.688 AM: [7660.6584] <2> tar_base::V_vTarMsgW: INF - Open File Backup license is not installed on the server. Open File Backup usage will be disabled.
11:01:41.704 AM: [7660.6584] <2> ov_log::V_GlobalLog: INF - BEDS_Init() Enter InitFlags:0x0
11:01:42.001 AM: [7660.6584] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: C:
11:01:42.001 AM: [7660.6584] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: D:
11:01:42.001 AM: [7660.6584] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: E:
11:01:42.001 AM: [7660.6584] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: Microsoft Terminal Services
11:01:42.001 AM: [7660.6584] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: Microsoft Windows Network
11:01:42.001 AM: [7660.6584] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: Web Client Network
11:01:42.001 AM: [7660.6584] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: Shadow?Copy?Components
11:01:43.938 AM: [7660.6584] <4> backup_create: INF - NetBackup Temp Directory: 'C:\Program Files\VERITAS\\NetBackup\Temp'
11:29:01.485 AM: [7660.6584] <2> tar_base::backup_finish: TAR - backup:                              2 files
11:29:01.485 AM: [7660.6584] <2> tar_base::backup_finish: TAR - backup:          file data: 967486464 bytes 86 gigabytes
11:29:01.485 AM: [7660.6584] <2> tar_base::backup_finish: TAR - backup:         image data: 967493632 bytes 86 gigabytes
11:29:01.485 AM: [7660.6584] <2> tar_base::backup_finish: TAR - backup:       elapsed time:       1638 secs     56965375 bps
11:29:01.501 AM: [7660.6584] <2> tar_base::V_vTarMsgW: INF - EXIT STATUS 0: the requested operation was successfully completed
11:29:01.501 AM: [7660.6584] <4> OVStopCmd: INF - EXIT - status = 0
11:29:01.517 AM: [7660.6584] <2> ov_log::V_GlobalLog: INF - BEDS_Term() Enter InitFlags:0x101
11:29:01.563 AM: [7660.6584] <4> OVShutdown: INF - Finished process
11:29:01.563 AM: [7660.6584] <4> WinMain: INF - Exiting C:\Program Files\VERITAS\NetBackup\bin\bpbkar32.exe
11:29:03.563 AM: [7660.6584] <4> ov_log::OVClose: INF - Closing log file: C:\Program Files\VERITAS\NetBackup\logs\BPBKAR\112609.LOG

Forum Discussion

Question about throughput

Related Content

ZFS BACKUP SLOW THROUGHPUT

Throughput Benchmarking

Symantec NetBackup hardware vs. software throughput question

Question about capacity license model

Elasticsearch - Upgrade Question