Video Screencast Help

Need better understanding about low throughput issues & it's troubleshooting methodology in NBU 7.5.0.X

Created: 02 Feb 2014 • Updated: 06 Feb 2014 | 5 comments
This issue has been solved. See solution.

Dear ALL,

Need better understanding about low throughput issues & it's troubleshooting methodology in NBU 7.5.0.X for all platform (Unix + windows)

- What I need to check for media server N/W configuration buffer parameters ?

- What exactly i can conclude from bptm log of respective server ?

- up to what extent Tape library is responsible for throughput issue

( scenario like tabe library hosted on " A " server showing delay in mounting media on " A " (delay parameter & all nothing have changed ) & same giving low throug-put for server B on which same tape drives are zoned . is this issue is relevant to each other & can cause

low throug-put )

Also mentioned most of the point that i may have missed out as per your experiacne

Thanks

Operating Systems:
Discussion Filed Under:

Comments 5 CommentsJump to latest comment

Marianne's picture

- What I need to check for media server N/W configuration buffer parameters ?

Before looking at buffer parameters, you need to find out where the bottle-neck is.  Mostly with client's ability to read from local disk because of bad fragmentation or bad lun layout on client filesystem.

- What exactly i can conclude from bptm log of respective server ? 

'Waited for full/empty buffer' will give you indication of where the problem is.
'Waited for full buffer' means the media server was waiting for data from client(s)
'Waited for empty buffer' means the media server was receiving data to be written to tape because data was received from client at a faster rate than could be written to tape.
With modern tape technology, this is hardly ever the case...

- up to what extent Tape library is responsible for throughput issue

None whatsoever.
Tape library does not write any data to tape.
OS device drivers (hba and tape driver) on media server server writes data to tape. It can only write as fast as data is received from client(s).

Some performance tuning docs:

How to benchmark the performance of the bpbkar32 process on a Windows client
http://www.symantec.com/docs/TECH1754

Overview of NetBackup performance testing.  
http://www.symantec.com/docs/TECH147296

Symantec NetBackup™ 7.0 - 7.1 Backup Planning and Performance Tuning Guide 
|http://www.symantec.com/docs/DOC4483

About tuning Windows for NetBackup  
http://www.symantec.com/docs/HOWTO56210

Designing your backup system 
http://www.symantec.com/docs/HOWTO56078

Supporting Storage Foundation and VCS on Unix and Windows as well as NetBackup on Unix and Windows
Handy NBU Links

Raaavan's picture

Thanks a lot .....!!!

Do we have any documentation for reading NBU logs & its terminology

Is below logs showing normal behavior since i am getting low throughput on the same media server

