High frequency GET requests.

[Niko Schwarz]

I've had a snippet of code that polls a local server very frequently, and I'm somewhat surprised in how many ways it's failing. I've tried to simplify it, and the following sadly isn't as diverse in its error messages. 

Here's the simplified version:

package main

import (

"fmt"

"log"

"net/http"

"sync"

"testing"

"time"

)

func TestProvoke(t *testing.T) {

go func() {

log.Fatal(http.ListenAndServe(":7000", http.HandlerFunc(func(out http.ResponseWriter, in *http.Request) {

out.Write([]byte("Hi"))

})))

}()

time.Sleep(500 * time.Millisecond)

var wg sync.WaitGroup

wg.Add(256)

for i := 0; i < 256; i++ {

go func() {

for j := 0; j < 400; j++ {

resp, err := http.Get("http://localhost:7000")

if err != nil {

panic(err)

}

resp.Body.Close()

}

wg.Done()

}()

}

wg.Wait()

}

It produces three error messages on OSX:

    panic: Get http://localhost:7000: dial tcp 127.0.0.1:7000: connection reset by peer

    panic: Get http://localhost:7000: lookup localhost: no such host

    panic: Get http://localhost:7000: dial tcp 127.0.0.1:7000: too many open files

The last of which actually makes sense, and can be avoided by `ulimit -n 10000`

The first might also make sense if I'm just overloading the server. However, the server doesn't give any log output indicating this. The middle one just seems nuts to me.

The original snippet was more interesting. It produced all of the previous, but also, after hundreds of successful runs:

   panic: dial tcp 127.0.0.1:9000: can't assign requested address

After running the original snippet, I usually can't open pages in the web browser for a few seconds after, as if I'm running out of sockets, file handles, or something of the sort.

[Nick Craig-Wood]

On 19/08/13 13:38, Niko Schwarz wrote:
> I've had a snippet of code that polls a local server very frequently,
> and I'm somewhat surprised in how many ways it's failing. I've tried to
> simplify it, and the following sadly isn't as diverse in its error
> messages.

[snip]

> It produces three error messages on OSX:
>
>
> panic: Get http://localhost:7000: dial tcp 127.0.0.1:7000:
> connection reset by peer
>
>
> panic: Get http://localhost:7000: lookup localhost: no such host
>
>
> panic: Get http://localhost:7000: dial tcp 127.0.0.1:7000: too many
> open files
>
>
> The last of which actually makes sense, and can be avoided by `ulimit -n
> 10000`
>
> The first might also make sense if I'm just overloading the server.
> However, the server doesn't give any log output indicating this. The
> middle one just seems nuts to me.

