crypto/tls: figure out why/how buffer size affects crypto/tls performance on windows

[adg]

It looks like a recent change to crypto/tls increased the duration of the throughput benchmarks beyond 10 minutes on the windows race builder.

https://build.golang.org/log/1217fb6191fad2bf98dc54b61cfbe51e33af21e6

BenchmarkThroughput/MaxPacket/1MB-4                    1    2226420000 ns/op       0.47 MB/s
BenchmarkThroughput/MaxPacket/2MB-4                    1    3995838000 ns/op       0.52 MB/s
BenchmarkThroughput/MaxPacket/4MB-4                    1    6992716500 ns/op       0.60 MB/s
BenchmarkThroughput/MaxPacket/8MB-4                    1    12010950000 ns/op      0.70 MB/s
BenchmarkThroughput/MaxPacket/16MB-4                   1    18002754000 ns/op      0.93 MB/s
BenchmarkThroughput/MaxPacket/32MB-4                   1    34987995000 ns/op      0.96 MB/s
BenchmarkThroughput/MaxPacket/64MB-4                   1    69017067000 ns/op      0.97 MB/s
*** Test killed: ran too long (10m0s).
FAIL    crypto/tls  600.061s

The benchmarks are run with -benchtime .1s, but many of the benchmarks take longer than 100 milliseconds.

One simple fix would be to increase the timeout, currently 10 minutes for all standard library benchmarks combined. But I'm hesitant to make builds take longer.

I will investigate why -benchtime doesn't appear to have the desired effect.

[adg]

Looks like I misread the log output. The crypto/tls package benchmarks alone are taking 10 minutes. Something is definitely wrong on windows.

[adg]

FWIW this takes 44 seconds on my MacBook:

$ go test -run=^$ -bench=. -v -race crypto/tls
BenchmarkThroughput/MaxPacket/1MB-4                  100      22417768 ns/op      46.77 MB/s
BenchmarkThroughput/MaxPacket/2MB-4                   50      37196722 ns/op      56.38 MB/s
BenchmarkThroughput/MaxPacket/4MB-4                   20      63029114 ns/op      66.55 MB/s
BenchmarkThroughput/MaxPacket/8MB-4                   10     111478777 ns/op      75.25 MB/s
BenchmarkThroughput/MaxPacket/16MB-4                   5     283195368 ns/op      59.24 MB/s
BenchmarkThroughput/MaxPacket/32MB-4                   3     491191446 ns/op      68.31 MB/s
BenchmarkThroughput/MaxPacket/64MB-4                   1    1032492829 ns/op      65.00 MB/s
BenchmarkThroughput/DynamicPacket/1MB-4               50      24004322 ns/op      43.68 MB/s
BenchmarkThroughput/DynamicPacket/2MB-4               30      41218780 ns/op      50.88 MB/s
BenchmarkThroughput/DynamicPacket/4MB-4               20      79591691 ns/op      52.70 MB/s
BenchmarkThroughput/DynamicPacket/8MB-4               10     120384840 ns/op      69.68 MB/s
BenchmarkThroughput/DynamicPacket/16MB-4               5     246487076 ns/op      68.07 MB/s
BenchmarkThroughput/DynamicPacket/32MB-4               3     442225137 ns/op      75.88 MB/s
BenchmarkThroughput/DynamicPacket/64MB-4               2     970823710 ns/op      69.13 MB/s
BenchmarkLatency/MaxPacket/200kbps-4                   2     703320882 ns/op
BenchmarkLatency/MaxPacket/500kbps-4                   5     285504385 ns/op
BenchmarkLatency/MaxPacket/1000kbps-4                 10     146081561 ns/op
BenchmarkLatency/MaxPacket/2000kbps-4                 20      76909455 ns/op
BenchmarkLatency/MaxPacket/5000kbps-4                 50      34849995 ns/op
BenchmarkLatency/DynamicPacket/200kbps-4              10     141680066 ns/op
BenchmarkLatency/DynamicPacket/500kbps-4              20      61072803 ns/op
BenchmarkLatency/DynamicPacket/1000kbps-4             50      34683166 ns/op
BenchmarkLatency/DynamicPacket/2000kbps-4            100      21136070 ns/op
BenchmarkLatency/DynamicPacket/5000kbps-4            100      13180012 ns/op
PASS
ok      crypto/tls  44.515s

[adg]

The crypto/tls benchmarks run 100x slower on the windows builder than they do on my laptop (with and without the race detector enabled):

