x/net/http2: investigate Server speed regressions from more select case

[bradfitz]

Go bug for tracking kubernetes/kubernetes#45216

It appears that the new select cases in http2.serverConn.serve slowed things down.

But tip (~Go 1.9) had a number of select improvements after Go 1.8, so it doesn't show up as much perhaps. See comments and numbers in the linked bug.

/cc @tombergan

[gopherbot]

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

[tombergan]

From the profile linked in kubernetes/kubernetes#45216, this looks like lock contention.

runtime.selectgoImpl: 13.06s of 451.69s
runtime.selunlock: 0.58s of 179.29s
runtime.sellock: 1.74s of 251.83s

Compare this to the profile from go 1.7:

runtime.selectgoImpl: 4.65s of 12.69s
runtime.selunlock: doesn't register
runtime.sellock: doesn't register

[josharian]

Pity--looks like mutex profiling doesn't include futex. I wonder how to detect which case is contended; if it is in fact lock contention, knowing which lock it is should give reproduction hints.

[bradfitz]

/cc @mdempsky @randall77 @aclements for any runtime help.

This is a pretty serious speed regression for Kubernetes, but one we can't yet repro in a stand-alone benchmark. Any clues?

[josharian]

@bradfitz it looks like BenchmarkGets has no concurrency (at least according to the trace viewer), so the select statement isn't under any contention. So if the problem is lock contention, it won't show up. Maybe b.RunParallel to the rescue?

[josharian]

(I tried hacking it in myself but broke all sorts of things--obviously requires more domain expertise than I have to get it right.)

[tombergan]

Here is a version of BenchmarkServerGets that adds concurrency. I cannot reproduce the bug though. The benchmark has the same runtime before and after commenting out the select cases listed in this comment.

I wonder if there's something about their testbed setup that makes really long scheduling delays possible? Or maybe they're running in a VM that has a weird implementation of sys_futex?

[josharian]

@tombergan thanks. That benchmark patch doesn't apply cleanly for me (mail a CL next time?), but I applied it manually, and got:

BenchmarkServerGets-8   	--- FAIL: BenchmarkServerGets-8
	server_test.go:2989: Error: timeout waiting for frame
	server_test.go:235: Framer read log:
		2017-05-10 07:25:51.540231465 Framer 0xc4205082a0: read SETTINGS len=24, settings: MAX_FRAME_SIZE=1048576, MAX_CONCURRENT_STREAMS=101, MAX_HEADER_LIST_SIZE=1048896, INITIAL_WINDOW_SIZE=1048576
		2017-05-10 07:25:51.54027134 Framer 0xc4205082a0: read WINDOW_UPDATE len=4 (conn) incr=983041
		2017-05-10 07:25:51.540286228 Framer 0xc4205082a0: read SETTINGS flags=ACK len=0
		2017-05-10 07:25:51.540439446 Framer 0xc4205082a0: read HEADERS flags=END_HEADERS stream=1 len=49
		2017-05-10 07:25:51.540454635 Framer 0xc4205082a0: read DATA flags=END_STREAM stream=1 len=12 data="Hello, world"

and lots more errors.

Anyway, from visually inspecting the patch, it does set up a concurrent get, but not N concurrent gets, so it doesn't appear that it would really introduce contention. You want something (waves hands) like:

  setUpServer()

  b.RunParallel(func(pb *testing.PB) {
        for pb.Next() {
            get()
        }
    })

You can check for full concurrency using runtime tracing. Be sure to use a short benchtime to avoid overwhelming amounts of data.

$ go test -bench=Gets -benchtime=50ms -trace=trace.out
$ go tool trace trace.out

You should see all procs active the whole time, not just one or two. If it is fully parallel, and there are contention effects, you should also be able to see the effect when you mess with -cpu:

$ go test -bench=Gets -cpu=1,2,4,8,16,32,64,128

[tombergan]

Sorry the patch didn't apply cleanly, not sure why that happened.

HTTP/2 frames must be serialized onto a TCP connection. Whether or not the "gets" run concurrently on the client side is not relevant to server-side concurrency. Previously, the test forced serial execution on the server because it waited for a response immediately after sending each request. My patched test reads the responses in a background goroutine so the server can respond concurrently with the client sending new requests. The client still needs to send requests serially (the st.writeHeaders call) because, again, HTTP/2 frames are serialized.

The server will serialize response frames, but each HTTP request handler should run concurrently. That serialization is managed by the serverConn.serve loop, which is the method that includes the large select stmt. The select stmt selects on new frames from the client, new write requests from HTTP handlers, completed net.Conn.write() calls (which happen in a background goroutine), timers, and other small things. Assuming lock contention is the problem, the contention is likely on st.wantWriteFrameCh, since that channel is written to by all request handler goroutines, while the other channels have only one writer.

Thanks for the tips about runtime tracing. Hopefully I have time later today to try that out.

[josharian]

Cool. Let me know if you have any problems with tracing; happy to help. Feel free to also ping me on some form of chat if interactive discussion would be helpful. Brad can give you my contact info.

[bradfitz]

@tombergan, yes, that's the sort of benchmark I was imagining: one connection, bunch of concurrent requests streaming from long-running handlers doing Write+Flush for b.N iterations or something. That sounds like what they're hitting with their "Watch" APIs.