Menu ▾ ▴

#244 Server stops sending data to clients in -R after 1024 connection attempts

1.0
accepted
Robert McMahon
None
2023-04-05
2023-03-15
Sean Farner
No

iperf version 2.1.n (15 March 2023) pthreads

Scenario:
40 network devices behind a NAT perform
2 second test downlink - iperf -c test_server%wwanX -e -w 1M -t 2 -yC -R
2 second test uplink - iperf -c test_server%wwanX -e -w 1M -t 2 -yC -R
After 1024 attemps both uplink and downlink on the server, the downlink connections stop getting data. We see the following error on the server side:
shutdown failed: Transport endpoint is not connected

When we Ctl-C on the server 1024 entries are shown (Uplink data output)
-0400:20230315151745.144,firewall-ip,3558,server-ip,5001,403,0.0-1048.6,145604,1110,114,114,0,0,0,0,0,0,0

Discussion

  • Sean Farner

    Sean Farner - 2023-03-15

    Additionally the memory used on the server continues to grow until it reaches this point, at which 3.8G have been used.
    For Reference System Specs:
    12 core system with 30GB of ram.

    Also the Server output never shows the uplink output until Ctl-C

    Edit:
    Took a closer look with top and 14.1G Virtual memory in use and 101% of a single core when this state is reached.

     

    Last edit: Sean Farner 2023-03-15

  • Robert McMahon

    Robert McMahon - 2023-03-15
    • status: open --> accepted
    • assigned_to: Robert McMahon
     

  • Sean Farner

    Sean Farner - 2023-03-15

    We also tried breaking it up to 2 servers, one for downlink and one for uplink on another port:

    This partially fixes the problem. We are able to continue receiving uplink and downlink data so far (currently around the 115th iteration out of 500), but we only have seen the first output on the uplink test server.
    I assume that we wil probably see the rest after we hit Ctrl-C

    We are seeing another issue as well, 2 processes with the same iperf -s -w 1M -yC -e -p 5003 command are at 100% CPU usage and a third has appeared that never goes above .7%.
    It stopped increasing in memory at 14.7G.

    Our goal is to be able to do a test with 600 active devices 500 consecutive times with the 2s tcp down, 2s up iperf test.

    I will continue retrying changing one of the arguments at a time -yC, -e and -w to see if any of these make a difference in the reporting of uplink.

     

  • Sean Farner

    Sean Farner - 2023-03-15

    When we remove the -yC and replaced it with --reportstyle C it showed reports of 1 device across 17 uplink transfers, the other 39 devices were held back until Ctl-C

    We then removed the -yC all together, we got the first part of the server message:
    [ 24] local 172.16.2.200 port 5003 connected with 172.16.10.135 port 13177 (icwnd/mss/irtt=12/1288/45059)
    but the
    [ ID] Interval Transfer Bandwidth [157] 0.00-3.26 sec 440 KBytes 1.11 Mbits/sec [158] 0.00-2.75 sec 800 KBytes 2.38 Mbits/sec [159] 0.00-2.41 sec 1.38 MBytes 4.78 Mbits/sec
    part of the message did not appear until the Ctrl+C

    removing -e had no change to behavior

    Removed all args other than -s and -p 5003 (uplink) (both client and server)
    Same behavior as removing the -yC it follows maybe 1 or 2 clients but hangs on reporting the rest until control C.

     

  • Robert McMahon

    Robert McMahon - 2023-03-15

    What operating system is being used here? Thanks.

     

  • Sean Farner

    Sean Farner - 2023-03-15

    Ubuntu 22.04
    kernel 6.2.1-060201-generic

     

  • Sean Farner

    Sean Farner - 2023-03-17

    We was able to recreate this with Alma 8.4 as well 4.18 kernel.

    Some additional information:

    We used a third box with Centos 7 behind a different NAT and were able to recreate the issue.

    Easy way to test, put the client behind a router and spawn 600 connections that repeat every 5 seconds. There will be a lack of reporting and you should see the memory usage of the process grow.

    We may have found a work around for our test by interleaving TCP uplink and UDP uplink tests. If we follow a TCP uplink test with a UDP uplink test, all of the hung connections are cleaned up immediately. We well add more info as we find it.

    Let us know if there is anything we can do to provide more information, like rebuild with a debug mode or something.

    Thanks,

    Sean

     

    • Robert McMahon

      Robert McMahon - 2023-03-22

      Have you used valgrind before? That could help with any memory leaks. You'll need to compile from source with symbols, e.g, make -j CFLAGS=-g CXXFLAGS=-g

       

      • Sean Farner

        Sean Farner - 2023-03-22

        I am familiar with valgrind. I'll take a look as soon as I get a chance.

         

        • Robert McMahon

          Robert McMahon - 2023-03-22

          Thanks, memory leaks are near impossible to find without tools like valgrind.

          Also, there is an option to enable thread debugging. It's another compile time option, i.e. ./configure --enable-thread-debug Output looks something like:

          [root@fedora iperf-2.1.n]# src/iperf -c 192.168.1.15 -i 1 --trip-times --tcp-write-times --histogram=1m -p 6001