$ gomote run user-adg-windows-amd64-race-0 bin/go test -run=^$ -bench=. -v -race -cpu=4 crypto/tls
BenchmarkThroughput/MaxPacket/1MB-4                    1    2283290800 ns/op       0.46 MB/s
BenchmarkThroughput/MaxPacket/2MB-4                    1    4006989800 ns/op       0.52 MB/s
BenchmarkThroughput/MaxPacket/4MB-4                    1    6988549600 ns/op       0.60 MB/s
BenchmarkThroughput/MaxPacket/8MB-4                    1    10019916000 ns/op      0.84 MB/s
BenchmarkThroughput/MaxPacket/16MB-4                   1    17996784800 ns/op      0.93 MB/s
^C
$ gomote run user-adg-windows-amd64-race-0 bin/go test -run=^$ -bench=. -v  -cpu=4 crypto/tls
BenchmarkThroughput/MaxPacket/1MB-4                    1    1591858000 ns/op       0.66 MB/s
BenchmarkThroughput/MaxPacket/2MB-4                    1    4998238800 ns/op       0.42 MB/s
BenchmarkThroughput/MaxPacket/4MB-4                    1    7999330600 ns/op       0.52 MB/s
BenchmarkThroughput/MaxPacket/8MB-4                    1    11974092600 ns/op      0.70 MB/s
BenchmarkThroughput/MaxPacket/16MB-4                   1    17979206000 ns/op      0.93 MB/s
BenchmarkThroughput/MaxPacket/32MB-4                   1    35982827000 ns/op      0.93 MB/s
BenchmarkThroughput/MaxPacket/64MB-4                   1    52988362800 ns/op      1.27 MB/s
^C

And it's not that the builder is slow. I compared the results of the bytes package's benchmarks between the windows builder and my macbook and found them comparable (within the same order of magnitude).

So we need to investigate why this is so slow on the windows builder. Is it just the test, or the crypto/tls package in general?

[adg]

I tried running the benchmarks on a linux-amd64 VM, and they run about as fast as on the real hardware. So it's not a GCE thing in general. I wonder if it's a windows+GCE thing? If someone with a physical windows box wants to help out, please run

go test -run=^$ -bench=. -v -race -cpu=4 crypto/tls

and paste your output here. Thanks.

[ChrisHines]

System info: Windows 7 Home Premium SP1
CPU: Intel Core 2 Quad, Q8400 @ 2.66 GHz

I built tip with CGO_ENABLED=0

C:\GoTip\go\src>\GoTip\go\bin\go version
go version devel +b3f98d7 Tue May 31 00:22:56 2016 +0000 windows/amd64

C:\GoTip\go\src>\GoTip\go\bin\go test -run=none -bench=. -v -cpu=4 -timeout=1m crypto/tls
BenchmarkThroughput/MaxPacket/1MB-4                   20          76700000 ns/op          13.67 MB/s
BenchmarkThroughput/MaxPacket/2MB-4                   10         149300000 ns/op          14.05 MB/s
BenchmarkThroughput/MaxPacket/4MB-4                    5         290000000 ns/op          14.46 MB/s
BenchmarkThroughput/MaxPacket/8MB-4                    2         566500000 ns/op          14.81 MB/s
BenchmarkThroughput/MaxPacket/16MB-4                   1        1125000000 ns/op          14.91 MB/s
BenchmarkThroughput/MaxPacket/32MB-4                   1        2295000000 ns/op          14.62 MB/s
BenchmarkThroughput/MaxPacket/64MB-4                   1        4517000000 ns/op          14.86 MB/s
BenchmarkThroughput/DynamicPacket/1MB-4         *** Test killed: ran too long (2m0s).
FAIL    crypto/tls      120.049s

I noticed something that could help. Once the DynamicPacket test started, CPU usage by tls.test.exe dropped to zero. When I run just the MaxPacket benchmarks they take 18.3s total and consume ~38% CPU (or ~1.5 cores) during that time.

[adg]

@ChrisHines thanks for that. Those numbers seem normal. So it does seem to be a combination of Windows and GCE.

I have another interesting finding. Lowering the read/write buffer size in the throughput test appears to dramatically affect run time. Reducing it from 1<<16 (64kb) to 1<<15 (32kb) yields these results:

