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

x/net/http2: Requesting data via http2 and closing the response body early uses 3-5x more memory than via http1 #16656

Closed
fd0 opened this issue Aug 10, 2016 · 8 comments
Milestone

Comments

@fd0
Copy link

fd0 commented Aug 10, 2016

  1. What version of Go are you using (go version)?
go version go1.6.3 linux/amd64

(It was reported to also occur on Go 1.7rc6)

  1. What operating system and processor architecture are you using (go env)?
GOARCH="amd64"
GOBIN=""
GOEXE=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOOS="linux"
GOPATH="/home/fd0/shared/work/go"
GORACE=""
GOROOT="/home/fd0/src/go"
GOTOOLDIR="/home/fd0/src/go/pkg/tool/linux_amd64"
GO15VENDOREXPERIMENT="1"
CC="gcc"
GOGCCFLAGS="-fPIC -m64 -pthread -fmessage-length=0"
CXX="g++"
CGO_ENABLED="1"
  1. What did you do?

Writing a program that requests a larger file via HTTP GET, but only reads the first few bytes of the response body, then calls Close() on it.

  1. What did you expect to see?

I expect that the HTTP download is aborted soon after the body is closed. Especially, I expect that only very little data is read from the server and stored in a buffer, regardless of the underlying transmission protocol.

  1. What did you see instead?

Requesting and then closing the body takes a lot of memory. Disabling http2 reduces this a lot.

At https://fd0.me/tmp/random100MB I've created a file with 100MB of random data. The following Go program was used to request the file, read the first 100 bytes, and then close the response body several times in a loop:

package main

import (
        "fmt"
        "io"
        "net/http"
        "runtime"
)

func main() {
        for i := 0; i < 100; i++ {
                resp, err := http.Get(fmt.Sprintf("https://fd0.me/tmp/random100MB?rand=%d", i))
                if err != nil {
                        panic(err)
                }

                buf := make([]byte, 100)
                _, err = io.ReadFull(resp.Body, buf)
                if err != nil {
                        panic(err)
                }

                err = resp.Body.Close()
                if err != nil {
                        panic(err)
                }
        }

        var mem runtime.MemStats
        runtime.ReadMemStats(&mem)

        fmt.Printf("requests are done, memory from system: %v\n", mem.Sys)
}

With Go 1.6.3 standard http client (uses http2), this takes about 500MB of memory:

$ go run http2test.go
requests are done, memory from system: 509364472

Disabling http2 reduces this a lot:

$ GODEBUG=http2client=0 go run http2test.go
requests are done, memory from system: 9312504

Server logs (Caddy in this case) show that much more data is actually read per request, ~2.5MiB via HTTP2 vs. ~200KiB via HTTP1:

1.2.3.4 - [09/Aug/2016:11:49:12 +0200] "GET /tmp/random100MB?rand=96 HTTP/2.0" 200 2490368
1.2.3.4 - [09/Aug/2016:11:49:12 +0200] "GET /tmp/random100MB?rand=97 HTTP/2.0" 200 2523136
1.2.3.4 - [09/Aug/2016:11:49:12 +0200] "GET /tmp/random100MB?rand=98 HTTP/2.0" 200 2523136
1.2.3.4 - [09/Aug/2016:11:49:12 +0200] "GET /tmp/random100MB?rand=99 HTTP/2.0" 200 2293760
1.2.3.4 - [09/Aug/2016:11:49:45 +0200] "GET /tmp/random100MB?rand=96 HTTP/1.1" 200 131072
1.2.3.4 - [09/Aug/2016:11:49:45 +0200] "GET /tmp/random100MB?rand=97 HTTP/1.1" 200 294912
1.2.3.4 - [09/Aug/2016:11:49:45 +0200] "GET /tmp/random100MB?rand=98 HTTP/1.1" 200 262144
1.2.3.4 - [09/Aug/2016:11:49:45 +0200] "GET /tmp/random100MB?rand=99 HTTP/1.1" 200 131072

