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

Drain Response.Body to enable TCP/TLS connection reuse (4x speedup) #317

Merged
merged 1 commit into from Mar 27, 2016

Conversation

Projects
None yet
@FiloSottile
Member

FiloSottile commented Mar 27, 2016

On successful queries (on errors ReadAll runs in CheckResponse), the
Response.Body is not read all the way to the EOF as json.Decoder is used,
which stops at the end of the object, which is probably followed by a \n.

Then, Response.Body.Close() is called. When that happens with a non-drained
Body, the TCP/TLS connection is closed (which makes sense, in case there was
still a lot to read from the network), stopping the Transport from reusing
it. Also, a library user can't drain the Body themselves because Close() is
called before passing the Response to the user.

Since we know GitHub API responses only carry a single JSON object, draining
before closing is free, and saving all those handshakes causes huge savings
in latency, bandwidth and CPU for both the client and the poor GitHub
servers.

Here's the result of running the benchmark below on a ADSL connection:

before: 2m3.001599093s
after: 33.753543928s

func main() {
    ts := oauth2.StaticTokenSource(
        &oauth2.Token{AccessToken: os.Getenv("GITHUB_TOKEN")},
    )
    tc := oauth2.NewClient(oauth2.NoContext, ts)
    gh := github.NewClient(tc)
    start := time.Now()
    for i := 0; i < 100; i++ {
        gh.Repositories.Get("FiloSottile", "gvt")
        fmt.Print(".")
    }
    fmt.Printf("\n%s\n", time.Now().Sub(start))
}
Drain Response.Body to enable TCP/TLS connection reuse (4x speedup)
On successful queries (on errors ReadAll runs in CheckResponse), the
Response.Body is not read all the way to the EOF as json.Decoder is used,
which stops at the end of the object, which is probably followed by a \n.

Then, Response.Body.Close() is called.  When that happens with a non-drained
Body, the TCP/TLS connection is closed (which makes sense, in case there was
still a lot to read from the network), stopping the Transport from reusing
it.  Also, a library user can't drain the Body themselves because Close() is
called before passing the Response to the user.

Since we know GitHub API responses only carry a single JSON object, draining
before closing is free, and saving all those handshakes causes huge savings
in latency, bandwidth and CPU for both the client and the poor GitHub
servers.

Here's the result of running the benchmark below on a ADSL connection:

    before: 2m3.001599093s
    after: 33.753543928s

    func main() {
    	ts := oauth2.StaticTokenSource(
    		&oauth2.Token{AccessToken: os.Getenv("GITHUB_TOKEN")},
    	)
    	tc := oauth2.NewClient(oauth2.NoContext, ts)
    	gh := github.NewClient(tc)
    	start := time.Now()
    	for i := 0; i < 100; i++ {
    		gh.Repositories.Get("FiloSottile", "gvt")
    		fmt.Print(".")
    	}
    	fmt.Printf("\n%s\n", time.Now().Sub(start))
    }
@dmitshur

This comment has been minimized.

Show comment
Hide comment
@dmitshur

dmitshur Mar 27, 2016

Member

Hey Filippo, this is really cool! I have one question, I'll post it inline.

Member

dmitshur commented Mar 27, 2016

Hey Filippo, this is really cool! I have one question, I'll post it inline.

defer resp.Body.Close()
defer func() {
// Drain and close the body to let the Transport reuse the connection
io.Copy(ioutil.Discard, resp.Body)

This comment has been minimized.

@dmitshur

dmitshur Mar 27, 2016

Member

On successful queries (on errors ReadAll runs in CheckResponse), the
Response.Body is not read all the way to the EOF as json.Decoder is used,
which stops at the end of the object, which is probably followed by a \n.

Since we know GitHub API responses only carry a single JSON object, draining
before closing is free

I'm just curious, but have you tried doing something like n, _ := io.Copy(ioutil.Discard, resp.Body) here and dump the value of n? I'm curious if it's indeed 1 and contains a '\n', or something else.

@dmitshur

dmitshur Mar 27, 2016

Member

On successful queries (on errors ReadAll runs in CheckResponse), the
Response.Body is not read all the way to the EOF as json.Decoder is used,
which stops at the end of the object, which is probably followed by a \n.

Since we know GitHub API responses only carry a single JSON object, draining
before closing is free

I'm just curious, but have you tried doing something like n, _ := io.Copy(ioutil.Discard, resp.Body) here and dump the value of n? I'm curious if it's indeed 1 and contains a '\n', or something else.

This comment has been minimized.

@FiloSottile

FiloSottile Mar 27, 2016

Member

Good question. Just tried and it turns out it's zero!

Maybe explicitly hitting io.EOF flips a flag somewhere, this looks like something the runtime could improve on.

@FiloSottile

FiloSottile Mar 27, 2016

Member

Good question. Just tried and it turns out it's zero!

Maybe explicitly hitting io.EOF flips a flag somewhere, this looks like something the runtime could improve on.

This comment has been minimized.

@dmitshur

dmitshur Mar 27, 2016

Member

Cool, thanks for checking!

I think that's probably normal, and not something runtime could do better.

In a general case, readers deal with streams where the EOF may not be known in advance.

The read method is documented to either return nil error first time and 0, EOF the next, but it's also valid to return EOF right away. It's up to the implementation which approach to use.

When Read encounters an error or end-of-file condition after successfully reading n > 0 bytes, it returns the number of bytes read. It may return the (non-nil) error from the same call or return the error (and n == 0) from a subsequent call. An instance of this general case is that a Reader returning a non-zero number of bytes at the end of the input stream may return either err == EOF or err == nil. The next Read should return 0, EOF.

When reading from a network stream or some other unknown source where you can't cheat and look ahead, you may not know it's EOF until you actively try to read more bytes.

Also see this snippet.

@dmitshur

dmitshur Mar 27, 2016

Member

Cool, thanks for checking!

I think that's probably normal, and not something runtime could do better.

In a general case, readers deal with streams where the EOF may not be known in advance.

The read method is documented to either return nil error first time and 0, EOF the next, but it's also valid to return EOF right away. It's up to the implementation which approach to use.

When Read encounters an error or end-of-file condition after successfully reading n > 0 bytes, it returns the number of bytes read. It may return the (non-nil) error from the same call or return the error (and n == 0) from a subsequent call. An instance of this general case is that a Reader returning a non-zero number of bytes at the end of the input stream may return either err == EOF or err == nil. The next Read should return 0, EOF.

When reading from a network stream or some other unknown source where you can't cheat and look ahead, you may not know it's EOF until you actively try to read more bytes.

Also see this snippet.

This comment has been minimized.

@willnorris

willnorris Mar 27, 2016

Member

interestingly, I just tried this, and it's apparently discarding 0 bytes, yet I'm still seeing the same speed improvements @FiloSottile is reporting. Maybe it's just the io.EOF that is left to be read which is preventing the transport from being reused?

@willnorris

willnorris Mar 27, 2016

Member

interestingly, I just tried this, and it's apparently discarding 0 bytes, yet I'm still seeing the same speed improvements @FiloSottile is reporting. Maybe it's just the io.EOF that is left to be read which is preventing the transport from being reused?

This comment has been minimized.

@FiloSottile

FiloSottile Mar 27, 2016

Member

My idea of runtime improvement would be a Read of, say, 512 bytes with a 50ms timeout happening on close, which would probably be good enough for cases like this one. But I'm getting OT, I'll bring this to golang/go :)

@FiloSottile

FiloSottile Mar 27, 2016

Member

My idea of runtime improvement would be a Read of, say, 512 bytes with a 50ms timeout happening on close, which would probably be good enough for cases like this one. But I'm getting OT, I'll bring this to golang/go :)

This comment has been minimized.

@willnorris

willnorris Mar 27, 2016

Member

psh. stupid GitHub not updating this comment thread so I didn't see your identical comments :)

@willnorris

willnorris Mar 27, 2016