$ gomote run user-adg-windows-amd64-race-0 go/bin/go test -run=^$ -bench=. -v -race -cpu=4 crypto/tls
BenchmarkThroughput/MaxPacket/1MB-4                   50      33806430 ns/op      31.02 MB/s
BenchmarkThroughput/MaxPacket/2MB-4                   30      56246400 ns/op      37.29 MB/s
BenchmarkThroughput/MaxPacket/4MB-4                   10     106243200 ns/op      39.48 MB/s
BenchmarkThroughput/MaxPacket/8MB-4                    5     201159000 ns/op      41.70 MB/s
BenchmarkThroughput/MaxPacket/16MB-4                   3     414036000 ns/op      40.52 MB/s
BenchmarkThroughput/MaxPacket/32MB-4                   2     772411500 ns/op      43.44 MB/s
BenchmarkThroughput/MaxPacket/64MB-4                   1    1570212000 ns/op      42.74 MB/s
BenchmarkThroughput/DynamicPacket/1MB-4                1    1854373500 ns/op       0.57 MB/s
BenchmarkThroughput/DynamicPacket/2MB-4                1    2018425500 ns/op       1.04 MB/s
BenchmarkThroughput/DynamicPacket/4MB-4                1    2045767500 ns/op       2.05 MB/s
BenchmarkThroughput/DynamicPacket/8MB-4                1    2107287000 ns/op       3.98 MB/s
BenchmarkThroughput/DynamicPacket/16MB-4               1    2205913500 ns/op       7.61 MB/s
BenchmarkThroughput/DynamicPacket/32MB-4               1    2430508500 ns/op      13.81 MB/s
BenchmarkThroughput/DynamicPacket/64MB-4               1    2810367000 ns/op      23.88 MB/s
BenchmarkLatency/MaxPacket/200kbps-4                   2     713821500 ns/op
BenchmarkLatency/MaxPacket/500kbps-4                   5     297246600 ns/op
BenchmarkLatency/MaxPacket/1000kbps-4                 10     158778900 ns/op
BenchmarkLatency/MaxPacket/2000kbps-4                 20      90082125 ns/op
BenchmarkLatency/MaxPacket/5000kbps-4                 30      49085400 ns/op
BenchmarkLatency/DynamicPacket/200kbps-4              10     153896400 ns/op
BenchmarkLatency/DynamicPacket/500kbps-4              20      75825225 ns/op
BenchmarkLatency/DynamicPacket/1000kbps-4             30      48564600 ns/op
BenchmarkLatency/DynamicPacket/2000kbps-4             50      36755460 ns/op
BenchmarkLatency/DynamicPacket/5000kbps-4             50      28630980 ns/op
PASS
ok      crypto/tls  47.659s

Still some slowness in the DynamicPacket benchmarks, but the others seem to have risen to normal range again.

Lowering it further to 1<<14 16kb yields numbers in the expected range for all benchmarks:

$ gomote run user-adg-windows-amd64-race-0 go/bin/go test -run=^$ -bench=. -v -race -cpu=4 crypto/tls
BenchmarkThroughput/MaxPacket/1MB-4                   30      39483150 ns/op      26.56 MB/s
BenchmarkThroughput/MaxPacket/2MB-4                   20      69917400 ns/op      29.99 MB/s
BenchmarkThroughput/MaxPacket/4MB-4                   10     127628550 ns/op      32.86 MB/s
BenchmarkThroughput/MaxPacket/8MB-4                    5     248421600 ns/op      33.77 MB/s
BenchmarkThroughput/MaxPacket/16MB-4                   3     477508500 ns/op      35.13 MB/s
BenchmarkThroughput/MaxPacket/32MB-4                   2     908633250 ns/op      36.93 MB/s
BenchmarkThroughput/MaxPacket/64MB-4                   1    1771371000 ns/op      37.89 MB/s
BenchmarkThroughput/DynamicPacket/1MB-4               30      41305950 ns/op      25.39 MB/s
BenchmarkThroughput/DynamicPacket/2MB-4               20      70600950 ns/op      29.70 MB/s
BenchmarkThroughput/DynamicPacket/4MB-4               10     134561700 ns/op      31.17 MB/s
BenchmarkThroughput/DynamicPacket/8MB-4                5     251741700 ns/op      33.32 MB/s
BenchmarkThroughput/DynamicPacket/16MB-4               2     550257750 ns/op      30.49 MB/s
BenchmarkThroughput/DynamicPacket/32MB-4               2     980894250 ns/op      34.21 MB/s
BenchmarkThroughput/DynamicPacket/64MB-4               1    1928587500 ns/op      34.80 MB/s
BenchmarkLatency/MaxPacket/200kbps-4                   2     713821500 ns/op
BenchmarkLatency/MaxPacket/500kbps-4                   5     298027800 ns/op
BenchmarkLatency/MaxPacket/1000kbps-4                 10     159169500 ns/op
BenchmarkLatency/MaxPacket/2000kbps-4                 20      90668025 ns/op
BenchmarkLatency/MaxPacket/5000kbps-4                 30      49313250 ns/op
BenchmarkLatency/DynamicPacket/200kbps-4              10     154384650 ns/op
BenchmarkLatency/DynamicPacket/500kbps-4              20      77387625 ns/op
BenchmarkLatency/DynamicPacket/1000kbps-4             30      48564600 ns/op
BenchmarkLatency/DynamicPacket/2000kbps-4             50      36325800 ns/op
BenchmarkLatency/DynamicPacket/5000kbps-4             50      28787220 ns/op
PASS
ok      crypto/tls  46.143s

So the network stack for Windows on GCE prefers smaller buffers?

I'll send a change to lower the buffer size, so that the tests run in a reasonable time, but we should find out why this is happening.

[ChrisHines]

I changed read/write buffer size to 1<<14 and reran the tests on my machine and got:

C:\GoTip\go\src>\GoTip\go\bin\go test -run=none -bench=. -v -cpu=4 crypto/tls
BenchmarkThroughput/MaxPacket/1MB-4                   10         112600000 ns/op           9.31 MB/s
BenchmarkThroughput/MaxPacket/2MB-4                    5         216600000 ns/op           9.68 MB/s
BenchmarkThroughput/MaxPacket/4MB-4                    3         430333333 ns/op           9.75 MB/s
BenchmarkThroughput/MaxPacket/8MB-4                    2         849500000 ns/op           9.87 MB/s
BenchmarkThroughput/MaxPacket/16MB-4                   1        1681000000 ns/op           9.98 MB/s
BenchmarkThroughput/MaxPacket/32MB-4                   1        3342000000 ns/op          10.04 MB/s
BenchmarkThroughput/MaxPacket/64MB-4                   1        6738000000 ns/op           9.96 MB/s
BenchmarkThroughput/DynamicPacket/1MB-4               10         110600000 ns/op           9.48 MB/s
BenchmarkThroughput/DynamicPacket/2MB-4                5         216600000 ns/op           9.68 MB/s
BenchmarkThroughput/DynamicPacket/4MB-4                3         423666666 ns/op           9.90 MB/s
BenchmarkThroughput/DynamicPacket/8MB-4                2         841500000 ns/op           9.97 MB/s
BenchmarkThroughput/DynamicPacket/16MB-4               1        1691000000 ns/op           9.92 MB/s
BenchmarkThroughput/DynamicPacket/32MB-4               1        3381000000 ns/op           9.92 MB/s
BenchmarkThroughput/DynamicPacket/64MB-4               1        6812000000 ns/op           9.85 MB/s
BenchmarkLatency/MaxPacket/200kbps-4                   2         707000000 ns/op
BenchmarkLatency/MaxPacket/500kbps-4                   5         288600000 ns/op
BenchmarkLatency/MaxPacket/1000kbps-4                 10         150200000 ns/op
BenchmarkLatency/MaxPacket/2000kbps-4                 20          80450000 ns/op
BenchmarkLatency/MaxPacket/5000kbps-4                 30          40366666 ns/op
BenchmarkLatency/DynamicPacket/200kbps-4              10         145100000 ns/op
BenchmarkLatency/DynamicPacket/500kbps-4              20          64050000 ns/op
BenchmarkLatency/DynamicPacket/1000kbps-4             30          38200000 ns/op
BenchmarkLatency/DynamicPacket/2000kbps-4             50          23940000 ns/op
BenchmarkLatency/DynamicPacket/5000kbps-4            100          17090000 ns/op
PASS
ok      crypto/tls      55.532s

[kardianos]

This isn't just a GCE issue. My Win7 box has terrible performance in the test code with "1<<16" but on par with my linux box (similar gen hardware) with "1<<14".

Terrible performance as in MaxPacket 0.05Mb/s (not just dyn packet).

[adg]

@kardianos thanks for the additional information. That's interesting. I wonder why, with the smaller buffer, the performance goes down on @ChrisHines' machine while it goes up on ours?

[gopherbot]

CL https://golang.org/cl/23574 mentions this issue.