In the real world, this came up as restic/restic#565 where a user described that accessing backup data (restic is a backup program) on s3 over http2 is impossible because the OOM killer terminates the process.

I'm not really sure what's going on here, or even if this is a bug at all.

I have a hunch that, in addition to loading more data, the http2 client code in this case forgets to free some buffers.

What do you think? Please feel free to use the URL above to test this.

@evanj
Copy link
Contributor

evanj commented Aug 12, 2016

FWIW I'm seeing something similar while reading files from Google Cloud Storage using that API. Again, setting GODEBUG=http2client=0 makes the memory usage constant.

@evanj
Copy link
Contributor

evanj commented Aug 12, 2016

This sounds very similar to #15930 which was marked fixed.

@fd0
Copy link
Author

fd0 commented Aug 12, 2016

GC trace is also very different:

$ GODEBUG=gctrace=1,http2client=1 go run main.go
gc 1 @0.032s 0%: 0.059+0.68+0.11 ms clock, 0.23+0/0.39/0.86+0.47 ms cpu, 4->4->0 MB, 5 MB goal, 4 P
gc 2 @0.050s 1%: 0.026+0.66+0.27 ms clock, 0.10+0/0.56/1.0+1.0 ms cpu, 4->4->0 MB, 5 MB goal, 4 P
gc 3 @0.068s 2%: 0.022+0.77+0.38 ms clock, 0.088+0.48/0.65/1.1+1.5 ms cpu, 4->4->0 MB, 5 MB goal, 4 P
gc 4 @0.088s 2%: 0.023+0.90+0.29 ms clock, 0.094+0.36/0.85/1.3+1.1 ms cpu, 4->4->1 MB, 5 MB goal, 4 P
# command-line-arguments
gc 1 @0.015s 5%: 0.059+2.1+0.38 ms clock, 0.17+1.2/1.4/2.4+1.1 ms cpu, 4->4->2 MB, 5 MB goal, 4 P
gc 2 @0.025s 8%: 0.017+2.2+0.49 ms clock, 0.070+1.7/2.1/2.9+1.9 ms cpu, 4->5->4 MB, 5 MB goal, 4 P
gc 3 @0.041s 8%: 0.021+2.8+0.14 ms clock, 0.086+2.3/2.5/5.3+0.59 ms cpu, 8->8->6 MB, 9 MB goal, 4 P
# command-line-arguments
gc 1 @0.015s 4%: 0.17+1.1+0.22 ms clock, 0.53+1.0/0.96/2.1+0.66 ms cpu, 4->4->2 MB, 5 MB goal, 4 P
gc 2 @0.024s 6%: 0.022+3.2+0.32 ms clock, 0.088+1.2/1.6/4.5+1.2 ms cpu, 5->5->4 MB, 6 MB goal, 4 P
gc 3 @0.045s 7%: 0.018+3.6+0.27 ms clock, 0.073+2.3/3.0/5.8+1.0 ms cpu, 8->8->7 MB, 9 MB goal, 4 P
gc 4 @0.069s 7%: 0.016+14+0.30 ms clock, 0.065+5.5/3.8/7.4+1.2 ms cpu, 13->15->12 MB, 14 MB goal, 4 P
gc 5 @0.106s 8%: 0.019+9.5+0.27 ms clock, 0.077+5.6/9.5/11+1.0 ms cpu, 20->20->18 MB, 22 MB goal, 4 P
gc 6 @0.178s 8%: 0.019+15+0.30 ms clock, 0.079+10/11/25+1.2 ms cpu, 35->36->28 MB, 36 MB goal, 4 P
gc 7 @0.286s 7%: 0.024+28+0.28 ms clock, 0.098+10/20/47+1.1 ms cpu, 55->57->47 MB, 57 MB goal, 4 P
gc 1 @0.027s 2%: 0.16+1.3+0.28 ms clock, 0.33+1.1/1.1/1.2+0.56 ms cpu, 4->4->1 MB, 5 MB goal, 4 P
gc 2 @0.064s 2%: 0.030+1.3+0.56 ms clock, 0.12+0.015/1.2/1.2+2.2 ms cpu, 4->4->2 MB, 5 MB goal, 4 P
gc 3 @0.087s 2%: 0.024+5.0+0.23 ms clock, 0.096+0/1.6/1.3+0.95 ms cpu, 6->6->5 MB, 7 MB goal, 4 P
gc 4 @0.133s 1%: 0.017+5.8+0.25 ms clock, 0.053+0.089/0.013/1.2+0.75 ms cpu, 9->10->7 MB, 10 MB goal, 4 P
gc 5 @0.180s 1%: 0.018+19+0.27 ms clock, 0.074+0.42/0.56/0.65+1.0 ms cpu, 12->14->11 MB, 13 MB goal, 4 P
gc 6 @0.260s 1%: 0.017+1.2+0.25 ms clock, 0.069+0.10/0.93/0.27+1.0 ms cpu, 17->17->13 MB, 18 MB goal, 4 P
gc 7 @0.381s 1%: 0.019+0.80+0.28 ms clock, 0.077+0.31/0.67/0.71+1.1 ms cpu, 27->27->20 MB, 28 MB goal, 4 P
gc 8 @0.578s 0%: 0.018+1.1+0.29 ms clock, 0.073+0.65/1.0/0.44+1.1 ms cpu, 39->39->31 MB, 40 MB goal, 4 P
gc 9 @0.820s 0%: 0.019+1.1+0.25 ms clock, 0.076+0.009/1.0/1.0+1.0 ms cpu, 60->60->45 MB, 62 MB goal, 4 P
gc 10 @1.226s 0%: 0.021+1.9+0.24 ms clock, 0.087+0/0.94/2.1+0.97 ms cpu, 88->88->67 MB, 90 MB goal, 4 P
gc 11 @1.854s 0%: 0.019+1.1+0.24 ms clock, 0.079+0.12/1.0/1.0+0.98 ms cpu, 131->131->99 MB, 134 MB goal, 4 P
gc 12 @2.717s 0%: 0.020+1.5+0.23 ms clock, 0.082+0/1.2/2.0+0.94 ms cpu, 195->195->148 MB, 199 MB goal, 4 P
requests are done, memory from system: 315361528

