net/http: unexpectedly slow initialization

[KAction]

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.

[bcmills]

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?

[KAction]

profile.gz

[mengzhuo]

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]

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

[tebeka]

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