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

fd0 · 2016-08-10T10:25:27Z

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)

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"

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.

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.

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.

The text was updated successfully, but these errors were encountered:

evanj · 2016-08-12T03:28:49Z

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 · 2016-08-12T03:31:05Z

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

fd0 · 2016-08-12T06:32:53Z

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 · 2016-08-26T16:43:29Z

/cc @bradfitz

quentinmit · 2016-09-29T18:43:44Z

ping @bradfitz

bradfitz · 2016-09-29T18:49:11Z

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 · 2016-10-21T21:00:20Z

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 · 2016-10-22T17:12:57Z

Thanks for looking into this issue!

fd0 mentioned this issue Aug 10, 2016

Memory leak when backing up over http2 to minio behind Nginx restic/restic#565

Closed

quentinmit added this to the Go1.8 milestone Aug 26, 2016

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 self-assigned this Sep 29, 2016

bradfitz added the help wanted label Sep 29, 2016

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 closed this as completed Oct 21, 2016

fdoumet mentioned this issue Jun 8, 2017

High memory usage due to Go HTTP2 early close bug GoogleCloudPlatform/gcsfuse#227

Closed

golang locked and limited conversation to collaborators Oct 22, 2017

gopherbot added the FrozenDueToAge label Oct 22, 2017

rsc unassigned bradfitz Jun 23, 2022

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

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

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

fd0 commented Aug 10, 2016 •

edited

Loading

evanj commented Aug 12, 2016

evanj commented Aug 12, 2016 •

edited

Loading

fd0 commented Aug 12, 2016

quentinmit commented Aug 26, 2016

quentinmit commented Sep 29, 2016

bradfitz commented Sep 29, 2016

bradfitz commented Oct 21, 2016

fd0 commented Oct 22, 2016

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

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

Comments

fd0 commented Aug 10, 2016 • edited Loading

evanj commented Aug 12, 2016

evanj commented Aug 12, 2016 • edited Loading

fd0 commented Aug 12, 2016

quentinmit commented Aug 26, 2016

quentinmit commented Sep 29, 2016

bradfitz commented Sep 29, 2016

bradfitz commented Oct 21, 2016

fd0 commented Oct 22, 2016

fd0 commented Aug 10, 2016 •

edited

Loading

evanj commented Aug 12, 2016 •

edited

Loading