net/http: improve performance for parsePostForm #14655

asticode · 2016-03-05T08:21:36Z

My main concern is using ioutil.ReadAll everytime the io.Reader is read in parsePostForm since it will then trigger bytes.makeSlice and allocate new space each and every time the function is called. Very similar to my open PR to @bradfitz's memcache library (bradfitz/gomemcache#45)

Instead I think using a sync.Pool of *bytes.Buffer would be a fairly better solution.

I've implemented the solution and added a benchmark to show you the performance improvements.

First of, here's the benchmark:

func BenchmarkParsePostForm(b *testing.B) {
    b.ReportAllocs()

    // Create bodies
    bodies := [][]byte{
        make([]byte, 100),
        make([]byte, 1000),
        make([]byte, 10000),
        make([]byte, 100000),
        make([]byte, 1000000),
        make([]byte, 10000000),
    }

    // Run
    b.RunParallel(func(pb *testing.PB) {
        for pb.Next() {
            // Create request
            r, e := NewRequest("POST", "/test", bytes.NewReader(bodies[rand.Intn(len(bodies))]))
            if e != nil {
                b.Error(e.Error())
            }

            // Add content type
            r.Header.Add("Content-Type", "application/x-www-form-urlencoded")

            // Parse post form
            e = r.ParseForm()
            if e != nil {
                b.Error(e.Error())
            }
        }
    })
}

Now here's the first run of the benchmark before the improvement:

$ go test ./src/net/http -v -run=^$ -bench=BenchmarkParsePostForm -benchtime=10s -parallel=4 -memprofile=prof.mem
BenchmarkParsePostForm-4        2000      11205322 ns/op     7821503 B/op         25 allocs/op
PASS
ok      net/http    32.253s

$ go tool pprof --alloc_space http.test prof.mem Entering interactive mode (type "help" for commands)
(pprof) top 
23140.16MB of 23187.37MB total (99.80%)
Dropped 11 nodes (cum <= 115.94MB)
      flat  flat%   sum%        cum   cum%
17720.08MB 76.42% 76.42% 17720.08MB 76.42%  bytes.makeSlice
 5418.08MB 23.37% 99.79% 23141.66MB 99.80%  net/http.parsePostForm
       2MB 0.0086% 99.80% 17722.08MB 76.43%  io/ioutil.readAll
     0     0% 99.80% 17720.08MB 76.42%  bytes.(*Buffer).ReadFrom
     0     0% 99.80% 17722.08MB 76.43%  io/ioutil.ReadAll
     0     0% 99.80% 23141.66MB 99.80%  net/http.(*Request).ParseForm
     0     0% 99.80% 23144.16MB 99.81%  net/http_test.BenchmarkParsePostForm.func1
     0     0% 99.80% 23187.37MB   100%  runtime.goexit
     0     0% 99.80% 23144.16MB 99.81%  testing.(*B).RunParallel.func1

