write benchmarks

[willscott]

Work on #76

Initially, running as go test -bench . -benchtime 15s -cpu 1,2,4 yields
(Without write coalescing):

goos: darwin
goarch: amd64
pkg: github.com/libp2p/go-mplex
BenchmarkSmallPackets      	 7616295	      2520 ns/op
BenchmarkSmallPackets-2    	 3293174	      5364 ns/op
BenchmarkSmallPackets-4    	 2551482	      7120 ns/op
BenchmarkLinearPackets     	 5917447	      2975 ns/op
BenchmarkLinearPackets-2   	 2833734	      6439 ns/op
BenchmarkLinearPackets-4   	 2556615	      7125 ns/op
PASS
ok  	github.com/libp2p/go-mplex	145.408s

With Write Coalescing:

goos: darwin
goarch: amd64
pkg: github.com/libp2p/go-mplex
BenchmarkSmallPackets      	  171469	    104704 ns/op
BenchmarkSmallPackets-2    	  298460	     66740 ns/op
BenchmarkSmallPackets-4    	  490029	     37051 ns/op
BenchmarkLinearPackets     	  249435	     73914 ns/op
BenchmarkLinearPackets-2   	  463890	     45462 ns/op
BenchmarkLinearPackets-4   	  755593	     25591 ns/op
PASS
ok  	github.com/libp2p/go-mplex	122.683s

This is the expected failure mode though, since we're representing a 0-latency, infinite-bandwidth network.

[willscott]

updated benchmarks to consider a case where Send()'s on the underlying net.Conn block. (via a time.Sleep)

This causes somewhat unbelievable benchmarks at present:

w/o coalescing
BenchmarkSmallPackets               6505782	      2815 ns/op
BenchmarkSlowConnSmallPackets 	    4860	   3899876 ns/op
w/  coalescing
BenchmarkSmallPackets 	            14959983	  1494 ns/op
BenchmarkSlowConnSmallPackets 	    363711387	  41.3 ns/op

[Stebalien]

Hm, yeah, something is fishy.

Does the lossy packet conn you're using correctly simulate packet loss for a TCP connection? That is, we don't expect data to actually be lost, we just expect things to slow down due to retransmissions.

[willscott]

The wrapper around the net.Conn blocks the sending thread with a Sleep based on packet size (to cap bandwidth) and latency. It is configured in these benchmarks to not drop any packets.

[Stebalien]

Ah, got it.

[willscott]

ok, some more reasonable numbers: (a 100kbps link with 30ms latency)

with write coalescing

BenchmarkSlowConnSmallPackets     	    1204	  23187782 ns/op	  15.87 MB/s
BenchmarkSlowConnSmallPackets-2   	    1002	  25399463 ns/op	  13.15 MB/s
BenchmarkSlowConnSmallPackets-4   	     834	  45408887 ns/op	   5.43 MB/s

without

BenchmarkSlowConnSmallPackets     	     982	  23468765 ns/op	  12.66 MB/s
BenchmarkSlowConnSmallPackets-2   	    1172	  23898852 ns/op	  15.07 MB/s
BenchmarkSlowConnSmallPackets-4   	     782	  26059704 ns/op	  10.15 MB/s

Interesting that the 4-core (more contention) test starts falling off link saturation in the write coalescing case. I'll re-run with a faster network and see how that trends.

[willscott]

This is now using libp2p/go-libp2p-testing#21

I believe the top numbers are actually due to imprecision in how go bench reports work done by parallel threads vs overall. I now no longer believe any meaningful change is incurred in mplex from write coalescing.

[willscott]

The current test failure is a good indication that this is actually testing something meaningful:

=== RUN   TestSmallPackets
CPU Bound Limit:    77422	     16554 ns/op	1422382.93 MB/s
Latency Bound Limit: 2.048s
Bandwidth Bound Limit: 102400Kbps
Network Bound Limit:   106479	     80539 ns/op	402083.71 MB/s
At MaxProc 1 102400Kbps / 1.024s latency:   119084	     39180 ns/op	923955.72 MB/s
At MaxProc 2 102400Kbps / 1.024s latency:   105529	     42951 ns/op	747012.03 MB/s
Slowdown is 11.370230%
--- FAIL: TestSmallPackets (139.25s)
    benchmarks_test.go:54: Slowdown from mplex was >1%: 0.113702

I'll push an update to indicate that a 10% slowdown (vs the current 1% limit) is acceptable, since that's what the current code hits on CI (this may also be due to CI running the test with the race detector on)

[willscott]

for comparison, the current local output
(with coalescing)

CPU Bound Limit:   395835	      3079 ns/op	39079050.22 MB/s
Latency Bound Limit: 16ms
Bandwidth Bound Limit: 102400Kbps
Network Bound Limit:   163454	      7607 ns/op	6537690.62 MB/s
At MaxProc 1 102400Kbps / 8ms latency:    53253	     23214 ns/op	697423.50 MB/s
At MaxProc 2 102400Kbps / 8ms latency:    53114	     23204 ns/op	695911.14 MB/s
At MaxProc 4 102400Kbps / 8ms latency:    52712	     23223 ns/op	690329.83 MB/s
Slowdown is 0.723299%
PASS

(without)

CPU Bound Limit:    60412	     19440 ns/op	945400.60 MB/s
Latency Bound Limit: 64ms
Bandwidth Bound Limit: 102400Kbps
Network Bound Limit:    40866	     28791 ns/op	432383.89 MB/s
At MaxProc 1 102400Kbps / 32ms latency:    52602	     25348 ns/op	630851.91 MB/s
At MaxProc 2 102400Kbps / 32ms latency:    56181	     23034 ns/op	741973.43 MB/s
At MaxProc 4 102400Kbps / 32ms latency:    55123	     23116 ns/op	725004.12 MB/s
Slowdown is 1.940173%
PASS

[Stebalien]

Feedback from sync call:

• It would be nice to get numbers on how many writes we're doing (an approximation of packets sent).
• It would be nice to re-run these tests with jitter.

Write coalescing is targeting jitter, packet-loss, and syscall overhead.

[Stebalien]

nits but otherwise the benchmarks look sane.

[Stebalien]

why defer?

[Stebalien]

return?

[Stebalien]

will panic if err != nil

[willscott]

Error above should exit already in that case, right?

[Stebalien]

@willscott could you re-disable write-coalescing so we can get these merged?

[willscott]

@willscott could you re-disable write-coalescing so we can get these merged?

rebased to remove