[netperf-talk] Problem with different runtime over wireless link

[Rick Jones]

Kai Koehne wrote:
> Hi,
> 
> I am having a hard time evaluating the performance of wireless links 
> using netperf-2.4.3. I want to measure two wireless links which might 
> interfere, and therefore started netperf in parallel on two different 
> hosts:
> 
> host1$ netperf -H 192.168.3.121 -c -C -i 30 -t UDP_STREAM -l 10 -v 2 -d 
> -d -- -H 192.168.100.121 -m 1472 -s 32768 -S 32768
> host2$ netperf -H 192.168.3.120 -c -C -i 30 -t UDP_STREAM -l 10 -v 2 -d 
> -d -- -H 192.168.101.120 -m 1472 -s 32768 -S 32768
> 
> To my understanding, the options say that 30 tests each one lasting 10 
> seconds tests are run over the 192.168.100.* / 192.168.101.* networks 
> (the wireless network), while the control channel is set up over the 
> 192.168.3.* networks (Ethernet).

That the the gist of it yes.  There are though as you have discovered 
"issues" which can alter that.

> In theory, netperf should run 10*30=300 seconds + some small overhead. 
> However, one netperf instance in fact runs for 873 seconds, and the 
> other one even for 2441 seconds! This of course invalids all results. I 
> imagine this is due to a lot of packet losses.

Yes.  I suspect that if you were to run some single-instance tests you 
would see that the runtime was rather longer than 10 seconds.  This 
stems from netperf wanting to know that the data made it to the other 
side.  To do that it "handshakes" with the netserver by calling 
shutdown(SHUT_WR) and then waiting for a read return of zero to signify 
that the netserver has closed its end.  The netserver, on getting the 
read return of zero from that shutdown(SHUT_WR) by netperf will then 
close() its socket, getting netperf out of that recv() call.

When there are packet losses, flushing that last SO_SNDBUF's worth of 
data might take a while.

Also, for the TCP_STREAM test, time spent in connect() is not (IIRC) 
counted and that might take a while.

> Is there a way to ensure that netperf only runs for a specified amount 
> of time? And if not, how will netperf4 handle such cases?

Short of eliminating the handshake, or the packet losses, no, there is 
no way.  And, even if we nuke that handshake, there could still be some 
delays in getting the _next_ iteration started as the netserver will 
still need to wait for the read return of zero to tell it the previous 
iteration was done - there is no timer running on the netserver side, or 
one runs the risk of that timer expiring before the netperf side's timer 
(notice the "PAD_TIME" kludge required for UDP tests...)

Netperf4 deals with this problem by not having the handshake, and by 
having data flow before and after the measurement interval.  Take all 
the (specified) test instances to the LOAD state, once they are there, 
then take all the (specified) test instances to the MEASure state, wait 
the measurement interval, put the tests into the load state...  that 
sort of thing.  So, even if there is skew in talking to all the test 
instances, one can be confident all the test instances are generating 
load while measurements are being taken.

I would _very_ much like more exposure for (and help with :) netperf4. 
However, if your current situation does not lend itself to that, some 
other considerations for "getting by" with netperf2 would include 
configuring with demo-mode enabled with --enable-demo .  You would then 
start up both netperfs with very (relatively speaking) long run times 
and without the confidence intervals and have them emit intermediate 
results (throughput only) at intervals.  You can log those to a file and 
then extract a subset of them from a timeframe when you knew both were 
running.  The downside is you won't get "in-band" CPU statistics - you 
would have to pull them out of the system(s) via other means.

Here is an example of demo-mode output:

raj at tardy:~/netperf2_test$ src/netperf -H tardy.cup.hp.com -D 1
TCP STREAM TEST from 0.0.0.0 (0.0.0.0) port 0 AF_INET to 
tardy.cup.hp.com (15.244.56.217) port 0 AF_INET : demo
Interim result:   55.07 10^6bits/s over 1.00 seconds
Interim result:   55.00 10^6bits/s over 1.00 seconds
Interim result:   55.41 10^6bits/s over 1.00 seconds
Interim result:   53.55 10^6bits/s over 1.04 seconds
Interim result:   54.18 10^6bits/s over 1.00 seconds
Interim result:   52.94 10^6bits/s over 1.02 seconds
Interim result:   54.13 10^6bits/s over 1.00 seconds
Interim result:   54.09 10^6bits/s over 1.00 seconds
Interim result:   53.96 10^6bits/s over 1.00 seconds
Recv   Send    Send
Socket Socket  Message  Elapsed
Size   Size    Size     Time     Throughput
bytes  bytes   bytes    secs.    10^6bits/sec

  32768  16384  16384    10.02      54.24

