Possible regression in 2.5.0 - iperf test w/packet loss frequently times out

[MagnusS]

A few weeks ago I was able to run the iperf test w/uniform packet loss 150 times locally without timeout (as mentioned here) with the master branch. I just repeated the experiment with current master (f31810c) and after a few attempts I've been unable to run more than max 8 tests in a row. Release 2.5.0 (455263d) also times out frequently.

With rev aab5709 the test runs fine. To rule out a bug in the newest version of the test I've also tried using the tests from master with aab5709 and got the same result (no timeouts). I also tried to double the timeout, in case it was caused by the reduced performance of the recently merged debug branch, but the test still times out - the connection seems to just stall when the test fails (see pcap output below).

This is the command I use - it runs 100 iperf tests and terminates if one of them fails.

for c in $(seq 1 100); do echo $c; date; ./test.byte test iperf 2 -v || break ; done

I've also increased the data size from 10mb back to 25mb in lib_tests/lib_iperf.ml, as this was set lower to reduce timeouts in Travis. With 10mb the test is less likely to timeout, but it is still unreliable (I was able to run 20 tests with 10mb vs 8 with 25mb).

Here are the last packets in the pcap output from three failed tests.

28749 109.963717   10.0.0.101 -> 10.0.0.100   TCP 1514 [TCP Previous segment not captured] 14476 > 5001 [PSH, ACK] Seq=21089701 Ack=1 Win=262140 Len=1460
28750 109.963846   10.0.0.101 -> 10.0.0.100   TCP 1514 14476 > 5001 [PSH, ACK] Seq=21091161 Ack=1 Win=262140 Len=1460
28751 109.963906   10.0.0.100 -> 10.0.0.101   TCP 54 [TCP Dup ACK 28748#1] 5001 > 14476 [ACK] Seq=1 Ack=21088241 Win=262140 Len=0
28752 109.964019   10.0.0.101 -> 10.0.0.100   TCP 1514 14476 > 5001 [PSH, ACK] Seq=21092621 Ack=1 Win=262140 Len=1460
28753 109.964080   10.0.0.100 -> 10.0.0.101   TCP 54 [TCP Dup ACK 28748#2] 5001 > 14476 [ACK] Seq=1 Ack=21088241 Win=262140 Len=0

29957 104.624361   10.0.0.100 -> 10.0.0.101   TCP 54 [TCP Dup ACK 29951#3] 5001 > 10208 [ACK] Seq=1 Ack=21978841 Win=262140 Len=0
29958 104.624419   10.0.0.101 -> 10.0.0.100   TCP 1514 [TCP Fast Retransmission] 10208 > 5001 [PSH, ACK] Seq=21978841 Ack=1 Win=262140 Len=1460
29959 104.624589   10.0.0.100 -> 10.0.0.101   TCP 54 5001 > 10208 [ACK] Seq=1 Ack=21984681 Win=262140 Len=0
29960 104.624684   10.0.0.101 -> 10.0.0.100   TCP 1514 [TCP Previous segment not captured] 10208 > 5001 [PSH, ACK] Seq=21986141 Ack=1 Win=262140 Len=1460
29961 104.624788   10.0.0.100 -> 10.0.0.101   TCP 54 [TCP Dup ACK 29959#1] 5001 > 10208 [ACK] Seq=1 Ack=21984681 Win=262140 Len=0

9338 103.079093   10.0.0.100 -> 10.0.0.101   TCP 54 5001 > 14140 [ACK] Seq=1 Ack=6841561 Win=262140 Len=0
9339 103.079269   10.0.0.101 -> 10.0.0.100   TCP 1514 [TCP Previous segment not captured] 14140 > 5001 [PSH, ACK] Seq=6843021 Ack=1 Win=262140 Len=1460
9340 103.079326   10.0.0.100 -> 10.0.0.101   TCP 54 [TCP Dup ACK 9338#1] 5001 > 14140 [ACK] Seq=1 Ack=6841561 Win=262140 Len=0
9341 103.079439   10.0.0.101 -> 10.0.0.100   TCP 1514 14140 > 5001 [PSH, ACK] Seq=6844481 Ack=1 Win=262140 Len=1460
9342 103.079501   10.0.0.100 -> 10.0.0.101   TCP 54 [TCP Dup ACK 9338#2] 5001 > 14140 [ACK] Seq=1 Ack=6841561 Win=262140 Len=0

This test sent 92 dup ack's before stalling:

29331  96.955952   10.0.0.101 -> 10.0.0.100   TCP 1514 [TCP Previous segment not captured] 18257 > 5001 [PSH, ACK] Seq=21510181 Ack=1 Win=262140 Len=1460
29332  96.956058   10.0.0.100 -> 10.0.0.101   TCP 54 [TCP Dup ACK 29330#1] 5001 > 18257 [ACK] Seq=1 Ack=21508721 Win=262140 Len=0
29333  96.956126   10.0.0.101 -> 10.0.0.100   TCP 1514 18257 > 5001 [PSH, ACK] Seq=21511641 Ack=1 Win=262140 Len=1460
29334  96.956231   10.0.0.100 -> 10.0.0.101   TCP 54 [TCP Dup ACK 29330#2] 5001 > 18257 [ACK] Seq=1 Ack=21508721 Win=262140 Len=0
29335  96.956295   10.0.0.101 -> 10.0.0.100   TCP 1514 18257 > 5001 [PSH, ACK] Seq=21513101 Ack=1 Win=262140 Len=1460
[...]
29514  96.979388   10.0.0.100 -> 10.0.0.101   TCP 54 [TCP Dup ACK 29330#92] 5001 > 18257 [ACK] Seq=1 Ack=21508721 Win=262140 Len=0
29515  96.979492   10.0.0.101 -> 10.0.0.100   TCP 1514 18257 > 5001 [PSH, ACK] Seq=21644501 Ack=1 Win=262140 Len=1460

[avsm]

Can you bisect this one back to see if a particular changeset caused it, Magnus?

[yomimono]

I'm about to attempt to confirm/deny that this is still failing since #156 was merged, also.

[MagnusS]

Sure - I'll try to find the commit.

[yomimono]

Still failing in a855bac (current latest) , unfortunately.

[MagnusS]

I'm running a script now to automatically test commits back in time to see when it starts failing. It will probably take a few hours to complete.

[MagnusS]

It looks like the test started failing after 7cecc9f.

[samoht]

eeeek. The main change here is 7cecc9f#diff-5d0c376089097530d3f7f9c4082b6443R27 when maybe changes the semantics of retransmission.... Could you add a test which fail if such retransmissions appears? Would be much easier to avoid future regressions... and I can try to revert part of the patch to see if that fixes the bug or not.

[MagnusS]

Hm - not sure what we should test for yet. The retransmissions mostly look normal until the connection stalls (at least to me, maybe someone else can spot something). It's only in rare cases that I've seen lots of retransmissions, so it could be a separate problem that usually corrects itself.

If you want to try to revert some of the changes it's relatively easy to reproduce/test with the for-loop above. It fails after just a few attempts (<10). The pcap output is stored in tests/pcap/tcp_iperf_two_stacks_uniform_packet_loss.pcap

[yomimono]

It's probably valuable to generate a trace with mirage-profile when we run this test as well as a packet dump; a trace from a failing test would probably be instructive.

[MagnusS]

(if testing with master it's faster to reproduce with 25_000_000 here)

[MagnusS]

Hm - would it be useful to add tracing in vnetif as well? Since both client and server are running in the same process we could (in theory at least :-)) track everything that happens as a result of a Netif.write call.

[talex5]

Any reason why we're doing performance testing using bytecode? I'd imagine native would be faster.

Anyway, here's a trace showing it being slow:

http://test.roscidus.com/traces/2015-07-02/tcp-perf-slow/

Test branch: https://github.com/talex5/mirage-tcpip/tree/trace-perf (aborts if a request takes > 1s)

Raw trace: http://test.roscidus.com/traces/2015-07-02/tcp-perf-slow/trace.ctf.bz2

[MagnusS]

@talex5 thanks!

The test is not really intended to be a performance test right now. It just verifies that we can transfer data between two stacks over different backends.

[talex5]

Here's a slightly suspicious bit of another run:

This is just before the system sleeps for a long time (the grey area on the right). We're doing a TCP fast transmit, but get stuck waiting for take tx_ack. I think this is due to the change in the code. Before, the retransmit was async. Now, we wait for it.

However, I don't know why that should be a problem.

[MagnusS]

Looks like the modified test in https://github.com/talex5/mirage-tcpip/tree/trace-perf also fails with the last "good" commit f583cad, so the traces above could be from states the stack is able to recover from. Would it be possible to just label the write as slow in the trace and not exit until the test times out? It seems that it can take a while to recover from the packet loss in some cases (15 sec +).

[talex5]

Yes, but you might need a very large trace buffer if you want to do that. If 1s delays are expected, then it might be easier to just raise the threshold to whatever you would consider unacceptable.

[balrajsingh]

I think as @talex5 observed the async fast retransmit may be the change
responsible for the stall. Is it possible to just revert this and check
again?

On Thu, Jul 2, 2015 at 1:43 PM, Thomas Leonard notifications@github.com
wrote:

Yes, but you might need a very large trace buffer if you want to do that.
If 1s delays are expected, then it might be easier to just raise the
threshold to whatever you would consider unacceptable.

—
Reply to this email directly or view it on GitHub
#157 (comment)
.

[MagnusS]

@balrajsingh Sure, I can check that - is it this xmit call?

7cecc9f#diff-5c19dbcb696d8a908ac70c39feacd849R352

[talex5]

@MagnusS how about using a fixed seed for the random number generator in Uniform_packet_loss? As it is, a test may fail simply due to randomness.

[MagnusS]

@balrajsingh @samoht The test still fails unfortunately...

[MagnusS]

@talex5 Hm - yes, but is (or was) very unlikely... but I guess we could get unlucky and drop a lot of packets in a row for instance.

Probably a good idea to add a seed - if we can seed the tcp/ip-stack as well we could have reproducible test runs

[balrajsingh]

Thanks @MagnusS, is there a pcap trace of a failed flow, or could you
create one - hopefully there'll be some clues in the trace.

On Thu, Jul 2, 2015 at 3:09 PM, Magnus Skjegstad notifications@github.com
wrote:

@talex5 https://github.com/talex5 Hm - yes, but is (or was) very
unlikely... but I guess we could get unlucky and drop a lot of packets in a
row for instance.

Probably a good idea to add a seed - if we can seed the tcp/ip-stack as
well we could have reproducible test runs

—
Reply to this email directly or view it on GitHub
#157 (comment)
.

[talex5]

@MagnusS Given the low rate of dropped packets (1%), is it reasonable that sending a segment between the two test stacks might take more than 10s? I would have thought TCP should recover before then.

[samoht]

The test still fails unfortunately...

did you push your patch somewhere?

[MagnusS]

@samoht I've pushed it here with @talex5's tracing version of the test (but with exit and debug disabled): https://github.com/magnuss/mirage-tcpip/tree/trace-iperf

Trace and pcap from failing test:
http://www.skjegstad.com/data/030715/iperf_test_timeout_c026b99.pcap.gz
http://www.skjegstad.com/data/030715/iperf_test_timeout_c026b99.ctf.gz

(the trace buffer may be too small here though)

[talex5]

@MagnusS would be useful to put a MProf.Trace.label in Uniform_packet_loss so we can see on the trace where a packet was dropped.

(also, if wire.ml would log the sequence number when it transmits a packet, we could correlate the packets in the trace with the ones in the pcap file).

Looking at the trace, it looks like the send_empty_ack thread sent an ack (tcp-to-ip+0), then some threads on the transmit side got notified of something, but didn't do anything. Maybe the ack was dropped? What should happen in that case?

[MagnusS]

Good idea - pushed a patch with labels for xmit-[seq] and pkt_drop now.

Another trace and pcap:
http://www.skjegstad.com/data/030715/iperf_test_timeout_25694cb.pcap.gz
http://www.skjegstad.com/data/030715/iperf_test_timeout_25694cb.ctf.gz

Console output

Iperf server: Received connection.
Iperf client: Made connection to server.
Iperf server: t = 1, rate = 58996d KBits/s, totbytes = 7374460, live_words = 23251
Tcp.Segment: TCP retransmission on timer seq = 474847255
Iperf server: t = 4, rate = 2706d KBits/s, totbytes = 8389160, live_words = 44786
write_and_check took > 1s!
Tcp.Segment: TCP retransmission on timer seq = 477158435
Iperf server: t = 7, rate = 6163d KBits/s, totbytes = 10700340, live_words = 41321
write_and_check took > 1s!
Tcp.Segment: TCP retransmission on timer seq = 477262095
Iperf server: t = 10, rate = 276d KBits/s, totbytes = 10804000, live_words = 26961
write_and_check took > 1s!
Tcp.Segment: TCP retransmission on timer seq = 478330815
Iperf server: t = 17, rate = 1221d KBits/s, totbytes = 11872720, live_words = 28783
write_and_check took > 1s!
Iperf server: t = 18, rate = 4754d KBits/s, totbytes = 12466940, live_words = 24853
Tcp.Segment: TCP retransmission on timer seq = 480960275
Iperf server: t = 34, rate = 1018d KBits/s, totbytes = 14502180, live_words = 27096
write_and_check took > 1s!
ARP: timeout 10.0.0.101
ARP: timeout 10.0.0.100
Tcp.Segment: TCP retransmission on timer seq = 482642195
ARP: transmitting probe -> 10.0.0.100
ARP responding to: who-has 10.0.0.100?
ARP: updating 10.0.0.100 -> 02:50:2a:16:6d:02
Iperf server: t = 71, rate = 364d KBits/s, totbytes = 16184100, live_words = 30371
ARP: transmitting probe -> 10.0.0.101
ARP responding to: who-has 10.0.0.101?
ARP: updating 10.0.0.101 -> 02:50:2a:16:6d:03
write_and_check took > 1s!
Iperf server: t = 72, rate = 21456d KBits/s, totbytes = 18866120, live_words = 27786
ARP: timeout 10.0.0.101

[talex5]

So, we dropped two packets close together. In both cases, the receiver sent a duplicate ack because it saw that a segment was missing. In the first case, we did a fast retransmission, but in the second we didn't for some reason. Is there some kind of back-off going on here?

Note: if you reenable logging, that will show up in the trace too, which might be helpful.

[balrajsingh]

There is indeed!

For tl;dr-ers: this TCP is designed to recover from the usual case on the
internet of at most 1 pkt loss per window. More than 1pkt loss may require
the timer to kick, which is supposed to be read as a severe event and which
slows TCP right down. It would then additively recover to the available
rate again (and not exponentially as it does at the beginning of the flow
using the misnamed slow start), which will feel like a slow down.

Long version:

Fast rexmit is designed to recover with almost no loss in transmission rate
when 1 packet per window is lost (equiv in a way to 1 pkt per RTT or 1 of
the packets in flight). This kind of loss is actually part of TCP itself as
it probes a larger and larger congestion window till a pkt loss occurs,
then halves the cwnd and starts over to probe the window again additively.

When the '3 duplicate ack signal' (I.e. 3 pure ack pkts that don't advance
the ack number) is received, TCP rexmits the missing pkt. If the rexmitted
pkt is also lost then the only way to recover is via the retransmission
timer.

If multiple pkts in a window are lost then the first loss will cause a
whole lot of dup acks (one for each pkt above the lost pkt). After the
first 3 of these are rxed fast rexmit will send the lost pkt. Now when this
pkt is acked the ack will move on to the next lost pkt. If this ack opens
up enough window to send 3 more pkts at the top of the window and if there
are 3 pkts to send then there will be 3 dup acks again and fast rexmit will
kick in again. If however close by pkts are lost or if a rexmitted pkt is
lost or there isn't any more data to send then the only way to recover from
that loss is by the timer which will slow things down a lot temporarily.

That said, there is always the possibility that there is a bug in the logic
of this recovery code.

BTW, one common hack used is to set the number of dup acks received to 2
while the TCP is still working in the original window where the first loss
occurred so then the ack to the rexmitted pkt will point to the next lost
pkt and it will be seen as the third dup ack which will cause an immediate
re-xmission of that pkt. This (or equiv) I think is actually a suggestion
in the RFC.

I'll look thru the code again tonight.

Thanks.
On 3 Jul 2015 11:58 am, "Thomas Leonard" notifications@github.com wrote:

So, we dropped two packets close together. In both cases, the receiver
sent a duplicate ack because it saw that a segment was missing. In the
first case, we did a fast retransmission, but in the second we didn't for
some reason. Is there some kind of back-off going on here?

Note: if you reenable logging, that will show up in the trace too, which
might be helpful.

—
Reply to this email directly or view it on GitHub
#157 (comment)
.

[talex5]

Thanks @balrajsingh! I wonder if the rto (retransmission timeout) calculation may be the problem. Here are some numbers I got with some extra debug:

Tcp.Window: srtt=18.0000 rttvar=9.0000 raw_rto=54.0000
Tcp.Window: rto: raw=54.000000, plus backoff_count 1 = 108.000000
Tcp.Segment: PUSHING TIMER - new time = 108.000000, new seq = 466500511

So, it thinks it the "smoothed round-trip time" between the two local stacks is 18s? Could it be including the delayed retransmissions in the srtt calculations? If so, this would explain the excessive 108s retransmission delay.

[balrajsingh]

The rto is supposed to back off exponentially with each loss and then when
it has success (a whole window of packets with no loss) it should smoothly
adjust itself back. It'll be interesting to see how the rto and related
variables change over the lifetime of this flow.

On Fri, Jul 3, 2015 at 3:33 PM, Thomas Leonard notifications@github.com
wrote:

Thanks @balrajsingh https://github.com/balrajsingh! I wonder if the rto
(retransmission timeout) calculation may be the problem. Here are some
numbers I got with some extra debug:

Tcp.Window: srtt=18.0000 rttvar=9.0000 raw_rto=54.0000
Tcp.Window: rto: raw=54.000000, plus backoff_count 1 = 108.000000
Tcp.Segment: PUSHING TIMER - new time = 108.000000, new seq = 466500511

So, it thinks it the "smoothed round-trip time" between the two local
stacks is 18s? Could it be including the delayed retransmissions in the
srtt calculations? If so, this would explain the excessive 108s
retransmission delay.

—
Reply to this email directly or view it on GitHub
#157 (comment)
.

[talex5]

@balrajsingh right - but srtt shouldn't be getting large though should it?

[balrajsingh]

I'm not sure, I'll look. It is supposed to be RFC 2988, if it doesn't
please fix.

There may be a problem there because SRTT is a blend of current SRTT with a
real measurement. If any loss or other problem occurs then the measurement
then its not a real measurement and should not be used - the flag
rtt_timer_on manages that. There may be a problem there. Again it'll be
informative to track how this variable changes.

On Fri, Jul 3, 2015 at 5:14 PM, Thomas Leonard notifications@github.com
wrote:

@balrajsingh https://github.com/balrajsingh right - but srtt shouldn't
be getting large though should it?

—
Reply to this email directly or view it on GitHub
#157 (comment)
.

[MagnusS]

Here's another trace+pcap of a failing test with more debugging enabled (code is here):

http://www.skjegstad/data/040715/iperf_test_timeout_11c3aa1.ctf.gz
http://www.skjegstad/data/040715/iperf_test_timeout_11c3aa1.pcap.gz

Here's the console output:

Tcp.PCB: process-synack: [channels=0 listens=0 connects=1]                                                                                                                                       [360/49796]
Tcp.PCB: new-client-connection: [channels=0 listens=0 connects=0]
Tcp.PCB: process-ack: [channels=0 listens=1 connects=0]
Iperf server: Received connection.
Iperf client: Made connection to server.
Tcp.Segment: TCP fast retransmission seq=466590242, dupack=466590242
Tcp.Segment: TCP fast retransmission seq=466759602, dupack=466759602
Tcp.Segment: TCP fast retransmission seq=467415142, dupack=467415142
Tcp.Segment: TCP fast retransmission seq=467482302, dupack=467482302
Tcp.Segment: TCP fast retransmission seq=467498362, dupack=467498362
Tcp.Segment: PUSHING TIMER - new time=1.000000, new seq=467504202
Tcp.Segment: TCP retransmission on timer seq = 467504202
Iperf server: t = 4, rate = 2085d KBits/s, totbytes = 1042440, live_words = 33109
Tcp.Segment: PUSHING TIMER - new time = 9.000000, new seq = 467504202
write_and_check took > 1s!
Tcp.Segment: TCP fast retransmission seq=467594722, dupack=467594722
Tcp.Segment: TCP fast retransmission seq=467892562, dupack=467892562
Tcp.Segment: TCP fast retransmission seq=468263402, dupack=468263402
Tcp.Segment: PUSHING TIMER - new time=1.000000, new seq=468280922
Tcp.Segment: TCP retransmission on timer seq = 468280922
Iperf server: t = 14, rate = 621d KBits/s, totbytes = 1819160, live_words = 34055
Tcp.Segment: PUSHING TIMER - new time = 22.500000, new seq = 468280922
write_and_check took > 1s!
Tcp.Segment: PUSHING TIMER - new time=22.500000, new seq=468283842
Tcp.Segment: TCP retransmission on timer seq = 468283842
Iperf server: t = 59, rate = 1d KBits/s, totbytes = 1822080, live_words = 34342
Tcp.Segment: PUSHING TIMER - new time = 270.000000, new seq = 468283842
write_and_check took > 1s!
Tcp.Segment: TCP fast retransmission seq=468755422, dupack=468755422
Tcp.Segment: TCP fast retransmission seq=468793382, dupack=468793382
Tcp.Segment: TCP fast retransmission seq=469196342, dupack=469196342
Iperf server: t = 60, rate = 8982d KBits/s, totbytes = 2944820, live_words = 23343
Tcp.Segment: TCP fast retransmission seq=469408042, dupack=469408042
Tcp.Segment: TCP fast retransmission seq=469504402, dupack=469504402
Tcp.Segment: TCP fast retransmission seq=469546742, dupack=469546742
ARP: timeout 10.0.0.101
ARP: timeout 10.0.0.100

The timer went up to 270 seconds when the test failed - the test timeout is 120 sec. Could the timer not be triggered properly after commit 7cecc9f? I'll try to wrap the other xmit-calls in the timer in async as well to see if that helps.

[MagnusS]

Looks like it works now! This call to xmit also had to be in Lwt.async: 7cecc9f#diff-5c19dbcb696d8a908ac70c39feacd849R298

I've run about 30 tests so far and the timer seems to never go above 1-2 seconds. I'll run a few more tests and prepare a PR :-)

It would be really nice to have some of this debugging and tracing available by default in the tests! Would it be possible to enable profiling automatically when it's supported?

[samoht]

yay! thanks for spotting this. If you have any idea to test that we don't have more regression (apart in forbidding me to push new code to that repository) that would be great. And yes, turning the profiling on during the test is a good idea!

[talex5]

@MagnusS you'd have to detect that the mirage-profile.unix ocamlfind module was present and conditionally compile some extra code. For now, I'd suggest just leaving the trace initialising code in there, but commented out.

[talex5]

(continuing the discussion in mirage/ocaml-git#117)

This has started happening again. My last two builds of CueKeeper on Travis failed with timeouts in the tcpip tests.

First failure:

#=== ERROR while installing tcpip.2.6.0 =======================================#
# opam-version 1.2.2
# os           linux
# command      make test TESTFLAGS=-v
# path         /home/travis/.opam/system/build/tcpip.2.6.0
# compiler     system (4.02.1)
# exit-code    2
# env-file     /home/travis/.opam/system/build/tcpip.2.6.0/tcpip-35867-62756b.env
# stdout-file  /home/travis/.opam/system/build/tcpip.2.6.0/tcpip-35867-62756b.out
# stderr-file  /home/travis/.opam/system/build/tcpip.2.6.0/tcpip-35867-62756b.err
### stdout ###
# [...]
[ERROR]     iperf    2   iperf with two stacks and uniform packet loss.
[SKIP]      iperf    3   iperf with two stacks, basic tests, longer.
[SKIP]      iperf    4   iperf with two stacks and uniform packet loss, longer.
# -- iperf.002 Failed --
# iperf with two stacks and uniform packet loss.
# ./_tests/iperf.002.output:
# --
# [exception] OUnitTest.OUnit_failure("iperf test timed out after 120.000000 seconds")
# 
# 1 error! in 1.047s. 17 tests run.

Failure on rebuild:

#=== ERROR while installing tcpip.2.6.0 =======================================#
# opam-version 1.2.2
# os           linux
# command      make test TESTFLAGS=-v
# path         /home/travis/.opam/system/build/tcpip.2.6.0
# compiler     system (4.02.1)
# exit-code    2
# env-file     /home/travis/.opam/system/build/tcpip.2.6.0/tcpip-35903-c947fc.env
# stdout-file  /home/travis/.opam/system/build/tcpip.2.6.0/tcpip-35903-c947fc.out
# stderr-file  /home/travis/.opam/system/build/tcpip.2.6.0/tcpip-35903-c947fc.err
### stdout ###
# [...]
[ERROR]     iperf    2   iperf with two stacks and uniform packet loss.
[SKIP]      iperf    3   iperf with two stacks, basic tests, longer.
[SKIP]      iperf    4   iperf with two stacks and uniform packet loss, longer.
# -- iperf.002 Failed --
# iperf with two stacks and uniform packet loss.
# ./_tests/iperf.002.output:
# --
# [exception] OUnitTest.OUnit_failure("iperf test timed out after 120.000000 seconds")
# 
# 1 error! in 1.128s. 17 tests run.

Did something change recently?

[MagnusS]

(continuing the discussion from mirage/ocaml-git#117)

@talex5 wrote

We could still have the 120s timeout, but they'd be virtual seconds, so not affected by the load on the machine running the tests (I'm assuming that's the cause).

Hm... How would we advance the virtual clock? I guess we could base it on how fast we can transfer data between the stacks and adjust the clock to a target throughput, but I'm not sure how well that would work with packet loss and varying throughput.

I think we should at least change the timeout to be reset for every new byte received (with normal clock for now) - then it would also be independent of the amount of data transferred. And two minutes without a single byte transferred seems very slow even for Travis :-)

[talex5]

@MagnusS when all callbacks scheduled for the current time have run, the clock advances automatically to the next scheduled event (sleep timeout). At least, that's how the CueKeeper test clock works:

https://github.com/talex5/cuekeeper/blob/94ee4e17d24da75cace5b15f10842baf8f557f58/tests/test.ml#L27

We should probably add a (virtual) delay to the virtual network to simulate packet transmission time. This would also allow simulation of networks of varying speeds.

Resetting the timeout after each byte might work too, but we also want to know when the stack really is behaving slowly, and if we make it too generous we might miss that. After all, the last time this happened it was a real bug...

[yomimono]

I think we've fixed the specific problems mentioned here with recent updates to tcpip. I'm closing this issue; please feel free to open new ones for work mentioned here that has yet to be completed.