Fixup response processing, enumerable bodies #3004

MSP-Greg · 2022-10-26T15:02:36Z

Description

PR #2896 added code to collect members of response bodies that are Arrays or Enums, and allow a size threshold that waits to send the collected bytes only when they exceed it. Previously, if the response body consisted of many small strings, each string was written. #2896 collects them, and only writes when they exceed the threshold. This may affect TTFB (time-to-first-byte). The limit value was also too high in #2896.

This causes issues with Enum bodies that mimic a streaming body. The size threshold has been removed for Enum bodies, but remains for true Array bodies.

Previously, due to the handling of Enum bodies, test code in Sinatra failed. The code is checked in an added test, `test_streaming_enum_body'.

Using the benchmarks in benchmark/local, this PR shows:

Puma repo branch 00-size-to-first-byte
benchmarks/local/response_time_wrk.sh -w2 -t5:5 -s tcp6 -Y
Body    ────────── req/sec ──────────   ─────── req 50% times ───────
 KB     array   chunk  string      io   array   chunk  string      io
1       19071   18666   19072   12774   0.152   0.149   0.150   0.263
10      18478   17246   18540   12424   0.159   0.177   0.152   0.260
100     13450    8179   14821    9467   0.324   0.369   0.284   1.160
256      9702    4183   14501    9481   0.545   0.782   0.317   1.170
512      6549    2340   12380    9304   1.080   1.150   0.518   1.170
1024     4216    1253    7418    8804   2.100   2.020   0.764   1.190
2048     2564     652    6372    8782   3.930   4.060   1.590   1.170
─────────────────────────────────────────────────────────────────────

Using 5.6.5 and configuring wait_for_less_busy_worker to match current master:

Puma repo branch 5-6-stable-bench
benchmarks/local/response_time_wrk.sh -w2 -t5:5 -s tcp6 -Y -C test/config/wflbw_dflt.rb
Body    ────────── req/sec ──────────   ─────── req 50% times ───────
 KB     array   chunk  string      io   array   chunk  string      io
1       11002   10865   10502   10135    1.42    1.42    1.47    1.52
10      10614   10609   10838    9739    1.46    1.45    1.42    1.59
100      7113    7011   10047    5449    2.18    2.21    1.53    2.86
256      4609    4560    8923    3359    3.39    3.41    1.73    4.67
512      3135    3110    8304    2107    5.01    5.05    1.87    7.47
1024     1919    1909    6108      74    8.21    8.25    2.55  214.25
2048     1090    1082    4530      39   14.49   14.64    3.42  406.58
─────────────────────────────────────────────────────────────────────

'Requests per second' has greatly increased for body sizes below 100kB, above increases are smaller.

Closes #3000.

Your checklist for this pull request

I have reviewed the guidelines for contributing to this repository.
I have added (or updated) appropriate tests if this PR fixes a bug or adds a feature.
My pull request is 100 lines added/removed or less so that it can be easily reviewed.
If this PR doesn't need tests (docs change), I added [ci skip] to the title of the PR.
If this closes any issues, I have added "Closes #issue" to the PR description or my commit messages.
I have updated the documentation accordingly.
All new and existing tests passed, including Rubocop.

lib/puma/request.rb

MSP-Greg · 2022-10-27T02:36:13Z

Never mind recent commits, accidentally clicked push...

MSP-Greg · 2022-10-31T14:51:38Z

This is now just a 'fixup' PR. Main issue is fixing enumerable bodies. Improvements also made to 'string' and 'array' bodies.

MSP-Greg · 2022-10-31T15:33:04Z

A note about cork/uncork. Remember that it dates back to remote console use (via sockets) a long time ago. Or, connections were a bit slower than. The Sinatra example code uses an enumerable body:

stream do |out|
  out << "It's gonna be legen -\n"
  sleep 0.5
  out << " (wait for it) \n"
  sleep 1
  out << "- dary!\n"
end

When I first added a test, I dropped the times to 0.1. This PR (and master) were failing with 0.1 times, but 5.6.5 was passing.

After wrestling with it for a while, I recalled that cork/uncork is about both buffered bytes that haven't been transmitted, and time between data, in that it will only hold data for so long.

With the lower times, the test would only pass if the amount of data was increased to exceed the limits in cork/uncork.

But, when I increased the times from 0.1 to the times used by the Sinatra example, the test passed with the minimal data used in the Sinatra example...

MSP-Greg · 2022-11-01T00:50:46Z

Found an issue with turbo-rails. The response body says it responds to to_ary, but when called, it returns nil. One would think it should return an empty array, but...

Simple fix, but I want to investigate further.

MSP-Greg · 2022-11-04T01:30:12Z

Update - I've got CI running turbo-rails testing using Rails 6.1 and 7.0. It's intermittently failing, trying to figure out why...

EDIT: Most, but not all of the CI failures are with Rails 6.1. Of course, I can't repo locally...

dentarg · 2022-11-05T11:50:12Z

I've got CI running turbo-rails testing using Rails 6.1 and 7.0

Where? Something the Puma repo should have?

dentarg · 2022-11-05T12:09:55Z

While this PR makes https://github.com/sinatra/sinatra/blob/v3.0.2/examples/stream.ru work again, I still have problems with my app, running from dentarg/testssl.web@f1fbd41 and this branch, the request returns immediately:

$ curl -s -v 'localhost:8080/?q=starkast.net'
*   Trying 127.0.0.1:8080...
* Connected to localhost (127.0.0.1) port 8080 (#0)
> GET /?q=starkast.net HTTP/1.1
> Host: localhost:8080
> User-Agent: curl/7.84.0
> Accept: */*
>
* Empty reply from server
* Closing connection 0
*

Logs from Puma

$ bundle exec puma
[57785] Puma starting in cluster mode...
[57785] * Puma version: 6.0.0 (ruby 3.1.2-p20) ("Sunflower")
[57785] *  Min threads: 0
[57785] *  Max threads: 16
[57785] *  Environment: development
[57785] *   Master PID: 57785
[57785] *      Workers: 2
[57785] *     Restarts: (✔) hot (✔) phased
[57785] * Listening on http://0.0.0.0:8080
[57785] Use Ctrl-C to stop
[57785] - Spawned worker: 57787
[57785] - Spawned worker: 57788
[57785] - Worker 1 (PID: 57788) booted in 0.08s, phase: 0
[57785] - Worker 0 (PID: 57787) booted in 0.08s, phase: 0
[7c2d4c6d] cli_agent? true command="testssl.sh --quiet --htmlfile /dev/stderr starkast.net"
[57788] 127.0.0.1 - - [05/Nov/2022:13:05:19 +0100] "GET /?q=starkast.net HTTP/1.1" 200 - 0.0106

MSP-Greg · 2022-11-05T14:42:56Z

@dentarg

Thanks for testing. I've got changes to this PR. As mentioned, I've added a workflow using turbo-rails.

I just ran the test. Both jobs failed the first time, I immediately reran it, and both passed. Locally, it always passes.

Trying to figure out why.

dentarg · 2022-11-05T16:22:26Z

Both jobs failed the first time, I immediately reran it, and both passed. Locally, it always passes.

Slow CI?

Maybe possible to simulate locally using Docker? docker update --cpus="0.05" ...

MSP-Greg · 2022-11-05T17:04:55Z

I've got CI running turbo-rails testing using Rails 6.1 and 7.0

Where?

In a branch that I'll cherry-pick back into this PR. Two jobs, last run took a minute. It's a little brittle, but it works. Most recent run. The 'test' CI run.

Something the Puma repo should have?

I think so. It uses ActionDispatch::Response::RackBody, Rack::BodyProxy, and Sprockets::Asset for responses/response bodies. Or, good 'real world' testing.

The branch is 00-turbo-rails in my fork, MSP-Greg/puma. Can you check with dentarg/testssl.web? If not, I can fork it.

Note the speed improvements shown in the first post. Some real gains. Granted, that's Puma's processing, and a lot of responses are constrained by the app's response time...

dentarg · 2022-11-05T17:21:08Z

The branch is 00-turbo-rails in my fork, MSP-Greg/puma. Can you check with dentarg/testssl.web?

It behaves the same as I reported above, Empty reply from server from curl.

MSP-Greg · 2022-11-05T17:32:51Z

Thanks. I’ll try it locally. Interested to find the issue…

MSP-Greg · 2022-11-05T18:07:10Z

How do I generate testssl.sh?

EDIT: installed 'bsdmainutils', ran bundle exec puma, must be a step I'm missing?

dentarg · 2022-11-05T18:09:31Z

That's https://testssl.sh/, if your WSL environment have Homebrew you can install it with brew install testssl (https://formulae.brew.sh/formula/testssl#default)

dentarg · 2022-11-05T18:11:09Z

Haven't tried it but spawning something else that's outputting to stdout and stderr should be the same thing I guess.

MSP-Greg · 2022-11-05T18:27:33Z

Thanks. Seem to be up and running. A Sinatra::Helpers::Stream is returned, still debugging...

MSP-Greg · 2022-11-11T20:58:02Z

@dentarg

Ok, Installed homebrew, then testssl. Running bundle exec puma in one terminal and curl -s -v 'localhost:8080/?q=starkast.net' in another, I get a lot of output, obviously ssl related. That was using:

gem "puma", git: "https://github.com/MSP-Greg/puma.git", branch: "00-turbo-rails"

The puma terminal shows:

[16da13cc] cli_agent? true command="testssl.sh --quiet --htmlfile /dev/stderr starkast.net"
[16da13cc] Completed
[22112] 127.0.0.1 - - [11/Nov/2022:14:45:23 -0600] "GET /?q=starkast.net HTTP/1.1" 200 - 150.6837

If you could test again... Thanks.

dentarg · 2022-11-11T22:48:23Z

Yes it works now

ioquatix · 2022-11-15T04:36:40Z

lib/puma/io_buffer.rb

@@ -22,6 +22,16 @@ def to_s
      read
    end

+    # Read & Reset - returns contents and resets
+    # @return [String] StringIO contents
+    def rd_and_rst


Suggested change

def rd_and_rst

def read_and_reset

Fixed, pushed back into 'Updates for response body processing'

ioquatix · 2022-11-15T04:37:02Z

lib/puma/request.rb

-            res_body.each { |part| length += part.bytesize; body << part }
-          end
-          resp_info[:content_length] = length
+        if res_body.respond_to?(:to_ary) && (array_body = res_body.to_ary) && array_body.is_a?(Array)


Suggested change

if res_body.respond_to?(:to_ary) && (array_body = res_body.to_ary) && array_body.is_a?(Array)

if res_body.respond_to?(:to_ary) && (array_body = res_body.to_ary)

I'm going to test this. I recall that one of the Rails wrapped responses/bodies returned nil when to_ary was called. Not.sure.

Kicking myself for not adding a comment about it. Give me a bit.

EDIT: Sorry, long day. If res_body.to_ary is nil, the third segment isn't needed.

Ahh I see... I think if to_ary returns nil, you can assume there is no body. This is out of alignment with the Rack spec in any case.

Fixed. Pushed back into 'Updates for response body processing'

ioquatix · 2022-11-15T04:37:43Z

lib/puma/request.rb

@@ -225,12 +235,13 @@ def prepare_response(status, headers, res_body, requests, client)
      io_buffer << line_ending

      if response_hijack
-        fast_write_str socket, io_buffer.to_s
+        fast_write_str socket, io_buffer.rd_and_rst


Suggested change

fast_write_str socket, io_buffer.rd_and_rst

fast_write_str socket, io_buffer.read_and_reset

Fixed, pushed back into 'Updates for response body processing'

ioquatix · 2022-11-15T04:39:40Z

test/test_cli.rb

@@ -25,6 +25,8 @@ def setup

    @events = Puma::Events.new
    @events.on_booted { @ready << "!" }
+
+    @puma_vers_re = "\\d+.\\d+.\\d+(\\.[a-z\\d]+)?"


Suggested change

@puma_vers_re = "\\d+.\\d+.\\d+(\\.[a-z\\d]+)?"

@puma_version_pattern = "\\d+.\\d+.\\d+(\\.[a-z\\d]+)?"

Fixed, pushed back into test_cli.rb - allow for Puma version like 6.0.1.dev or 6.0.1.rc1

ioquatix · 2022-11-15T05:35:46Z

LGTM.

dentarg reviewed Oct 26, 2022

View reviewed changes

lib/puma/request.rb Outdated Show resolved Hide resolved

MSP-Greg force-pushed the 00-size-to-first-byte branch from d205d07 to 180406c Compare October 26, 2022 18:41

MSP-Greg force-pushed the 00-size-to-first-byte branch from 6f20970 to f7db054 Compare October 27, 2022 16:36

nateberkopec linked an issue Oct 28, 2022 that may be closed by this pull request

Sinatra streaming broken in Puma 6.0.0 #3000

Closed

nateberkopec added the feature label Oct 28, 2022

MSP-Greg force-pushed the 00-size-to-first-byte branch from f7db054 to a3ba077 Compare October 31, 2022 04:41

MSP-Greg marked this pull request as ready for review October 31, 2022 04:52

MSP-Greg force-pushed the 00-size-to-first-byte branch from a3ba077 to 85f5284 Compare October 31, 2022 14:48

MSP-Greg changed the title ~~Add size_to_first_byte option for response processing~~ Fixup response processing, enumerable bodies Oct 31, 2022

MSP-Greg added bug and removed feature labels Oct 31, 2022

MSP-Greg mentioned this pull request Nov 2, 2022

Correctly close app body for all code paths #3002

Merged

7 tasks

Create turbo-rails.yml - allow failure

a490d05

MSP-Greg force-pushed the 00-size-to-first-byte branch 2 times, most recently from c537474 to b3dd077 Compare November 13, 2022 23:17

MSP-Greg mentioned this pull request Nov 14, 2022

Streaming bodies, PR #2740, WebSocket #3007

Closed

jarthod mentioned this pull request Nov 14, 2022

Sinatra streaming broken in Puma 6.0.0 #3000

Closed

ioquatix reviewed Nov 15, 2022

View reviewed changes

MSP-Greg force-pushed the 00-size-to-first-byte branch from b3dd077 to a0c8b80 Compare November 15, 2022 05:23

MSP-Greg added 4 commits November 14, 2022 23:46

Updates for response body processing

6b6e7e0

test_puma_server.rb - add test_streaming_enum_body_1 and _2

26fae91

test_cli.rb - allow for Puma version like 6.0.1.dev or 6.0.1.rc1

083b422

Update Puma version to 6.0.1.dev

a37953f

MSP-Greg force-pushed the 00-size-to-first-byte branch from a0c8b80 to a37953f Compare November 15, 2022 05:46

MSP-Greg merged commit e500146 into puma:master Nov 24, 2022

MSP-Greg deleted the 00-size-to-first-byte branch November 24, 2022 14:45

GustavoCaso mentioned this pull request Sep 27, 2023

Update Puma version for ruby weblog DataDog/system-tests#1629

Closed

5 tasks

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Fixup response processing, enumerable bodies #3004

Fixup response processing, enumerable bodies #3004

MSP-Greg commented Oct 26, 2022 •

edited

MSP-Greg commented Oct 27, 2022

MSP-Greg commented Oct 31, 2022

MSP-Greg commented Oct 31, 2022

MSP-Greg commented Nov 1, 2022

MSP-Greg commented Nov 4, 2022 •

edited

dentarg commented Nov 5, 2022

dentarg commented Nov 5, 2022

MSP-Greg commented Nov 5, 2022

dentarg commented Nov 5, 2022

MSP-Greg commented Nov 5, 2022

dentarg commented Nov 5, 2022

MSP-Greg commented Nov 5, 2022

MSP-Greg commented Nov 5, 2022 •

edited

dentarg commented Nov 5, 2022

dentarg commented Nov 5, 2022

MSP-Greg commented Nov 5, 2022

MSP-Greg commented Nov 11, 2022 •

edited

dentarg commented Nov 11, 2022

ioquatix Nov 15, 2022

MSP-Greg Nov 15, 2022

ioquatix Nov 15, 2022

MSP-Greg Nov 15, 2022 •

edited

ioquatix Nov 15, 2022

MSP-Greg Nov 15, 2022 •

edited

ioquatix Nov 15, 2022

MSP-Greg Nov 15, 2022

ioquatix Nov 15, 2022

MSP-Greg Nov 15, 2022

ioquatix commented Nov 15, 2022

	if res_body.respond_to?(:to_ary) && (array_body = res_body.to_ary) && array_body.is_a?(Array)
	if res_body.respond_to?(:to_ary) && (array_body = res_body.to_ary)

	fast_write_str socket, io_buffer.rd_and_rst
	fast_write_str socket, io_buffer.read_and_reset

	@puma_vers_re = "\\d+.\\d+.\\d+(\\.[a-z\\d]+)?"
	@puma_version_pattern = "\\d+.\\d+.\\d+(\\.[a-z\\d]+)?"

Fixup response processing, enumerable bodies #3004

Fixup response processing, enumerable bodies #3004

Conversation

MSP-Greg commented Oct 26, 2022 • edited

Description

Your checklist for this pull request

MSP-Greg commented Oct 27, 2022

MSP-Greg commented Oct 31, 2022

MSP-Greg commented Oct 31, 2022

MSP-Greg commented Nov 1, 2022

MSP-Greg commented Nov 4, 2022 • edited

dentarg commented Nov 5, 2022

dentarg commented Nov 5, 2022

MSP-Greg commented Nov 5, 2022

dentarg commented Nov 5, 2022

MSP-Greg commented Nov 5, 2022

dentarg commented Nov 5, 2022

MSP-Greg commented Nov 5, 2022

MSP-Greg commented Nov 5, 2022 • edited

dentarg commented Nov 5, 2022

dentarg commented Nov 5, 2022

MSP-Greg commented Nov 5, 2022

MSP-Greg commented Nov 11, 2022 • edited

dentarg commented Nov 11, 2022

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

MSP-Greg Nov 15, 2022 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

MSP-Greg Nov 15, 2022 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ioquatix commented Nov 15, 2022

MSP-Greg commented Oct 26, 2022 •

edited

MSP-Greg commented Nov 4, 2022 •

edited

MSP-Greg commented Nov 5, 2022 •

edited

MSP-Greg commented Nov 11, 2022 •

edited

MSP-Greg Nov 15, 2022 •

edited

MSP-Greg Nov 15, 2022 •

edited