x/net/http2: high RAM usage after closing response bodies early with HTTP2 connections #20448

Closed
jacobsa opened this Issue May 22, 2017 · 14 comments

Comments

Projects
None yet
7 participants
@jacobsa
Contributor

jacobsa commented May 22, 2017

> go version
go version go1.8.1 darwin/amd64

The HTTP/2 client appears to use a large amount of memory when the user opens several serial requests to the same server, reading a small amount from each very large response body, and then closing the body.

This was discovered in GoogleCloudPlatform/gcsfuse#227. gcsfuse is a fuse file system for Google Cloud Storage. Because the file system doesn't know how much of the GCS object is going to be read, when it detects what appears to be a sequential read through a file handle, it opens an HTTP request to GCS for the entire object, consuming what the client reads sequentially and then cancelling the request by closing the response body. The user in that issue noticed that making 500 such request serially causes gcsfuse to use 2 GiB of memory, even after closing all response bodies and performing garbage collection.

While on an airplane without Wi-Fi I managed to reproduce this in a self-contained program. The program starts a server with a handler that returns 1 GiB of data. Then it repeatedly makes GET requests where the client reads 10 MiB and then closes the body. The client optionally sleeps between reads from the response body, simulating a reasonable bandwidth internet connection. Afterward the program dumps a memory profile.

You can run it like this, using a little utility I wrote to easily see peak memory usage:

> go get -u github.com/jacobsa/cputime
> go get -u golang.org/x/net/http2
> go run $GOROOT/src/crypto/tls/generate_cert.go --host=localhost
> cputime ./reproduce --slow_client=[true|false] --http2=[true|false]

Here are the max RSS results I get:

  • HTTP/1, fast client: 12.62 MiB
  • HTTP/1, slow client: 11.29 MiB
  • HTTP/2, fast client: 19.13 MiB
  • HTTP/2, slow client: 450.80 MiB (!!)

450 MiB is insane, given that only one request is in flight at a time. I see that http.http2transportDefaultStreamFlow is 4 MiB, so I would expect at most 8 MiB of buffer usage for send and receive buffers, plus a few megs of overhead from the program itself.

According to the memory profile, pretty much all of that 450 MiB is in the pipe buffer written to by the client read loop. Note that the high usage persists even if I call runtime.GC several times after making each request.

I don't think the client is doing anything against the rules according to the package documentation (but please correct me if I'm wrong). So memory usage this high seems like a bug.

(By the way, the bandwidth achieved when using HTTP/2 is also generally lower than HTTP/1, and is much more variable. Should I file an issue for the poor performance too?)

@jacobsa jacobsa referenced this issue in GoogleCloudPlatform/gcsfuse May 22, 2017

Closed

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

@odeke-em odeke-em changed the title from net/http2: high RAM usage after closing response bodies early to /x/net/http2: high RAM usage after closing response bodies early with HTTP2 connections May 22, 2017

@odeke-em

This comment has been minimized.

Show comment
Hide comment
@odeke-em

odeke-em May 22, 2017

Member

/cc HTTP folks @bradfitz @tombergan and then compiler+runtime squad @josharian @aclements

Member

odeke-em commented May 22, 2017

/cc HTTP folks @bradfitz @tombergan and then compiler+runtime squad @josharian @aclements

@josharian

This comment has been minimized.

Show comment
Hide comment
@josharian

josharian May 22, 2017

Contributor

Possibly related: #19469, #18336.

Contributor

josharian commented May 22, 2017

Possibly related: #19469, #18336.

@aclements

This comment has been minimized.

Show comment
Hide comment
@aclements

aclements May 22, 2017

Member

At a glance, it sounds like the pipe buffer might simply not have the back-pressure that it needs, so the client side of the connection is filling it up with much of the 1GB response even though only 10MB is being drained. I wouldn't guess that this is a compiler/runtime issue unless there's evidence that the HTTP/2 client implementation shouldn't be retaining that memory.

Member

aclements commented May 22, 2017

