net/http: HTTP/1 server got 0.5μs slower in Go 1.8

[OneOfOne]

Please answer these questions before submitting your issue. Thanks!

What version of Go are you using (go version)?

Go 1.7.5, 1.8 rc3 and git

What operating system and processor architecture are you using (go env)?

Arch Linux 64bit

What did you do?

go run https://gist.github.com/OneOfOne/4d7e13977886ddab825870bc3422a901
switch terminals and run wrk -c 20 -d 30s http://localhost:8081

What did you expect to see?

Same throughput as 1.7 or faster.

What did you see instead?

go tip fd37b8c

Running 30s test @ http://localhost:8081
  2 threads and 20 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency   195.30us  470.12us  16.30ms   95.11%
    Req/Sec    85.62k     6.00k   95.21k    80.83%
  5110713 requests in 30.01s, 721.35MB read
Requests/sec: 170322.67
Transfer/sec:     24.04MB

go 1.8rc3 758a728

Running 30s test @ http://localhost:8081
  2 threads and 20 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency   192.49us  451.74us  15.14ms   95.02%
    Req/Sec    85.91k     6.37k   97.60k    83.50%
  5130079 requests in 30.01s, 724.08MB read
Requests/sec: 170941.23
Transfer/sec:     24.13MB

go 1.7.5

Running 30s test @ http://localhost:8081
  2 threads and 20 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency   210.16us  528.53us  14.78ms   94.13%
    Req/Sec    94.34k     4.31k  103.56k    73.83%
  5631803 requests in 30.01s, 794.89MB read
Requests/sec: 187673.03
Transfer/sec:     26.49MB

[bradfitz]

Too late for Go 1.8, but we can look into performance during Go 1.9.

[bradfitz]

Anybody want to investigate the difference? What's a Go 1.7 vs Go 1.8 CPU profile say?

[OneOfOne]

Updated play with pprof: https://play.golang.org/p/GZ4zQOg1Wf

I ran go tool pprof http://localhost:6060/debug/pprof/profile, switched terms and ran wrk -c 20 -d 30s http://localhost:6060/.

go tip

(pprof) top
36600ms of 80000ms total (45.75%)
Dropped 297 nodes (cum <= 400ms)
Showing top 10 nodes out of 135 (cum >= 970ms)
      flat  flat%   sum%        cum   cum%
   26360ms 32.95% 32.95%    27340ms 34.17%  syscall.Syscall
    2280ms  2.85% 35.80%     5740ms  7.17%  runtime.mallocgc
    1310ms  1.64% 37.44%     1310ms  1.64%  runtime.heapBitsSetType
    1260ms  1.57% 39.01%     1260ms  1.57%  runtime._ExternalCode
    1030ms  1.29% 40.30%     7280ms  9.10%  net/http.(*chunkWriter).writeHeader
     970ms  1.21% 41.51%      970ms  1.21%  runtime.epollwait
     900ms  1.12% 42.64%      920ms  1.15%  runtime.mapiternext
     880ms  1.10% 43.74%      880ms  1.10%  runtime.usleep
     820ms  1.03% 44.76%     1490ms  1.86%  runtime.deferreturn
     790ms  0.99% 45.75%      970ms  1.21%  runtime.mapaccess1_faststr
(pprof) top -cum
27.89s of 80s total (34.86%)
Dropped 297 nodes (cum <= 0.40s)
Showing top 10 nodes out of 135 (cum >= 23.44s)
      flat  flat%   sum%        cum   cum%
     0.01s 0.013% 0.013%     73.46s 91.83%  runtime.goexit
     0.55s  0.69%   0.7%     69.55s 86.94%  net/http.(*conn).serve
     0.30s  0.38%  1.07%     35.91s 44.89%  net/http.(*response).finishRequest
     0.15s  0.19%  1.26%     32.10s 40.12%  bufio.(*Writer).Flush
    26.36s 32.95% 34.21%     27.34s 34.17%  syscall.Syscall
     0.10s  0.12% 34.34%     24.56s 30.70%  net/http.checkConnErrorWriter.Write
         0     0% 34.34%     24.44s 30.55%  net.(*conn).Write
     0.23s  0.29% 34.62%     24.44s 30.55%  net.(*netFD).Write
     0.06s 0.075% 34.70%     23.50s 29.38%  syscall.Write
     0.13s  0.16% 34.86%     23.44s 29.30%  syscall.write

go 1.7.5