00:02:34.394 [19863] <2> write_data: waited for full buffer 116315 times, delayed 220936 times
00:03:54.972 [1036] <2> write_data: waited for full buffer 452 times, delayed 633 times
00:03:56.552 [7545] <2> write_backup_completion_stats: waited for full buffer 174828 times, delayed 319505 times
00:04:21.695 [1037] <2> write_data: waited for full buffer 1858 times, delayed 2278 times
00:06:57.409 [20602] <2> write_data: waited for full buffer 124327 times, delayed 221262 times
00:17:55.200 [29074] <2> write_data: waited for full buffer 69975 times, delayed 93633 times
00:22:26.347 [1564] <2> write_data: waited for full buffer 36094 times, delayed 63537 times
00:33:42.301 [1128] <2> write_backup_completion_stats: waited for full buffer 93154 times, delayed 110411 times
00:44:28.238 [8772] <2> write_data: waited for full buffer 660 times, delayed 3545 times
00:44:40.637 [8811] <2> write_data: waited for full buffer 672 times, delayed 3866 times
00:44:58.550 [8776] <2> write_data: waited for full buffer 848 times, delayed 5448 times
00:48:09.181 [8812] <2> write_data: waited for full buffer 5576 times, delayed 17339 times
00:53:17.427 [8814] <2> write_data: waited for full buffer 4257 times, delayed 37796 times
01:11:36.719 [12511] <2> write_data: waited for full buffer 5992 times, delayed 35560 times
01:23:08.091 [12544] <2> write_data: waited for full buffer 11556 times, delayed 80886 times
01:25:21.870 [12550] <2> write_data: waited for full buffer 12466 times, delayed 89628 times
01:41:41.220 [12555] <2> write_data: waited for full buffer 33070 times, delayed 153557 times
01:54:02.819 [8710] <2> write_data: waited for full buffer 31800 times, delayed 280678 times
01:59:59.163 [12551] <2> write_data: waited for full buffer 22077 times, delayed 227204 times
02:02:54.303 [10492] <2> write_data: waited for full buffer 32827 times, delayed 280244 times
02:15:27.145 [26580] <2> write_data: waited for full buffer 1 times, delayed 66 times
02:34:41.679 [68] <2> write_data: waited for full buffer 17 times, delayed 2956 times
02:35:17.008 [88] <2> write_data: waited for full buffer 17 times, delayed 5196 times
02:37:38.143 [12552] <2> write_data: waited for full buffer 43452 times, delayed 376219 times
02:40:57.116 [67] <2> write_data: waited for full buffer 237 times, delayed 27928 times
02:42:20.476 [422] <2> write_data: waited for full buffer 237 times, delayed 28486 times
03:03:48.192 [5865] <2> write_data: waited for full buffer 27 times, delayed 834 times
03:05:58.684 [6322] <2> write_data: waited for full buffer 1 times, delayed 1056 times
03:08:45.845 [17028] <2> write_data: waited for full buffer 54954 times, delayed 408305 times
03:09:14.395 [6650] <2> write_data: waited for full buffer 112866 times, delayed 619253 times
03:22:53.238 [6425] <2> write_data: waited for full buffer 4929 times, delayed 66298 times
03:28:04.294 [14570] <2> write_data: waited for full buffer 92651 times, delayed 533181 times
03:33:40.366 [24196] <2> write_data: waited for full buffer 24761 times, delayed 359458 times
03:59:57.988 [18366] <2> write_data: waited for full buffer 94451 times, delayed 581938 times
04:04:08.176 [17439] <2> write_data: waited for full buffer 141 times, delayed 1786 times
04:10:00.341 [5866] <2> write_data: waited for full buffer 31357 times, delayed 263186 times
04:13:40.112 [544] <2> write_data: waited for full buffer 49752 times, delayed 387208 times
04:14:04.239 [20381] <2> write_backup_completion_stats: waited for full buffer 7993 times, delayed 83561 times
05:09:21.029 [17408] <2> write_data: waited for full buffer 32867 times, delayed 260667 times
05:19:21.123 [6907] <2> write_backup_completion_stats: waited for full buffer 196689 times, delayed 919489 times
06:10:51.615 [19251] <2> write_data: waited for full buffer 148139 times, delayed 1699435 times
06:32:59.496 [14767] <2> write_data: waited for full buffer 3463 times, delayed 29787 times
06:34:01.675 [4409] <2> write_backup_completion_stats: waited for full buffer 22434 times, delayed 240631 times
06:37:45.554 [16750] <2> write_data: waited for full buffer 210100 times, delayed 1238796 times
08:02:16.220 [7028] <2> write_data: waited for full buffer 144369 times, delayed 1160697 times
08:16:04.155 [14600] <2> write_data: waited for full buffer 76974 times, delayed 1681604 times
08:22:27.063 [17435] <2> write_data: waited for full buffer 104499 times, delayed 1027170 times
08:39:16.058 [18431] <2> write_data: waited for full buffer 111518 times, delayed 1694968 times
08:49:50.053 [29075] <2> write_data: waited for full buffer 149568 times, delayed 892203 times
08:54:20.802 [16718] <2> write_data: waited for full buffer 171907 times, delayed 1786524 times
08:55:45.729 [29325] <2> write_backup_completion_stats: waited for full buffer 25466 times, delayed 292153 times
09:20:39.019 [11731] <2> write_data: waited for full buffer 15960 times, delayed 151368 times
09:52:29.684 [23980] <2> write_data: waited for full buffer 11731 times, delayed 13458 times
10:04:28.267 [26093] <2> write_data: waited for full buffer 9824 times, delayed 11181 times
10:08:16.630 [10461] <2> write_data: waited for full buffer 139331 times, delayed 970878 times
10:09:04.680 [28286] <2> write_data: waited for full buffer 1615 times, delayed 1856 times
10:09:30.670 [28286] <2> write_data: waited for full buffer 576 times, delayed 644 times
10:12:48.642 [28286] <2> write_data: waited for full buffer 6598 times, delayed 7506 times
10:23:19.265 [69] <2> write_data: waited for full buffer 14518 times, delayed 16540 times
10:28:02.408 [2111] <2> write_data: waited for full buffer 931 times, delayed 1075 times
10:28:53.884 [2111] <2> write_data: waited for full buffer 1844 times, delayed 2082 times
10:30:50.977 [2111] <2> write_data: waited for full buffer 2343 times, delayed 2682 times
10:31:52.883 [2111] <2> write_data: waited for full buffer 1213 times, delayed 1355 times
10:33:32.123 [2111] <2> write_data: waited for full buffer 4117 times, delayed 4736 times
10:34:12.633 [10521] <2> write_data: waited for full buffer 17363 times, delayed 1077961 times
10:36:28.183 [4097] <2> write_data: waited for full buffer 0 times, delayed 0 times
10:36:31.762 [4097] <2> write_data: waited for full buffer 1 times, delayed 19 times
10:36:37.692 [4097] <2> write_data: waited for full buffer 73 times, delayed 86 times
10:37:28.436 [4097] <2> write_data: waited for full buffer 1671 times, delayed 1880 times
10:38:46.919 [4097] <2> write_data: waited for full buffer 3081 times, delayed 3609 times
10:39:00.811 [4097] <2> write_data: waited for full buffer 0 times, delayed 0 times
10:39:04.103 [4097] <2> write_data: waited for full buffer 0 times, delayed 0 times
10:40:39.414 [4097] <2> write_data: waited for full buffer 4076 times, delayed 4626 times
10:42:17.292 [4097] <2> write_data: waited for full buffer 4052 times, delayed 4656 times
10:42:26.823 [4097] <2> write_data: waited for full buffer 8 times, delayed 8 times
10:48:16.191 [10488] <2> write_data: waited for full buffer 165180 times, delayed 1127901 times
10:48:40.917 [6274] <2> write_data: waited for full buffer 7130 times, delayed 8273 times
10:56:18.415 [732] <2> write_data: waited for full buffer 1713 times, delayed 2226 times
10:57:03.127 [732] <2> write_data: waited for full buffer 1501 times, delayed 1725 times
10:59:19.422 [732] <2> write_data: waited for full buffer 252 times, delayed 290 times
11:01:26.569 [732] <2> write_data: waited for full buffer 4129 times, delayed 4976 times
11:12:59.907 [10214] <2> write_data: waited for full buffer 12855 times, delayed 16695 times
11:19:50.709 [5015] <2> write_data: waited for full buffer 485520 times, delayed 2590184 times
11:30:13.442 [12177] <2> write_data: waited for full buffer 18028 times, delayed 22936 times
11:30:52.951 [26666] <2> write_backup_completion_stats: waited for full buffer 135892 times, delayed 971138 times
11:38:54.006 [6995] <2> write_backup_completion_stats: waited for full buffer 186882 times, delayed 2009638 times
11:46:43.140 [15625] <2> write_data: waited for full buffer 27695 times, delayed 42042 times
11:47:37.252 [15986] <2> write_data: waited for full buffer 10063 times, delayed 16321 times
11:51:20.428 [18807] <2> write_data: waited for full buffer 23 times, delayed 29 times
11:51:24.498 [18807] <2> write_data: waited for full buffer 0 times, delayed 0 times
11:51:25.632 [18526] <2> write_data: waited for full buffer 3852 times, delayed 5313 times
11:51:28.577 [18807] <2> write_data: waited for full buffer 0 times, delayed 0 times
11:51:33.641 [18807] <2> write_data: waited for full buffer 30 times, delayed 44 times
11:55:12.145 [18807] <2> write_data: waited for full buffer 9064 times, delayed 11581 times
11:56:28.110 [18526] <2> write_data: waited for full buffer 8133 times, delayed 10762 times
11:59:25.956 [20514] <2> write_data: waited for full buffer 2474 times, delayed 3238 times
12:05:27.241 [29875] <2> write_data: waited for full buffer 1521402 times, delayed 4029993 times
12:06:22.607 [21633] <2> write_data: waited for full buffer 3052 times, delayed 3440 times
12:08:27.324 [28905] <2> write_data: waited for full buffer 196744 times, delayed 1687086 times
12:08:54.517 [21633] <2> write_data: waited for full buffer 5020 times, delayed 5670 times
12:11:12.820 [21633] <2> write_data: waited for full buffer 6125 times, delayed 7110 times
12:17:47.559 [20773] <2> write_data: waited for full buffer 19255 times, delayed 22026 times
12:19:56.687 [21636] <2> write_data: waited for full buffer 30567 times, delayed 37303 times
12:30:31.555 [24796] <2> write_data: waited for full buffer 11666 times, delayed 13655 times
12:40:00.814 [27609] <2> write_data: waited for full buffer 12095 times, delayed 14908 times
12:42:42.717 [28045] <2> write_data: waited for full buffer 14471 times, delayed 17941 times
12:44:19.220 [25796] <2> write_data: waited for full buffer 35445 times, delayed 45487 times
12:49:36.541 [508] <2> write_data: waited for full buffer 3619 times, delayed 4257 times
12:53:52.261 [508] <2> write_data: waited for full buffer 7698 times, delayed 9741 times
12:57:38.367 [144] <2> write_data: waited for full buffer 399 times, delayed 487 times
12:57:47.677 [144] <2> write_data: waited for full buffer 301 times, delayed 336 times
12:58:12.411 [144] <2> write_data: waited for full buffer 556 times, delayed 689 times
12:59:55.736 [29804] <2> write_data: waited for full buffer 5872 times, delayed 7186 times
13:03:57.096 [144] <2> write_data: waited for full buffer 14885 times, delayed 17557 times
13:04:22.537 [578] <2> write_data: waited for full buffer 26078 times, delayed 32082 times
13:05:54.075 [4347] <2> write_data: waited for full buffer 34 times, delayed 39 times
13:06:06.462 [4347] <2> write_data: waited for full buffer 400 times, delayed 474 times
13:06:09.951 [4347] <2> write_data: waited for full buffer 0 times, delayed 0 times
13:07:40.094 [4347] <2> write_data: waited for full buffer 3384 times, delayed 4136 times
13:08:45.666 [3916] <2> write_data: waited for full buffer 12106 times, delayed 13936 times
13:10:02.717 [4347] <2> write_data: waited for full buffer 3634 times, delayed 4695 times
13:18:56.793 [4710] <2> write_data: waited for full buffer 14231 times, delayed 17158 times
13:19:03.912 [24169] <2> write_data: waited for full buffer 161806 times, delayed 2689820 times
13:23:00.955 [5869] <2> write_data: waited for full buffer 523407 times, delayed 2444690 times
13:35:09.675 [9021] <2> write_data: waited for full buffer 11787 times, delayed 13998 times
13:37:00.427 [7649] <2> write_data: waited for full buffer 26305 times, delayed 32057 times
13:45:15.653 [10700] <2> write_data: waited for full buffer 20178 times, delayed 23702 times
13:49:11.164 [12316] <2> write_data: waited for full buffer 3428 times, delayed 4354 times
13:51:11.101 [12316] <2> write_data: waited for full buffer 3934 times, delayed 4846 times
13:57:30.475 [13531] <2> write_data: waited for full buffer 12872 times, delayed 15012 times
14:05:41.118 [14730] <2> write_data: waited for full buffer 7510 times, delayed 8607 times
14:16:33.973 [16378] <2> write_data: waited for full buffer 16096 times, delayed 18758 times
14:17:37.944 [4266] <2> write_backup_completion_stats: waited for full buffer 688495 times, delayed 2680058 times
14:19:02.312 [18421] <2> write_data: waited for full buffer 2484 times, delayed 2760 times
14:21:12.519 [18421] <2> write_data: waited for full buffer 1997 times, delayed 2324 times
14:22:34.768 [18421] <2> write_data: waited for full buffer 3280 times, delayed 3873 times
14:24:46.034 [19656] <2> write_data: waited for full buffer 554 times, delayed 681 times
14:25:27.614 [19656] <2> write_data: waited for full buffer 1352 times, delayed 1589 times
14:27:57.034 [20306] <2> write_data: waited for full buffer 2849 times, delayed 3368 times
14:28:15.917 [20306] <2> write_data: waited for full buffer 399 times, delayed 462 times
14:30:01.826 [20306] <2> write_data: waited for full buffer 4113 times, delayed 5031 times
14:30:39.167 [20306] <2> write_data: waited for full buffer 858 times, delayed 1085 times
14:30:50.999 [20306] <2> write_data: waited for full buffer 0 times, delayed 0 times
14:31:19.368 [20306] <2> write_data: waited for full buffer 272 times, delayed 365 times
14:31:45.218 [20306] <2> write_data: waited for full buffer 506 times, delayed 581 times
14:32:45.202 [20306] <2> write_data: waited for full buffer 2262 times, delayed 2746 times
14:35:46.421 [21864] <2> write_data: waited for full buffer 5117 times, delayed 6036 times
14:36:51.559 [21864] <2> write_data: waited for full buffer 2600 times, delayed 3146 times
14:39:34.329 [21864] <2> write_data: waited for full buffer 4729 times, delayed 5682 times
14:46:44.905 [24366] <2> write_data: waited for full buffer 1378 times, delayed 2081 times
14:48:02.727 [24366] <2> write_data: waited for full buffer 3396 times, delayed 4058 times
15:00:22.459 [24361] <2> write_data: waited for full buffer 34589 times, delayed 47303 times
15:02:34.878 [12465] <2> write_data: waited for full buffer 253510 times, delayed 3308718 times
15:07:10.133 [24362] <2> write_data: waited for full buffer 48281 times, delayed 61712 times
15:10:03.928 [28935] <2> write_data: waited for full buffer 2 times, delayed 16 times
15:10:11.966 [28935] <2> write_data: waited for full buffer 163 times, delayed 232 times
15:10:21.820 [28935] <2> write_data: waited for full buffer 240 times, delayed 404 times
15:10:31.494 [28935] <2> write_data: waited for full buffer 233 times, delayed 386 times
15:11:39.970 [28935] <2> write_data: waited for full buffer 1985 times, delayed 3000 times
15:20:01.632 [28935] <2> write_data: waited for full buffer 21695 times, delayed 28845 times
15:22:07.865 [28935] <2> write_data: waited for full buffer 4791 times, delayed 7026 times
15:38:00.912 [25103] <2> write_data: waited for full buffer 110480 times, delayed 142286 times
15:42:03.488 [27726] <2> write_data: waited for full buffer 108933 times, delayed 137035 times
16:05:26.066 [6722] <2> write_data: waited for full buffer 43079 times, delayed 54031 times
16:14:06.628 [8136] <2> write_backup_completion_stats: waited for full buffer 204903 times, delayed 1842121 times
17:22:13.644 [12499] <2> write_data: waited for full buffer 667715 times, delayed 3860404 times
18:14:20.175 [2621] <2> write_data: waited for full buffer 4798 times, delayed 53980 times
18:25:19.186 [29851] <2> write_data: waited for full buffer 71707 times, delayed 101138 times
18:34:04.116 [2713] <2> write_data: waited for full buffer 40670 times, delayed 128549 times
19:23:52.928 [17469] <2> write_backup_completion_stats: waited for full buffer 5818 times, delayed 28027 times
19:30:47.221 [17474] <2> write_data: waited for full buffer 14222 times, delayed 60486 times
19:52:36.209 [989] <2> write_data: waited for full buffer 746252 times, delayed 3959784 times
20:18:00.795 [12804] <2> write_backup_completion_stats: waited for full buffer 2063387 times, delayed 3205106 times
20:26:31.649 [28225] <2> write_data: waited for full buffer 15316 times, delayed 57779 times
 

