Extremely bad performance after upgrade from Netbackup 8.0 to 8.1.1

[fazhar]

After Upgradign our IWndows master from 773 to 8.1.1, numerous backups and replication have started to fail with socket erros but completing successfully mostly on rerun. while running bptestbpcd on multiple clients , its gettign failed intermittently  for many clients.

we opened case with support but so far nothing concrete has been achieved. Checked with n/w OS team and did all possible nic/ network related settings but issue is still there. anyone else is faving such issue

[Marianne]

Have you logged a Support call with Veritas about issues experienced after upgrade? 

My guess is that the performance problem and socket errors are 2 separate issues.

Are you using MSDP on media servers? 
This is a known issue for NBU 8.1: https://www.veritas.com/support/en_US/article.100041390

Plus the rolling MSDP conversion:
https://vox.veritas.com/t5/NetBackup/Extremely-bad-performance-after-upgrade-from-Netbackup-8-0-to-8...
MSDP EEB : https://www.veritas.com/support/en_US/article.100043461

About the socket errors and bptestbpcd failure - 
can you show us an example of bptestbpcd failure (with -verbose -debug)?
There are no 'known issues' w.r.t to comms in 8.1 and later. 
See LBN: https://www.veritas.com/support/en_US/article.000127571

[fazhar]

we are not using MSDP but DD boost and all DDRs are running at 6.0

we tested bptestbpcd multiple times for different clients in a loop and we cann see socket error in between. below is one such output:

<2> put_string: cannot write data to network:  An existing connection was forcibly closed by
the remote host.

PS C:\temp> .\test1.bat

C:\temp>bptestbpcd -host qtc-db068p -debug
04:17:41.489 [27760.27376] <2> bptestbpcd: VERBOSE = 0
04:17:41.489 [27760.27376] <8> cache_item_to_file: [vnet_addrinfo.c:6857] rename() failed 13 0xd
04:17:41.489 [27760.27376] <8> vnet_cached_getaddrinfo_and_update: [vnet_addrinfo.c:1858] cache_item_to_file() failed 0
0x0
04:17:41.505 [27760.27376] <2> vnet_pbxConnect_ex: pbxConnectExEx Succeeded
04:17:41.505 [27760.27376] <2> logconnections: BPCD CONNECT FROM 10.44.72.40.57563 TO 10.44.71.45.1556 fd = 604
04:17:41.505 [27760.27376] <2> vnet_connect_to_vnetd_bpcd: js_bpcd_info: 0000000002A8BB40
04:17:41.521 [27760.27376] <2> vnet_pbxConnect_ex: pbxConnectExEx Succeeded
04:17:41.552 [27760.27376] <8> do_pbx_service: [vnet_connect.c:2581] via PBX VNETD CONNECT FROM 10.44.72.40.57565 TO 10.
44.71.45.1556 fd = 608
04:17:41.552 [27760.27376] <8> vnet_vnetd_connect_forward_socket_begin: [vnet_vnetd.c:458] VN_REQUEST_CONNECT_FORWARD_SO
CKET 10 0xa
04:17:41.568 [27760.27376] <8> vnet_vnetd_connect_forward_socket_begin: [vnet_vnetd.c:483] ipc_string 52694
04:17:41.630 [27760.27376] <2> bpcr_get_version_rqst: bpcd version: 07730000
1 1 1
10.44.72.40:57563 -> 10.44.71.45:1556
10.44.72.40:57565 -> 10.44.71.45:1556
<2>bptestbpcd: EXIT status = 0
04:17:41.646 [27760.27376] <2> bptestbpcd: EXIT status = 0

C:\temp>bptestbpcd -host qtc-db068p -debug
04:17:41.677 [29320.15416] <2> bptestbpcd: VERBOSE = 0
04:17:41.693 [29320.15416] <8> cache_item_to_file: [vnet_addrinfo.c:6857] rename() failed 13 0xd
04:17:41.693 [29320.15416] <8> vnet_cached_getaddrinfo_and_update: [vnet_addrinfo.c:1858] cache_item_to_file() failed 0
0x0
04:17:41.693 [29320.15416] <2> vnet_pbxConnect_ex: pbxConnectExEx Succeeded
04:17:41.708 [29320.15416] <2> logconnections: BPCD CONNECT FROM 10.44.72.40.57570 TO 10.44.71.45.1556 fd = 604
04:17:41.708 [29320.15416] <2> vnet_connect_to_vnetd_bpcd: js_bpcd_info: 000000000203B540
04:17:41.708 [29320.15416] <2> vnet_pbxConnect_ex: pbxConnectExEx Succeeded
04:17:41.739 [29320.15416] <8> do_pbx_service: [vnet_connect.c:2581] via PBX VNETD CONNECT FROM 10.44.72.40.57572 TO 10.
44.71.45.1556 fd = 608
04:17:41.755 [29320.15416] <8> vnet_vnetd_connect_forward_socket_begin: [vnet_vnetd.c:458] VN_REQUEST_CONNECT_FORWARD_SO
CKET 10 0xa
04:17:41.755 [29320.15416] <8> vnet_vnetd_connect_forward_socket_begin: [vnet_vnetd.c:483] ipc_string 52696
04:17:41.818 [29320.15416] <2> bpcr_get_version_rqst: bpcd version: 07730000
1 1 1
10.44.72.40:57570 -> 10.44.71.45:1556
10.44.72.40:57572 -> 10.44.71.45:1556
<2>bptestbpcd: EXIT status = 0
04:17:41.833 [29320.15416] <2> bptestbpcd: EXIT status = 0