I suspect it is a consequence of running out of sockets. Quite likely a
name lookup needs a socket (don't know exactly how OS X works though!).


--
Nick Craig-Wood <ni...@craig-wood.com> -- http://www.craig-wood.com/nick

[Niko Schwarz]

This page says that I have 16k ports to play with:

http://superuser.com/questions/145989/does-mac-os-x-throttle-the-rate-of-socket-creation

So, given that I never need more than 512 at any point in time -- what's wrong? Why aren't they recycled properly?

Niko

[Dave Cheney]

Which version of Go are you running? Can you try with tip?

--
You received this message because you are subscribed to the Google Groups "golang-nuts" group.
To unsubscribe from this group and stop receiving emails from it, send an email to golang-nuts...@googlegroups.com.
For more options, visit https://groups.google.com/groups/opt_out.

[Dave Cheney]

Sockets are recycled instantly, google TIME_WAIT, and use lsof -p on your process as it runs. 

--

[Konstantin Khomoutov]

On Mon, 19 Aug 2013 06:24:08 -0700 (PDT)
Niko Schwarz <niko.s...@googlemail.com> wrote:

[...]

> > > I've had a snippet of code that polls a local server very
> > > frequently, and I'm somewhat surprised in how many ways it's
> > > failing. I've tried to simplify it, and the following sadly isn't
> > > as diverse in its error messages.

[...]

> > > panic: Get http://localhost:7000: lookup localhost: no such
> > > host

[...]

> > > The first might also make sense if I'm just overloading the
> > > server. However, the server doesn't give any log output
> > > indicating this. The middle one just seems nuts to me.
> >
> > I suspect it is a consequence of running out of sockets. Quite
> > likely a name lookup needs a socket (don't know exactly how OS X
> > works though!).
> >

> This page says that I have 16k ports to play with:
>
> http://superuser.com/questions/145989/does-mac-os-x-throttle-the-rate-of-socket-creation
>
> So, given that I never need more than 512 at any point in time --
> what's wrong? Why aren't they recycled properly?

Then I'd try to spawn `lsof` on the PID of your testing process [3]
before panicking and dump the state of its descriptors into a file for
post-mortem inspection -- see [1] (via [2]).

P.S.
Please don't top-post.

1. http://stackoverflow.com/a/798265/720999
2. http://macosx.com/forums/mac-os-x-system-mac-software/320133-proc-pid-fd-mapping-macosx.html
3. http://golang.org/pkg/os/#Getpid

[Konstantin Khomoutov]

On Mon, 19 Aug 2013 06:24:08 -0700 (PDT)
Niko Schwarz <niko.s...@googlemail.com> wrote:

[...]

> > > I've had a snippet of code that polls a local server very
> > > frequently, and I'm somewhat surprised in how many ways it's
> > > failing. I've tried to simplify it, and the following sadly isn't
> > > as diverse in its error messages.

[...]

> > > panic: Get http://localhost:7000: lookup localhost: no such
> > > host

[...]

> > > The first might also make sense if I'm just overloading the
> > > server. However, the server doesn't give any log output
> > > indicating this. The middle one just seems nuts to me.
> >
> > I suspect it is a consequence of running out of sockets. Quite
> > likely a name lookup needs a socket (don't know exactly how OS X
> > works though!).
> >

> This page says that I have 16k ports to play with:
>
> http://superuser.com/questions/145989/does-mac-os-x-throttle-the-rate-of-socket-creation
>
> So, given that I never need more than 512 at any point in time --
> what's wrong? Why aren't they recycled properly?

[Eli Janssen]

It looks like you aren't reading the response body before closing it. If you don't read the body, and simply close, then the connection will not be reused.

Try adding a `io.Copy(ioutil.Discard, resp.Body)` before your call to `resp.Body.Close()`.

>> Nick Craig-Wood <ni...@craig-wood.com <javascript:>> --

[Niko Schwarz]

Eli,

That was indeed the problem and solution. I just don't understand why. The code in transfer.go reads:

func (b *body) Close() error {

if b.closed {

return nil

}

var err error

switch {

case b.hdr == nil && b.closing:

// no trailer and closing the connection next.

// no point in reading to EOF.

case b.res != nil && b.res.requestBodyLimitHit:

// In a server request, don't continue reading from the client

// if we've already hit the maximum body size set by the

// handler. If this is set, that also means the TCP connection

// is about to be closed, so getting to the next HTTP request

// in the stream is not necessary.

case b.Reader == eofReader:

// Nothing to read. No need to io.Copy from it.

default:

// Fully consume the body, which will also lead to us reading

// the trailer headers after the body, if present.

_, err = io.Copy(ioutil.Discard, b)

}

b.closed = true

return err

}

I find reasonably obvious from the comments that it should never be necessary to both close and read discard. Therefore, I think I've hit a bug, no?

@Andrew: Behavior is the same on 1.1.2 and on tip.

Niko

[Eli Janssen]

https://code.google.com/p/go/source/detail?r=d4e1ec84876c0f5611ab86a03826da14b866efb2&name=release-branch.go1.1&path=/src/pkg/net/http/transport.go

code has moved around a bit since then, but it looks like the relevant parts in transport are now here:
https://code.google.com/p/go/source/browse/src/pkg/net/http/transport.go#745
and here:
https://code.google.com/p/go/source/browse/src/pkg/net/http/transport.go#1008

this comment, is also informative:
https://code.google.com/p/go/source/browse/src/pkg/net/http/transport.go#964

mailing list references:
https://groups.google.com/d/topic/golang-nuts/K0iAoVhAouE/discussion
https://groups.google.com/d/topic/golang-nuts/l2rEBV6XhhI/discussion

>
> @Andrew: Behavior is the same on 1.1.2 and on tip.
>
> Niko
>
>
> On Monday, August 19, 2013 9:10:41 PM UTC+2, Eli Janssen wrote:
>>
>> It looks like you aren't reading the response body before closing it. If
>> you don't read the body, and simply close, then the connection will not be
>> reused.
>>
>> Try adding a `io.Copy(ioutil.Discard, resp.Body)` before your call to
>> `resp.Body.Close()`.
>>

>> On Aug 19, 2013, at 6:24 AM, Niko Schwarz <niko.s...@googlemail.com<javascript:>>

>> an email to golang-nuts...@googlegroups.com <javascript:>.

[Carlos Castillo]

You should probably use net/http/httptest to build your test-server. This way you don't need to time.Sleep() to avoid the race between when the server starts (in it's own go-routine) and when the client connections are made.