* queued is always 0 @ 2010-06-29 0:26 Ryan King 2010-06-29 0:50 ` Eric Wong 0 siblings, 1 reply; 9+ messages in thread From: Ryan King @ 2010-06-29 0:26 UTC (permalink / raw) To: raindrops 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 ^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: queued is always 0 2010-06-29 0:26 queued is always 0 Ryan King @ 2010-06-29 0:50 ` Eric Wong 2010-06-30 1:12 ` Ryan King 0 siblings, 1 reply; 9+ messages in thread From: Eric Wong @ 2010-06-29 0:50 UTC (permalink / raw) To: raindrops 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 ^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: queued is always 0 2010-06-29 0:50 ` Eric Wong @ 2010-06-30 1:12 ` Ryan King 2010-06-30 2:45 ` Eric Wong 0 siblings, 1 reply; 9+ messages in thread From: Ryan King @ 2010-06-30 1:12 UTC (permalink / raw) To: raindrops 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 ^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: queued is always 0 2010-06-30 1:12 ` Ryan King @ 2010-06-30 2:45 ` Eric Wong 2010-06-30 18:51 ` Ryan King 0 siblings, 1 reply; 9+ messages in thread From: Eric Wong @ 2010-06-30 2:45 UTC (permalink / raw) To: raindrops 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 ^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: queued is always 0 2010-06-30 2:45 ` Eric Wong @ 2010-06-30 18:51 ` Ryan King 2010-06-30 23:18 ` Ryan King 2010-07-01 10:18 ` Eric Wong 0 siblings, 2 replies; 9+ messages in thread From: Ryan King @ 2010-06-30 18:51 UTC (permalink / raw) To: raindrops 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 > ^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: queued is always 0 2010-06-30 18:51 ` Ryan King @ 2010-06-30 23:18 ` Ryan King 2010-07-01 10:18 ` Eric Wong 1 sibling, 0 replies; 9+ messages in thread From: Ryan King @ 2010-06-30 23:18 UTC (permalink / raw) To: raindrops 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 ^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: queued is always 0 2010-06-30 18:51 ` Ryan King 2010-06-30 23:18 ` Ryan King @ 2010-07-01 10:18 ` Eric Wong 2010-07-01 18:37 ` Ryan King 1 sibling, 1 reply; 9+ messages in thread From: Eric Wong @ 2010-07-01 10:18 UTC (permalink / raw) To: raindrops 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 ^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: queued is always 0 2010-07-01 10:18 ` Eric Wong @ 2010-07-01 18:37 ` Ryan King 2010-07-02 2:51 ` Eric Wong 0 siblings, 1 reply; 9+ messages in thread From: Ryan King @ 2010-07-01 18:37 UTC (permalink / raw) To: raindrops 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 ^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: queued is always 0 2010-07-01 18:37 ` Ryan King @ 2010-07-02 2:51 ` Eric Wong 0 siblings, 0 replies; 9+ messages in thread From: Eric Wong @ 2010-07-02 2:51 UTC (permalink / raw) To: raindrops 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 ^ permalink raw reply [flat|nested] 9+ messages in thread
end of thread, other threads:[~2010-07-02 2:51 UTC | newest] Thread overview: 9+ messages (download: mbox.gz / follow: Atom feed) -- links below jump to the message on this page -- 2010-06-29 0:26 queued is always 0 Ryan King 2010-06-29 0:50 ` Eric Wong 2010-06-30 1:12 ` Ryan King 2010-06-30 2:45 ` Eric Wong 2010-06-30 18:51 ` Ryan King 2010-06-30 23:18 ` Ryan King 2010-07-01 10:18 ` Eric Wong 2010-07-01 18:37 ` Ryan King 2010-07-02 2:51 ` Eric Wong
Code repositories for project(s) associated with this public inbox https://yhbt.net/raindrops.git/ This is a public inbox, see mirroring instructions for how to clone and mirror all data and code used for this inbox; as well as URLs for read-only IMAP folder(s) and NNTP newsgroup(s).