(pprof) top
40520ms of 82240ms total (49.27%)
Dropped 281 nodes (cum <= 411.20ms)
Showing top 10 nodes out of 128 (cum >= 860ms)
      flat  flat%   sum%        cum   cum%
   29480ms 35.85% 35.85%    30920ms 37.60%  syscall.Syscall
    2550ms  3.10% 38.95%     5710ms  6.94%  runtime.mallocgc
    1560ms  1.90% 40.84%     1590ms  1.93%  runtime.heapBitsSetType
    1220ms  1.48% 42.33%     1220ms  1.48%  runtime.epollwait
    1050ms  1.28% 43.60%     2750ms  3.34%  runtime.mapassign1
    1050ms  1.28% 44.88%     1080ms  1.31%  runtime.mapiternext
    1000ms  1.22% 46.10%     7890ms  9.59%  net/http.(*chunkWriter).writeHeader
     880ms  1.07% 47.17%     2910ms  3.54%  net/http.DetectContentType
     870ms  1.06% 48.22%     1010ms  1.23%  runtime.mapaccess1_faststr
     860ms  1.05% 49.27%      860ms  1.05%  runtime.futex
(pprof) top -cum
31.67s of 82.24s total (38.51%)
Dropped 281 nodes (cum <= 0.41s)
Showing top 10 nodes out of 128 (cum >= 27.69s)
      flat  flat%   sum%        cum   cum%
         0     0%     0%     75.77s 92.13%  runtime.goexit
     0.44s  0.54%  0.54%     74.26s 90.30%  net/http.(*conn).serve
     0.27s  0.33%  0.86%     37.08s 45.09%  net/http.(*response).finishRequest
     0.18s  0.22%  1.08%     36.44s 44.31%  bufio.(*Writer).Flush
     0.25s   0.3%  1.39%     36.26s 44.09%  bufio.(*Writer).flush
    29.48s 35.85% 37.23%     30.92s 37.60%  syscall.Syscall
     0.12s  0.15% 37.38%     27.99s 34.03%  net/http.checkConnErrorWriter.Write
     0.69s  0.84% 38.22%     27.85s 33.86%  net/http.(*conn).readRequest
     0.08s 0.097% 38.31%     27.77s 33.77%  net.(*conn).Write
     0.16s  0.19% 38.51%     27.69s 33.67%  net.(*netFD).Write

Let me know if you want me to do anything specific.

[FrozenPrincess]

Ouch, I'm seeing the same thing with about a 20% slowdown on my webserver benchmark with 1.8r3, and a slightly bigger binary size too

[OneOfOne]

I realize it's late on the release cycle but 20% regression on http is a huge regression for a lot of people.

I'm willing to help debug if you tell me what's needed @bradfitz.

[bradfitz]

I'm willing to help debug if you tell me what's needed @bradfitz.

Step 1 is debugging why it got slower. If you find any clues, let me know.

[dlsniper]

@OneOfOne how does this work for non-hello world applications? Do you see any issues there? Maybe 20% for Hello World apps is acceptable until 1.9?

@bradfitz I think the feature for Shutdown is causing lower performance for the kind of 'hello world' apps/tests.

			select {
			case <-srv.getDoneChan():
return ErrServerClosed
//....

Look here .

At 1.7 it was just a for loop.

Can somebody confirm my assumption?

Thanks,
kataras

[mholt]

I am not able to reproduce the OP's results. I'm on a Mac, and I'm using slightly older versions of Go.

$ wrk -c 20 -d 30s http://localhost:8081  # go 1.8 RC2
Running 30s test @ http://localhost:8081
  2 threads and 20 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency     0.87ms    6.99ms 151.45ms   99.38%
    Req/Sec    25.22k     2.34k   33.28k    66.94%
  1510655 requests in 30.10s, 213.22MB read
Requests/sec:  50188.34
Transfer/sec:      7.08MB

$ wrk -c 20 -d 30s http://localhost:8081  # go 1.7.4
Running 30s test @ http://localhost:8081
  2 threads and 20 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency   840.73us    6.85ms 151.46ms   99.41%
    Req/Sec    26.05k     3.67k   33.43k    60.96%
  1560770 requests in 30.10s, 220.29MB read
Requests/sec:  51853.50
Transfer/sec:      7.32MB

There's a slight difference but it's smaller than 20%, almost negligible here.

[bradfitz]

@kataras, do you have evidence in favor of that theory?

You can confirm it yourself: delete those lines and measure again.

I would be surprised, though.

[cstockton]

@kataras That looks like it is probably it. In addition to the select you have a mutex acquire and a unlock that is done in a defer (which I know recently got sped up, but are still a bit slower than a direct unlock.

func (s *Server) getDoneChan() <-chan struct{} {
	s.mu.Lock()
	defer s.mu.Unlock()
	return s.getDoneChanLocked()
}

Since the accept loop is such a hot path, it may be worth moving the shutdown select into a separate goroutine and using sync/atomic to signal shutdown in the accept loop.

EDIT:
I don't think it's just this, just tried tip without the select all together and it adds about 7us (5%~).