Member

psh. stupid GitHub not updating this comment thread so I didn't see your identical comments :)

@marcosnils

This comment has been minimized.

Show comment
Hide comment
@marcosnils

marcosnils Mar 27, 2016

Maybe it's a good idea to add a test for this?

marcosnils commented Mar 27, 2016

Maybe it's a good idea to add a test for this?

@FiloSottile

This comment has been minimized.

Show comment
Hide comment
@FiloSottile

FiloSottile Mar 27, 2016

Member

I don't have time to write one today (1:30am 😲), but I think one can be written like this

  • make one request
  • replace Dial in the Transport with panic()
  • make another request

But it might be flappy, as no behavior is guaranteed here AFAICT.

Can't think of a simpler one.

Member

FiloSottile commented Mar 27, 2016

I don't have time to write one today (1:30am 😲), but I think one can be written like this

  • make one request
  • replace Dial in the Transport with panic()
  • make another request

But it might be flappy, as no behavior is guaranteed here AFAICT.

Can't think of a simpler one.

@dmitshur

This comment has been minimized.

Show comment
Hide comment
@dmitshur

dmitshur Mar 27, 2016

Member

I don't think it's necessary to have a test for this, unless someone can come up with a reliable one. This is just normal behavior, and it's explained well in the comment in code. This change is not about correctness (the current code is also correct), it's about an optimization.

Member

dmitshur commented Mar 27, 2016

I don't think it's necessary to have a test for this, unless someone can come up with a reliable one. This is just normal behavior, and it's explained well in the comment in code. This change is not about correctness (the current code is also correct), it's about an optimization.

@willnorris willnorris merged commit e0ff711 into google:master Mar 27, 2016

2 checks passed

cla/google All necessary CLAs are signed
continuous-integration/travis-ci/pr The Travis CI build passed
Details
@willnorris

This comment has been minimized.

Show comment
Hide comment
@willnorris

willnorris Mar 27, 2016

Member

Thanks for the patch @FiloSottile!

Member

willnorris commented Mar 27, 2016

Thanks for the patch @FiloSottile!

@marcosnils

This comment has been minimized.

Show comment
Hide comment
@marcosnils

marcosnils Mar 28, 2016

make one request
replace Dial in the Transport with panic()
make another request

Why not just mocking with an httptest server any of the github endpoints and use go-github to make the request?. I'm not familiar with the library (I came here through the gophers slack) but I believe it would be fairy simple to do this and assert that the connection is being reused (I've done this in the past with some other projects. )

Thoughts?

marcosnils commented Mar 28, 2016

make one request
replace Dial in the Transport with panic()
make another request

Why not just mocking with an httptest server any of the github endpoints and use go-github to make the request?. I'm not familiar with the library (I came here through the gophers slack) but I believe it would be fairy simple to do this and assert that the connection is being reused (I've done this in the past with some other projects. )

Thoughts?

@bradfitz

This comment has been minimized.

Show comment
Hide comment
@bradfitz

bradfitz Mar 29, 2016

Contributor

Hi, author of net/http here. I cannot reproduce this result.

