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

Jump to bottom

net/http: unexpectedly slow initialization #50511

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

net/http: unexpectedly slow initialization #50511

KAction opened this issue Jan 8, 2022 · 5 comments
Labels
help wanted NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. Performance
Milestone
Backlog

Comments

@KAction
Copy link

KAction commented Jan 8, 2022 •
edited

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 bcmills added Performance NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. help wanted labels Jan 10, 2022
@bcmills
Copy link
Contributor

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 commented Jan 10, 2022

profile.gz

@mengzhuo
Copy link
Contributor

mengzhuo commented Jan 11, 2022 •
edited

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

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

@tebeka
Copy link
Contributor

tebeka commented Nov 23, 2023

For me with an /etc/hosts of 10,000 lines it's not that slow (go 1.21.4) comparing to curl (my network is slow)

$ time curl https://ifconfig.me
2a06:c701:7033:b900:cb81:fd2c:98e6:828bcurl https://ifconfig.me  0.04s user 0.01s system 11% cpu 0.473 total

$ time /tmp/t                  
2a06:c701:7033:b900:cb81:fd2c:98e6:828b/tmp/t  0.04s user 0.02s system 17% cpu 0.353 total

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
help wanted NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. Performance
Projects
None yet
Milestone
Backlog
Development

No branches or pull requests
4 participants
@tebeka @mengzhuo @bcmills @KAction