Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

net/http: HTTP/1.1 performance degradation in 1.15beta1 #39543

Open
proyb6 opened this issue Jun 12, 2020 · 11 comments
Open

net/http: HTTP/1.1 performance degradation in 1.15beta1 #39543

proyb6 opened this issue Jun 12, 2020 · 11 comments

Comments

@proyb6
Copy link

@proyb6 proyb6 commented Jun 12, 2020

I am seeing 5% performance degradation when benchmark HTTP in plaintext on macOS Catalina. Ran test more than 3 times shown lesser 500 requests per second on 1.15beta1.

Simple hello world test on both 1 core:
go1.14.4 darwin/amd64

wrk -c100 -d5 http://localhost:8090/hello
Running 5s test @ http://localhost:8090/hello
  2 threads and 100 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency     3.32ms    0.91ms  15.67ms   79.06%
    Req/Sec    15.16k     1.12k   18.43k    86.27%
  153782 requests in 5.10s, 19.07MB read
Requests/sec:  30156.31
Transfer/sec:      3.74MB

go1.15beta1 darwin/amd64

wrk -c100 -d5 http://localhost:8090/hello
Running 5s test @ http://localhost:8090/hello
  2 threads and 100 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency     3.46ms    0.96ms  18.74ms   80.29%
    Req/Sec    14.55k     0.87k   17.22k    92.16%
  147583 requests in 5.10s, 18.30MB read
Requests/sec:  28941.41
Transfer/sec:      3.59MB
@ianlancetaylor ianlancetaylor changed the title HTTP performance degration net/http: performance degration in 1.15beta1 Jun 12, 2020
@ianlancetaylor ianlancetaylor added this to the Go1.15 milestone Jun 12, 2020
@ianlancetaylor
Copy link
Contributor

@ianlancetaylor ianlancetaylor commented Jun 12, 2020

Can you use the net/http/pprof package and collect CPU profiles from both versions? Thanks.

CC @bradfitz

@proyb6
Copy link
Author

@proyb6 proyb6 commented Jun 12, 2020

cpuprofile.zip

Attached on both versions.

@ianlancetaylor
Copy link
Contributor

@ianlancetaylor ianlancetaylor commented Jun 12, 2020

Thanks. Unfortunately I don't see the problem.

I'll mark this as a release blocker for now. I hope that somebody will be able to find what changed.

Can you share the code that you are using for benchmarking? Thanks.

@proyb6
Copy link
Author

@proyb6 proyb6 commented Jun 13, 2020

Sure, the following example:

package main

import (
    "fmt"
    "net/http"
//  "runtime"
     _ "net/http/pprof"
)

func hello(w http.ResponseWriter, req *http.Request) {
        fmt.Fprintf(w, "hello world!\n")
}

func main() {
//      runtime.GOMAXPROCS(1)
        http.HandleFunc("/hello", hello)
        http.ListenAndServe(":8090", nil)
}
@smasher164 smasher164 changed the title net/http: performance degration in 1.15beta1 net/http: performance degradation in 1.15beta1 Jun 13, 2020
@golang golang deleted a comment Jun 14, 2020
@andybons
Copy link
Member

@andybons andybons commented Jun 15, 2020

@neild
Copy link
Contributor

@neild neild commented Jun 18, 2020

I can confirm that I see a difference in 1.14 vs. 1.15beta1. Linux, amd64, GOMAXPROCS(1), the above test program and ten runs each of wrk -c100 -d5.

$ grep ^Request bench.go1.14
Requests/sec:  43433.19
Requests/sec:  43201.69
Requests/sec:  44116.82
Requests/sec:  43029.81
Requests/sec:  43827.57
Requests/sec:  42289.91
Requests/sec:  43815.39
Requests/sec:  44036.54
Requests/sec:  43955.58
Requests/sec:  43393.49

$ grep ^Request bench.go1.15
Requests/sec:  40063.74
Requests/sec:  40559.97
Requests/sec:  41783.38
Requests/sec:  41255.86
Requests/sec:  41534.14
Requests/sec:  40796.73
Requests/sec:  41519.93
Requests/sec:  39966.21
Requests/sec:  41283.03
Requests/sec:  41853.80

With default GOMAXPROCS, the difference was less pronounced. Nothing obvious to me in profiles. Will look further.

@dr2chase
Copy link
Contributor

@dr2chase dr2chase commented Jun 23, 2020

I took a stab at reproducing this just now, 1.14 vs 1.15tip, Linux, amd64, 12 processor box but GOMAXPROCS=1. 30 repetitions of 10 seconds of work:

( for i in {1..30} ; do wrk -c100 -d10 http://localhost:8114/hello; done; )  >& b114.log ; ( for i in {1..30} ; do wrk -c100 -d10 http://localhost:8115/hello; done; )  >& b115.log ;

Comparing averages, tip is 0.3% slower, comparing medians, 0.1% slower.

Got curious about what had changed since beta1, and noticed:

* 8b98498a58 net/http: make Transport.RoundTrip preserve Requests
* f84bbd52b0 cmd/compile: mark block control instruction unsafe in "all unsafe" functions

Benchmarked again at f84bbd5 (just before the change to net/http), and now it's 4% slower.

I will try the same experiment later today on a Mac laptop, once I am done using it for meetings.

@dr2chase
Copy link
Contributor

@dr2chase dr2chase commented Jun 23, 2020

I tried the comparison on a Mac laptop, Chrome and IDE shut down, but the numbers (30 repetitions of 10-second runs) were too noisy to be useful. I need to try again, very carefully, but I it would be nice if the bug filer could try tip and see if things look better, since (once!) they seemed better for me on Linux.

@dmitshur
Copy link
Member

@dmitshur dmitshur commented Jun 23, 2020

Thanks for looking @dr2chase. I can try reproducing this on a Mac laptop too.

it would be nice if the bug filer could try tip and see if things look better

@proyb6 Are you able to try again with the latest tip commit? (The gotip command may be convenient for this.)

@dr2chase
Copy link
Contributor

@dr2chase dr2chase commented Jun 24, 2020

FYI, I ran a second experiment on Linux (same machine, but this time using "perflock" for the benchmarked server).

perflock ./114 >& 114-run.log &
for j in {1..5} ; do ( for i in {1..25} ; do wrk -c100 -d5 http://localhost:8114/hello; done; )  >& b114-${j}.log ; done;
kill %1

perflock ./115 >& 115-run.log &
for j in {1..5} ; do ( for i in {1..25} ; do wrk -c100 -d5 http://localhost:8115/hello; done; )  >& b115-${j}.log ; done;
kill %1

perflock ./115-tip >& tip-run.log &
for j in {1..5}
kill %1

First, it looks like the bug is indeed reproducible against f84bbd5. Notice how there's not much difference among either group of 5, max/min is under 1%.

  114 run 1 114 run 2 114 run 3 114 run 4 114 run 5 max/min   115 run 1 115 run 2 115 run 3 115 run 4 115 run 5 max/min
  38399.48 38280.89 38339.71 38193.77 38316.30 1.005385715   36391.54 36522.23 36334.43 36273.72 36408.57 1.006850987
  38388.11 38315.11 38395.04 38400.81 38357.88 1.002236715   36563.58 36613.01 36353.43 36445.3 36562.06 1.007140454
              mean(115)/mean(114) 0.948 0.954 0.948 0.950 0.950  
              median(115)/median(114) 0.952 0.956 0.947 0.949 0.953  

It also looks like the bug is fixed at tip, and also that there's more noise among the runs at tip (same numbers for 114). Note that I am taking maxs and mins of numbers that are already medians or averages, and I was using perflock, so this is a little interesting, maybe some service process woke up during the benchmarks.

  114 run 1 114 run 2 114 run 3 114 run 4 114 run 5 max/min   tip run 1 tip run 2 tip run 3 tip run 4 tip run 5 max/min
averages 38399.48 38280.89 38339.71 38193.77 38316.30 1.005385715   38246.86 37958.87 38003.92 38281.55 38381.32 1.011129077
medians 38388.11 38315.11 38395.04 38400.81 38357.88 1.002236715   38309.13 37897.57 38123.49 38318.6 38409.12 1.013498227
              mean(tip)/mean(114) 0.996 0.992 0.991 1.002 1.002  
              median(tip)/median(114) 0.998 0.989 0.993 0.998 1.001  

That is, I believe the bug is consistently reproducible on my pretty-quiet (office-quarantined) deskside box, and it has also been fixed, most likely by the first commit after f84bbd5 but perhaps by a later one.

@dmitshur
Copy link
Member

@dmitshur dmitshur commented Jun 25, 2020

I reproduced this with results similar to what's posted above on a macOS laptop, and I don't have much new information to add. The difference between 1.14.4 and tip (3b2f67a) is very small compared to the variance of the micro benchmark, especially without artificial restrictions such as GOMAXPROCS=1, and I wasn't able to narrow it down further.

It seems to correlate to the various changes to net/http between 1.14 and tip (https://github.com/golang/go/commits/master/src/net/http), most of which were minor strictness/correctness improvements, and none were optimizations.

Perhaps someone else can narrow it down further or more conclusively, but I did not find an actionable issue here.

@dmitshur dmitshur changed the title net/http: performance degradation in 1.15beta1 net/http: HTTP/1.1 performance degradation in 1.15beta1 Jun 25, 2020
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Linked pull requests

Successfully merging a pull request may close this issue.

None yet
6 participants
You can’t perform that action at this time.