Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Negative values in loss report with UDP #914

Closed
danielaCasasv opened this issue Sep 29, 2019 · 5 comments
Closed

Negative values in loss report with UDP #914

danielaCasasv opened this issue Sep 29, 2019 · 5 comments
Labels
bug

Comments

@danielaCasasv
Copy link

danielaCasasv commented Sep 29, 2019 •
edited

# Context

  • Version of iperf3: 3.7+
  • Hardware: Intel
  • Operating system: Ubuntu14.04.6 server running on VM (virtualBox 5.2.28)

# Bug Report
Got a report with negative values in the lost_packets and losr_percent counters at server side logfile.

  • Expected Behavior:
    { "streams": [{ "socket": 6, "start": 19.000102, "end": 20.000105, "seconds": 1.0000029802322388, "bytes": 166520, "bits_per_second": 1332156.0298656528, "jitter_ms": 2.8512847190910904, "lost_packets": 0, "packets": 115, "lost_percent": 0, "omitted": false, "sender": false }], "sum": { "start": 19.000102, "end": 20.000105, "seconds": 1.0000029802322388, "bytes": 166520, "bits_per_second": 1332156.0298656528, "jitter_ms": 2.8512847190910904, "lost_packets": 0, "packets": 115, "lost_percent": 0, "omitted": false, "sender": false }
    The above stream report just appeared as expected in the same logfile than the next stream report (the one with negative values)

  • Actual Behavior
    { "streams": [{ "socket": 6, "start": 21.000194, "end": 22.000068, "seconds": 0.99987399578094482, "bytes": 372136, "bits_per_second": 2977463.1729218694, "jitter_ms": 2110.7105786449633, "lost_packets": -111, "packets": 146, "lost_percent": -76.027397260273972, "omitted": false, "sender": false }], "sum": { "start": 21.000194, "end": 22.000068, "seconds": 0.99987399578094482, "bytes": 372136, "bits_per_second": 2977463.1729218694, "jitter_ms": 2110.7105786449633, "lost_packets": -111, "packets": 146, "lost_percent": -76.027397260273972, "omitted": false, "sender": false }

  • Steps to Reproduce
    command server side: iperf3 -s -p 11002 -1 -J --logfile serverOut_11_to_2.json
    command client side: iperf3 -c 10.0.0.2 -p 11002 -u -b 1675.289k -t 40 -J --logfile clientOut_11_to_2.json

I have reproduced several of such a test between different hosts and it just happens randomly so it is hard to reproduce.

I am employing Mininet 2.2.1 in the VM to deploy a network with 23 nodes and 36 links.
I am generating specfic amounts of traffic from hosts in my network regardind a traffic matrix (that is whay I set a value -b in the client side). I just realized about this issue when analyzing all the logfiles. What could I be doing wrong? I will appreaciate your help. Thanks!
@danielaCasasv danielaCasasv changed the title Negative values un Negative values in loss report with UDP Sep 29, 2019
@bmah888
Copy link
Contributor

bmah888 commented Oct 18, 2019

I agree those values shouldn't be negative! At the moment I don't have any insight into how they got that way...it doesn't look like you are doing anything particularly unusual that might cause this problem.

@bmah888 bmah888 added the bug label Oct 18, 2019
@dmozzoni
Copy link

Hi,

I'm also seeing similar behavior where negative lost packets are being reported. Like the original poster, it happens only sporadically. I've seen it present in two different ways.

Setup:

  • We are using a slightly modified iperf3 version (based on v3.5) so that the interval results are thrown into a Mongo database too (you'll see below a couple extra command flags to support that), but none of the actual traffic code was touched. Our test has 32 simultaneous iperf3 client/server pairs running udp traffic between 2 Linux devices (one Ubuntu 18.04 and one yocto). I've only seen one pair affected at a time, although the person that reported it to me said he's seen multiple pairs affected.

Case 1:

  • This is the most common case. The first interval shows huge jitter, packet, and lost packet values, but normal throughput. Then all subsequent intervals will have zero packet and negative lost packet values (throughput and jitter seem normal). Curiously, transposing the absolute value of the lostPacket/packet values would provide the expected result.

  • High initial jitter is brought up in Issue Jitter starts at unreasonably high values (e.g. 1e5) #842, where NTP sync is mentioned. We do have our two devices NTP synced and the other 31 pairs (on the same two devices) that are concurrently running don't exhibit the same issue.

  • There is a line in iperf_api.c (line 2745 in the latest master) that corresponds to the calculation of lost packets (cnt_error) in an interval: temp.interval_cnt_error = sp->cnt_error - irp->cnt_error; I'm not much of a C programmer, so I quickly got lost, but I guess if for some reason the cnt_error for the stream was 0 and the value in the iperf_interval_results wasn't, then a negative value could occur. Maybe it's just a coincidence, but it seems weird that the lost packet values (e.g. -170) are the negative of the values I would expect for packets ( e.g. 170).

  • iperf3 client (commandline and output):

iperf3 --octoerror --bind=192.168.222.202 --bitrate=2m --client=192.168.222.4 --connect-timeout=500 --dscp=0 --forceflush --interval=1 --mongo --parallel=1 --port=24731 --reverse --set-mss=8000 --time=32 --udp --window=2M


46:24.1: time: Thu, 31 Oct 2019 17:46:23 GMT  timesecs: 1572543983  Client mode: connecting_to  host: 192.168.222.4  port : 24731
46:24.1: Connecting to host 192.168.222.4, port 24731
46:24.1: Reverse mode, remote host 192.168.222.4 is sending
46:24.9: [  8] local 192.168.222.202 port 34524 connected to 192.168.222.4 port 24731
46:24.9: protocol: UDP  num_streams: 1  blksize: 1448  omit: 0  duration: 32  bytes: 0  blocks: 0  reverse: 1
46:24.9: [ ID] Interval           Transfer     Bitrate         Jitter    Lost/Total Datagrams
46:24.9: [  8]   0.00-1.00   sec   246 KBytes  2.02 Mbits/sec  2567541.936 ms  393365/393539 (1e+02%) 
46:26.0: [  8]   1.00-2.00   sec   240 KBytes  1.97 Mbits/sec  49.376 ms  -170/0 (0%) 
46:26.4: [  8]   2.00-3.00   sec   247 KBytes  2.03 Mbits/sec  4.897 ms  -175/0 (0%) 
46:27.4: [  8]   3.00-4.00   sec   245 KBytes  2.00 Mbits/sec  4.799 ms  -173/0 (0%) 
46:28.4: [  8]   4.00-5.00   sec   243 KBytes  1.99 Mbits/sec  5.500 ms  -172/0 (0%) 
46:29.4: [  8]   5.00-6.00   sec   246 KBytes  2.02 Mbits/sec  4.971 ms  -174/0 (0%) 
46:30.4: [  8]   6.00-7.00   sec   242 KBytes  1.98 Mbits/sec  5.427 ms  -171/0 (0%) 
46:31.4: [  8]   7.00-8.00   sec   246 KBytes  2.02 Mbits/sec  5.356 ms  -174/0 (0%) 
46:32.4: [  8]   8.00-9.00   sec   243 KBytes  1.99 Mbits/sec  5.389 ms  -172/0 (0%) 
46:33.4: [  8]   9.00-10.00  sec   246 KBytes  2.02 Mbits/sec  5.580 ms  -174/0 (0%) 
46:34.4: [  8]  10.00-11.00  sec   243 KBytes  1.99 Mbits/sec  5.046 ms  -172/0 (0%) 
46:35.4: [  8]  11.00-12.00  sec   243 KBytes  1.99 Mbits/sec  5.526 ms  -172/0 (0%) 
46:36.4: [  8]  12.00-13.00  sec   243 KBytes  1.99 Mbits/sec  4.986 ms  -172/0 (0%) 
46:37.4: [  8]  13.00-14.00  sec   246 KBytes  2.02 Mbits/sec  4.939 ms  -174/0 (0%) 
46:38.4: [  8]  14.00-15.00  sec   245 KBytes  2.00 Mbits/sec  6.100 ms  -173/0 (0%) 
46:39.4: [  8]  15.00-16.00  sec   243 KBytes  1.99 Mbits/sec  5.215 ms  -172/0 (0%) 
46:40.4: [  8]  16.00-17.00  sec   245 KBytes  2.00 Mbits/sec  5.513 ms  -173/0 (0%) 
46:41.4: [  8]  17.00-18.00  sec   243 KBytes  1.99 Mbits/sec  5.874 ms  -172/0 (0%) 
46:42.4: [  8]  18.00-19.00  sec   242 KBytes  1.98 Mbits/sec  5.172 ms  -171/0 (0%) 
46:43.4: [  8]  19.00-20.00  sec   247 KBytes  2.03 Mbits/sec  5.680 ms  -175/0 (0%) 
46:44.4: [  8]  20.00-21.00  sec   242 KBytes  1.98 Mbits/sec  5.185 ms  -171/0 (0%) 
46:45.4: [  8]  21.00-22.00  sec   245 KBytes  2.00 Mbits/sec  4.800 ms  -173/0 (0%) 
46:46.4: [  8]  22.00-23.00  sec   245 KBytes  2.00 Mbits/sec  4.909 ms  -173/0 (0%) 
46:47.4: [  8]  23.00-24.00  sec   245 KBytes  2.00 Mbits/sec  4.643 ms  -173/0 (0%) 
46:48.4: [  8]  24.00-25.00  sec   245 KBytes  2.00 Mbits/sec  5.953 ms  -173/0 (0%) 
46:49.4: [  8]  25.00-26.00  sec   243 KBytes  1.99 Mbits/sec  5.300 ms  -172/0 (0%) 
46:50.4: [  8]  26.00-27.00  sec   246 KBytes  2.02 Mbits/sec  5.048 ms  -174/0 (0%) 
46:51.4: [  8]  27.00-28.00  sec   245 KBytes  2.00 Mbits/sec  5.019 ms  -173/0 (0%) 
46:52.4: [  8]  28.00-29.00  sec   243 KBytes  1.99 Mbits/sec  5.198 ms  -172/0 (0%) 
46:53.4: [  8]  29.00-30.00  sec   243 KBytes  1.99 Mbits/sec  5.016 ms  -172/0 (0%) 
46:54.4: [  8]  30.00-31.00  sec   243 KBytes  1.99 Mbits/sec  5.106 ms  -172/0 (0%) 
46:55.7: [  8]  31.00-32.00  sec   245 KBytes  2.00 Mbits/sec  3.244 ms  -173/0 (0%) 
46:55.7: - - - - - - - - - - - - - - - - - - - - - - - - -
46:55.7: [ ID] Interval           Transfer     Bitrate         Jitter    Lost/Total Datagrams
46:55.7: [  8]   0.00-32.02  sec  7.64 MBytes  2.00 Mbits/sec  0.000 ms  0/5529 (0%)  sender
46:55.7: [SUM]  0.0-32.0 sec  5525 datagrams received out-of-order
46:55.7: [  8]   0.00-32.00  sec  7.63 MBytes  2.00 Mbits/sec  3.244 ms  388013/393539 (99%)  receiver
  • iperf3 server (commandline and output):
iperf3 --octoerror --bind=192.168.222.4 --forceflush --interval=1 --port=24731 --server


46:15.4: -----------------------------------------------------------
46:15.4: Server listening on 24731
46:15.4: -----------------------------------------------------------
46:23.3: time: Thu, 31 Oct 2019 17:46:23 GMT  timesecs: 1572543983  Server mode: accepted_connection  host: 192.168.222.202  port: 33344
46:23.3: Accepted connection from 192.168.222.202, port 33344
46:24.3: [  7] local 192.168.222.4 port 24731 connected to 192.168.222.202 port 34524
46:24.3: protocol: UDP  num_streams: 1  blksize: 1448  omit: 0  duration: 32  bytes: 0  blocks: 0  reverse: 1
46:24.3: [ ID] Interval           Transfer     Bitrate         Total Datagrams
46:24.3: [  7]   0.00-1.00   sec   245 KBytes  2.00 Mbits/sec  173 
46:25.3: [  7]   1.00-2.00   sec   245 KBytes  2.00 Mbits/sec  173 
46:26.3: [  7]   2.00-3.00   sec   243 KBytes  1.99 Mbits/sec  172 
46:27.3: [  7]   3.00-4.00   sec   245 KBytes  2.00 Mbits/sec  173 
46:28.3: [  7]   4.00-5.00   sec   245 KBytes  2.00 Mbits/sec  173 
46:29.3: [  7]   5.00-6.00   sec   243 KBytes  1.99 Mbits/sec  172 
46:30.3: [  7]   6.00-7.00   sec   245 KBytes  2.00 Mbits/sec  173 
46:31.3: [  7]   7.00-8.00   sec   245 KBytes  2.00 Mbits/sec  173 
46:32.3: [  7]   8.00-9.00   sec   243 KBytes  1.99 Mbits/sec  172 
46:33.3: [  7]   9.00-10.00  sec   245 KBytes  2.00 Mbits/sec  173 
46:34.3: [  7]  10.00-11.00  sec   245 KBytes  2.00 Mbits/sec  173 
46:35.3: [  7]  11.00-12.00  sec   243 KBytes  1.99 Mbits/sec  172 
46:36.3: [  7]  12.00-13.00  sec   245 KBytes  2.00 Mbits/sec  173 
46:37.3: [  7]  13.00-14.00  sec   243 KBytes  1.99 Mbits/sec  172 
46:38.3: [  7]  14.00-15.00  sec   245 KBytes  2.00 Mbits/sec  173 
46:39.3: [  7]  15.00-16.00  sec   245 KBytes  2.00 Mbits/sec  173 
46:40.3: [  7]  16.00-17.00  sec   243 KBytes  1.99 Mbits/sec  172 
46:41.3: [  7]  17.00-18.00  sec   245 KBytes  2.00 Mbits/sec  173 
46:42.3: [  7]  18.00-19.00  sec   245 KBytes  2.00 Mbits/sec  173 
46:43.3: [  7]  19.00-20.00  sec   243 KBytes  1.99 Mbits/sec  172 
46:44.3: [  7]  20.00-21.00  sec   245 KBytes  2.00 Mbits/sec  173 
46:45.3: [  7]  21.00-22.00  sec   245 KBytes  2.00 Mbits/sec  173 
46:46.3: [  7]  22.00-23.00  sec   243 KBytes  1.99 Mbits/sec  172 
46:47.3: [  7]  23.00-24.00  sec   245 KBytes  2.00 Mbits/sec  173 
46:48.3: [  7]  24.00-25.00  sec   245 KBytes  2.00 Mbits/sec  173 
46:49.3: [  7]  25.00-26.00  sec   243 KBytes  1.99 Mbits/sec  172 
46:50.3: [  7]  26.00-27.00  sec   245 KBytes  2.00 Mbits/sec  173 
46:51.3: [  7]  27.00-28.00  sec   245 KBytes  2.00 Mbits/sec  173 
46:52.3: [  7]  28.00-29.00  sec   243 KBytes  1.99 Mbits/sec  172 
46:53.3: [  7]  29.00-30.00  sec   245 KBytes  2.00 Mbits/sec  173 
46:54.3: [  7]  30.00-31.00  sec   245 KBytes  2.00 Mbits/sec  173 
46:55.3: [  7]  31.00-32.00  sec   243 KBytes  1.99 Mbits/sec  172 
46:55.4: [  7]  32.00-32.02  sec  5.66 KBytes  2.38 Mbits/sec  4 
46:55.4: - - - - - - - - - - - - - - - - - - - - - - - - -
46:55.4: [ ID] Interval           Transfer     Bitrate         Jitter    Lost/Total Datagrams
46:55.4: [  7]   0.00-32.02  sec  7.64 MBytes  2.00 Mbits/sec  0.000 ms  0/5529 (0%)  sender

Case 2:

  • I've only seen this once so far. The test seems to run normally, but the last interval has a negative lost packet value (otherwise everything else seems ok (i.e. no zero packets or spiked values)).

  • iperf3 client (commandline and output):

iperf3 --octoerror --bind=192.168.222.202 --bitrate=2m --client=192.168.222.4 --connect-timeout=500 --dscp=0 --forceflush --interval=1 --mongo --parallel=1 --port=14069 --reverse --set-mss=8000 --time=32 --udp --window=2M

41:23.9: time: Thu, 31 Oct 2019 15:41:23 GMT  timesecs: 1572536483  Client mode: connecting_to  host: 192.168.222.4  port : 14069
41:23.9: Connecting to host 192.168.222.4, port 14069
41:23.9: Reverse mode, remote host 192.168.222.4 is sending
41:24.9: [  8] local 192.168.222.202 port 49732 connected to 192.168.222.4 port 14069
41:24.9: protocol: UDP  num_streams: 1  blksize: 1448  omit: 0  duration: 32  bytes: 0  blocks: 0  reverse: 1
41:24.9: [ ID] Interval           Transfer     Bitrate         Jitter    Lost/Total Datagrams
41:24.9: [  8]   0.00-1.00   sec   245 KBytes  2.00 Mbits/sec  5.052 ms  0/173 (0%) 
41:25.7: [  8]   1.00-2.00   sec   243 KBytes  1.99 Mbits/sec  4.923 ms  0/172 (0%) 
41:26.8: [  8]   2.00-3.00   sec   245 KBytes  2.00 Mbits/sec  5.997 ms  0/173 (0%) 
41:27.4: [  8]   3.00-4.00   sec   243 KBytes  1.99 Mbits/sec  6.019 ms  0/172 (0%) 
41:28.4: [  8]   4.00-5.00   sec   245 KBytes  2.00 Mbits/sec  4.799 ms  0/173 (0%) 
41:29.4: [  8]   5.00-6.00   sec   245 KBytes  2.00 Mbits/sec  6.097 ms  0/173 (0%) 
41:30.4: [  8]   6.00-7.00   sec   245 KBytes  2.00 Mbits/sec  5.287 ms  0/173 (0%) 
41:31.4: [  8]   7.00-8.00   sec   245 KBytes  2.00 Mbits/sec  5.652 ms  0/173 (0%) 
41:32.4: [  8]   8.00-9.00   sec   243 KBytes  1.99 Mbits/sec  4.803 ms  0/172 (0%) 
41:33.4: [  8]   9.00-10.00  sec   246 KBytes  2.02 Mbits/sec  5.248 ms  0/174 (0%) 
41:34.4: [  8]  10.00-11.00  sec   243 KBytes  1.99 Mbits/sec  5.175 ms  0/172 (0%) 
41:35.4: [  8]  11.00-12.00  sec   245 KBytes  2.00 Mbits/sec  4.627 ms  0/173 (0%) 
41:36.4: [  8]  12.00-13.00  sec   242 KBytes  1.98 Mbits/sec  5.089 ms  0/171 (0%) 
41:37.4: [  8]  13.00-14.00  sec   247 KBytes  2.03 Mbits/sec  5.438 ms  0/175 (0%) 
41:38.4: [  8]  14.00-15.00  sec   240 KBytes  1.97 Mbits/sec  5.313 ms  0/170 (0%) 
41:39.4: [  8]  15.00-16.00  sec   246 KBytes  2.02 Mbits/sec  5.015 ms  0/174 (0%) 
41:40.4: [  8]  16.00-17.00  sec   243 KBytes  1.99 Mbits/sec  5.195 ms  0/172 (0%) 
41:41.4: [  8]  17.00-18.00  sec   246 KBytes  2.02 Mbits/sec  5.085 ms  0/174 (0%) 
41:42.4: [  8]  18.00-19.00  sec   243 KBytes  1.99 Mbits/sec  7.104 ms  0/172 (0%) 
41:43.4: [  8]  19.00-20.00  sec   245 KBytes  2.00 Mbits/sec  5.546 ms  0/173 (0%) 
41:44.4: [  8]  20.00-21.00  sec   243 KBytes  1.99 Mbits/sec  5.211 ms  0/172 (0%) 
41:45.4: [  8]  21.00-22.00  sec   245 KBytes  2.00 Mbits/sec  4.971 ms  0/173 (0%) 
41:46.4: [  8]  22.00-23.00  sec   245 KBytes  2.00 Mbits/sec  4.990 ms  0/173 (0%) 
41:47.4: [  8]  23.00-24.00  sec   240 KBytes  1.97 Mbits/sec  5.803 ms  0/170 (0%) 
41:48.4: [  8]  24.00-25.00  sec   246 KBytes  2.02 Mbits/sec  6.120 ms  0/174 (0%) 
41:49.4: [  8]  25.00-26.00  sec   246 KBytes  2.02 Mbits/sec  5.042 ms  0/174 (0%) 
41:50.4: [  8]  26.00-27.00  sec   243 KBytes  1.99 Mbits/sec  5.061 ms  0/172 (0%) 
41:51.4: [  8]  27.00-28.00  sec   243 KBytes  1.99 Mbits/sec  5.063 ms  0/172 (0%) 
41:52.4: [  8]  28.00-29.00  sec   246 KBytes  2.02 Mbits/sec  4.918 ms  0/174 (0%) 
41:53.4: [  8]  29.00-30.00  sec   243 KBytes  1.99 Mbits/sec  5.847 ms  0/172 (0%) 
41:54.4: [  8]  30.00-31.00  sec   242 KBytes  1.98 Mbits/sec  4.966 ms  2/173 (1.2%) 
41:55.4: [  8]  31.00-32.00  sec   247 KBytes  2.03 Mbits/sec  5.648 ms  -2/173 (-1.2%) 
41:55.4: - - - - - - - - - - - - - - - - - - - - - - - - -
41:55.4: [ ID] Interval           Transfer     Bitrate         Jitter    Lost/Total Datagrams
41:55.4: [  8]   0.00-32.01  sec  7.63 MBytes  2.00 Mbits/sec  0.000 ms  0/5527 (0%)  sender
41:55.4: [SUM]  0.0-32.0 sec  13 datagrams received out-of-order
41:55.4: [  8]   0.00-32.00  sec  7.63 MBytes  2.00 Mbits/sec  5.648 ms  0/5526 (0%)  receiver
  • iperf3 server (commandline and output):
iperf3 --octoerror --bind=192.168.222.4 --forceflush --interval=1 --port=14069 --server

41:23.4: time: Thu, 31 Oct 2019 15:41:23 GMT  timesecs: 1572536483  Server mode: accepted_connection  host: 192.168.222.202  port: 40600
41:23.4: Accepted connection from 192.168.222.202, port 40600
41:24.4: [  7] local 192.168.222.4 port 14069 connected to 192.168.222.202 port 49732
41:24.4: protocol: UDP  num_streams: 1  blksize: 1448  omit: 0  duration: 32  bytes: 0  blocks: 0  reverse: 1
41:24.4: [ ID] Interval           Transfer     Bitrate         Total Datagrams
41:24.4: [  7]   0.00-1.00   sec   245 KBytes  2.00 Mbits/sec  173 
41:25.4: [  7]   1.00-2.00   sec   245 KBytes  2.00 Mbits/sec  173 
41:26.4: [  7]   2.00-3.00   sec   243 KBytes  1.99 Mbits/sec  172 
41:27.4: [  7]   3.00-4.00   sec   245 KBytes  2.00 Mbits/sec  173 
41:28.4: [  7]   4.00-5.00   sec   245 KBytes  2.00 Mbits/sec  173 
41:29.4: [  7]   5.00-6.00   sec   243 KBytes  1.99 Mbits/sec  172 
41:30.4: [  7]   6.00-7.00   sec   245 KBytes  2.00 Mbits/sec  173 
41:31.4: [  7]   7.00-8.00   sec   245 KBytes  2.00 Mbits/sec  173 
41:32.4: [  7]   8.00-9.00   sec   243 KBytes  1.99 Mbits/sec  172 
41:33.4: [  7]   9.00-10.00  sec   245 KBytes  2.00 Mbits/sec  173 
41:34.4: [  7]  10.00-11.00  sec   245 KBytes  2.00 Mbits/sec  173 
41:35.4: [  7]  11.00-12.00  sec   243 KBytes  1.99 Mbits/sec  172 
41:36.4: [  7]  12.00-13.00  sec   245 KBytes  2.00 Mbits/sec  173 
41:37.4: [  7]  13.00-14.00  sec   243 KBytes  1.99 Mbits/sec  172 
41:38.4: [  7]  14.00-15.00  sec   245 KBytes  2.00 Mbits/sec  173 
41:39.4: [  7]  15.00-16.00  sec   245 KBytes  2.00 Mbits/sec  173 
41:40.4: [  7]  16.00-17.00  sec   243 KBytes  1.99 Mbits/sec  172 
41:41.4: [  7]  17.00-18.00  sec   245 KBytes  2.00 Mbits/sec  173 
41:42.4: [  7]  18.00-19.00  sec   245 KBytes  2.00 Mbits/sec  173 
41:43.4: [  7]  19.00-20.00  sec   243 KBytes  1.99 Mbits/sec  172 
41:44.4: [  7]  20.00-21.00  sec   245 KBytes  2.00 Mbits/sec  173 
41:45.4: [  7]  21.00-22.00  sec   245 KBytes  2.00 Mbits/sec  173 
41:46.4: [  7]  22.00-23.00  sec   243 KBytes  1.99 Mbits/sec  172 
41:47.4: [  7]  23.00-24.00  sec   245 KBytes  2.00 Mbits/sec  173 
41:48.4: [  7]  24.00-25.00  sec   245 KBytes  2.00 Mbits/sec  173 
41:49.4: [  7]  25.00-26.00  sec   243 KBytes  1.99 Mbits/sec  172 
41:50.4: [  7]  26.00-27.00  sec   245 KBytes  2.00 Mbits/sec  173 
41:51.4: [  7]  27.00-28.00  sec   245 KBytes  2.00 Mbits/sec  173 
41:52.4: [  7]  28.00-29.00  sec   243 KBytes  1.99 Mbits/sec  172 
41:53.4: [  7]  29.00-30.00  sec   245 KBytes  2.00 Mbits/sec  173 
41:54.4: [  7]  30.00-31.00  sec   245 KBytes  2.00 Mbits/sec  173 
41:55.4: [  7]  31.00-32.00  sec   243 KBytes  1.99 Mbits/sec  172 
41:55.4: [  7]  32.00-32.01  sec  2.83 KBytes  2.59 Mbits/sec  2 
41:55.4: - - - - - - - - - - - - - - - - - - - - - - - - -
41:55.4: [ ID] Interval           Transfer     Bitrate         Jitter    Lost/Total Datagrams
41:55.4: [  7]   0.00-32.01  sec  7.63 MBytes  2.00 Mbits/sec  0.000 ms  0/5527 (0%)  sender
41:55.4: iperf test finished.
41:55.4: -----------------------------------------------------------
41:55.4: Server listening on 14069
41:55.4: -----------------------------------------------------------

@Carlitops
Copy link

Carlitops commented Feb 6, 2020 •
edited by bmah888

Hi guys, have you overcome this problem?
I'm experiencing similar issue, I don't know what that means.

Accepted connection from 172.16.0.1, port 48634
[  5] local 172.16.0.3 port 5201 connected to 172.16.0.1 port 42108
[ ID] Interval           Transfer     Bitrate         Jitter    Lost/Total Datagrams
[  5]   0.00-1.00   sec  4.53 MBytes  38.0 Mbits/sec  0.060 ms  -1931109556/-1931109555 (0%)  
[  5]   1.00-2.00   sec  4.77 MBytes  40.0 Mbits/sec  0.084 ms  0/0 (0%)  
[  5]   2.00-3.00   sec  4.77 MBytes  40.0 Mbits/sec  0.133 ms  0/0 (0%)  
[  5]   3.00-4.00   sec  4.76 MBytes  40.0 Mbits/sec  0.048 ms  0/0 (0%)  
[  5]   4.00-5.00   sec  4.56 MBytes  38.2 Mbits/sec  0.277 ms  0/0 (0%)  
[  5]   5.00-6.00   sec  4.80 MBytes  40.3 Mbits/sec  0.093 ms  0/0 (0%)  
[  5]   6.00-7.00   sec  4.54 MBytes  38.1 Mbits/sec  0.116 ms  0/0 (0%)  
[  5]   7.00-8.00   sec  4.77 MBytes  40.0 Mbits/sec  0.044 ms  0/0 (0%)  
[  5]   8.00-9.00   sec  4.77 MBytes  40.0 Mbits/sec  0.059 ms  0/0 (0%)  
[  5]   9.00-10.00  sec  4.38 MBytes  36.7 Mbits/sec  0.175 ms  0/0 (0%)  
[  5]  10.00-10.05  sec   119 KBytes  19.8 Mbits/sec  0.155 ms  0/0 (0%)  
- - - - - - - - - - - - - - - - - - - - - - - - -
[ ID] Interval           Transfer     Bitrate         Jitter    Lost/Total Datagrams
[SUM]  0.0-10.0 sec  34730 datagrams received out-of-order
[  5]   0.00-10.05  sec  46.8 MBytes  39.0 Mbits/sec  0.155 ms  -1931109556/-1931109555 (0%)  receiver

(reformatted for clarity)

@davidBar-On
Copy link
Contributor

Hi,
Negative lost packets value seem to be generally o.k. It means that packets that were considered lost in previous intervals were received. E.g., in the following case given above:

41:54.4: [  8]  30.00-31.00  sec   242 KBytes  1.98 Mbits/sec  4.966 ms  2/173 (1.2%) 
41:55.4: [  8]  31.00-32.00  sec   247 KBytes  2.03 Mbits/sec  5.648 ms  -2/173 (-1.2%)

The -2 lost packets means that that the two packets lost in interval 30.00-31.00 were received in interval 31.00-32.00.

The real total packets received in the interval is therefore "Total"-"Lost" (e.g. 173-(-2)=175 packets were received in interval 31.00-32.00)

For the original case posted, data is missing regarding interval 20.000105-21.000194. As in interval 21.000194-22.000068, 146-(-111)=257 packets were received, it seems that there was a serious network buffering and reorder in interval 20.000105-21.000194, which caused a packet to arrive before 111 preceding packets, and the 111 packets arrived only during the following interval.

It seems that the main issue is that sometimes the first packet is received with garbled packet count or is received truncated, so the packet counter is garbled. E.g. in:

46:24.9: [ ID] Interval          Transfer    Bitrate         Jitter          Lost/Total Datagrams
46:24.9: [  8] 0.00-1.00   sec   246 KBytes  2.02 Mbits/sec  2567541.936 ms  393365/393539 (1e+02%)

probably there was a problem with the first packet assumed to be received, so its garbled packet count was 393539. Practically, 393539-393365=174 packets were received in the first interval. All following intervals shows negative number of lost packets, since each received packet is considered recovery of lost packet from the first interval, until more than 393539 packets will be received.

Later I will send a pull request with suggested changes to guard against using garbled packet counter.

davidBar-On added a commit to davidBar-On/iperf that referenced this issue Feb 25, 2020
@davidBar-On
Workaround for issue esnet#914 - protect from garbled packet counter
4e935e4
@davidBar-On davidBar-On mentioned this issue Feb 25, 2020
Closed
@bmah888 bmah888 mentioned this issue Sep 14, 2020
Open
@davidBar-On davidBar-On mentioned this issue Feb 16, 2021
Closed
@davidBar-On davidBar-On mentioned this issue Apr 27, 2021
Open
@davidBar-On davidBar-On mentioned this issue Jan 8, 2022
Merged
@bmah888
Copy link
Contributor

bmah888 commented Feb 14, 2022

Believed fixed by #1260

@bmah888 bmah888 closed this as completed Feb 14, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
5 participants
@bmah888 @dmozzoni @Carlitops @danielaCasasv @davidBar-On