Perf issue: High longtail response times with KeepAlive=true when running with(or without) workers

[schneems]

Describe the bug

When using ab with -k or using hey (a go based a/b network testing library) I see very high long tail response times that is an order of magnitude of what I would expect.

AB without keepalive:

$  ab -c 10 -n 200 127.0.0.1:3000/
...
Percentage of the requests served within a certain time (ms)
  50%    420
  66%    421
  75%    422
  80%    422
  90%    423
  95%    424
  98%    426
  99%    428
 100%    432 (longest request)

Longest request took 432ms

With keepalive:

$  ab -c 10 -n 200 -k 127.0.0.1:3000/
...
Percentage of the requests served within a certain time (ms)
  50%    205
  66%    205
  75%    206
  80%    206
  90%   1852
  95%   2258
  98%   2273
  99%   2450
 100%   2477 (longest request)

Longest request took 2,477ms (or 5.7x longer than without keepalive).

Puma config:

$ cat Gemfile
source "https://rubygems.org"

gem "puma"
gem "rack"
⛄️ 3.3.1 🚀 /private/tmp/e3f9bf2d7f5e861b6de95d7e48a1b5b0
$ cat config.ru
require 'rack'

response = ['200', {'Content-Type' => 'text/html'}, ['Hello, World!']]
app = Proc.new do |env|
  sleep 0.2
  response
end

run app
$ bundle exec puma -t5 -p 3000
Puma starting in single mode...
* Puma version: 6.4.2 (ruby 3.3.1-p55) ("The Eagle of Durango")
*  Min threads: 5
*  Max threads: 5
*  Environment: development
*          PID: 7434
* Listening on http://0.0.0.0:3000
Use Ctrl-C to stop

To Reproduce

• Use the above example app that sleeps for 200ms
• Boot with bundle exec puma -t5 -p 3000
• Hit with AB and keepalive enabled or hey

$ hey -c 10 -n 200 http://localhost:3000/

Summary:
  Total:	8.3877 secs
  Slowest:	2.4628 secs
  Fastest:	0.2005 secs
  Average:	0.3612 secs
  Requests/sec:	23.8445

  Total data:	2600 bytes
  Size/request:	13 bytes

Response time histogram:
  0.201 [1]	|
  0.427 [184]	|■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■
  0.653 [0]	|
  0.879 [0]	|
  1.105 [0]	|
  1.332 [0]	|
  1.558 [0]	|
  1.784 [0]	|
  2.010 [0]	|
  2.237 [0]	|
  2.463 [15]	|■■■

Extra observations

• Enabling workers makes the problem go away
• Disabling keepalive makes the problem go away

In server.rb the codepaths diverge

puma/lib/puma/server.rb

Lines 467 to 469 in 796d8c6

	case handle_request(client, requests + 1)
	when false
	break

and that could be an okay place to look. Also within prepare_response() in lib/puma/request.rb. The return value of true indicates keepalive and false indicates no keepalive.

Edit (extra): you can also use existing middleware in the puma directory puma -t5 -p3000 test/rackup/sleep.ru and hit the sleep0.2 endpoint to achieve roughly the same behavior.

Edit (extra): From within the puma directory you can run:

$ bundle exec ruby -Ilib bin/puma -t5  -p 3000 test/rackup/sleep.ru

[schneems]

Similar issue from earlier #2625 h/t @slizco

[dentarg]

Have you seen #3443? Not sure we need more issues?

[dentarg]

And #2311

[schneems]

Nope, agreed on the duplicate, closing. Thanks.

[schneems]

Moving a discussion from slack over here. I was struggling to understand what exactly is going on. Others got there before me, but I'm going to re-explain in my own words/understanding and trying not to leave anything out so hopefully someone new to the problem has a better starting place.

Thanks @bensheldon and @slizco in addition to @dentarg.

Also, I want to re-open this issue as a fresh discussion of the understanding of the core problem. If it fizzles out, I'm happy to close.

Variance explanation

A very short and overly simplified description of the problem is this: Puma's keepalive behavior allows requests to jump in line in the queue when they're from the same connection even when other requests by other clients/connections have been waiting for awhile.

Long: The variance happens due to this: Here's a simple lifecycle of a request for one puma thread for one connection:

• A request comes in, the reactor sees it's fully buffered, hands it to a thread
• The thread processes the request, so sleeps 200ms (due to application code)
• When done, a response is delivered, puma sees keepalive is true so the connection is still open, it takes then next request from the same client and repeats this process
• That occurs 10 times until puma sees that the default max_fast_inline has been reached

Let's say there's 2 threads and the hey CLI is trying to use 3 connections. Each connection gets to completely utilize a puma thread for up to 10 requests due to max_fast_inline. Let's call the hey connections A, B, and C and the puma threads one and two.

• Connection A makes a request, It's received by puma thread one and follows the pattern above.
• Connection B makes a request, It's received by puma thread two and follows the pattern above.
• Connection C makes a request and is stuck waiting in the reactor or on the TCP socket.
• Thread one keeps processing requests until it hit's it's inline maximum and then it returns the connection back into the reactor.
• Connection C's first request is picked up by thread one. At this point it's had to wait 10x 200ms to be processed so it's total round trip time is 2000ms + 200ms which is what we're seeing.

Thoughts on optimization

Short: The easiest thing that I believe will improve the situation is setting the default of max_fast_inline to the same as the max number of threads. The theoretical "best" solution might not be possible and would involve preferring to preserve request received order over minimizing TCP connection overhead.

Long: We're trying to tune a few different values here:

• Minimize TCP slowstart overhead (the value prop of Keepalive)
• Minimize request variance
• Maximize server throughput
• Maximize client throughput

So the question is: Is there a better way to tune the system to min/max the outcome that we want. Or at least make good tradeoffs. I would think about this like I did with https://www.schneems.com/2020/07/08/a-fast-car-needs-good-brakes-how-we-added-client-rate-throttling-to-the-platform-api-gem/.

One way to do it is thinking about different ideal scenarios and how different values relate to each other:
In the scenario that all requests are from the same client, then we would ideally never want to close the connection so they never have to pay the TCP slowstart fee again. However as soon as you have a single request from a different connection, you would block it forever. Basically this strategy would provide the absolute minimum TCP slowstart overhead, but the absolute maximum request variance.

In the scenario that no requests are from the same client then Puma has to pay the overhead of doing some checks, but otherwise all numbers would seem to be ideal (or at least, we cannot improve them by changing behavior).
Those are the two extremes.
The current strategy of dealing with a mixed workload or a sustained load where the number of clients is higher than the number of threads is to treat each client fairly by way of limiting the total number of requests they're allowed to have jump the queue before being asked to wait their turn. But fair doesn't always me equal. This leads to very high request variance. If we tune this number up, then the TCP slowstart overhead gets lower, but at the cost of higher request variance. Tuning it down to a low number (like 1 or 0) would effectively disable the keepalive behavior which would maximize slowstart overhead at the cost of request variance.

Effectively: With only this parameter to tune, you end up with an inverse correlation of two values we want to optimize. We can maybe pick a better default, but we can also explore other signals to use to trigger a switch. By signals I mean, things we can measure. Such as timing information (like request/response times) or other countable things.
We saw that we could minimize request variance by disabling this keepalive behavior. But that mazimizes TCP slowstart overhead. Is there something we could signal off of that doesn't have a 1:1 inverse correlation? If the problem is linejumping, then an idealized algorithm could be: process requests in the order they come always. If the next request is from the same client, don't close the connection. However, I'm guessing that this is either impossible to know or difficult. In the absence of perfect information, we can use a proxy, possibly we could use timing values? My one reservation would be that constructing time objects can be expensive, and comparing them can be as well. Also depending on where you're getting the timing data from, it might be unreliable.

We could have the value be clock time based instead of request time based, set a maximum time a thread can devote to a single client like Ruby's thread "quantum." The question is how should we tune the value? Or what would an ideal value be? If it's less than the median response time, then it's the same as disabling keepalive behavior. If it's too high, then we get the same behavior as today.