(pprof) list parsePostForm
Total: 22.64GB
ROUTINE ======================== net/http.parsePostForm in /home/asticode/projects/go/go/src/net/http/request.go
    5.29GB    22.60GB (flat, cum) 99.80% of Total
     .          .    884:   // RFC 2616, section 7.2.1 - empty type
     .          .    885:   //   SHOULD be treated as application/octet-stream
     .          .    886:   if ct == "" {
     .          .    887:       ct = "application/octet-stream"
     .          .    888:   }
     .   512.02kB    889:   ct, _, err = mime.ParseMediaType(ct)
     .          .    890:   switch {
     .          .    891:   case ct == "application/x-www-form-urlencoded":
     .          .    892:       var reader io.Reader = r.Body
     .          .    893:       maxFormSize := int64(1<<63 - 1)
     .          .    894:       if _, ok := r.Body.(*maxBytesReader); !ok {
     .          .    895:           maxFormSize = int64(10 << 20) // 10 MB is a lot of text.
     .          .    896:           reader = io.LimitReader(r.Body, maxFormSize+1)
     .          .    897:       }
     .    17.31GB    898:       b, e := ioutil.ReadAll(reader)
     .          .    899:       if e != nil {
     .          .    900:           if err == nil {
     .          .    901:               err = e
     .          .    902:           }
     .          .    903:           break
     .          .    904:       }
     .          .    905:       if int64(len(b)) > maxFormSize {
     .          .    906:           err = errors.New("http: POST too large")
     .          .    907:           return
     .          .    908:       }
    5.29GB     5.29GB    909:       vs, e = url.ParseQuery(string(b))
     .          .    910:       if err == nil {
     .          .    911:           err = e
     .          .    912:       }
     .          .    913:   case ct == "multipart/form-data":
     .          .    914:       // handled by ParseMultipartForm (which is calling us, or should be)

You can see that ioutil.ReadAll(reader) at line 898 is eating 17.31GB.

Now here's the result of the benchmark after the improvement I suggest:

$ go test ./src/net/http -v -run=^$ -bench=BenchmarkParsePostForm -benchtime=10s -parallel=4 -memprofile=prof.mem
BenchmarkParsePostForm-4        2000       7830166 ns/op     1874354 B/op         18 allocs/op
PASS
ok      net/http    17.011s

$ go tool pprof --alloc_space http.test prof.mem Entering interactive mode (type "help" for commands)
(pprof) top
4030.01MB of 4033.51MB total (99.91%)
Dropped 7 nodes (cum <= 20.17MB)
      flat  flat%   sum%        cum   cum%
 3638.12MB 90.20% 90.20%  3998.51MB 99.13%  net/http.parsePostForm
  359.40MB  8.91% 99.11%   359.40MB  8.91%  bytes.makeSlice
   31.99MB  0.79% 99.90%    31.99MB  0.79%  net/http_test.BenchmarkParsePostForm
    0.50MB 0.012% 99.91%  4001.52MB 99.21%  net/http_test.BenchmarkParsePostForm.func1
     0     0% 99.91%   359.40MB  8.91%  bytes.(*Buffer).ReadFrom
     0     0% 99.91%  3999.01MB 99.14%  net/http.(*Request).ParseForm
     0     0% 99.91%  4033.51MB   100%  runtime.goexit
     0     0% 99.91%  4001.52MB 99.21%  testing.(*B).RunParallel.func1
     0     0% 99.91%    31.99MB  0.79%  testing.(*B).launch
     0     0% 99.91%    31.99MB  0.79%  testing.(*B).runN

(pprof) list parsePostForm
Total: 3.94GB
ROUTINE ======================== net/http.parsePostForm in /home/asticode/projects/go/go/src/net/http/request.go
    3.55GB     3.90GB (flat, cum) 99.13% of Total
     .          .    895:   // RFC 2616, section 7.2.1 - empty type
     .          .    896:   //   SHOULD be treated as application/octet-stream
     .          .    897:   if ct == "" {
     .          .    898:       ct = "application/octet-stream"
     .          .    899:   }
     .   512.05kB    900:   ct, _, err = mime.ParseMediaType(ct)
     .          .    901:   switch {
     .          .    902:   case ct == "application/x-www-form-urlencoded":
     .          .    903:       var reader io.Reader = r.Body
     .          .    904:       maxFormSize := int64(1<<63 - 1)
     .          .    905:       if _, ok := r.Body.(*maxBytesReader); !ok {
     .          .    906:           maxFormSize = int64(10 << 20) // 10 MB is a lot of text.
     .          .    907:           reader = io.LimitReader(r.Body, maxFormSize+1)
     .          .    908:       }
     .          .    909:       buf := bufferPool.Get().(*bytes.Buffer)
     .          .    910:       defer freeBuffer(buf)
     .   359.40MB    911:       _, e := buf.ReadFrom(reader)
     .          .    912:       if e != nil {
     .          .    913:           if err == nil {
     .          .    914:               err = e
     .          .    915:           }
     .          .    916:           break
     .          .    917:       }
     .          .    918:       if int64(buf.Len()) > maxFormSize {
     .          .    919:           err = errors.New("http: POST too large")
     .          .    920:           return
     .          .    921:       }
    3.55GB     3.55GB    922:       vs, e = url.ParseQuery(buf.String())
     .          .    923:       if err == nil {
     .          .    924:           err = e
     .          .    925:       }
     .          .    926:   case ct == "multipart/form-data":
     .          .    927:   // handled by ParseMultipartForm (which is calling us, or should be)

The very same command, this time at line 911, now eats only 359.40MB for the same number of requests.

If you need any extra information please let me know.

If you think this performance proposal is sound I'll mail the change for review using codereview.

Cheers
Quentin

bradfitz · 2016-03-05T16:29:25Z

Actually, instead of a sync.Pool I'd prefer to parse the io.Reader directory into a url.Values instead of doing the conversion from []byte to string on the whole input. I'd prefer to just do a bunch of little conversions from little byte slices to little strings.

(In the future, it might be nice to not even allocate for the common map keys, since most http.Handlers receiving POSTs will be getting the same map keys repeatedly. But there's no great place to stash that cache, since we don't know which handler the request is for (yet). We might know that later, if #14660 happens, since we could associate a Handler with a Request via context keys... but that's just thinking ahead and not needed for addressing this garbage)

asticode · 2016-03-05T20:43:18Z

You mean for instance adding a url.ParseQueryFromReader method that takes an io.Reader and returns a url.Values by reading byte by byte in the reader and parsing the body ?

bradfitz · 2016-03-05T21:47:22Z

Without adding any new public API, though.

asticode · 2016-03-06T15:43:46Z

OK so to avoid adding a public API I've added a parsePostFormURLEncoded method in the http package such as :

var (
    byteAmp = []byte("&")
    byteEqual = []byte("=")
    byteSemiColon = []byte(";")
)

func parsePostFormURLEncoded(reader io.Reader, vs url.Values, maxFormSize int64) (err error) {
    var buf bytes.Buffer
    var key string
    var value string
    var i int64
    b := make([]byte, 1)
    for {
        if i >= maxFormSize {
            err = errors.New("http: POST too large")
            return
        }
        n, e := reader.Read(b)
        if e != nil && e.Error() != io.EOF.Error() {
            err = e
            return
        }
        i += int64(n)
        if bytes.Equal(b, byteEqual) {
            key, e = url.QueryUnescape(buf.String())
            if e != nil {
                err = e
                return
            }
            buf.Reset()
        } else if bytes.Equal(b, byteAmp) || bytes.Equal(b, byteSemiColon) || n == 0 {
            value, e = url.QueryUnescape(buf.String())
            if e != nil {
                err = e
                return
            }
            vs[key] = append(vs[key], value)
            buf.Reset()
        } else {
            buf.Write(b)
        }
        if n == 0 {
            return
        }
    }
    return
}

Is that what you had in mind ?

Because running the same benchmark gives me worse results than the last 2 benchmarks :

$ go test ./src/net/http -v -run=^$ -bench=BenchmarkParsePostForm -benchtime=10s -parallel=4 -memprofile=prof.mem
BenchmarkParsePostForm-4         500      30509320 ns/op     7506321 B/op         29 allocs/op
PASS
ok      net/http    26.665s

Just by looking at this result we can see that it's 3 times slower and allocates as much as the original implementation (since this time it only does 500 repetitions vs 2000 last time)

$ go tool pprof --alloc_space http.test prof.mem Entering interactive mode (type "help" for commands)
(pprof) top
6091.52MB of 6093.02MB total (  100%)
Dropped 2 nodes (cum <= 30.47MB)
Showing top 10 nodes out of 12 (cum >= 6050.36MB)
      flat  flat%   sum%        cum   cum%
 4644.73MB 76.23% 76.23%  4644.73MB 76.23%  bytes.makeSlice
 1403.63MB 23.04% 99.27%  6048.36MB 99.27%  net/http.parsePostFormURLEncoded
   42.66MB   0.7%   100%    42.66MB   0.7%  net/http_test.BenchmarkParsePostForm
    0.50MB 0.0082%   100%  6048.86MB 99.28%  net/http.parsePostForm
     0     0%   100%  4644.73MB 76.23%  bytes.(*Buffer).Write
     0     0%   100%  4644.73MB 76.23%  bytes.(*Buffer).grow
     0     0%   100%  6048.86MB 99.28%  net/http.(*Request).ParseForm
     0     0%   100%  6050.36MB 99.30%  net/http_test.BenchmarkParsePostForm.func1
     0     0%   100%  6093.02MB   100%  runtime.goexit
     0     0%   100%  6050.36MB 99.30%  testing.(*B).RunParallel.func1
(pprof) list parsePostFormURLEncoded
Total: 5.95GB
ROUTINE ======================== net/http.parsePostFormURLEncoded in /home/asticode/projects/go/go/src/net/http/request.go
    1.37GB     5.91GB (flat, cum) 99.27% of Total
     .          .    940:               err = e
     .          .    941:               return
     .          .    942:           }
     .          .    943:           buf.Reset()
     .          .    944:       } else if bytes.Equal(b, byteAmp) || bytes.Equal(b, byteSemiColon) || n == 0 {
    1.37GB     1.37GB    945:           value, e = url.QueryUnescape(buf.String())
     .          .    946:           if e != nil {
     .          .    947:               err = e
     .          .    948:               return
     .          .    949:           }
     .          .    950:           vs[key] = append(vs[key], value)
     .          .    951:           buf.Reset()
     .          .    952:       } else {
     .     4.54GB    953:           buf.Write(b)
     .          .    954:       }
     .          .    955:       if n == 0 {
     .          .    956:           return
     .          .    957:       }
     .          .    958:   }

