queued is always 0

queued is always 0

[Ryan King]

I'm trying to see if raindrops will help us instrument our stack, so
I'm doing some tests.

I have 16 unicorns running our app with rainbows and am hitting it
with ab with a concurrency of 100. However, according to
linux-tcp-listener-stats.rb I have 0 queued requests. Maybe I'm
missing something, but shouldn't there be queued requests somewhere
here?

-ryan

Re: queued is always 0

[Eric Wong]

Ryan King <ryan@twitter.com> wrote:
> I'm trying to see if raindrops will help us instrument our stack, so
> I'm doing some tests.
> 
> I have 16 unicorns running our app with rainbows and am hitting it
> with ab with a concurrency of 100. However, according to
> linux-tcp-listener-stats.rb I have 0 queued requests. Maybe I'm
> missing something, but shouldn't there be queued requests somewhere
> here?

Hi Ryan,

The Unicorns could be accept()-ing connections fast enough and the
queued connections aren't noticeable[1].

Try sending SIGWINCH to the Unicorn master process and they
should be queueing up because all the workers will have stopped.
(SIGHUP to restart the workers).


You can test and walk through this yourself on IRB, too:

1. startup irb: "irb -rsocket", then inside irb:

   server = TCPServer.new '127.0.0.1', 3000


2. Now, hit the address you started the server on in a different
   terminal with curl:

     curl -v http://127.0.0.1:3000/  # curl should block here

3. Run linux-tcp-listener-stats:

    ./examples/linux-tcp-listener-stats.rb 127.0.0.1:3000
    # You should see one queued, zero active

4. Back in irb, accept the connection:

   client = server.accept # should get a TCPSocket object

5. Run linux-tcp-listener-stats again:

    ./examples/linux-tcp-listener-stats.rb 127.0.0.1:3000
    # You should see one active, zero queued


If you fire up more curl instances in other terminals without
running "server.accept" in IRB, you should see more queued.

Let me know how it goes for you.