It feels like setting the max_fast_inline to the same value as the number of maximum threads is a reasonable default. It's not perfect, a system with 128 threads could force a client to wait 25,600 seconds. But on average there should be one new thread taking a new client every "cycle" (if you define a cycle as every puma thread processing one request). From this lens, the problem seems like maybe the problem is about the ratio of max_fast_inline to threads. This seems easy, and somewhat intuitive. I just worry that the delta between ideal and actual behavior is larger than we would expect. We could have set to min(max_threads, 10) and avoid unexpected terminal behavior, at worst we're saying the behavior wouldn't change versus today.

We could maybe investigate getting more/better information from the system in terms of a "lookahead" or timing based comparison. But tuning the default value of max_fast_inline down seems like a good sell. I like when magic numbers can be kinda explained, and would venture to suggest we set max_fast_inline 's default to be the same value as puma's max threads.

I was curious what Falcon (or others) are doing with keepalive, but a quick grep didn't get me much. @ioquatix I'm curious if you've got thoughts or opinions on this issue and my analysis.

[schneems]

To validate my logic here's some manual testing, by adjusting max_fast_inline down.

With puma threads = 2, max fast inline = 2, and hey connections = 3:

$ hey -c 3 -n 200 http://localhost:3000/

Summary:
  Total:	20.7240 secs
  Slowest:	0.6296 secs
  Fastest:	0.2008 secs
  Average:	0.3077 secs
  Requests/sec:	9.5542

  Total data:	2574 bytes
  Size/request:	13 bytes

Response time histogram:
  0.201 [1]	|
  0.244 [103]	|■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■
  0.287 [0]	|
  0.329 [0]	|
  0.372 [0]	|
  0.415 [43]	|■■■■■■■■■■■■■■■■■
  0.458 [49]	|■■■■■■■■■■■■■■■■■■■
  0.501 [0]	|
  0.544 [0]	|
  0.587 [0]	|
  0.630 [2]	|■


Latency distribution:
  10% in 0.2030 secs
  25% in 0.2049 secs
  50% in 0.2090 secs
  75% in 0.4167 secs
  90% in 0.4418 secs
  95% in 0.4487 secs
  99% in 0.6296 secs

Details (average, fastest, slowest):
  DNS+dialup:	0.0008 secs, 0.2008 secs, 0.6296 secs
  DNS-lookup:	0.0004 secs, 0.0000 secs, 0.0042 secs
  req write:	0.0001 secs, 0.0000 secs, 0.0006 secs
  resp wait:	0.3066 secs, 0.2007 secs, 0.6252 secs
  resp read:	0.0001 secs, 0.0000 secs, 0.0010 secs

Status code distribution:
  [200]	198 responses

With puma threads = 5, max fast inline = 5, and hey connections = 6:

$ hey -c 6 -n 200 http://localhost:3000/

Summary:
  Total:	9.0548 secs
  Slowest:	1.2390 secs
  Fastest:	0.2005 secs
  Average:	0.2432 secs
  Requests/sec:	21.8670

  Total data:	2574 bytes
  Size/request:	13 bytes

Response time histogram:
  0.201 [1]	|
  0.304 [174]	|■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■
  0.408 [3]	|■
  0.512 [13]	|■■■
  0.616 [0]	|
  0.720 [3]	|■
  0.824 [1]	|
  0.927 [2]	|
  1.031 [0]	|
  1.135 [0]	|
  1.239 [1]	|


Latency distribution:
  10% in 0.2022 secs
  25% in 0.2039 secs
  50% in 0.2051 secs
  75% in 0.2065 secs
  90% in 0.4093 secs
  95% in 0.4170 secs
  99% in 1.2390 secs

Details (average, fastest, slowest):
  DNS+dialup:	0.0002 secs, 0.2005 secs, 1.2390 secs
  DNS-lookup:	0.0002 secs, 0.0000 secs, 0.0022 secs
  req write:	0.0000 secs, 0.0000 secs, 0.0003 secs
  resp wait:	0.2428 secs, 0.2004 secs, 1.2353 secs
  resp read:	0.0001 secs, 0.0000 secs, 0.0017 secs