Is there any particular reason you don't want to go the sync.Pool way ?

If you still do, is there anything I've misinterpreted from your guidelines that would worsen the benchmark ?

bradfitz · 2016-03-06T15:59:51Z

If you want me to do a code review, please send a change in Gerrit. See https://golang.org/doc/contribute.html

Otherwise I can look into this later, writing a fast version. There are a number of things not fast about your code.

asticode · 2016-03-06T16:36:55Z

Just sent the change in Gerrit. Looking forward for your code review :)
Cheers

gopherbot · 2016-03-06T17:00:43Z

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

bradfitz · 2016-09-30T14:51:28Z

@odeke-em, are you interested in taking this over now that the tree is open?

Or @asticode, if you're still interested you could pick up your CL and finish it.

asticode · 2016-09-30T15:33:56Z

@bradfitz I'll try to pick it up this week-end
@odeke-em let me know if you're working on this as well
Cheers

odeke-em · 2016-09-30T17:17:41Z

Thank you for the assignment @bradfitz am very happy to help out with this.
Alright, @asticode we can work on your CL, I am already one of the reviewers on it so I'll be updated when there is movement on it, thanks.

asticode · 2016-10-01T17:13:40Z

@odeke-em FYI I've just pushed my changes with the benchmark included in the commit message

gopherbot · 2016-10-05T20:25:33Z

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

gopherbot · 2016-10-05T21:35:12Z

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


        Revert "net/http: improve performance for parsePostForm"

This reverts commit 59320c3. Reasons: This CL was causing failures on a large regression test that we run within Google. The issues arises from two bugs in the CL: * The CL dropped support for ';' as a delimiter (see https://golang.org/issue/2210) * The handling of an empty string caused an empty record to be added when no record was added (see https://golang.org/cl/30454 for my attempted fix) The logic being added is essentially a variation of url.ParseQuery, but altered to accept an io.Reader instead of a string. Since it is duplicated (but modified) logic, there needs to be good tests to ensure that it's implementation doesn't drift in functionality from url.ParseQuery. Fixing the above issues and adding the associated regression tests leads to >100 lines of codes. For a 4% reduction in CPU time, I think this complexity and duplicated logic is not worth the effort. As such, I am abandoning my efforts to fix the existing issues and believe that reverting CL/20301 is the better course of action. Updates #14655 Change-Id: Ibb5be0a5b48a16c46337e213b79467fcafee69df Reviewed-on: https://go-review.googlesource.com/30470 Run-TryBot: Joe Tsai <thebrokentoaster@gmail.com> TryBot-Result: Gobot Gobot <gobot@golang.org> Reviewed-by: Brad Fitzpatrick <bradfitz@golang.org>

asticode changed the title ~~net/http: performance improvement for parsePostForm~~ proposal: net/http: improve performance for parsePostForm Mar 5, 2016

bradfitz added this to the Go1.7 milestone Mar 5, 2016

bradfitz added the Performance label Mar 5, 2016

rsc modified the milestones: Go1.8, Go1.7 May 18, 2016

bradfitz self-assigned this Aug 22, 2016

bradfitz changed the title ~~proposal: net/http: improve performance for parsePostForm~~ net/http: improve performance for parsePostForm Aug 22, 2016

bradfitz assigned odeke-em Sep 30, 2016

bradfitz modified the milestones: Go1.8Maybe, Go1.8 Sep 30, 2016

bradfitz added the help wanted label Sep 30, 2016

gopherbot closed this in 59320c3 Oct 4, 2016

asticode mentioned this issue Oct 6, 2016

net/http: Add missing tests for parsePostForm #17368

Closed

golang locked and limited conversation to collaborators Oct 5, 2017

gopherbot added the FrozenDueToAge label Oct 5, 2017

golang / go

net/http: improve performance for parsePostForm #14655

net/http: improve performance for parsePostForm #14655

asticode commented Mar 5, 2016

This comment has been minimized.

bradfitz commented Mar 5, 2016

This comment has been minimized.

asticode commented Mar 5, 2016

This comment has been minimized.

bradfitz commented Mar 5, 2016

This comment has been minimized.

asticode commented Mar 6, 2016

This comment has been minimized.

bradfitz commented Mar 6, 2016

This comment has been minimized.

asticode commented Mar 6, 2016

This comment has been minimized.

gopherbot commented Mar 6, 2016

This comment has been minimized.

bradfitz commented Sep 30, 2016

This comment has been minimized.

asticode commented Sep 30, 2016

This comment has been minimized.

odeke-em commented Sep 30, 2016

This comment has been minimized.

asticode commented Oct 1, 2016

This comment has been minimized.

gopherbot commented Oct 5, 2016

This comment has been minimized.

gopherbot commented Oct 5, 2016

golang / go

Join GitHub today

net/http: improve performance for parsePostForm #14655

net/http: improve performance for parsePostForm #14655

Comments

asticode commented Mar 5, 2016

This comment has been minimized.

bradfitz commented Mar 5, 2016

This comment has been minimized.

asticode commented Mar 5, 2016

This comment has been minimized.

bradfitz commented Mar 5, 2016

This comment has been minimized.

asticode commented Mar 6, 2016

This comment has been minimized.

bradfitz commented Mar 6, 2016

This comment has been minimized.

asticode commented Mar 6, 2016

This comment has been minimized.

gopherbot commented Mar 6, 2016

This comment has been minimized.

bradfitz commented Sep 30, 2016

This comment has been minimized.

asticode commented Sep 30, 2016

This comment has been minimized.

odeke-em commented Sep 30, 2016

This comment has been minimized.

asticode commented Oct 1, 2016

This comment has been minimized.

gopherbot commented Oct 5, 2016

This comment has been minimized.

gopherbot commented Oct 5, 2016