C:\temp>bptestbpcd -host qtc-db068p -debug
04:17:42.052 [27232.29796] <2> bptestbpcd: VERBOSE = 0
04:17:42.068 [27232.29796] <8> cache_item_to_file: [vnet_addrinfo.c:6857] rename() failed 13 0xd
04:17:42.068 [27232.29796] <8> vnet_cached_getaddrinfo_and_update: [vnet_addrinfo.c:1858] cache_item_to_file() failed 0
0x0
04:17:42.068 [27232.29796] <2> vnet_pbxConnect_ex: pbxConnectExEx Succeeded
04:17:42.083 [27232.29796] <16> vnet_connect_with_opts: connect() failed: 10048
04:17:42.083 [27232.29796] <16> vnet_proxy_helper_connect_try: vnet_connect_with_opts() failed: 10
04:17:42.083 [27232.29796] <16> vnet_proxy_helper_connect_try: js_helper = {"service": "outbound_proxy", "sockaddr": {"f
amily": {"number": 2, "symbol": "AF_INET", "description": "IPv4"}, "length": 16, "ipstr": "127.0.0.1", "port": 62130, "i
p_port": "127.0.0.1:62130"}, "pid": 4316}
04:17:42.083 [27232.29796] <16> vnet_proxy_helper_connect_try: ../../libvlibs/vnet_proxy.c.1551: status = 10, JSON strin
g = {"service": "outbound_proxy", "sockaddr": {"family": {"number": 2, "symbol": "AF_INET", "description": "IPv4"}, "len
gth": 16, "ipstr": "127.0.0.1", "port": 62130, "ip_port": "127.0.0.1:62130"}, "pid": 4316}
04:17:42.146 [27232.29796] <2> logconnections: BPCD CONNECT FROM 10.44.72.40.57583 TO 10.44.71.45.1556 fd = 564
04:17:42.146 [27232.29796] <2> vnet_connect_to_vnetd_bpcd: js_bpcd_info: 0000000002E5BAE0
04:17:42.177 [27232.29796] <2> vnet_pbxConnect_ex: pbxConnectExEx Succeeded
04:17:42.208 [27232.29796] <8> do_pbx_service: [vnet_connect.c:2581] via PBX VNETD CONNECT FROM 10.44.72.40.57586 TO 10.
44.71.45.1556 fd = 600
04:17:42.208 [27232.29796] <8> vnet_vnetd_connect_forward_socket_begin: [vnet_vnetd.c:458] VN_REQUEST_CONNECT_FORWARD_SO
CKET 10 0xa
04:17:42.208 [27232.29796] <8> vnet_vnetd_connect_forward_socket_begin: [vnet_vnetd.c:483] ipc_string 52701
04:17:42.239 [27232.29796] <2> put_string: cannot write data to network:  An existing connection was forcibly closed by
the remote host.
04:17:42.239 [27232.29796] <2> bpcr_put_vnetd_forward_socket: put_string 52701 failed: 10054
04:17:42.239 [27232.29796] <2> local_bpcr_connect: bpcr_put_vnetd_forward_socket failed: 24
04:17:42.239 [27232.29796] <2> ConnectToBPCD: bpcd_connect_and_verify(qtc-db068p, qtc-db068p) failed: 24
04:17:42.239 [27232.29796] <16> bptestbpcd main: JSON proxy message = {"allow_large_status": {"timestamp": 1538738262, "
who": "vnet_tss_init", "line_number": 32, "comment": "allow vnet status > 255", "data": true}, "direct_connect": {"times
tamp": 1538738262, "who": "connect_to_service", "line_number": 834, "comment": "connect parameters", "data": {"who": "vn
et_connect_to_vnetd_bpcd", "host": "qtc-db068p", "service": "vnetd", "override_required_interface": null, "extra_tries_o
n_connect": 0, "getsock_disable_to": 0, "overide_connect_timeout": 0, "connect_options": null}}, "proxy_request": {"time
stamp": 1538738262, "who": "vnet_proxy_build_request", "line_number": 3300, "comment": "request to local proxy", "data":
 {"bpcd_info": {"remote_client": "qtc-db068p", "remote_host": "qtc-db068p", "remote_probably_dhcp": false, "proxy_flag":
 32, "proxy_flag_hex": "0x00000020", "cmd_sock": 564}, "i_am_daemon": false, "domain_constraints": {}, "service": "vnetd
", "auth_only": false, "pid": 27232, "ssa": false, "local_user": "p-fazhar1@PROD", "host": "qtc-db068p", "peer_host": "q
tc-db068p", "isTestConnection": true, "peer_client": "qtc-db068p", "local_client": "qtc-bku001.prod.ds.russell.com", "lo
cal_dhcp_interval": 0, "peer_dhcp_info": null, "local_hostname": "qtc-bku001.prod.ds.russell.com", "secure_peer": false,
 "resilient": false, "nbrntd_peer_addr": null, "nbrntd_sock_addr": null, "hand_back": false, "request_timeout": 14410}},
 "proxy_response": {"timestamp": 1538738262, "who": "vnet_proxy_parse_response", "line_number": 3472, "comment": "respon
se from local proxy", "data": {"status": 0, "local_proxy_info": {}, "domain_constraints_set": {"process_hint": "78130727
-87db-4f53-907c-6b4b501bdb85", "process_hint_reason": "there was no inherited hint, the connected peer was not a master
server, so defaulted to primary master", "process_hint_server_name": "qtc-bku001.prod.ds.russell.com"}, "statusmsgxml":
"<?xml version=\"1.0\" encoding=\"utf-8\"?><StatusMsgDoc><StatusMsg NBUStatus=\"0\" Severity=\"0\"></StatusMsg></StatusM
sgDoc>"}}, "status": {"timestamp": 1538738262, "who": "connect_to_service", "line_number": 981, "comment": "vnet status"
, "data": 0}}
<16>bptestbpcd main: Function ConnectToBPCD(qtc-db068p) failed: 24
04:17:42.239 [27232.29796] <16> bptestbpcd main: Function ConnectToBPCD(qtc-db068p) failed: 24
<16>bptestbpcd main: socket write failed
04:17:42.255 [27232.29796] <16> bptestbpcd main: socket write failed
<2>bptestbpcd: socket write failed
04:17:42.255 [27232.29796] <2> bptestbpcd: socket write failed
<2>bptestbpcd: EXIT status = 24
04:17:42.271 [27232.29796] <2> bptestbpcd: EXIT status = 24
socket write failed

C:\temp>bptestbpcd -host qtc-db068p -debug
04:17:42.302 [29656.31356] <2> bptestbpcd: VERBOSE = 0
04:17:42.318 [29656.31356] <8> cache_item_to_file: [vnet_addrinfo.c:6857] rename() failed 13 0xd
04:17:42.318 [29656.31356] <8> vnet_cached_getaddrinfo_and_update: [vnet_addrinfo.c:1858] cache_item_to_file() failed 0
0x0
04:17:42.318 [29656.31356] <2> vnet_pbxConnect_ex: pbxConnectExEx Succeeded
04:17:42.333 [29656.31356] <2> logconnections: BPCD CONNECT FROM 10.44.72.40.57588 TO 10.44.71.45.1556 fd = 604
04:17:42.333 [29656.31356] <2> vnet_connect_to_vnetd_bpcd: js_bpcd_info: 0000000002C5AF40
04:17:42.333 [29656.31356] <2> vnet_pbxConnect_ex: pbxConnectExEx Succeeded
04:17:42.380 [29656.31356] <8> do_pbx_service: [vnet_connect.c:2581] via PBX VNETD CONNECT FROM 10.44.72.40.57590 TO 10.
44.71.45.1556 fd = 608
04:17:42.380 [29656.31356] <8> vnet_vnetd_connect_forward_socket_begin: [vnet_vnetd.c:458] VN_REQUEST_CONNECT_FORWARD_SO
CKET 10 0xa
04:17:42.380 [29656.31356] <8> vnet_vnetd_connect_forward_socket_begin: [vnet_vnetd.c:483] ipc_string 52702
04:17:42.458 [29656.31356] <2> bpcr_get_version_rqst: bpcd version: 07730000
1 1 1
10.44.72.40:57588 -> 10.44.71.45:1556
10.44.72.40:57590 -> 10.44.71.45:1556
<2>bptestbpcd: EXIT status = 0
04:17:42.474 [29656.31356] <2> bptestbpcd: EXIT status = 0

C:\temp>bptestbpcd -host qtc-db068p -debug
04:17:42.505 [25828.31492] <2> bptestbpcd: VERBOSE = 0
04:17:42.521 [25828.31492] <8> cache_item_to_file: [vnet_addrinfo.c:6857] rename() failed 13 0xd
04:17:42.521 [25828.31492] <8> vnet_cached_getaddrinfo_and_update: [vnet_addrinfo.c:1858] cache_item_to_file() failed 0
0x0
04:17:42.521 [25828.31492] <2> vnet_pbxConnect_ex: pbxConnectExEx Succeeded
04:17:42.536 [25828.31492] <2> logconnections: BPCD CONNECT FROM 10.44.72.40.57596 TO 10.44.71.45.1556 fd = 604
04:17:42.536 [25828.31492] <2> vnet_connect_to_vnetd_bpcd: js_bpcd_info: 00000000027CAF40
04:17:42.536 [25828.31492] <2> vnet_pbxConnect_ex: pbxConnectExEx Succeeded
04:17:42.583 [25828.31492] <8> do_pbx_service: [vnet_connect.c:2581] via PBX VNETD CONNECT FROM 10.44.72.40.57598 TO 10.
44.71.45.1556 fd = 616
04:17:42.583 [25828.31492] <8> vnet_vnetd_connect_forward_socket_begin: [vnet_vnetd.c:458] VN_REQUEST_CONNECT_FORWARD_SO
CKET 10 0xa
04:17:42.583 [25828.31492] <8> vnet_vnetd_connect_forward_socket_begin: [vnet_vnetd.c:483] ipc_string 52704
04:17:42.646 [25828.31492] <2> bpcr_get_version_rqst: bpcd version: 07730000
1 1 1
10.44.72.40:57596 -> 10.44.71.45:1556
10.44.72.40:57598 -> 10.44.71.45:1556
<2>bptestbpcd: EXIT status = 0
04:17:42.661 [25828.31492] <2> bptestbpcd: EXIT status = 0

C:\temp>bptestbpcd -host qtc-db068p -debug
04:17:43.396 [28580.27880] <2> bptestbpcd: VERBOSE = 0
04:17:43.411 [28580.27880] <8> cache_item_to_file: [vnet_addrinfo.c:6857] rename() failed 13 0xd
04:17:43.411 [28580.27880] <8> vnet_cached_getaddrinfo_and_update: [vnet_addrinfo.c:1858] cache_item_to_file() failed 0
0x0
04:17:43.411 [28580.27880] <2> vnet_pbxConnect_ex: pbxConnectExEx Succeeded
04:17:43.427 [28580.27880] <2> logconnections: BPCD CONNECT FROM 10.44.72.40.57637 TO 10.44.71.45.1556 fd = 564
04:17:43.427 [28580.27880] <2> vnet_connect_to_vnetd_bpcd: js_bpcd_info: 000000000270B840
04:17:43.427 [28580.27880] <2> vnet_pbxConnect_ex: pbxConnectExEx Succeeded
04:17:43.474 [28580.27880] <8> do_pbx_service: [vnet_connect.c:2581] via PBX VNETD CONNECT FROM 10.44.72.40.57640 TO 10.
44.71.45.1556 fd = 584
04:17:43.474 [28580.27880] <8> vnet_vnetd_connect_forward_socket_begin: [vnet_vnetd.c:458] VN_REQUEST_CONNECT_FORWARD_SO
CKET 10 0xa
04:17:43.474 [28580.27880] <8> vnet_vnetd_connect_forward_socket_begin: [vnet_vnetd.c:483] ipc_string 52713
04:17:43.536 [28580.27880] <2> bpcr_get_version_rqst: bpcd version: 07730000
1 1 1
10.44.72.40:57637 -> 10.44.71.45:1556
10.44.72.40:57640 -> 10.44.71.45:1556
<2>bptestbpcd: EXIT status = 0
04:17:43.552 [28580.27880] <2> bptestbpcd: EXIT status = 0

support case is also opened and its not escalated to engineering team with windows and n/w expert from veritas side.its been more than week now.

[Marianne]

You may want to add -verbose and also check client's bpcd log.

We see winsock errors in  bptestbpcd output : 10048 and 10054:

04:17:42.083 [27232.29796] <16> vnet_connect_with_opts: connect() failed: 10048

04:17:42.239 [27232.29796] <2> bpcr_put_vnetd_forward_socket: put_string 52701 failed: 10054

http://www.destructor.de/firebird/winsockerrors.htm    

10048

WSAEADDRINUSE

Address already in use

10054

WSAECONNRESET

Connection reset by peer