Versus:

$ GODEBUG=gctrace=1,http2client=0 go run main.go
gc 1 @0.020s 2%: 0.14+0.61+0.22 ms clock, 0.43+0.39/0.41/0.36+0.66 ms cpu, 4->4->0 MB, 5 MB goal, 4 P
gc 2 @0.032s 2%: 0.021+0.64+0.090 ms clock, 0.084+0.010/0.57/0.59+0.36 ms cpu, 4->4->0 MB, 5 MB goal, 4 P
gc 3 @0.044s 2%: 0.019+0.71+0.24 ms clock, 0.076+0/0.51/1.0+0.96 ms cpu, 4->4->1 MB, 5 MB goal, 4 P
gc 4 @0.055s 2%: 0.017+0.93+0.25 ms clock, 0.069+0/0.75/1.4+1.0 ms cpu, 4->4->1 MB, 5 MB goal, 4 P
# command-line-arguments
gc 1 @0.010s 4%: 0.074+3.3+0.32 ms clock, 0.22+0/1.1/4.4+0.96 ms cpu, 4->4->2 MB, 5 MB goal, 4 P
gc 2 @0.019s 23%: 3.8+0.23+0.34 ms clock, 15+0/3.7/8.1+1.3 ms cpu, 5->5->4 MB, 6 MB goal, 4 P
gc 3 @0.035s 18%: 0.020+3.9+0.35 ms clock, 0.083+0/3.8/9.5+1.4 ms cpu, 8->8->6 MB, 9 MB goal, 4 P
# command-line-arguments
gc 1 @0.012s 4%: 0.068+6.4+0.30 ms clock, 0.20+0/2.7/0.74+0.92 ms cpu, 4->4->3 MB, 5 MB goal, 4 P
gc 2 @0.024s 7%: 0.026+3.6+0.26 ms clock, 0.10+0.021/3.5/2.4+1.0 ms cpu, 5->5->4 MB, 6 MB goal, 4 P
gc 3 @0.043s 8%: 0.020+4.4+0.24 ms clock, 0.080+2.0/3.9/6.0+0.96 ms cpu, 8->8->7 MB, 9 MB goal, 4 P
gc 4 @0.069s 7%: 0.023+15+0.078 ms clock, 0.094+5.8/4.1/8.1+0.31 ms cpu, 13->15->12 MB, 14 MB goal, 4 P
gc 5 @0.111s 8%: 0.020+8.9+0.27 ms clock, 0.081+6.4/7.0/15+1.0 ms cpu, 20->20->18 MB, 23 MB goal, 4 P
gc 6 @0.182s 8%: 0.020+17+0.32 ms clock, 0.081+10/17/22+1.3 ms cpu, 36->37->29 MB, 37 MB goal, 4 P
gc 7 @0.292s 9%: 0.023+35+0.29 ms clock, 0.093+15/34/50+1.1 ms cpu, 56->58->49 MB, 58 MB goal, 4 P
gc 1 @0.031s 1%: 0.12+1.6+0.11 ms clock, 0.25+0.030/1.5/0.31+0.23 ms cpu, 4->4->1 MB, 5 MB goal, 4 P
gc 2 @0.178s 0%: 0.093+1.3+0.25 ms clock, 0.37+0.53/0.76/0.12+1.0 ms cpu, 4->4->1 MB, 5 MB goal, 4 P
gc 3 @0.322s 0%: 0.032+1.0+0.30 ms clock, 0.13+0.56/0.75/0.42+1.2 ms cpu, 4->4->1 MB, 5 MB goal, 4 P
gc 4 @0.461s 0%: 0.028+0.98+0.26 ms clock, 0.11+0.017/0.97/1.3+1.0 ms cpu, 4->4->1 MB, 5 MB goal, 4 P
gc 5 @0.580s 0%: 0.007+1.1+0.25 ms clock, 0.031+0.27/1.0/0.30+1.0 ms cpu, 4->4->1 MB, 5 MB goal, 4 P
gc 6 @0.700s 0%: 0.009+1.4+0.25 ms clock, 0.037+0.35/1.3/0.051+1.0 ms cpu, 4->4->1 MB, 5 MB goal, 4 P
requests are done, memory from system: 9312504

@quentinmit quentinmit added this to the Go1.8 milestone Aug 26, 2016
@quentinmit
Copy link
Contributor

/cc @bradfitz

@quentinmit
Copy link
Contributor

ping @bradfitz

@quentinmit quentinmit added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Sep 29, 2016
@bradfitz bradfitz self-assigned this Sep 29, 2016
@bradfitz
Copy link
Contributor

I'll take ownership of this, but it's pretty low priority for now. If others could investigate, I'd appreciate it.

/cc @bmizerany too

@bradfitz bradfitz removed help wanted NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. labels Oct 21, 2016
@bradfitz
Copy link
Contributor

This is actually expected.

http2's Transport is always reading from the peer and has a initial window size of bytes it'll read, compared to http1.

So I would expect more allocations.

Is this actually a problem? I don't imagine reading part of the response happens often.

Closing until there's reason to believe we need to change anything.

@fd0
Copy link
Author

fd0 commented Oct 22, 2016

Thanks for looking into this issue!

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Projects
None yet
Development

No branches or pull requests

5 participants