[1] - On a side note, Unicorn is very aggressive about accepting
      connections, it speculatively tries to accept() after each
      application dispatch (which could've taken a long time)
      instead of running select() on the listen socket first.

-- 
Eric Wong

Re: queued is always 0

[Ryan King]

On Mon, Jun 28, 2010 at 5:50 PM, Eric Wong <normalperson@yhbt.net> wrote:
> Ryan King <ryan@twitter.com> wrote:
>> I'm trying to see if raindrops will help us instrument our stack, so
>> I'm doing some tests.
>>
>> I have 16 unicorns running our app with rainbows and am hitting it
>> with ab with a concurrency of 100. However, according to
>> linux-tcp-listener-stats.rb I have 0 queued requests. Maybe I'm
>> missing something, but shouldn't there be queued requests somewhere
>> here?
>
> Hi Ryan,
>
> The Unicorns could be accept()-ing connections fast enough and the
> queued connections aren't noticeable[1].
>
> Try sending SIGWINCH to the Unicorn master process and they
> should be queueing up because all the workers will have stopped.
> (SIGHUP to restart the workers).
>
>
> You can test and walk through this yourself on IRB, too:
>
> 1. startup irb: "irb -rsocket", then inside irb:
>
>   server = TCPServer.new '127.0.0.1', 3000
>
>
> 2. Now, hit the address you started the server on in a different
>   terminal with curl:
>
>     curl -v http://127.0.0.1:3000/  # curl should block here
>
> 3. Run linux-tcp-listener-stats:
>
>    ./examples/linux-tcp-listener-stats.rb 127.0.0.1:3000
>    # You should see one queued, zero active
>
> 4. Back in irb, accept the connection:
>
>   client = server.accept # should get a TCPSocket object
>
> 5. Run linux-tcp-listener-stats again:
>
>    ./examples/linux-tcp-listener-stats.rb 127.0.0.1:3000
>    # You should see one active, zero queued
>
>
> If you fire up more curl instances in other terminals without
> running "server.accept" in IRB, you should see more queued.
>
> Let me know how it goes for you.
>
> [1] - On a side note, Unicorn is very aggressive about accepting
>      connections, it speculatively tries to accept() after each
>      application dispatch (which could've taken a long time)
>      instead of running select() on the listen socket first.

I did as you describe here and I got the expected results.

I think I'm just confused at this point. We have 16 unicorns running,
with 100 clients, but no queued connections, which makes me assume
that we have accepted connections that we can't actually service yet.
Is this true?

-ryan

Re: queued is always 0

[Eric Wong]

Ryan King <ryan@twitter.com> wrote:
> On Mon, Jun 28, 2010 at 5:50 PM, Eric Wong <normalperson@yhbt.net> wrote:
> > Ryan King <ryan@twitter.com> wrote:
> >> I'm trying to see if raindrops will help us instrument our stack, so
> >> I'm doing some tests.
> >>
> >> I have 16 unicorns running our app with rainbows and am hitting it
> >> with ab with a concurrency of 100. However, according to
> >> linux-tcp-listener-stats.rb I have 0 queued requests. Maybe I'm
> >> missing something, but shouldn't there be queued requests somewhere
> >> here?
> >
> > Hi Ryan,
> >
> > The Unicorns could be accept()-ing connections fast enough and the
> > queued connections aren't noticeable[1].

<snip>

> I did as you describe here and I got the expected results.
> 
> I think I'm just confused at this point. We have 16 unicorns running,
> with 100 clients, but no queued connections, which makes me assume
> that we have accepted connections that we can't actually service yet.
> Is this true?

Not true with Unicorn.  Unicorn won't accept connections it can't
service, ever.

It could be ab itself isn't able to keep up with the requests/responses.

How fast are your response times?

What happens when you run fewer Unicorn workers or increase concurrency
with ab?

How large are your responses?

If you have small responses, Unicorn could've also finished writing the
response to the socket buffers and accepted another connection by the
time ab gets around to reading the socket.

Under Linux, Unicorn (and Mongrel) also uses TCP_DEFER_ACCEPT with a
value of 1 (second)[1], so it won't even register in the queue if
ab opened the socket and didn't have a chance to write to it, yet...

You could try commenting out the setsockopt call to set
TCP_DEFER_ACCEPT in lib/unicorn/socket_helper.rb for testing
and see if the queue jumps up, too..


I noticed that the usage string for linux-tcp-listener-stats.rb was
wrong yesterday (and updated it in rainbows.git), but you can try
running it in a tight delay loop with "-d <seconds>":

  ruby linux-tcp-listener-stats.rb -d 0.01 | awk '$3 != 0 { print $0}'

The above will only print lines if there are queued connections.  You
can replace "-d 0.01" with a smaller number, but Raindrops (and the
underlying tcpdiag kernel module) can only give a snapshot of the
current queue size).



[1] - I should actually make the defer timeout configurable, especially
      for Rainbows!  nginx sets this to 60s and it seems to work fine.

-- 
Eric Wong

Re: queued is always 0

[Ryan King]

On Tue, Jun 29, 2010 at 7:45 PM, Eric Wong <normalperson@yhbt.net> wrote:
> Ryan King <ryan@twitter.com> wrote:
>> On Mon, Jun 28, 2010 at 5:50 PM, Eric Wong <normalperson@yhbt.net> wrote:
>> > Ryan King <ryan@twitter.com> wrote:
>> >> I'm trying to see if raindrops will help us instrument our stack, so
>> >> I'm doing some tests.
>> >>
>> >> I have 16 unicorns running our app with rainbows and am hitting it
>> >> with ab with a concurrency of 100. However, according to
>> >> linux-tcp-listener-stats.rb I have 0 queued requests. Maybe I'm
>> >> missing something, but shouldn't there be queued requests somewhere
>> >> here?
>> >
>> > Hi Ryan,
>> >
>> > The Unicorns could be accept()-ing connections fast enough and the
>> > queued connections aren't noticeable[1].
>
> <snip>
>
>> I did as you describe here and I got the expected results.
>>
>> I think I'm just confused at this point. We have 16 unicorns running,
>> with 100 clients, but no queued connections, which makes me assume
>> that we have accepted connections that we can't actually service yet.
>> Is this true?
>
> Not true with Unicorn.  Unicorn won't accept connections it can't
> service, ever.
>
> It could be ab itself isn't able to keep up with the requests/responses.
>
> How fast are your response times?

Pretty slow, actually. Running with concurrency of 16 (with 16 workers):


  Connection Times (ms)
                min  mean[+/-sd] median   max
  Connect:        0    0   1.0      0      12
  Processing:  1698 2444 351.8   2403    5885
  Waiting:     1698 2444 351.9   2403    5885
  Total:       1698 2444 352.0   2403    5886

  Percentage of the requests served within a certain time (ms)
    50%   2403
    66%   2533
    75%   2616
    80%   2670
    90%   2900
    95%   3085
    98%   3285
    99%   3478
   100%   5886 (longest request)


> What happens when you run fewer Unicorn workers or increase concurrency
> with ab?

I bumped the concurrency up to 2000 (with 16 workers) and still no
queuing (according to raindrops).

Interestingly, when I ran this benchmark ab died because of timeouts.
I lowered the concurrency back to 16 and ran it again, which quickly
caused timeouts. When I looked at the unicorn processes it was obvious
that they were still processing a backlog processes from the first ab
run. I'm not sure if this is how it is supposed to work, but it was
surprising to me.

> How large are your responses?

About 43 KB.

> If you have small responses, Unicorn could've also finished writing the
> response to the socket buffers and accepted another connection by the
> time ab gets around to reading the socket.
>
> Under Linux, Unicorn (and Mongrel) also uses TCP_DEFER_ACCEPT with a
> value of 1 (second)[1], so it won't even register in the queue if
> ab opened the socket and didn't have a chance to write to it, yet...
>
> You could try commenting out the setsockopt call to set
> TCP_DEFER_ACCEPT in lib/unicorn/socket_helper.rb for testing
> and see if the queue jumps up, too..

We're not setting the tcp_nodelay option, so that code shouldn't be
getting run, right?

> I noticed that the usage string for linux-tcp-listener-stats.rb was
> wrong yesterday (and updated it in rainbows.git), but you can try
> running it in a tight delay loop with "-d <seconds>":
>
>  ruby linux-tcp-listener-stats.rb -d 0.01 | awk '$3 != 0 { print $0}'
>
> The above will only print lines if there are queued connections.  You
> can replace "-d 0.01" with a smaller number, but Raindrops (and the
> underlying tcpdiag kernel module) can only give a snapshot of the
> current queue size).

I had done basically the same thing in previous test runs. Never any
queued requests.

I'm really hoping that I just misunderstand something here, but it
seems that our unicorn processes are accepting connections long before
they can service them.

-ryan

>
>
> [1] - I should actually make the defer timeout configurable, especially
>      for Rainbows!  nginx sets this to 60s and it seems to work fine.
>
> --
> Eric Wong
>

Re: queued is always 0

[Ryan King]

Not sure if this is relevant, but we're running a slightly older
version of unicorn: 0.96.1. Would that have an effect here?

-ryan

Re: queued is always 0

[Eric Wong]

Ryan King <ryan@twitter.com> wrote:

Sorry for the late response, I was afk the entire day.

> On Tue, Jun 29, 2010 at 7:45 PM, Eric Wong <normalperson@yhbt.net> wrote:
> > Ryan King <ryan@twitter.com> wrote:
> >> On Mon, Jun 28, 2010 at 5:50 PM, Eric Wong <normalperson@yhbt.net> wrote:
<snip>

> > What happens when you run fewer Unicorn workers or increase concurrency
> > with ab?
> 
> I bumped the concurrency up to 2000 (with 16 workers) and still no
> queuing (according to raindrops).
> 
> Interestingly, when I ran this benchmark ab died because of timeouts.
> I lowered the concurrency back to 16 and ran it again, which quickly
> caused timeouts. When I looked at the unicorn processes it was obvious
> that they were still processing a backlog processes from the first ab
> run. I'm not sure if this is how it is supposed to work, but it was
> surprising to me.

They were buffered in the kernel, and Unicorn doesn't have a good way to
know if a client disconnected until Unicorn tries writing the response
(often not even the first packets).

> > How large are your responses?
> 
> About 43 KB.

That should be small enough to fit inside the default socket buffers
without ever blocking.

> > If you have small responses, Unicorn could've also finished writing the
> > response to the socket buffers and accepted another connection by the
> > time ab gets around to reading the socket.
> >
> > Under Linux, Unicorn (and Mongrel) also uses TCP_DEFER_ACCEPT with a
> > value of 1 (second)[1], so it won't even register in the queue if
> > ab opened the socket and didn't have a chance to write to it, yet...
> >
> > You could try commenting out the setsockopt call to set
> > TCP_DEFER_ACCEPT in lib/unicorn/socket_helper.rb for testing
> > and see if the queue jumps up, too..
> 
> We're not setting the tcp_nodelay option, so that code shouldn't be
> getting run, right?

It does run and we always set TCP_DEFER_ACCEPT (since the Mongrel days).
It is safe to disable for Unicorn if you're behind a reverse proxy,
but it shouldn't be a noticeable performance hit either way.

I'll definitely make this configurable in the future (since higher
values are desirable against some attacks), but there's no reason to
disable it for anything other than benchmarking/testing you're doing
now..

> > I noticed that the usage string for linux-tcp-listener-stats.rb was
> > wrong yesterday (and updated it in rainbows.git), but you can try
> > running it in a tight delay loop with "-d <seconds>":
> >
> >  ruby linux-tcp-listener-stats.rb -d 0.01 | awk '$3 != 0 { print $0}'
> >
> > The above will only print lines if there are queued connections.  You
> > can replace "-d 0.01" with a smaller number, but Raindrops (and the
> > underlying tcpdiag kernel module) can only give a snapshot of the
> > current queue size).
> 
> I had done basically the same thing in previous test runs. Never any
> queued requests.
> 
> I'm really hoping that I just misunderstand something here, but it
> seems that our unicorn processes are accepting connections long before
> they can service them.

Now that I think about it, it could be possible you're making a small
mistake in your linux-tcp-listener-stats invocation.

Unicorn listens to all interfaces on a specified port by default (e.g.
0.0.0.0:8080)  So you would need to point linux-tcp-listener-stats.rb
to "0.0.0.0:8080" and not "127.0.0.1:8080" (which may provide you
with a list of _client_ sockets, not server ones).


It looks like raindrops may double count localhost connections
because the client and server address are on the same host, and
I seem to recall tcpdiag not providing a way to filter those...
(It is very late at night for me, so I'll look at this again
sometime tomorrow.)

-- 
Eric Wong

Re: queued is always 0

[Ryan King]