At a glance, it sounds like the pipe buffer might simply not have the back-pressure that it needs, so the client side of the connection is filling it up with much of the 1GB response even though only 10MB is being drained. I wouldn't guess that this is a compiler/runtime issue unless there's evidence that the HTTP/2 client implementation shouldn't be retaining that memory.

@tombergan

This comment has been minimized.

Show comment
Hide comment
@tombergan

tombergan May 22, 2017

Contributor

I haven't had a chance to try running reproduce.go, but I believe the problem is that we keep writing to cs.bufPipe after the response body is closed if the server has more data to send. Note that we never set cs.bufPipe.b to nil, and closing a response body fails future Reads but not future Writes. I bet this problem wouldn't exist if the request was canceled rather than closed (not that I suggest doing that, this is clearly a bug).

https://github.com/golang/net/blob/master/http2/transport.go#L1669
https://github.com/golang/net/blob/master/http2/transport.go#L1705

Contributor

tombergan commented May 22, 2017

I haven't had a chance to try running reproduce.go, but I believe the problem is that we keep writing to cs.bufPipe after the response body is closed if the server has more data to send. Note that we never set cs.bufPipe.b to nil, and closing a response body fails future Reads but not future Writes. I bet this problem wouldn't exist if the request was canceled rather than closed (not that I suggest doing that, this is clearly a bug).

https://github.com/golang/net/blob/master/http2/transport.go#L1669
https://github.com/golang/net/blob/master/http2/transport.go#L1705

@gopherbot

This comment has been minimized.

Show comment
Hide comment

CL https://golang.org/cl/43810 mentions this issue.

@tombergan

This comment has been minimized.

Show comment
Hide comment
@tombergan

tombergan May 22, 2017

Contributor

Before https://golang.org/cl/43810:
HTTP/2 fast: 15MB
HTTP/2 slow: 150MB

After https://golang.org/cl/43810:
HTTP/2 fast: 12MB
HTTP/2 slow: 21MB

Contributor

tombergan commented May 22, 2017

Before https://golang.org/cl/43810:
HTTP/2 fast: 15MB
HTTP/2 slow: 150MB

After https://golang.org/cl/43810:
HTTP/2 fast: 12MB
HTTP/2 slow: 21MB

@bradfitz bradfitz changed the title from /x/net/http2: high RAM usage after closing response bodies early with HTTP2 connections to x/net/http2: high RAM usage after closing response bodies early with HTTP2 connections May 22, 2017

@bradfitz bradfitz added this to the Go1.9 milestone May 22, 2017

@tombergan

This comment has been minimized.

Show comment
Hide comment
@tombergan

tombergan May 22, 2017

Contributor

@jacobsa We have a partial fix (see above). However, note that each HTTP/2 connection has a 1GB flow-control window by default, and currently there isn't a knob to adjust this value.
https://github.com/golang/net/blob/master/http2/transport.go#L37

If the above fix is not good enough for you and you want a separate knob, could you file another bug? Thanks!

Contributor

tombergan commented May 22, 2017

@jacobsa We have a partial fix (see above). However, note that each HTTP/2 connection has a 1GB flow-control window by default, and currently there isn't a knob to adjust this value.
https://github.com/golang/net/blob/master/http2/transport.go#L37

If the above fix is not good enough for you and you want a separate knob, could you file another bug? Thanks!

@gopherbot

This comment has been minimized.

Show comment
Hide comment

CL https://golang.org/cl/43853 mentions this issue.

gopherbot pushed a commit to golang/net that referenced this issue May 22, 2017

http2: mostly test for Transport memory issue
Updates golang/go#20448

Change-Id: I6366b0b0b36d81095ab347ca35e1e72169c05c15
Reviewed-on: https://go-review.googlesource.com/43853
Run-TryBot: Brad Fitzpatrick <bradfitz@golang.org>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: Tom Bergan <tombergan@google.com>
@jacobsa

This comment has been minimized.

Show comment
Hide comment
@jacobsa

jacobsa May 23, 2017

Contributor