Notice that while I asked for reports one second apart (-D 1) they were 
sometimes longer - this stems from netperf's attempt to minimize the 
number of gettimeofday() calls it makes (contrary to popular belief, 
gettimeofday isn't "free" everywhere...).  So it guesses how many units 
of work it must do to take that long.  If it takes longer, that interval 
takes longer, but it should then adjust.

Here is an example where I disconnected the cable for a bit:

raj at tardy:~/netperf2_test$ src/netperf -H tardy.cup.hp.com -D 1
TCP STREAM TEST from 0.0.0.0 (0.0.0.0) port 0 AF_INET to 
tardy.cup.hp.com (15.244.56.217) port 0 AF_INET : demo
Interim result:   53.47 10^6bits/s over 1.01 seconds
Interim result:   12.44 10^6bits/s over 4.30 seconds
Interim result:   55.22 10^6bits/s over 1.00 seconds
Interim result:   53.14 10^6bits/s over 1.04 seconds
Interim result:   53.48 10^6bits/s over 1.00 seconds
Interim result:   52.80 10^6bits/s over 1.01 seconds
Recv   Send    Send
Socket Socket  Message  Elapsed
Size   Size    Size     Time     Throughput
bytes  bytes   bytes    secs.    10^6bits/sec

  32768  16384  16384    10.02      35.80

Notice that the second "one second" interval was actuall 4.3 :)

The interim results will respond to the -f option to change the output 
units:

raj at tardy:~/netperf2_test$ src/netperf -H tardy.cup.hp.com -D 1 -f M
TCP STREAM TEST from 0.0.0.0 (0.0.0.0) port 0 AF_INET to 
tardy.cup.hp.com (15.244.56.217) port 0 AF_INET : demo
Interim result:    5.74 MBytes/s over 1.01 seconds
Interim result:    6.08 MBytes/s over 1.00 seconds
Interim result:    5.87 MBytes/s over 1.03 seconds
Interim result:    5.75 MBytes/s over 1.02 seconds
Interim result:    5.55 MBytes/s over 1.04 seconds
Interim result:    5.74 MBytes/s over 1.00 seconds
Interim result:    5.41 MBytes/s over 1.06 seconds
Interim result:    5.75 MBytes/s over 1.00 seconds
Interim result:    5.82 MBytes/s over 1.00 seconds
Recv   Send    Send
Socket Socket  Message  Elapsed
Size   Size    Size     Time     Throughput
bytes  bytes   bytes    secs.    MBytes/sec

  32768  16384  16384    10.01       5.77


The time interval doesn't have to be whole seconds:

raj at tardy:~/netperf2_test$ src/netperf -H tardy.cup.hp.com -D 1.33
TCP STREAM TEST from 0.0.0.0 (0.0.0.0) port 0 AF_INET to 
tardy.cup.hp.com (15.244.56.217) port 0 AF_INET : demo
Interim result:   54.63 10^6bits/s over 1.33 seconds
Interim result:   54.25 10^6bits/s over 1.34 seconds
Interim result:   52.55 10^6bits/s over 1.37 seconds
Interim result:   51.68 10^6bits/s over 1.35 seconds
Interim result:   53.92 10^6bits/s over 1.33 seconds
Interim result:   53.94 10^6bits/s over 1.33 seconds
Interim result:   54.67 10^6bits/s over 1.33 seconds
Recv   Send    Send
Socket Socket  Message  Elapsed
Size   Size    Size     Time     Throughput
bytes  bytes   bytes    secs.    10^6bits/sec

  32768  16384  16384    10.02      53.54


and it can be less than a second:

raj at tardy:~/netperf2_test$ src/netperf -H tardy.cup.hp.com -D 0.33 -l 3
TCP STREAM TEST from 0.0.0.0 (0.0.0.0) port 0 AF_INET to 
tardy.cup.hp.com (15.244.56.217) port 0 AF_INET : demo
Interim result:   53.60 10^6bits/s over 0.33 seconds
Interim result:   53.64 10^6bits/s over 0.33 seconds
Interim result:   51.28 10^6bits/s over 0.35 seconds
Interim result:   55.03 10^6bits/s over 0.33 seconds
Interim result:   55.49 10^6bits/s over 0.33 seconds
Interim result:   56.81 10^6bits/s over 0.33 seconds
Interim result:   50.39 10^6bits/s over 0.37 seconds
Interim result:   45.74 10^6bits/s over 0.36 seconds
Recv   Send    Send
Socket Socket  Message  Elapsed
Size   Size    Size     Time     Throughput
bytes  bytes   bytes    secs.    10^6bits/sec

  32768  16384  16384    3.02       51.95

The leading zero is important it seems - my initial try was with just 
".33" and it gave me whole seconds.

happy benchmarking,

rick jones

> PS: The detailed logs of both netperf runs (determined by -d -d) look 
> quite similar. I did not attach them due to their size; however, if of 
> interest I would happily send them to you.

Thanks for gathering them, but I don't think we need them at this point.