Marianne's picture

The Backup Planning and Performance Tuning Guide tells you how to read and interpret bptm logs.

It seems data is arriving at very slow speed at media server.

You need to start with read performance on the clients.
Next step is to check network.
How many NICs in your media server(s)?
A single 1Gb NIC can only receive data at +- 100MB/sec. This speed is hardly enough to stream one LTO3 tape drive...

 

Supporting Storage Foundation and VCS on Unix and Windows as well as NetBackup on Unix and Windows
Handy NBU Links

SOLUTION
jim dalton's picture

Run a synthetic test ie one that doesnt have to read disk/data but creates its own: back that data up and it tells you everything in the chain from server to media but excludes the clients ability to give you data (which is usually the bottleneck). Alternatively run a backup to a locally attached drive if you can: and if you can give it a selection of file sizes and numbers you will see how netbackup behaves. Lots of small files is slower than a handful of large files.If you run a large (multiGB) backup of one file to local drive and the drive doesnt hit maxspeed, then it needs looking at. Once you know the drive is ABLE to hit max speed, the rest is just bottleneck searching or manipulating the backup load.

Theres heaps of info on this on the forum.

Dont forget: you cant get out more than the slowest part of the chain and it needs to be balanced ( aka designed!) so throwing tape drives at a problem where the clients are on 100mbit is never going to work.

Jim 

Raaavan's picture

Hi Marianne spot on as always .!!!!

There was Network bandwidth issue between netbackup media & master server ports

also thanks jimi for your note ....!!!!