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: unexpectedly slow initialization #50511

Open
KAction opened this issue Jan 8, 2022 · 4 comments
Open

net/http: unexpectedly slow initialization #50511

KAction opened this issue Jan 8, 2022 · 4 comments

Comments

@KAction
Copy link

@KAction KAction commented Jan 8, 2022

Here is trivial program that makes GET request:

import (
        "fmt"
        "io/ioutil"
        "log"
        "net/http"
)

func main() {
        resp, _ := http.Get("https://ifconfig.me")
        defer resp.Body.Close()
        body, err := ioutil.ReadAll(resp.Body)
        if err != nil {
                log.Fatal(err)
        }

        fmt.Print(string(body))
}

When compiled and run on Darwin system (using binary distribution), it have more or less expected performance -- twice as slow compared to curl.

$ /usr/bin/time ./hello
173.66.169.194        0.25 real         0.05 user         0.01 sys
$ /usr/bin/time curl https://ifconfig.me
173.66.169.194        0.12 real         0.01 user         0.01 sys

But when I compile and run it on my Linux box (Linux void-live 5.13.13_1 #1 SMP Fri Aug 27 13:28:13 UTC 2021 x86_64 GNU/Linux),
also using binary distribution, I get following results:

$ time ./hello
173.66.169.194
real      0m 1.03s
user    0m 1.30s
sys     0m 0.14s
$ time curl https://ifconfig.me
173.66.169.194
real      0m 0.16s
user    0m 0.06s
sys     0m 0.00s

Difference is much bigger. This time seems to come from some one-time initialization -- second request made in same program is fast. Here is annotated strace. It looks like it is doing many "rt_sigreturn" calls, but this is just my guess.

I have access to another linux box, with unusual kernel (lacking madvise(2), for example), which have more of the same problem: first request takes around 4 seconds, any subsequent work as expected.

@KAction KAction changed the title net/http is unexpectedly slow compared to curl(1) net/http has unexpectedly slow initialization Jan 8, 2022
@bcmills
Copy link
Member

@bcmills bcmills commented Jan 10, 2022

The rt_sigreturn calls are in response to SIGURG, which the runtime uses for asynchronous preemption.

That seems to imply that the latency is going into something CPU-bound, and the fact that the reported user time exceeds the reported real time corroborates that at least part of the program is spending non-trivial CPU on something.

If you add a pprof.StartCPUProfile at the beginning of func main and pprof.StopCPUProfile at the end, does it show anything interesting?

@bcmills bcmills added this to the Backlog milestone Jan 10, 2022
@bcmills bcmills changed the title net/http has unexpectedly slow initialization net/http: unexpectedly slow initialization Jan 10, 2022
@KAction
Copy link
Author

@KAction KAction commented Jan 10, 2022

@mengzhuo
Copy link
Contributor

@mengzhuo mengzhuo commented Jan 11, 2022

Take a look at the strace log, it seems stalled after reading a large host file (14M) .

2022-01-08 09:58:49.823669500 read(6, "10.0.2.4 sourcehut.local\n10.0.2."..., 65536) = 65536
....after 7 seconds? still reading...
2022-01-08 09:58:56.787029500 read(6, "384.keywordblocks.com\n0.0.0.0 22"..., 65522) = 65522

I've tested on my Linux box, parsing 19M host file(655360 lines with same host name) takes 800ms for the first time and 3ms for second time.

@mengzhuo
Copy link
Contributor

@mengzhuo mengzhuo commented Jan 11, 2022

@bcmills maybe we can change title to: "net: takes too long to parse *nix host file" ?

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
3 participants