Status code distribution:
  [200]	198 responses

It's better on average, but the relationship with the upper bound didn't change. It's still average response time multiplied by max_fast_inline plus 1. So (200 * (5 + 1) ~= 1,200)

[evanphx]

@schneems Setting max_fast_inline == max_threads makes complete sense to me and I'm a little ashamed that we didn't do that from the very beginning! Clamping it at a max value of 10 also makes sense.

Improving correctness here would mean dynamically adjusting max_fast_inline according to queue latency. We could get very in the weeds on that, only to conclude that setting max_fast_inline == min(max_threads, 10) results in effectively the same latency gains. Given the work required, fully onboard making this change.

[slizco]

@schneems
This is 100% my understanding as well:

• Connection C makes a request and is stuck waiting in the reactor or on the TCP socket.
• Thread one keeps processing requests until it hit’s it’s inline maximum and then it returns the connection back into the reactor.
• Connection C’s first request is picked up by thread one. At this point it’s had to wait 10x 200ms to be processed so it’s total round trip time is 2000ms + 200ms which is what we’re seeing.

I agree with you it’s a trade-off between time spent in TCP operations versus providing “stable” request handling times. For many Puma applications (like those running on Heroku), it’s unlikely that the next request in-line (based on the time it entered the queue) will be on the same connection the thread is already handling. This is due to the roughly even distribution of requests/connections across the Heroku routers. Each router should be handling an equal fraction of the requests for an app. The same is true for Puma apps running on different cloud providers with various load balancer set-ups.

I’m a bit skeptical of this:

It feels like setting the max_fast_inline to the same value as the number of maximum threads is a reasonable default. It's not perfect, a system with 128 threads could force a client to wait 25,600 seconds. But on average there should be one new thread taking a new client every "cycle" (if you define a cycle as every puma thread processing one request). From this lens, the problem seems like maybe the problem is about the ratio of max_fast_inline to threads. This seems easy, and somewhat intuitive. I just worry that the delta between ideal and actual behavior is larger than we would expect. We could have set to min(max_threads, 10) and avoid unexpected terminal behavior, at worst we're saying the behavior wouldn't change versus today.

I think the other big considerations are:

• The number of connections inbound to the Puma worker. If there are more connections than threads, you can almost guarantee requests will be waiting in the queue for a duration of max_fast_inline*request_handling_time (under current logic). If we used min(max_threads, 10) as the comparison value, that at best improves the longest queue times to max_threads*request_handling_time. With more threads, that number gets worse.
• The typical request handling times really matter here. If the application processes requests quickly, all <1ms, processing requests in-line is not such a big deal. If there is any sort of mid-longer delay (like our 200ms artificial server lag), you’re going to start to see request queue times upwards of 2s. If you use min(max_threads, 10) as the comparison value, you'll see the highest queue times at ~1s with a max_threads=5.

[slizco]

I believe the best way to ensure requests are handled in order and minimize queue time is to set max_fast_inline=1 and return the client to the reactor at the end of each request handling while not closing the connection. That means the reactor has to do more work than if a client could process 10 requests in a row, but at least it means stable connections at the TCP level.

I believe that's actually the intention of this block:

puma/lib/puma/server.rb

Lines 488 to 495 in 5fc43d7

	unless next_request_ready
	break unless @queue_requests
	client.set_timeout @persistent_timeout
	if @reactor.add client
	close_socket = false
	break
	end
	end

but I am not sure it's behaving as expected.

I have yet to confirm if we are getting inside this unless statement, will test this out soon.

[evanphx]

@slizco A totally fair assessment. One option is to only even consider checking for a next request on the client if the queue is empty. In that way, if someone is waiting, we get to them ASAP. But in the case that we could handle the next request without starving someone else, we do.

[evanphx]

Ah! We actually meant to do just that but I think the conditional is inverted!