On Thu, Jul 1, 2010 at 3:18 AM, Eric Wong <normalperson@yhbt.net> wrote:
> Ryan King <ryan@twitter.com> wrote:
>
> Sorry for the late response, I was afk the entire day.
>
>> On Tue, Jun 29, 2010 at 7:45 PM, Eric Wong <normalperson@yhbt.net> wrote:
>> > Ryan King <ryan@twitter.com> wrote:
>> >> On Mon, Jun 28, 2010 at 5:50 PM, Eric Wong <normalperson@yhbt.net> wrote:
> <snip>
>
>> > What happens when you run fewer Unicorn workers or increase concurrency
>> > with ab?
>>
>> I bumped the concurrency up to 2000 (with 16 workers) and still no
>> queuing (according to raindrops).
>>
>> Interestingly, when I ran this benchmark ab died because of timeouts.
>> I lowered the concurrency back to 16 and ran it again, which quickly
>> caused timeouts. When I looked at the unicorn processes it was obvious
>> that they were still processing a backlog processes from the first ab
>> run. I'm not sure if this is how it is supposed to work, but it was
>> surprising to me.
>
> They were buffered in the kernel, and Unicorn doesn't have a good way to
> know if a client disconnected until Unicorn tries writing the response
> (often not even the first packets).
>
>> > How large are your responses?
>>
>> About 43 KB.
>
> That should be small enough to fit inside the default socket buffers
> without ever blocking.
>
>> > If you have small responses, Unicorn could've also finished writing the
>> > response to the socket buffers and accepted another connection by the
>> > time ab gets around to reading the socket.
>> >
>> > Under Linux, Unicorn (and Mongrel) also uses TCP_DEFER_ACCEPT with a
>> > value of 1 (second)[1], so it won't even register in the queue if
>> > ab opened the socket and didn't have a chance to write to it, yet...
>> >
>> > You could try commenting out the setsockopt call to set
>> > TCP_DEFER_ACCEPT in lib/unicorn/socket_helper.rb for testing
>> > and see if the queue jumps up, too..
>>
>> We're not setting the tcp_nodelay option, so that code shouldn't be
>> getting run, right?
>
> It does run and we always set TCP_DEFER_ACCEPT (since the Mongrel days).
> It is safe to disable for Unicorn if you're behind a reverse proxy,
> but it shouldn't be a noticeable performance hit either way.
>
> I'll definitely make this configurable in the future (since higher
> values are desirable against some attacks), but there's no reason to
> disable it for anything other than benchmarking/testing you're doing
> now..
>
>> > I noticed that the usage string for linux-tcp-listener-stats.rb was
>> > wrong yesterday (and updated it in rainbows.git), but you can try
>> > running it in a tight delay loop with "-d <seconds>":
>> >
>> >  ruby linux-tcp-listener-stats.rb -d 0.01 | awk '$3 != 0 { print $0}'
>> >
>> > The above will only print lines if there are queued connections.  You
>> > can replace "-d 0.01" with a smaller number, but Raindrops (and the
>> > underlying tcpdiag kernel module) can only give a snapshot of the
>> > current queue size).
>>
>> I had done basically the same thing in previous test runs. Never any
>> queued requests.
>>
>> I'm really hoping that I just misunderstand something here, but it
>> seems that our unicorn processes are accepting connections long before
>> they can service them.
>
> Now that I think about it, it could be possible you're making a small
> mistake in your linux-tcp-listener-stats invocation.
>
> Unicorn listens to all interfaces on a specified port by default (e.g.
> 0.0.0.0:8080)  So you would need to point linux-tcp-listener-stats.rb
> to "0.0.0.0:8080" and not "127.0.0.1:8080" (which may provide you
> with a list of _client_ sockets, not server ones).

God, you're right. This is the problem. When I switch the invocation
it works as expected.

> It looks like raindrops may double count localhost connections
> because the client and server address are on the same host, and
> I seem to recall tcpdiag not providing a way to filter those...
> (It is very late at night for me, so I'll look at this again
> sometime tomorrow.)

In this test, its counting the ab connections on 127.0.0.1, but the
server connections on 0.0.0.0.

-ryan

Re: queued is always 0

[Eric Wong]

Ryan King <ryan@twitter.com> wrote:
> On Thu, Jul 1, 2010 at 3:18 AM, Eric Wong <normalperson@yhbt.net> wrote:
> > Now that I think about it, it could be possible you're making a small
> > mistake in your linux-tcp-listener-stats invocation.
> >
> > Unicorn listens to all interfaces on a specified port by default (e.g.
> > 0.0.0.0:8080)  So you would need to point linux-tcp-listener-stats.rb
> > to "0.0.0.0:8080" and not "127.0.0.1:8080" (which may provide you
> > with a list of _client_ sockets, not server ones).
> 
> God, you're right. This is the problem. When I switch the invocation
> it works as expected.

Awesome.  I've just pushed out a patch to raindrops.git to have
linux-tcp-listener-stats warn if it detects a listener on
0.0.0.0:#{port} but was passed an address of 127.X.Y.Z:#{port}.

Hopefully it's less confusing for future users.

I didn't want to make (currently) invalid addresses raise an exception,
since sometimes I run the script before starting the server or leave
it running when I shut the server down.

> > It looks like raindrops may double count localhost connections
> > because the client and server address are on the same host, and
> > I seem to recall tcpdiag not providing a way to filter those...
> > (It is very late at night for me, so I'll look at this again
> > sometime tomorrow.)
> 
> In this test, its counting the ab connections on 127.0.0.1, but the
> server connections on 0.0.0.0.

Yup, the counts look correct to each address.  I was tired last
night :x

-- 
Eric Wong