THREAD(162460):[13:19:52.965468] Copy thread settings (malloc) from/to=0x17ddeb0/0x17de490 report/sum/fullduplex (nil)/(nil)/(nil)
THREAD(162460):[13:19:52.965820] Copy Settings: MBUF malloc 131584 bytes (0x7f2c53113010)
THREAD(162460):[13:19:52.965942] Thread_run_wrapper(0x17de490 mode=4) thread counts tot/trfc=1/0 (id=1393632832)
THREAD(162461):[13:19:52.966007] Reporter thread started
THREAD(162461):[13:19:52.966255] Alloc common rpt/com/size 0x7f2c4c000bb0/0x7f2c4c000d80/520
THREAD(162462):[13:19:52.966306] Client constructor with thread 0x17ddeb0 sum=(nil) (flags=2003200)
THREAD(162460):[13:19:52.966366] Thread_run_wrapper(0x17ddeb0 mode=2) thread counts tot/trfc=2/1 (id=1385240128)
THREAD(162461):[13:19:52.966433] Reporter await done
THREAD(162462):[13:19:52.966638] Launch: client spawn thread basic (sock=-1)
THREAD(162462):[13:19:52.966658] Set socket IP_TOS to 0x0
THREAD(162462):[13:19:52.971869] Alloc common rpt/com/size 0x7f2c44000e40/0x7f2c44001080/520
THREAD(162462):[13:19:52.971888] Init settings report hdr/rpt/com 0x7f2c44000e20/0x7f2c44000e40/0x7f2c44001080
THREAD(162462):[13:19:52.971896] Jobq *POST* report 0x7f2c44000e20 (settings)
THREAD(162462):[13:19:52.971907] Alloc common rpt/com/size 0x7f2c44001330/0x7f2c44001500/520
THREAD(162462):[13:19:52.971915] Init connection report hdr/rpt/com 0x7f2c44001310/0x7f2c44001330/0x7f2c44001500
THREAD(162462):[13:19:52.971927] Jobq *POST* report 0x7f2c44001310 (connection)
THREAD(162461):[13:19:52.971946] Jobq *WAIT* exit  (nil)/0x7f2c44000e20 cond=0x442d80 threads u/t=2/1
THREAD(162461):[13:19:52.971968] Jobq *ROOT* 0x7f2c44000e20 (last=(nil))
------------------------------------------------------------
Client connecting to 192.168.1.15, TCP port 6001 with pid 162460 (1 flows)
THREAD(162462):[13:19:52.971995] Client start sync enterred
Write buffer size: 131072 Byte (writetimer-enabled)
THREAD(162462):[13:19:52.972023] Alloc common rpt/com/size 0x7f2c440017f0/0x7f2c440020c0/520
TCP congestion control using reno
TOS set to 0x0 (Nagle on)
TCP window size: 85.0 KByte (default)
Event based writes (pending queue watermark at 16384 bytes)
THREAD(162462):[13:19:52.972058] Init 10000 element packet ring=0x7f2c44002350 consumer=0x442d80 producer=0x17de198 total rings=1 enable=1
THREAD(162462):[13:19:52.972073] Init data report hdr/rpt/com=0x7f2c44001790/0x7f2c440017b0/0x7f2c440020c0 multireport/fullduplex=(nil)/(nil) pring(bytes)/cond=0x7f2c44002350(2640056)/0x17de198 (socket=3)
Enabled write histograms bin-width=1.000 ms, bins=100000
------------------------------------------------------------
THREAD(162461):[13:19:52.972098] Jobq *FREE* report hdr/rpt 0x7f2c44000e20/0x7f2c44000e40 (settings)
THREAD(162461):[13:19:52.972112] Free common=0x7f2c44001080
THREAD(162461):[13:19:52.972125] Jobq *REMOVE* 0x7f2c44000e20
THREAD(162461):[13:19:52.972136] Jobq *ROOT* 0x7f2c44001310 (last=(nil))
THREAD(162462):[13:19:52.972148] histo create 0x7f2c44002410
[  1] local 192.168.1.234%eth1 port 33720 connected with 192.168.1.15 port 6001 (prefetch=16384) (trip-times) (sock=3) (icwnd/mss/irtt=14/1448/4962) (ct=5.04 ms) on 2023-03-22 13:19:52.966 (PDT)
THREAD(162461):[13:19:52.972191] Jobq *FREE* report hdr/rpt 0x7f2c44001310/0x7f2c44001330 (connection)
THREAD(162461):[13:19:52.972202] Free common=0x7f2c44001500
THREAD(162461):[13:19:52.972212] Jobq *REMOVE* 0x7f2c44001310
THREAD(162462):[13:19:52.972423] Client header init size 244 (0x7f2c53134010)
THREAD(162462):[13:19:52.972453] Client(3) report start/ipg=1679516392.972452 next=1679516393.972452
THREAD(162462):[13:19:52.972464] Client start sync exited
THREAD(162462):[13:19:52.972477] Jobq *POST* report 0x7f2c44001790 (data)
THREAD(162461):[13:19:52.972491] Jobq *WAIT* exit  (nil)/0x7f2c44001790 cond=0x442d80 threads u/t=2/1
THREAD(162461):[13:19:52.972508] Jobq *ROOT* 0x7f2c44001790 (last=(nil))
[ ID] Interval        Transfer    Bandwidth       Write/Err  Rtry     Cwnd/RTT        NetPwr  write-times avg/min/max/stdev (cnt)
[  1] 0.00-1.00 sec  54.6 MBytes   458 Mbits/sec  437/0          0    5603K/49254 us  1163  2.278/0.196/15.225/1.820 ms (437)
THREAD(162461):[13:19:53.989035] histo create 0x7f2c4c001070
[  1] 0.00-1.00 sec W8-PDF: bin(w=1ms):cnt(437)=1:159,2:59,3:85,4:55,5:43,6:23,7:8,8:3,10:1,16:1 (5.00/95.00/99.7%=1/6/10,Outliers=0,obl/obu=0/0)
[  1] 1.00-2.00 sec  53.4 MBytes   448 Mbits/sec  427/0          0    5603K/46830 us  1195  2.333/0.422/9.019/1.659 ms (427)
[  1] 1.00-2.00 sec W8-PDF: bin(w=1ms):cnt(427)=1:147,2:56,3:81,4:68,5:45,6:19,7:8,8:1,9:1,10:1 (5.00/95.00/99.7%=1/6/9,Outliers=0,obl/obu=0/0)
[  1] 2.00-3.00 sec  53.6 MBytes   450 Mbits/sec  429/0          0    5603K/48815 us  1152  2.325/0.468/8.162/1.632 ms (429)
[  1] 2.00-3.00 sec W8-PDF: bin(w=1ms):cnt(429)=1:141,2:74,3:74,4:54,5:57,6:21,7:6,8:1,9:1 (5.00/95.00/99.7%=1/6/8,Outliers=0,obl/obu=0/0)
^CTHREAD(162462):[13:19:56.417429] Client calls shutdown() SHUTW_WR on tcp socket 3
THREAD(162462):[13:19:56.476789] Client detected server close 3
THREAD(162462):[13:19:56.476897] Reporting last packet for 0x7f2c440017b0  qdepth=0 sock=3
THREAD(162462):[13:19:56.476932] Traffic thread awaiting reporter to be done with 0x7f2c440017b0 and cond 0x17de198
[  1] 3.00-3.50 sec  23.9 MBytes   397 Mbits/sec  191/0          0    5603K/49132 us  1010  2.321/0.487/6.936/1.568 ms (191)
[  1] 3.00-3.50 sec W8(f)-PDF: bin(w=1ms):cnt(1484)=1:505,2:221,3:281,4:203,5:168,6:72,7:24,8:5,9:2,10:2,16:1 (5.00/95.00/99.7%=1/6/9,Outliers=0,obl/obu=0/0)
[  1] 0.00-3.50 sec   186 MBytes   444 Mbits/sec  1484/0          0    5603K/49132 us  1130  2.313/0.196/15.225/1.688 ms (1484)
[  1] 0.00-3.50 sec W8(f)-PDF: bin(w=1ms):cnt(1484)=1:505,2:221,3:281,4:203,5:168,6:72,7:24,8:5,9:2,10:2,16:1 (5.00/95.00/99.7%=1/6/9,Outliers=0,obl/obu=0/0)
THREAD(162461):[13:19:56.493668] Jobq *REMOVE* 0x7f2c44001790
THREAD(162462):[13:19:56.493735] client close sock=3
THREAD(162462):[13:19:56.493836] Jobq *FREE* report hdr/rpt 0x7f2c44001790/0x7f2c440017b0 (data)
THREAD(162462):[13:19:56.493873] Free report hdr=0x7f2c440017b0 reporter thread suspend count=218 packetring=0x7f2c44002350 histo=(nil) frame histo=(nil)
THREAD(162462):[13:19:56.493909] Free packet ring=0x7f2c44002350 producer=0x17de198 (consumer=0x442d80) awaits = 0 total rings = 0
THREAD(162462):[13:19:56.494029] Free common=0x7f2c440020c0
THREAD(162462):[13:19:56.494063] Client destructor sock=3 report=(nil) server-reverse=false fullduplex=false
THREAD(162462):[13:19:56.494112] Free thread settings=0x17ddeb0
THREAD(162462):[13:19:56.494211] Signal sent to reporter thread
THREAD(162461):[13:19:56.494239] Jobq *WAIT* exit  (nil)/(nil) cond=0x442d80 threads u/t=1/0
THREAD(162461):[13:19:56.494320] Free common=0x7f2c4c000d80
THREAD(162461):[13:19:56.494362] Reporter thread finished user/traffic 1/0
THREAD(162461):[13:19:56.494415] Free thread settings=0x17de490
           

  • Robert McMahon

    Robert McMahon - 2023-03-17

    Thanks for all of this. I haven't had a chance to investigate yet. Hopefully soon.

     

  • Sean Farner

    Sean Farner - 2023-04-05

    Sorry for the delay, we ended up altering our test procedure to work around the issue as much as we could.(We started 64 servers to spread the load) I can also provide a little more insight on what is happening after digging in to the network side a little more. During our network exercise, we encountered this problem primarily on UDP downlink testing (-R)

    When we had 400-600 connections behind a NAT, whether it be a router or the EPC of a cellular network, there appears to be a problem with getting the socket FIN packet through that tells iperf the client is closing the socket. (Verified in tcpdump/wireshark). Since the client never sees the acknowledgement the socket is stuck in FIN_WAIT_1 state waiting for the ack from the server.

    I was browsing the iperf2 source a little and noticed that it calls recv without any sort of select or timeout. The only escape from the recv while loop is a socket error when the socket is closed. Since we never get the FIN Packet through the NAT, the socket never knows to shut down, and the connection remains up.

    We have two suggestions for ways to possibly solve this.

    1. Add a -t flag for server side execution which would limit the time the socket stays open for the duration or duration+10% (I've seen a lot of iperf tests for 600 seconds run 605-610). Then at the end of time it would close the socket and report the results.

    2. Add an optional flag for an adjustable timeout for the socket. If we go 15,30,60 seconds without receiving anything shutdown the socket, report and move on.

    I realize this is probably not a use case many will encounter, but if I can get some time I will look at creating a new function
    recvn_timed( int inSock, char *outBuf, int inLen, int flags, int timeout)

    in socket_io.c. and see if this potentially solves the problem we see.

    Thanks for the support.

    Sean

     

    Last edit: Sean Farner 2023-04-05

Log in to post a comment.

auth0 logo