@tombergan: thanks. This is 4 MiB per stream by default though, right? I have thought in the past that it ought to be tunable (it seems way too high for low-latency/bandwidth connections, and too low for high-latency/bandwidth connections), but I've never had a good way to choose a value myself so never filed an issue. If I come up with something better, I will file.

Contributor

jacobsa commented May 23, 2017

@tombergan: thanks. This is 4 MiB per stream by default though, right? I have thought in the past that it ought to be tunable (it seems way too high for low-latency/bandwidth connections, and too low for high-latency/bandwidth connections), but I've never had a good way to choose a value myself so never filed an issue. If I come up with something better, I will file.

@tombergan

This comment has been minimized.

Show comment
Hide comment
@tombergan

tombergan May 23, 2017

Contributor

That's right, 4MB per stream, so with enough concurrent streams, 1GB memory usage can be WAI.

Contributor

tombergan commented May 23, 2017

That's right, 4MB per stream, so with enough concurrent streams, 1GB memory usage can be WAI.

gopherbot pushed a commit to golang/net that referenced this issue May 23, 2017

http2: Discard DATA frames from the server after the response body is…
… closed

After a response body is closed, we keep writing to the bufPipe. This
accumulates bytes that will never be read, wasting memory. The fix is to
discard the buffer on pipe.BreakWithError.

Updates golang/go#20448

Change-Id: Ia2cf46cb8c401fd8091ef3785eb48fe7b188bb57
Reviewed-on: https://go-review.googlesource.com/43810
Run-TryBot: Tom Bergan <tombergan@google.com>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: Brad Fitzpatrick <bradfitz@golang.org>
@jacobsa

This comment has been minimized.

Show comment
Hide comment
@jacobsa

jacobsa May 23, 2017

Contributor

@tombergan: question about golang/net@1a26cf0: are the existing contents of the pipe buffer also discarded when it is closed (rather than just the future data frames)? It's not clear to me from the CL description.

Contributor

jacobsa commented May 23, 2017

@tombergan: question about golang/net@1a26cf0: are the existing contents of the pipe buffer also discarded when it is closed (rather than just the future data frames)? It's not clear to me from the CL description.

@tombergan

This comment has been minimized.

Show comment
Hide comment
@tombergan

tombergan May 23, 2017

Contributor

Yes, the existing contents of the pipe buffer are discarded when the response body is closed (see line 120 of pipe.go)

Contributor

tombergan commented May 23, 2017

Yes, the existing contents of the pipe buffer are discarded when the response body is closed (see line 120 of pipe.go)

@jacobsa

This comment has been minimized.

Show comment
Hide comment
@jacobsa

jacobsa May 23, 2017

Contributor

Thanks, I missed that. LGTM.

Contributor

jacobsa commented May 23, 2017

Thanks, I missed that. LGTM.

@gopherbot

This comment has been minimized.

Show comment
Hide comment

CL https://golang.org/cl/44006 mentions this issue.

@gopherbot gopherbot closed this in e6e6cad May 24, 2017

c3mb0 pushed a commit to c3mb0/net that referenced this issue Apr 2, 2018

http2: mostly test for Transport memory issue
Updates golang/go#20448

Change-Id: I6366b0b0b36d81095ab347ca35e1e72169c05c15
Reviewed-on: https://go-review.googlesource.com/43853
Run-TryBot: Brad Fitzpatrick <bradfitz@golang.org>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: Tom Bergan <tombergan@google.com>

c3mb0 pushed a commit to c3mb0/net that referenced this issue Apr 2, 2018

http2: Discard DATA frames from the server after the response body is…
… closed

After a response body is closed, we keep writing to the bufPipe. This
accumulates bytes that will never be read, wasting memory. The fix is to
discard the buffer on pipe.BreakWithError.

Updates golang/go#20448

Change-Id: Ia2cf46cb8c401fd8091ef3785eb48fe7b188bb57
Reviewed-on: https://go-review.googlesource.com/43810
Run-TryBot: Tom Bergan <tombergan@google.com>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: Brad Fitzpatrick <bradfitz@golang.org>

@golang golang locked and limited conversation to collaborators May 24, 2018

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