The underlying reader (the one beneath the oauth2.Transport's onEOFReader) is returning (83, io.EOF), which is successfully recycling the TCP connection, even without your patch.

Are your measurements actually from that code, or similar-ish code?

Which version of Go?
Which version of oauth2?

Contributor

bradfitz commented Mar 29, 2016

Hi, author of net/http here. I cannot reproduce this result.

The underlying reader (the one beneath the oauth2.Transport's onEOFReader) is returning (83, io.EOF), which is successfully recycling the TCP connection, even without your patch.

Are your measurements actually from that code, or similar-ish code?

Which version of Go?
Which version of oauth2?

@dmitshur

This comment has been minimized.

Show comment
Hide comment
@dmitshur

dmitshur Mar 29, 2016

Member

@bradfitz, I tried to reproduce this just now, and I was able to reliably see a significant performance difference. Exact program that I ran:

package main

import (
    "fmt"
    "log"
    "os"
    "time"

    "github.com/google/go-github/github"
    "golang.org/x/oauth2"
)

func main() {
    ts := oauth2.StaticTokenSource(
        &oauth2.Token{AccessToken: os.Getenv("GITHUB_TOKEN")},
    )
    tc := oauth2.NewClient(oauth2.NoContext, ts)
    gh := github.NewClient(tc)
    start := time.Now()
    for i := 0; i < 100; i++ {
        _, _, err := gh.Repositories.Get("FiloSottile", "gvt")
        if err != nil {
            log.Fatalln(err)
        }
        fmt.Print(".")
    }
    fmt.Printf("\n%s\n", time.Now().Sub(start))
}

I'm on go version go1.6 darwin/amd64, OS X 10.11.4 (15E65), and using latest current versions of all dependent repos:

Here are 4 runs with this change and 4 runs without, interleaved.

$ go list -f '{{join .Deps "\n"}}' . | gostatus -stdin -v
     github.com/google/go-querystring/...
     github.com/google/go-github/...
     golang.org/x/net/...
     golang.org/x/oauth2/...
$ go run main.go
....................................................................................................
15.141031633s
$ go run main.go
....................................................................................................
42.322153704s
$ go run main.go
....................................................................................................
14.219332967s
$ go run main.go
....................................................................................................
1m12.91558721s
$ go run main.go
....................................................................................................
15.287252642s
$ go run main.go
....................................................................................................
53.149206247s
$ go run main.go
....................................................................................................
18.676132354s
$ go run main.go
....................................................................................................
52.90852069s

The only difference between the alternate runs are whether io.Copy(ioutil.Discard, resp.Body) was commented out or not. As you can see, it makes a significant difference each time.

The fast runs (14-18 seconds) are with this change applied, and the slow runs (42-73 seconds) were with //io.Copy(ioutil.Discard, resp.Body) commented out.

Appendix

I've also tried adding error checking to the draining and body closing calls, just to see if there were any unexpected values there. There were no panics with either of:

defer func() {
    // Drain and close the body to let the Transport reuse the connection
    n, err := io.Copy(ioutil.Discard, resp.Body)
    if err != nil {
        panic(err)
    }
    if n != 0 {
        panic(fmt.Errorf("unexpected n: %v", n))
    }
    err = resp.Body.Close()
    if err != nil {
        panic(err)
    }
}()

Nor:

defer func() {
    // Drain and close the body to let the Transport reuse the connection
    /*n, err := io.Copy(ioutil.Discard, resp.Body)
    if err != nil {
        panic(err)
    }
    if n != 0 {
        panic(fmt.Errorf("unexpected n: %v", n))
    }*/
    err := resp.Body.Close()
    if err != nil {
        panic(err)
    }
}()

The performance difference remained as before.

Member

dmitshur commented Mar 29, 2016

@bradfitz, I tried to reproduce this just now, and I was able to reliably see a significant performance difference. Exact program that I ran:

package main

import (
    "fmt"
    "log"
    "os"
    "time"

    "github.com/google/go-github/github"
    "golang.org/x/oauth2"
)

func main() {
    ts := oauth2.StaticTokenSource(
        &oauth2.Token{AccessToken: os.Getenv("GITHUB_TOKEN")},
    )
    tc := oauth2.NewClient(oauth2.NoContext, ts)
    gh := github.NewClient(tc)
    start := time.Now()
    for i := 0; i < 100; i++ {
        _, _, err := gh.Repositories.Get("FiloSottile", "gvt")
        if err != nil {
            log.Fatalln(err)
        }
        fmt.Print(".")
    }
    fmt.Printf("\n%s\n", time.Now().Sub(start))
}

I'm on go version go1.6 darwin/amd64, OS X 10.11.4 (15E65), and using latest current versions of all dependent repos:

Here are 4 runs with this change and 4 runs without, interleaved.

$ go list -f '{{join .Deps "\n"}}' . | gostatus -stdin -v
     github.com/google/go-querystring/...
     github.com/google/go-github/...
     golang.org/x/net/...
     golang.org/x/oauth2/...
$ go run main.go
....................................................................................................
15.141031633s
$ go run main.go
....................................................................................................
42.322153704s
$ go run main.go
....................................................................................................
14.219332967s
$ go run main.go
....................................................................................................
1m12.91558721s
$ go run main.go
....................................................................................................
15.287252642s
$ go run main.go
....................................................................................................
53.149206247s
$ go run main.go
....................................................................................................
18.676132354s
$ go run main.go
....................................................................................................
52.90852069s

The only difference between the alternate runs are whether io.Copy(ioutil.Discard, resp.Body) was commented out or not. As you can see, it makes a significant difference each time.

The fast runs (14-18 seconds) are with this change applied, and the slow runs (42-73 seconds) were with //io.Copy(ioutil.Discard, resp.Body) commented out.

Appendix

I've also tried adding error checking to the draining and body closing calls, just to see if there were any unexpected values there. There were no panics with either of:

defer func() {
    // Drain and close the body to let the Transport reuse the connection
    n, err := io.Copy(ioutil.Discard, resp.Body)
    if err != nil {
        panic(err)
    }
    if n != 0 {
        panic(fmt.Errorf("unexpected n: %v", n))
    }
    err = resp.Body.Close()
    if err != nil {
        panic(err)
    }
}()

Nor:

defer func() {
    // Drain and close the body to let the Transport reuse the connection
    /*n, err := io.Copy(ioutil.Discard, resp.Body)
    if err != nil {
        panic(err)
    }
    if n != 0 {
        panic(fmt.Errorf("unexpected n: %v", n))
    }*/
    err := resp.Body.Close()
    if err != nil {
        panic(err)
    }
}()

The performance difference remained as before.

@dsymonds

This comment has been minimized.

Show comment
Hide comment
@dsymonds

dsymonds Mar 29, 2016

Member

Any chance you could try that experiment using Go tip? Brad was testing with (I believe) a version pretty close to tip. I wonder if there's something that changed in net/http since go1.6.

Member

dsymonds commented Mar 29, 2016

Any chance you could try that experiment using Go tip? Brad was testing with (I believe) a version pretty close to tip. I wonder if there's something that changed in net/http since go1.6.

@dmitshur

This comment has been minimized.

Show comment
Hide comment
@dmitshur

dmitshur Mar 29, 2016

Member

Sure, I can try with tip. It'll be a few moments because I'll have to get it and build it.

Member

dmitshur commented Mar 29, 2016

Sure, I can try with tip. It'll be a few moments because I'll have to get it and build it.

@dsymonds

This comment has been minimized.

Show comment
Hide comment
@dsymonds

dsymonds Mar 29, 2016

Member

Actually, never mind. I think I can reproduce it now at tip, on darwin/amd64 too.

Member

dsymonds commented Mar 29, 2016

Actually, never mind. I think I can reproduce it now at tip, on darwin/amd64 too.

@dsymonds

This comment has been minimized.

Show comment
Hide comment
@dsymonds

dsymonds Mar 29, 2016

Member

Here's me running your program in the same configurations you did:

$ go run x.go
....................................................................................................
30.027496143s
$ go run x.go
....................................................................................................
1m51.14892534s

I guess @bradfitz and I will poke into this some more tomorrow now that we have a reproduction case. Thanks @shurcooL!

Member

dsymonds commented Mar 29, 2016

Here's me running your program in the same configurations you did:

$ go run x.go
....................................................................................................
30.027496143s
$ go run x.go
....................................................................................................
1m51.14892534s

I guess @bradfitz and I will poke into this some more tomorrow now that we have a reproduction case. Thanks @shurcooL!

@dmitshur

This comment has been minimized.

Show comment
Hide comment
@dmitshur

dmitshur Mar 29, 2016

Member

FWIW, I had already started, and I was curious, so I tried 1.6 and tip in a Linux VM (Ubuntu 14.04), and I was able to reproduce it there too. Both with 1.6 and current tip (golang/go@45d334e). See screenshot.

Member

dmitshur commented Mar 29, 2016

FWIW, I had already started, and I was curious, so I tried 1.6 and tip in a Linux VM (Ubuntu 14.04), and I was able to reproduce it there too. Both with 1.6 and current tip (golang/go@45d334e). See screenshot.

@FiloSottile

This comment has been minimized.

Show comment
Hide comment
@FiloSottile

FiloSottile Mar 29, 2016

Member

@shurcooL and @dsymonds answered most questions already, but just to confirm I tested with 1.6 and tip on OS X, with and without oauth2, with and without using DefaultTransport.

Member

FiloSottile commented Mar 29, 2016

@shurcooL and @dsymonds answered most questions already, but just to confirm I tested with 1.6 and tip on OS X, with and without oauth2, with and without using DefaultTransport.

@slimmy

This comment has been minimized.

Show comment
Hide comment
@slimmy

slimmy Mar 29, 2016

Sorry for being slightly OT but why doesn't Close() drain the body itself?

slimmy commented Mar 29, 2016

Sorry for being slightly OT but why doesn't Close() drain the body itself?

@kofalt

This comment has been minimized.

Show comment
Hide comment
@kofalt

kofalt Mar 29, 2016

@slimmy: because closing a connection would then potentially block for a long time - or forever - if the other end of a connection has a lot of / infinite bytes still to be sent. Imagine calling Close only to block on receiving the rest of a 10 GB file you didn't want.

As mentioned in the PR:

Response.Body.Close() is called. When that happens with a non-drained
Body, the TCP/TLS connection is closed (which makes sense, in case there was
still a lot to read from the network)

kofalt commented Mar 29, 2016

@slimmy: because closing a connection would then potentially block for a long time - or forever - if the other end of a connection has a lot of / infinite bytes still to be sent. Imagine calling Close only to block on receiving the rest of a 10 GB file you didn't want.

As mentioned in the PR:

Response.Body.Close() is called. When that happens with a non-drained
Body, the TCP/TLS connection is closed (which makes sense, in case there was
still a lot to read from the network)

@slimmy

This comment has been minimized.

Show comment
Hide comment
@slimmy

slimmy Mar 29, 2016

@kofalt: That makes sense, but it doesn't seem like something that would actually happen a lot in practice. Maybe it should be configurable to make Close() drain the body.

slimmy commented Mar 29, 2016

@kofalt: That makes sense, but it doesn't seem like something that would actually happen a lot in practice. Maybe it should be configurable to make Close() drain the body.

@devlo

This comment has been minimized.

Show comment
Hide comment
@devlo

devlo Mar 29, 2016

@slimmy

Because of bad actors in internet that would send infinite number of bytes to your site.

devlo commented Mar 29, 2016

@slimmy

Because of bad actors in internet that would send infinite number of bytes to your site.

@slimmy

This comment has been minimized.

Show comment
Hide comment
@slimmy

slimmy Mar 29, 2016

@devlo: I get that, but everyone using io.Copy(ioutil.Discard, resp.Body) to enable the reuse of the TCP connection would be susceptible that as well no?

slimmy commented Mar 29, 2016

@devlo: I get that, but everyone using io.Copy(ioutil.Discard, resp.Body) to enable the reuse of the TCP connection would be susceptible that as well no?

@devlo

This comment has been minimized.

Show comment
Hide comment
@devlo

devlo Mar 29, 2016

@slimmy

You can use io.LimitedReader in this case to mitigate that.

devlo commented Mar 29, 2016

@slimmy

You can use io.LimitedReader in this case to mitigate that.

@slimmy

This comment has been minimized.

Show comment
Hide comment
@slimmy

slimmy Mar 29, 2016

@devlo

I'm just trying to understand it all in the context of this PR. To achieve maximum performance you have to make sure you read all of the response body (so that the TCP connection can be reused). But in doing so you are risking large (possibly infinite) streams of data. So the solution is to only utilize this "trick" when you are fetching data from trusted sources (i.e GitHub as in the case of this PR)?

slimmy commented Mar 29, 2016

@devlo

I'm just trying to understand it all in the context of this PR. To achieve maximum performance you have to make sure you read all of the response body (so that the TCP connection can be reused). But in doing so you are risking large (possibly infinite) streams of data. So the solution is to only utilize this "trick" when you are fetching data from trusted sources (i.e GitHub as in the case of this PR)?

@kevin-cantwell

This comment has been minimized.

Show comment
Hide comment
@kevin-cantwell

kevin-cantwell Mar 29, 2016

I'm trying to reproduce this issue in its purest form (ie: Without any dependencies beyond the standard packages), but so far am unable to. I want to fully appreciate if this is a problem for anyone using net/http or if it's limited to this project.

Here is my attempt (results in the readme): https://github.com/kevin-cantwell/tcpdraintest

It appears the performance differences are greatest when the number of requests is low. I'm reusing the default http client and my json responses are empty objects with a few extra newline characters to drain. Am I doing it wrong?

kevin-cantwell commented Mar 29, 2016

I'm trying to reproduce this issue in its purest form (ie: Without any dependencies beyond the standard packages), but so far am unable to. I want to fully appreciate if this is a problem for anyone using net/http or if it's limited to this project.

Here is my attempt (results in the readme): https://github.com/kevin-cantwell/tcpdraintest

It appears the performance differences are greatest when the number of requests is low. I'm reusing the default http client and my json responses are empty objects with a few extra newline characters to drain. Am I doing it wrong?

@kevin-cantwell

This comment has been minimized.

Show comment
Hide comment
@kevin-cantwell

kevin-cantwell Mar 29, 2016

Ok, I think I understand a bit more about this. Seems like this change makes the biggest difference when there is a large number of bytes remaining in the body after json parsing. A few extra bytes doesn't seem to matter much, even at high request volumes. But if you've got hundreds or thousands of extra bytes after json decoding is done, then yes, this could seriously affect performance. My question then is: without committing to draining the entire remaining bytes (which as @kofalt pointed out, could be GB of data), how far should one read before just closing the response? Because unless you read quite far, the performance gains might not be visible.

Another question I might raise is: Is it even reasonable to expect there to be lots of bytes after a terminating json character? There could easily be a newline or two, but hundreds or thousands of them? I'm skeptical that any api would serve that.

Again, if I'm missing the point somehow, please illuminate me! :)

kevin-cantwell commented Mar 29, 2016

Ok, I think I understand a bit more about this. Seems like this change makes the biggest difference when there is a large number of bytes remaining in the body after json parsing. A few extra bytes doesn't seem to matter much, even at high request volumes. But if you've got hundreds or thousands of extra bytes after json decoding is done, then yes, this could seriously affect performance. My question then is: without committing to draining the entire remaining bytes (which as @kofalt pointed out, could be GB of data), how far should one read before just closing the response? Because unless you read quite far, the performance gains might not be visible.

Another question I might raise is: Is it even reasonable to expect there to be lots of bytes after a terminating json character? There could easily be a newline or two, but hundreds or thousands of them? I'm skeptical that any api would serve that.

Again, if I'm missing the point somehow, please illuminate me! :)

@willnorris

This comment has been minimized.

Show comment
Hide comment
@willnorris

willnorris Mar 29, 2016

Member

Ok, I think I understand a bit more about this. Seems like this change makes the biggest difference when there is a large number of bytes remaining in the body after json parsing.

In the GitHub cases above, there are actually no remaining bytes after json parsing, so I don't think your statement here is correct. One current working guess is that the io.EOF hasn't been reached, and that's what is causing the connection to not be reused.

Member

willnorris commented Mar 29, 2016

Ok, I think I understand a bit more about this. Seems like this change makes the biggest difference when there is a large number of bytes remaining in the body after json parsing.

In the GitHub cases above, there are actually no remaining bytes after json parsing, so I don't think your statement here is correct. One current working guess is that the io.EOF hasn't been reached, and that's what is causing the connection to not be reused.

@dmitshur

This comment has been minimized.

Show comment
Hide comment
@dmitshur

dmitshur Mar 29, 2016

Member

But in doing so you are risking large (possibly infinite) streams of data. So the solution is to only utilize this "trick" when you are fetching data from trusted sources (i.e GitHub as in the case of this PR)?

@slimmy, have you seen this inline #317 (comment)? A proposed suggestion there is to "read, say, 512 bytes with a 50ms timeout happening on close, which would probably be good enough for cases like this one."

I'm trying to reproduce this issue in its purest form (ie: Without any dependencies beyond the standard packages), but so far am unable to. I want to fully appreciate if this is a problem for anyone using net/http or if it's limited to this project.

@kevin-cantwell, an extremely important aspect of this is the fact that these are TLS connections being made, since the protocol used is https, not http. TLS connection handshake is quite expensive, so reusing TLS connections made to a remote server will offer great savings. Reusing non-TLS connections to localhost will have very little gains, and what's what your test appears to be trying to do from what I can tell.

Member

dmitshur commented Mar 29, 2016

But in doing so you are risking large (possibly infinite) streams of data. So the solution is to only utilize this "trick" when you are fetching data from trusted sources (i.e GitHub as in the case of this PR)?

@slimmy, have you seen this inline #317 (comment)? A proposed suggestion there is to "read, say, 512 bytes with a 50ms timeout happening on close, which would probably be good enough for cases like this one."

I'm trying to reproduce this issue in its purest form (ie: Without any dependencies beyond the standard packages), but so far am unable to. I want to fully appreciate if this is a problem for anyone using net/http or if it's limited to this project.

@kevin-cantwell, an extremely important aspect of this is the fact that these are TLS connections being made, since the protocol used is https, not http. TLS connection handshake is quite expensive, so reusing TLS connections made to a remote server will offer great savings. Reusing non-TLS connections to localhost will have very little gains, and what's what your test appears to be trying to do from what I can tell.

@kevin-cantwell

This comment has been minimized.

Show comment
Hide comment
@kevin-cantwell

kevin-cantwell Mar 29, 2016

TLS connection handshake is quite expensive, so reusing TLS connections made to a remote server will offer great savings. Reusing non-TLS connections to localhost will have very little gains, and what's what your test appears to be trying to do from what I can tell.

@shurcooL That makes sense, thanks! And when I use an https api I can confirm the performance gains:

Output:

$ go version
go version go1.6 darwin/amd64

$ go run main.go https://api.github.com/repos/google/go-github 10
Without drain (x10): 1.302103099s
   With drain (x10): 282.559111ms

$ go run main.go https://api.github.com/repos/google/go-github 100
Without drain (x100): 8.339789738s
   With drain (x100): 2.694648312s

$ go run main.go https://api.github.com/repos/google/go-github 1000
Without drain (x1000): 1m16.253147895s
   With drain (x1000): 32.260955511s

Source code:

package main

import (
    "encoding/json"
    "fmt"
    "io"
    "io/ioutil"
    "net/http"
    "os"
    "strconv"
    "time"
)

func main() {
    url := os.Args[1]
    n, _ := strconv.Atoi(os.Args[2])

    client := http.DefaultClient

    d1 := run(client, url, n, false)
    d2 := run(client, url, n, true)

    fmt.Printf("Without drain (x%d): %v\n", n, d1)
    fmt.Printf("   With drain (x%d): %v\n", n, d2)
}

func run(client *http.Client, url string, n int, drain bool) time.Duration {
    var total time.Duration
    for i := 0; i < n; i++ {
        start := time.Now()
        resp, err := client.Get(url)
        if err != nil {
            panic(err)
        }
        dec := json.NewDecoder(resp.Body)
        var body map[string]interface{}
        if err := dec.Decode(&body); err != nil {
            panic(err)
        }
        timing := time.Since(start)
        total += timing

        if drain {
            io.Copy(ioutil.Discard, resp.Body)
        }
        resp.Body.Close()
    }
    return total
}

kevin-cantwell commented Mar 29, 2016

TLS connection handshake is quite expensive, so reusing TLS connections made to a remote server will offer great savings. Reusing non-TLS connections to localhost will have very little gains, and what's what your test appears to be trying to do from what I can tell.

@shurcooL That makes sense, thanks! And when I use an https api I can confirm the performance gains:

Output:

$ go version
go version go1.6 darwin/amd64

$ go run main.go https://api.github.com/repos/google/go-github 10
Without drain (x10): 1.302103099s
   With drain (x10): 282.559111ms

$ go run main.go https://api.github.com/repos/google/go-github 100
Without drain (x100): 8.339789738s
   With drain (x100): 2.694648312s

$ go run main.go https://api.github.com/repos/google/go-github 1000
Without drain (x1000): 1m16.253147895s
   With drain (x1000): 32.260955511s

Source code:

package main

import (
    "encoding/json"
    "fmt"
    "io"
    "io/ioutil"
    "net/http"
    "os"
    "strconv"
    "time"
)

func main() {
    url := os.Args[1]
    n, _ := strconv.Atoi(os.Args[2])

    client := http.DefaultClient

    d1 := run(client, url, n, false)
    d2 := run(client, url, n, true)

    fmt.Printf("Without drain (x%d): %v\n", n, d1)
    fmt.Printf("   With drain (x%d): %v\n", n, d2)
}

func run(client *http.Client, url string, n int, drain bool) time.Duration {
    var total time.Duration
    for i := 0; i < n; i++ {
        start := time.Now()
        resp, err := client.Get(url)
        if err != nil {
            panic(err)
        }
        dec := json.NewDecoder(resp.Body)
        var body map[string]interface{}
        if err := dec.Decode(&body); err != nil {
            panic(err)
        }
        timing := time.Since(start)
        total += timing

        if drain {
            io.Copy(ioutil.Discard, resp.Body)
        }
        resp.Body.Close()
    }
    return total
}
@bradfitz

This comment has been minimized.

Show comment
Hide comment
@bradfitz

bradfitz Mar 29, 2016

Contributor

Okay, I can reproduce now. I had a typo.

As background, Go used to auto-drain (around Go 1.0 and Go 1.1 era) but it was problematic for a number of reasons and we changed the behavior to be more predictable but also pushed io.EOFs earlier for many readers and made the final Read-with-EOF on the connection also auto-recycle the TCP connection for people who forget to Close. It seems there's a Reader not doing early (n, io.EOF) instead of (n, nil)+(0, io.EOF) somewhere.

I see the final 0-byte HTTP/1.1 EOF chunk arriving in the final read:

2016/03/30 09:23:20 transport-1.Read(4096) = 1370, <nil> = "HTTP/1.1 200 OK\r\nServer: GitHub.com\r\nDate: Tue, 29 Mar 2016 22:22:34 GMT\r\nContent-Type: application/json; charset=utf-8\r\nTransfer-Encoding: chunked\r\nStatus: 200 OK\r\nX-RateLimit-Limit: 5000\r\nX-RateLimit-Remaining: 4946\r\nX-RateLimit-Reset: 1459293399\r\nCache-Control: private, max-age=60, s-maxage=60\r\nVary: Accept, Authorization, Cookie, X-GitHub-OTP\r\nETag: W/\"ee6421a9addcf34be8071a9b78863cb0\"\r\nLast-Modified: Tue, 29 Mar 2016 10:05:03 GMT\r\nX-OAuth-Scopes: repo\r\nX-Accepted-OAuth-Scopes: repo\r\nX-GitHub-Media-Type: github.drax-preview; format=json\r\nAccess-Control-Expose-Headers: ETag, Link, X-GitHub-OTP, X-RateLimit-Limit, X-RateLimit-Remaining, X-RateLimit-Reset, X-OAuth-Scopes, X-Accepted-OAuth-Scopes, X-Poll-Interval\r\nAccess-Control-Allow-Origin: *\r\nContent-Security-Policy: default-src 'none'\r\nStrict-Transport-Security: max-age=31536000; includeSubdomains; preload\r\nX-Content-Type-Options: nosniff\r\nX-Frame-Options: deny\r\nX-XSS-Protection: 1; mode=block\r\nVary: Accept-Encoding\r\nX-Served-By: 7f48e2f7761567e923121f17538d7a6d\r\nContent-Encoding: gzip\r\nX-GitHub-Request-Id: 4A7D38D6:36CB:143A0579:56FB002A\r\n\r\n4aa\r\n\x1f\x8b\b\x00\x00\x00\x00\x00\x00\x03\xa5X]o\xdb6\x14\xfd+\x86^焲\x13w\xb3\x80\xa1{XV\x14Xۡˆa/\x06-\xd1\x12\x11I\x14H\xcaA*\xe4\xbf\xef\\\x91\x92eé\x13\xee%\x91%\x9e\xc3\xc3\xfbA\xde\xcb.\x92Y\x94\xdc.ַ\xab\xe5z1\x8fj^\x89(\x89\xf2\xbd\x8d\xe6Ѯ-ˍ\u007f\xf3\x9b,՟\xcaZY\n澪\xc7Z\xe8(\xe9\xa2R\xe5\xb2\x06h2\x04`\xe2],\x97\xa0\xbd\x9dG|\xcf-כV\x97\x18WXۘ\x841\xf7\xd2\\\xe7\xd2\x16\xed\xb65B\xa7\xaa\xb6\xa2\xb6ש\xaaX\xcb<\xfa\xfd\xfe\xe7\x1b\xf0\xe5ړ\x10q\x84\x17'd\x8d\xf4D\x0e\r6Î\x15\x15\xb6*O$\xb8\xa9{\xc4\xf1\u061d*K\xf5\b\x8eS\xcd\x17\xa6a#\x90\xecד\xc8:\x0f#\x01\xb0c\xca\x16\x02\x86\xc3r\x9e\xc9\b\xd2\xd87K\xeaA\x1d\xa3\u007f\x1b\x99\x11\x8d\x813\xb4"
2016/03/30 09:23:20 transport-1.Read(4096) = ....
2016/03/30 09:23:20 transport-1.Read(4096) = 949, <nil> = "\xc8\xde*\xcb\xc3 \x8a\\\xff\xdc1-\x1a\xd5\xf3\xb5[\x93j\xd9X\xa9\xea7\xcb;\x02\x83L\xe9\x9c\xd7\xf2\x1b\x0f\"\x03\u0600\x83\x84\xbdYH\x0f\x02X\xec\x11\x83oF;T\xc7\x1a-\xf7<}\"\xb3h\x91\n\xb9\x87\x9d\xc3\x18O\xe0 \xb4O\re\xe7_\x88\x06\xb2\xba\xb4bó\x8a\x92o\xc7K#\x9e\xe7Q?\xbbŠ\xfe\xc5\x1c\xb9\xf6ʘ\xf7I\x9d\x89ёn\x1b\x98I3C\b\xcer5\x83Y2\xa5\x11\x953\xabT9\xdb)\xdd\u007f\xf9\xf0e\xb1\xfa\xfb\xee\xf3\xaf_\xbe\xde\xfd\xf3\xc7\xdd\u05cf\x9f\xee>\xdf\xcfg[nD6S\xf5,\xdf^9 \x14\x03\xf20J\xfbn\xfe\xf6\xbe\x98\xe6\xa4\xd7G\f\x17\\s\x16\x8a\xbc\x04\x10\x12\x1e\xc4S\x10\x9ep\x1d\xc3_\x9fB)r\x9bo\x95\xe6V]\xda$\xce\v:\"\xe8\xd8\xf4'Ŏ\x15\xbc\n\x12\xda\x03AP(\x15f\xa9\x1e\b\x02iL+^\x15\xba\xe7\x17\xd8\xe3\r\x1b\xf2\xa2n\xab\xad\xdb\xc4^\x93\r\xe7)\x1d\x12ڸ12\xaf\x85\b\xb2\xd0\b\xeeذ\xafn5\xaf\xd3\"\x8cn\xc0v\xcc=\xf5\xde\xe3y\x904\xc2\x01\xbe-\xd56\b\x8f\xf3\x8c\xf5\xe0\x8e\x99\x82\xbb\x13\xc3nB\xd5\x10\x1ba\x8fȴ\xd8\x05K#\xecHfu\xa0\xffzY\x04\x1e\xa9p0Y\xb82H׀e\x9d\xb7X\xc9\xeb\xbc\xe5y\x18\xdb\b\x86\x17\xe9\xb8\xcc\xf9\xb7\x8bE\xc4\xf9X?\xa0AE\x85\x91\x96\xdb6|\xb39\xe0I\x99;\xaf\x91\x8fa&;\xc0\x0fd\xfd\xe1\xff\xfd\x8aⅅN\x8a\x87~\xa9U%/\x1d\xbf\xe7\x99<\xf4(\\\xff\a\x1d\xc5\xd9)%\xfd\xbe\\\x1d\xbc,\x8f\xb0\x1d;\xec\x85n\x93\xf5\xac!\xd6\xf3\xbb\xec\xa0k\xca\xed\xab\xe9 \x17\x0fX\xd6\xfd\xd0p[\xd0N\x82)\x1a\xaeE\x88H\x0fe\x1dU\x05\xcf\xd7\xd7\xd7]!x_\x89VB\af\x9aC\x82\x82\xeb\xb4@\x95\x15\xa2\xab\x1b\xb0\xa8\x0e*n\xfb\x8avG\xb22T\xb8\xa5\xe2Y\x90\xedF0\x88\x9c{B\xb49\xe4ԟ\rڱ A=p\xcaT\xa1\x8b3V\xd5a{\xdc\x01=嬕\x95;\x99\xbe\xa6l?\x9f\x1eG\x04\xdd{#\xebT\xccyY\xce\x11uV\xa6\x12q\x88ړ\xbc\x83\xc2K\x84Y\xc2!!\x1bm\xae\xab\xd0K\x81\x90\f\xb2\xaa\x16\x0e\xdb1\xd7Te\xa2)\xd5S\xf0\xee0\x81S\xb2i\x812>\xdbp\x8b2|\x19/VW\xf1\xfa*^\xddNjd\xf5.\x89\x97\xffbL\xdbdGc\xde]\xc57W\xcb\xf5\xfd\"N\xe2U\x12\xdfИ\xa65ń\xc6\r\xf9\xe9~qC4\xb71\r\xc16\xe7\xe3\x13Oh\xcb\xcf\xf7\xc4T\u007fS\x83\r\x801\xc5\x01\xf0\xcbaxrrG\xe0\x87\xa7%\x02\xed$\x03.ϱ?=K^\x86@R\xa1*\xd1\xe0\xccv7\x03F~\xc3\xd3\"^\x1d\x9d\xc1\xa9jkXs\xb9^ΣGnQ\xee\xe1\xf4\x9b\xbe\x1c\xcen\x90|PD\xca\xcd\xc6ea\x94X\xddR7\x857\x87잼|\x94\x0fr:\x88\xb4\x98\xe1\x85\xebY\x86\x99p\x1bRI\xad\x95\xbf\r\xa9\x91\x9b\xe8y\x1bQ\xfb\xb9\x06Ik\xd7.\x81e\t\xc8d@\x94\xe0Ӱ\x00\xbf\x9eL\xecx[ڍ\xab@\xb1\x80\x8a\x1b\xdb7\x89\xee\xe1̇F\xe8\n\xab\xa3\x8e\x9d.q\xa6}\xa4\v\x9b\xb1Q\xa3\xedí\x05\rf)SQ\x1b\x98\xb7\xa3V\x8af\xeac\xc2\xdf\x12}\xfax?\xfbݏ\xb8pC\xe3\x89\fs\x04;\xc4{\x8b;\x89q\xa2Z\xd8G\xf4l\xa3\x87`\x84i\xd9\xe2\u0379\xf8\xf1\xf9?\xb7a\x95\x03\xc3\x12\x00\x00\r\n0\r\n\r\n"
Read on *http.bodyEOFSignal = 512, <nil>
Read on *http.bodyEOFSignal = 1024, <nil>
Read on *http.bodyEOFSignal = 2048, <nil>
Read on *http.bodyEOFSignal = 1219, <nil>
Draining...
tryPutIdleConn = <nil>

(Scroll to the right forever and you can see \x00\x00\r\n0\r\n\r\n" at the end)

Contributor

bradfitz commented Mar 29, 2016

Okay, I can reproduce now. I had a typo.

As background, Go used to auto-drain (around Go 1.0 and Go 1.1 era) but it was problematic for a number of reasons and we changed the behavior to be more predictable but also pushed io.EOFs earlier for many readers and made the final Read-with-EOF on the connection also auto-recycle the TCP connection for people who forget to Close. It seems there's a Reader not doing early (n, io.EOF) instead of (n, nil)+(0, io.EOF) somewhere.

I see the final 0-byte HTTP/1.1 EOF chunk arriving in the final read:

2016/03/30 09:23:20 transport-1.Read(4096) = 1370, <nil> = "HTTP/1.1 200 OK\r\nServer: GitHub.com\r\nDate: Tue, 29 Mar 2016 22:22:34 GMT\r\nContent-Type: application/json; charset=utf-8\r\nTransfer-Encoding: chunked\r\nStatus: 200 OK\r\nX-RateLimit-Limit: 5000\r\nX-RateLimit-Remaining: 4946\r\nX-RateLimit-Reset: 1459293399\r\nCache-Control: private, max-age=60, s-maxage=60\r\nVary: Accept, Authorization, Cookie, X-GitHub-OTP\r\nETag: W/\"ee6421a9addcf34be8071a9b78863cb0\"\r\nLast-Modified: Tue, 29 Mar 2016 10:05:03 GMT\r\nX-OAuth-Scopes: repo\r\nX-Accepted-OAuth-Scopes: repo\r\nX-GitHub-Media-Type: github.drax-preview; format=json\r\nAccess-Control-Expose-Headers: ETag, Link, X-GitHub-OTP, X-RateLimit-Limit, X-RateLimit-Remaining, X-RateLimit-Reset, X-OAuth-Scopes, X-Accepted-OAuth-Scopes, X-Poll-Interval\r\nAccess-Control-Allow-Origin: *\r\nContent-Security-Policy: default-src 'none'\r\nStrict-Transport-Security: max-age=31536000; includeSubdomains; preload\r\nX-Content-Type-Options: nosniff\r\nX-Frame-Options: deny\r\nX-XSS-Protection: 1; mode=block\r\nVary: Accept-Encoding\r\nX-Served-By: 7f48e2f7761567e923121f17538d7a6d\r\nContent-Encoding: gzip\r\nX-GitHub-Request-Id: 4A7D38D6:36CB:143A0579:56FB002A\r\n\r\n4aa\r\n\x1f\x8b\b\x00\x00\x00\x00\x00\x00\x03\xa5X]o\xdb6\x14\xfd+\x86^焲\x13w\xb3\x80\xa1{XV\x14Xۡˆa/\x06-\xd1\x12\x11I\x14H\xcaA*\xe4\xbf\xef\\\x91\x92eé\x13\xee%\x91%\x9e\xc3\xc3\xfbA\xde\xcb.\x92Y\x94\xdc.ַ\xab\xe5z1\x8fj^\x89(\x89\xf2\xbd\x8d\xe6Ѯ-ˍ\u007f\xf3\x9b,՟\xcaZY\n澪\xc7Z\xe8(\xe9\xa2R\xe5\xb2\x06h2\x04`\xe2],\x97\xa0\xbd\x9dG|\xcf-כV\x97\x18WXۘ\x841\xf7\xd2\\\xe7\xd2\x16\xed\xb65B\xa7\xaa\xb6\xa2\xb6ש\xaaX\xcb<\xfa\xfd\xfe\xe7\x1b\xf0\xe5ړ\x10q\x84\x17'd\x8d\xf4D\x0e\r6Î\x15\x15\xb6*O$\xb8\xa9{\xc4\xf1\u061d*K\xf5\b\x8eS\xcd\x17\xa6a#\x90\xecד\xc8:\x0f#\x01\xb0c\xca\x16\x02\x86\xc3r\x9e\xc9\b\xd2\xd87K\xeaA\x1d\xa3\u007f\x1b\x99\x11\x8d\x813\xb4"
2016/03/30 09:23:20 transport-1.Read(4096) = ....
2016/03/30 09:23:20 transport-1.Read(4096) = 949, <nil> = "\xc8\xde*\xcb\xc3 \x8a\\\xff\xdc1-\x1a\xd5\xf3\xb5[\x93j\xd9X\xa9\xea7\xcb;\x02\x83L\xe9\x9c\xd7\xf2\x1b\x0f\"\x03\u0600\x83\x84\xbdYH\x0f\x02X\xec\x11\x83oF;T\xc7\x1a-\xf7<}\"\xb3h\x91\n\xb9\x87\x9d\xc3\x18O\xe0 \xb4O\re\xe7_\x88\x06\xb2\xba\xb4bó\x8a\x92o\xc7K#\x9e\xe7Q?\xbbŠ\xfe\xc5\x1c\xb9\xf6ʘ\xf7I\x9d\x89ёn\x1b\x98I3C\b\xcer5\x83Y2\xa5\x11\x953\xabT9\xdb)\xdd\u007f\xf9\xf0e\xb1\xfa\xfb\xee\xf3\xaf_\xbe\xde\xfd\xf3\xc7\xdd\u05cf\x9f\xee>\xdf\xcfg[nD6S\xf5,\xdf^9 \x14\x03\xf20J\xfbn\xfe\xf6\xbe\x98\xe6\xa4\xd7G\f\x17\\s\x16\x8a\xbc\x04\x10\x12\x1e\xc4S\x10\x9ep\x1d\xc3_\x9fB)r\x9bo\x95\xe6V]\xda$\xce\v:\"\xe8\xd8\xf4'Ŏ\x15\xbc\n\x12\xda\x03AP(\x15f\xa9\x1e\b\x02iL+^\x15\xba\xe7\x17\xd8\xe3\r\x1b\xf2\xa2n\xab\xad\xdb\xc4^\x93\r\xe7)\x1d\x12ڸ12\xaf\x85\b\xb2\xd0\b\xeeذ\xafn5\xaf\xd3\"\x8cn\xc0v\xcc=\xf5\xde\xe3y\x904\xc2\x01\xbe-\xd56\b\x8f\xf3\x8c\xf5\xe0\x8e\x99\x82\xbb\x13\xc3nB\xd5\x10\x1ba\x8fȴ\xd8\x05K#\xecHfu\xa0\xffzY\x04\x1e\xa9p0Y\xb82H׀e\x9d\xb7X\xc9\xeb\xbc\xe5y\x18\xdb\b\x86\x17\xe9\xb8\xcc\xf9\xb7\x8bE\xc4\xf9X?\xa0AE\x85\x91\x96\xdb6|\xb39\xe0I\x99;\xaf\x91\x8fa&;\xc0\x0fd\xfd\xe1\xff\xfd\x8aⅅN\x8a\x87~\xa9U%/\x1d\xbf\xe7\x99<\xf4(\\\xff\a\x1d\xc5\xd9)%\xfd\xbe\\\x1d\xbc,\x8f\xb0\x1d;\xec\x85n\x93\xf5\xac!\xd6\xf3\xbb\xec\xa0k\xca\xed\xab\xe9 \x17\x0fX\xd6\xfd\xd0p[\xd0N\x82)\x1a\xaeE\x88H\x0fe\x1dU\x05\xcf\xd7\xd7\xd7]!x_\x89VB\af\x9aC\x82\x82\xeb\xb4@\x95\x15\xa2\xab\x1b\xb0\xa8\x0e*n\xfb\x8avG\xb22T\xb8\xa5\xe2Y\x90\xedF0\x88\x9c{B\xb49\xe4ԟ\rڱ A=p\xcaT\xa1\x8b3V\xd5a{\xdc\x01=嬕\x95;\x99\xbe\xa6l?\x9f\x1eG\x04\xdd{#\xebT\xccyY\xce\x11uV\xa6\x12q\x88ړ\xbc\x83\xc2K\x84Y\xc2!!\x1bm\xae\xab\xd0K\x81\x90\f\xb2\xaa\x16\x0e\xdb1\xd7Te\xa2)\xd5S\xf0\xee0\x81S\xb2i\x812>\xdbp\x8b2|\x19/VW\xf1\xfa*^\xddNjd\xf5.\x89\x97\xffbL\xdbdGc\xde]\xc57W\xcb\xf5\xfd\"N\xe2U\x12\xdfИ\xa65ń\xc6\r\xf9\xe9~qC4\xb71\r\xc16\xe7\xe3\x13Oh\xcb\xcf\xf7\xc4T\u007fS\x83\r\x801\xc5\x01\xf0\xcbaxrrG\xe0\x87\xa7%\x02\xed$\x03.ϱ?=K^\x86@R\xa1*\xd1\xe0\xccv7\x03F~\xc3\xd3\"^\x1d\x9d\xc1\xa9jkXs\xb9^ΣGnQ\xee\xe1\xf4\x9b\xbe\x1c\xcen\x90|PD\xca\xcd\xc6ea\x94X\xddR7\x857\x87잼|\x94\x0fr:\x88\xb4\x98\xe1\x85\xebY\x86\x99p\x1bRI\xad\x95\xbf\r\xa9\x91\x9b\xe8y\x1bQ\xfb\xb9\x06Ik\xd7.\x81e\t\xc8d@\x94\xe0Ӱ\x00\xbf\x9eL\xecx[ڍ\xab@\xb1\x80\x8a\x1b\xdb7\x89\xee\xe1̇F\xe8\n\xab\xa3\x8e\x9d.q\xa6}\xa4\v\x9b\xb1Q\xa3\xedí\x05\rf)SQ\x1b\x98\xb7\xa3V\x8af\xeac\xc2\xdf\x12}\xfax?\xfbݏ\xb8pC\xe3\x89\fs\x04;\xc4{\x8b;\x89q\xa2Z\xd8G\xf4l\xa3\x87`\x84i\xd9\xe2\u0379\xf8\xf1\xf9?\xb7a\x95\x03\xc3\x12\x00\x00\r\n0\r\n\r\n"
Read on *http.bodyEOFSignal = 512, <nil>
Read on *http.bodyEOFSignal = 1024, <nil>
Read on *http.bodyEOFSignal = 2048, <nil>
Read on *http.bodyEOFSignal = 1219, <nil>
Draining...
tryPutIdleConn = <nil>

(Scroll to the right forever and you can see \x00\x00\r\n0\r\n\r\n" at the end)

@bashtian

This comment has been minimized.

Show comment
Hide comment
@bradfitz

This comment has been minimized.

Show comment
Hide comment
@bradfitz

bradfitz Mar 30, 2016

Contributor

I sent out https://go-review.googlesource.com/21290

@bashtian, what about that line?

Contributor

bradfitz commented Mar 30, 2016

I sent out https://go-review.googlesource.com/21290

@bashtian, what about that line?

@bradfitz

This comment has been minimized.

Show comment
Hide comment
@bradfitz

bradfitz Mar 30, 2016

Contributor

Actually, better fix: https://golang.org/cl/21291

Contributor

bradfitz commented Mar 30, 2016

Actually, better fix: https://golang.org/cl/21291

gopherbot pushed a commit to golang/go that referenced this pull request Mar 30, 2016

net/http: reuse HTTP/1 Transport conns more for gzipped responses
Flip around the composition order of the http.Response.Body's
gzip.Reader vs. the reader which keeps track of waiting to see the end
of the HTTP/1 response framing (whether that's a Content-Length or
HTTP/1.1 chunking).

Previously:

user -> http.Response.Body
     -> bodyEOFSignal
     -> gzipReader
     -> gzip.Reader
     -> bufio.Reader
   [ -> http/1.1 de-chunking reader ]   optional
     -> http1 framing *body

But because bodyEOFSignal was waiting to see an EOF from the
underlying gzip.Reader before reusing the connection, and gzip.Reader
(or more specifically: the flate.Reader) wasn't returning an early
io.EOF with the final chunk, the bodyEOfSignal was never releasing the
connection, because the EOF from the http1 framing was read by a party
who didn't care about it yet: the helper bufio.Reader created to do
byte-at-a-time reading in the flate.Reader.

Flip the read composition around to:

user -> http.Response.Body
     -> gzipReader
     -> gzip.Reader
     -> bufio.Reader
     -> bodyEOFSignal
   [ -> http/1.1 de-chunking reader ]   optional
     -> http1 framing *body

Now when gzip.Reader does its byte-at-a-time reading via the
bufio.Reader, the bufio.Reader will do its big reads against the
bodyEOFSignal reader instead, which will then see the underlying http1
framing EOF, and be able to reuse the connection.

Updates google/go-github#317
Updates #14867
And related abandoned fix to flate.Reader: https://golang.org/cl/21290

Change-Id: I3729dfdffe832ad943b84f4734b0f59b0e834749
Reviewed-on: https://go-review.googlesource.com/21291
Reviewed-by: David Symonds <dsymonds@golang.org>
Run-TryBot: Brad Fitzpatrick <bradfitz@golang.org>
TryBot-Result: Gobot Gobot <gobot@golang.org>

asamy added a commit to doctype/steam that referenced this pull request Mar 30, 2016

http response: drain body when we know we won't read
This allows it to re-use the connection instead of creating a new one.
See: google/go-github#317

Signed-off-by: A. Samy <f.fallen45@gmail.com>
@extemporalgenome

This comment has been minimized.

Show comment
Hide comment
@extemporalgenome

extemporalgenome Mar 31, 2016

@FiloSottile unbounded io.Copy calls should be avoided in this case. io.CopyN or just a Read with, say, and upper bound of 1 KiB would be much, much safer -- if the server side has a bug that causes it to send megabytes or worse of extra data down the socket, you don't want to read all that just as an optimization for reusing the connection (you really want to have the constraint of: "if there's not much left in the pipe, then reuse. Otherwise, force close")

extemporalgenome commented Mar 31, 2016

@FiloSottile unbounded io.Copy calls should be avoided in this case. io.CopyN or just a Read with, say, and upper bound of 1 KiB would be much, much safer -- if the server side has a bug that causes it to send megabytes or worse of extra data down the socket, you don't want to read all that just as an optimization for reusing the connection (you really want to have the constraint of: "if there's not much left in the pipe, then reuse. Otherwise, force close")

@willnorris

This comment has been minimized.

Show comment
Hide comment
@willnorris

willnorris Mar 31, 2016

Member

@extemporalgenome good idea about using io.CopyN instead here. I'll make that change.

Member

willnorris commented Mar 31, 2016

@extemporalgenome good idea about using io.CopyN instead here. I'll make that change.

willnorris added a commit that referenced this pull request Mar 31, 2016

gopherbot pushed a commit to golang/go that referenced this pull request Mar 31, 2016

compress/flate: make Reader.Read return io.EOF eagerly
Rather than checking the block final bit on the next invocation
of nextBlock, we check it at the termination of the current block.
This ensures that we return (n, io.EOF) instead of (0, io.EOF)
more frequently for most streams.

However, there are certain situations where an eager io.EOF is not done:
1) We previously returned from Read because the write buffer of the internal
dictionary was full, and it just so happens that there is no more data
remaining in the stream.
2) There exists a [non-final, empty, raw block] after all blocks that
actually contain uncompressed data. We cannot return io.EOF eagerly here
since it would break flushing semantics.

Both situations happen infrequently, but it is still important to note that
this change does *not* guarantee that flate will *always* return (n, io.EOF).

Furthermore, this CL makes no changes to the pattern of ReadByte calls
to the underlying io.ByteReader.

Below is the motivation for this change, pulling the text from
@bradfitz's CL/21290:

net/http and other things work better when io.Reader implementations
return (n, io.EOF) at the end, instead of (n, nil) followed by (0,
io.EOF). Both are legal, but the standard library has been moving
towards n+io.EOF.

An investigation of net/http connection re-use in
google/go-github#317 revealed that with gzip
compression + http/1.1 chunking, the net/http package was not
automatically reusing the underlying TCP connections when the final
EOF bytes were already read off the wire. The net/http package only
reuses the connection if the underlying Readers (many of them nested
in this case) all eagerly return io.EOF.

Previous related CLs:
    https://golang.org/cl/76400046 - tls.Reader
    https://golang.org/cl/58240043 - http chunked reader

In addition to net/http, this behavior also helps things like
ioutil.ReadAll (see comments about performance improvements in
https://codereview.appspot.com/49570044)

Updates #14867
Updates google/go-github#317

Change-Id: I637c45552efb561d34b13ed918b73c660f668378
Reviewed-on: https://go-review.googlesource.com/21302
Run-TryBot: Brad Fitzpatrick <bradfitz@golang.org>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: Brad Fitzpatrick <bradfitz@golang.org>

@DmitriyMV DmitriyMV referenced this pull request Jun 23, 2016

Closed

Drain Response.Body #3

@at15 at15 referenced this pull request Aug 16, 2017

Open

Client, Request, Response #2

0 of 2 tasks complete

jasonwbarnett pushed a commit to jasonwbarnett/fileserver that referenced this pull request Jul 11, 2018

net/http: reuse HTTP/1 Transport conns more for gzipped responses
Flip around the composition order of the http.Response.Body's
gzip.Reader vs. the reader which keeps track of waiting to see the end
of the HTTP/1 response framing (whether that's a Content-Length or
HTTP/1.1 chunking).

Previously:

user -> http.Response.Body
     -> bodyEOFSignal
     -> gzipReader
     -> gzip.Reader
     -> bufio.Reader
   [ -> http/1.1 de-chunking reader ]   optional
     -> http1 framing *body

But because bodyEOFSignal was waiting to see an EOF from the
underlying gzip.Reader before reusing the connection, and gzip.Reader
(or more specifically: the flate.Reader) wasn't returning an early
io.EOF with the final chunk, the bodyEOfSignal was never releasing the
connection, because the EOF from the http1 framing was read by a party
who didn't care about it yet: the helper bufio.Reader created to do
byte-at-a-time reading in the flate.Reader.

Flip the read composition around to:

user -> http.Response.Body
     -> gzipReader
     -> gzip.Reader
     -> bufio.Reader
     -> bodyEOFSignal
   [ -> http/1.1 de-chunking reader ]   optional
     -> http1 framing *body

Now when gzip.Reader does its byte-at-a-time reading via the
bufio.Reader, the bufio.Reader will do its big reads against the
bodyEOFSignal reader instead, which will then see the underlying http1
framing EOF, and be able to reuse the connection.

Updates google/go-github#317
Updates #14867
And related abandoned fix to flate.Reader: https://golang.org/cl/21290

Change-Id: I3729dfdffe832ad943b84f4734b0f59b0e834749
Reviewed-on: https://go-review.googlesource.com/21291
Reviewed-by: David Symonds <dsymonds@golang.org>
Run-TryBot: Brad Fitzpatrick <bradfitz@golang.org>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment