From f2eb2ecfde2a0e162acc1d463a9fb5b7a69f3b0d Mon Sep 17 00:00:00 2001 From: Rian McGuire Date: Tue, 24 Apr 2018 15:54:51 -0300 Subject: [PATCH] Request body read time metric Measure the time spent reading the HTTP request body and expose it to the Rack app as `env['puma.request_body_wait']`. This can be combined with a timestamp from a upstream proxy to get an indication of how long a request was waiting for a Puma thread to become available. Fixes https://github.com/puma/puma/issues/1541 --- docs/architecture.md | 1 + docs/deployment.md | 16 ++++++++++++++++ lib/puma/client.rb | 34 ++++++++++++++++++---------------- test/test_puma_server.rb | 40 ++++++++++++++++++++++++++++++++++++++++ 4 files changed, 75 insertions(+), 16 deletions(-) diff --git a/docs/architecture.md b/docs/architecture.md index c1f70262..958c6a25 100644 --- a/docs/architecture.md +++ b/docs/architecture.md @@ -20,6 +20,7 @@ Clustered mode is shown/discussed here. Single mode is analogous to having a sin * By default, a single, separate thread is used to receive HTTP requests across the socket. * When at least one worker thread is available for work, a connection is accepted and placed in this request buffer * This thread waits for entire HTTP requests to be received over the connection + * The time spent waiting for the HTTP request body to be received is exposed to the Rack app as `env['puma.request_body_wait']` (milliseconds) * Once received, the connection is pushed into the "todo" set * Worker threads pop work off the "todo" set for processing * The thread processes the request via the rack application (which generates the HTTP response) diff --git a/docs/deployment.md b/docs/deployment.md index 09a51622..612375d1 100644 --- a/docs/deployment.md +++ b/docs/deployment.md @@ -54,6 +54,22 @@ up resources. Watching your CPU utilization over time and aim for about 70% on average. This means you've got capacity still but aren't starving threads. +**Measuring utilization** + +Using a timestamp header from an upstream proxy server (eg. nginx or haproxy), it's +possible to get an indication of how long requests have been waiting for a Puma +thread to become available. + +* Have your upstream proxy set a header with the time it received the request: + * nginx: `proxy_set_header X-Request-Start "${msec}";` + * haproxy: `http-request set-header X-Request-Start "%t";` +* In your Rack middleware, determine the amount of time elapsed since `X-Request-Start`. +* To improve accuracy, you will want to subtract time spent waiting for slow clients: + * `env['puma.request_body_wait']` contains the number of milliseconds Puma spent + waiting for the client to send the request body. + * haproxy: `%Th` (TLS handshake time) and `%Ti` (idle time before request) can + can also be added as headers. + ## Daemonizing I prefer to not daemonize my servers and use something like `runit` or `upstart` to diff --git a/lib/puma/client.rb b/lib/puma/client.rb index f0dc872e..113c8c3e 100644 --- a/lib/puma/client.rb +++ b/lib/puma/client.rb @@ -158,8 +158,7 @@ module Puma @body.rewind rest = io.read @buffer = rest.empty? ? nil : rest - @requests_served += 1 - @ready = true + set_ready return true end @@ -207,8 +206,7 @@ module Puma unless chunk @body.close @buffer = nil - @requests_served += 1 - @ready = true + set_ready raise EOFError end @@ -217,6 +215,8 @@ module Puma end def setup_body + @body_read_start = Process.clock_gettime(Process::CLOCK_MONOTONIC, :millisecond) + if @env[HTTP_EXPECT] == CONTINUE # TODO allow a hook here to check the headers before # going forward @@ -241,8 +241,7 @@ module Puma unless cl @buffer = body.empty? ? nil : body @body = EmptyBody - @requests_served += 1 - @ready = true + set_ready return true end @@ -251,8 +250,7 @@ module Puma if remain <= 0 @body = StringIO.new(body) @buffer = nil - @requests_served += 1 - @ready = true + set_ready return true end @@ -287,8 +285,7 @@ module Puma # No data means a closed socket unless data @buffer = nil - @requests_served += 1 - @ready = true + set_ready raise EOFError end @@ -324,8 +321,7 @@ module Puma # No data means a closed socket unless data @buffer = nil - @requests_served += 1 - @ready = true + set_ready raise EOFError end @@ -402,8 +398,7 @@ module Puma unless chunk @body.close @buffer = nil - @requests_served += 1 - @ready = true + set_ready raise EOFError end @@ -412,8 +407,7 @@ module Puma if remain <= 0 @body.rewind @buffer = nil - @requests_served += 1 - @ready = true + set_ready return true end @@ -422,6 +416,14 @@ module Puma false end + def set_ready + if @body_read_start + @env['puma.request_body_wait'] = Process.clock_gettime(Process::CLOCK_MONOTONIC, :millisecond) - @body_read_start + end + @requests_served += 1 + @ready = true + end + def write_400 begin @io << ERROR_400_RESPONSE diff --git a/test/test_puma_server.rb b/test/test_puma_server.rb index 94292eed..fd62c50f 100644 --- a/test/test_puma_server.rb +++ b/test/test_puma_server.rb @@ -691,4 +691,44 @@ EOF assert_equal "HTTP/1.0 200 OK\r\nX-Empty-Header: \r\n\r\n", data end + + def test_request_body_wait + request_body_wait = nil + @server.app = proc { |env| + request_body_wait = env['puma.request_body_wait'] + [204, {}, []] + } + + @server.add_tcp_listener @host, @port + @server.run + + sock = TCPSocket.new @host, @server.connected_port + sock << "POST / HTTP/1.1\r\nHost: test.com\r\nContent-Type: text/plain\r\nContent-Length: 5\r\n\r\nh" + sleep 1 + sock << "ello" + + sock.gets + + assert request_body_wait >= 1000 + end + + def test_request_body_wait_chunked + request_body_wait = nil + @server.app = proc { |env| + request_body_wait = env['puma.request_body_wait'] + [204, {}, []] + } + + @server.add_tcp_listener @host, @port + @server.run + + sock = TCPSocket.new @host, @server.connected_port + sock << "GET / HTTP/1.1\r\nConnection: close\r\nTransfer-Encoding: chunked\r\n\r\n1\r\nh\r\n" + sleep 1 + sock << "4\r\nello\r\n0\r\n" + + sock.gets + + assert request_body_wait >= 1000 + end end