Puma HTTP サーバーの挙動等を調査したことのメモ

Puma を使ったアプリケーションを触っているのですが、Puma についてわかっていないので少しドキュメントを読んだり動かしたりしたメモです

Puma のアーキテクチャ

概要図は下記にあります。

puma/docs/architecture.md at v6.4.2 · puma/puma · GitHub

Puma は、クラスターモードとシングルモードの 2 つのモードのいずれかで動作するようです。シングルモードでは、1 つの Puma プロセス(ワーカー)のみが起動します。クラスターモードでは、マスタープロセスが起動され、それに対して、fork() システムコールを使用して 1 つ以上の子プロセス(ワーカー)が作成されます。

Puma 起動時に TCP または UNIX ソケットをリッスンします。

puma/lib/puma/server.rb at v6.4.2 · puma/puma · GitHub

外部からのリクエストをバックログの値分までは受け付けられるようです。スレッドがソケットからリクエストを読み取りスレッド内部で「todo」という配列に格納されるようです。

試す

Rails のサンプルアプリケーションを使って試してみます。

環境

Ruby はインストールされているものとします。

% cat /etc/os-release
PRETTY_NAME="Debian GNU/Linux 12 (bookworm)"
NAME="Debian GNU/Linux"
VERSION_ID="12"
VERSION="12 (bookworm)"
VERSION_CODENAME=bookworm
ID=debian
HOME_URL="https://www.debian.org/"
SUPPORT_URL="https://www.debian.org/support"
BUG_REPORT_URL="https://bugs.debian.org/"

% ruby -v
ruby 3.1.2p20 (2022-04-12 revision 4491bb740a) [x86_64-linux-gnu]

bunlder インストール

% gem install bundler

% bundler -v
Bundler version 2.3.7

Rails プロジェクト作成

bundler 用のディレクトリを作成します。

% mkdir -p /path/to/sandbox

% cd !$

bundler を初期化します。Gemfileが生成されます。

% bundle init
Writing new Gemfile to /path/to/sandbox/Gemfile

Gemfile を編集して、以下のようにします。

# frozen_string_literal: true

source "https://rubygems.org"

ruby "3.1.2"

gem "rails", "~> 7.1.3", ">= 7.1.3.2"
gem "puma", ">= 5.0"

gem "sprockets-rails"
gem "sqlite3", "~> 1.4"
gem "importmap-rails"
gem "turbo-rails"
gem "stimulus-rails"
gem "jbuilder"
gem "tzinfo-data", platforms: %i[ mswin mswin64 mingw x64_mingw jruby ]
gem "bootsnap", require: false

group :development, :test do
  gem "debug", platforms: %i[ mri mswin mswin64 mingw x64_mingw ]
end

group :development do
  gem "web-console"
  gem "error_highlight", ">= 0.4.0", platforms: [:ruby]
end

group :test do
  gem "capybara"
  gem "selenium-webdriver"
end

bundler を使ってインストールします。 Debianだとスーパーユーザー権限がないとデフォルトの場所にインストールできないので、インストールパスをプロジェクトディレクトリ内の vendor/bunlde にしておきます。

% bundle config set path 'vendor/bunlde'

% bundle install

Rails プロジェクトを新規に作成します。

% bundle exec rails new .

Rails を起動します。

% bundle exec rails s
=> Booting Puma
=> Rails 7.1.3.2 application starting in development
=> Run `bin/rails server --help` for more startup options
Puma starting in single mode...
* Puma version: 6.4.2 (ruby 3.1.2-p20) ("The Eagle of Durango")
*  Min threads: 5
*  Max threads: 5
*  Environment: development
*          PID: 3850903
* Listening on http://127.0.0.1:3000
* Listening on http://[::1]:3000

top コマンドを使ってプロセスの状態を見てみます。

% top -p 3850903 -H

puma srv tp 00X がワーカースレッドで、5つ起動しています。 reactor などもスレッドとして起動しているようです。

top - 04:08:47 up 52 days, 17:16,  2 users,  load average: 0.00, 0.00, 0.00
Threads:  13 total,   0 running,  13 sleeping,   0 stopped,   0 zombie
%Cpu(s):  0.3 us,  0.2 sy,  0.0 ni, 99.5 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
MiB Mem :   3928.8 total,    535.9 free,   2103.6 used,   1581.9 buff/cache
MiB Swap:      0.0 total,      0.0 free,      0.0 used.   1825.2 avail Mem

    PID USER      PR  NI    VIRT    RES    SHR S  %CPU  %MEM     TIME+ COMMAND
3850903 dshimizu  20   0  960064 102668  13916 S   0.0   2.6   0:02.89 ruby3.1
3850916 dshimizu  20   0  960064 102668  13916 S   0.0   2.6   0:00.03 DEBUGGER__::SES
3850920 dshimizu  20   0  960064 102668  13916 S   0.0   2.6   0:00.32 puma plgn bg 0
3850921 dshimizu  20   0  960064 102668  13916 S   0.0   2.6   0:00.44 puma srv tp 001
3850922 dshimizu  20   0  960064 102668  13916 S   0.0   2.6   0:00.00 puma srv tp 002
3850923 dshimizu  20   0  960064 102668  13916 S   0.0   2.6   0:00.00 puma srv tp 003
3850924 dshimizu  20   0  960064 102668  13916 S   0.0   2.6   0:00.00 puma srv tp 004
3850925 dshimizu  20   0  960064 102668  13916 S   0.0   2.6   0:00.00 puma srv tp 005
3850926 dshimizu  20   0  960064 102668  13916 S   0.0   2.6   0:00.02 puma reactor
3850927 dshimizu  20   0  960064 102668  13916 S   0.0   2.6   0:00.48 puma srv thread
3850928 dshimizu  20   0  960064 102668  13916 S   0.0   2.6   0:00.01 puma srv thread
3850929 dshimizu  20   0  960064 102668  13916 S   0.0   2.6   0:00.00 puma srv
3850935 dshimizu  20   0  960064 102668  13916 S   0.0   2.6   0:00.02 reaper.rb:42

処理中のPumaスレッド数を上回るHTTPリクエストを投げた時の動き

puma にはリクエストタイムアウトの仕組みがないようで、そのままの状態で使うと、大量のリクエストが来た場合に、スレッド数を上回るリクエストは、クライアント側のタイムアウト設定値だけ待機し、それを超えると接続が切られるようです。

この時、例えば、ECS で Rails/Puma を動かしている場合、重いリクエストで空きのスレッドがなくなっている場合、ALB ヘルスチェックリクエストも滞留することになってヘルスチェックに失敗し、ECSタスクがターゲットとして登録されているALB上のターゲットノードのステータスがUnhealty状態になり、ECS タスクが停止する形になる、といった状態が発生する可能性があります。

試してみます。

config/routes.rb に resources :samples, only: [:index, :show] を追記します。

Rails.application.routes.draw do
  # Define your application routes per the DSL in https://guides.rubyonrails.org/routing.html

  # Reveal health status on /up that returns 200 if the app boots with no exceptions, otherwise 500.
  # Can be used by load balancers and uptime monitors to verify that the app is live.
  get "up" => "rails/health#show", as: :rails_health_check

  # Defines the root path route ("/")
  # root "posts#index"

  resources :samples, only: [:index, :show]
end

app/controllers/samples_controller.rb を作成し、samples エンドポイントで60秒待機するようにするため、以下のようにしておきます。

class SamplesController < ApplicationController
  def index
    puts 'Started to wait 60 seconds'
    sleep 60
    puts 'Finished waiting'

    head :ok

  end

  def show

  end
end

Railsを起動します。 puma が5スレッド起動してます。

% bundle exec rails s
=> Booting Puma
=> Rails 7.1.3.2 application starting in development
=> Run `bin/rails server --help` for more startup options
Puma starting in single mode...
* Puma version: 6.4.2 (ruby 3.1.2-p20) ("The Eagle of Durango")
*  Min threads: 5
*  Max threads: 5
*  Environment: development
*          PID: 1051532
* Listening on http://127.0.0.1:3000
* Listening on http://[::1]:3000
Use Ctrl-C to stop

10個のリクエストを並列で投げてみます。 Curlでのタイムアウト値を3秒にしています。

% para=10; seq $para | xargs -I{} -P$para curl -v --max-time 3 http://127.0.0.1:3000/samples

クライアント側(curl)の10リクエスト全てタイムアウトしました。

*   Trying 127.0.0.1:3000...
* Connected to 127.0.0.1 (127.0.0.1) port 3000 (#0)
*   Trying 127.0.0.1:3000...
* Connected to 127.0.0.1 (127.0.0.1) port 3000 (#0)
> GET /samples HTTP/1.1
> Host: 127.0.0.1:3000
> User-Agent: curl/7.88.1
> Accept: */*
>> GET /samples HTTP/1.1
> Host: 127.0.0.1:3000
> User-Agent: curl/7.88.1
> Accept: */*
>

*   Trying 127.0.0.1:3000...
* Connected to 127.0.0.1 (127.0.0.1) port 3000 (#0)
> GET /samples HTTP/1.1
> Host: 127.0.0.1:3000
> User-Agent: curl/7.88.1
> Accept: */*
>
*   Trying 127.0.0.1:3000...
* Connected to 127.0.0.1 (127.0.0.1) port 3000 (#0)
> GET /samples HTTP/1.1
> Host: 127.0.0.1:3000
> User-Agent: curl/7.88.1
> Accept: */*
>
*   Trying 127.0.0.1:3000...
* Connected to 127.0.0.1 (127.0.0.1) port 3000 (#0)
> GET /samples HTTP/1.1
> Host: 127.0.0.1:3000
> User-Agent: curl/7.88.1
> Accept: */*
>
*   Trying 127.0.0.1:3000...
* Connected to 127.0.0.1 (127.0.0.1) port 3000 (#0)
> GET /samples HTTP/1.1
> Host: 127.0.0.1:3000
> User-Agent: curl/7.88.1
> Accept: */*
>
*   Trying 127.0.0.1:3000...
* Connected to 127.0.0.1 (127.0.0.1) port 3000 (#0)
> GET /samples HTTP/1.1
> Host: 127.0.0.1:3000
> User-Agent: curl/7.88.1
> Accept: */*
>
*   Trying 127.0.0.1:3000...
* Connected to 127.0.0.1 (127.0.0.1) port 3000 (#0)
> GET /samples HTTP/1.1
> Host: 127.0.0.1:3000
> User-Agent: curl/7.88.1
> Accept: */*
>
*   Trying 127.0.0.1:3000...
* Connected to 127.0.0.1 (127.0.0.1) port 3000 (#0)
> GET /samples HTTP/1.1
> Host: 127.0.0.1:3000
> User-Agent: curl/7.88.1
> Accept: */*
>
*   Trying 127.0.0.1:3000...
* Connected to 127.0.0.1 (127.0.0.1) port 3000 (#0)
> GET /samples HTTP/1.1
> Host: 127.0.0.1:3000
> User-Agent: curl/7.88.1
> Accept: */*
>
* Operation timed out after 3000 milliseconds with 0 bytes received
* Closing connection 0
curl: (28) Operation timed out after 3000 milliseconds with 0 bytes received
* Operation timed out after 3001 milliseconds with 0 bytes received
* Closing connection 0
curl: (28) Operation timed out after 3001 milliseconds with 0 bytes received
* Operation timed out after 3001 milliseconds with 0 bytes received
* Closing connection 0
curl: (28) Operation timed out after 3001 milliseconds with 0 bytes received
* Operation timed out after 3001 milliseconds with 0 bytes received
* Closing connection 0
curl: (28) Operation timed out after 3001 milliseconds with 0 bytes received
* Operation timed out after 3001 milliseconds with 0 bytes received
* Closing connection 0
curl: (28) Operation timed out after 3001 milliseconds with 0 bytes received
* Operation timed out after 3001 milliseconds with 0 bytes received
* Closing connection 0
curl: (28) Operation timed out after 3001 milliseconds with 0 bytes received
* Operation timed out after 3001 milliseconds with 0 bytes received
* Closing connection 0
curl: (28) Operation timed out after 3001 milliseconds with 0 bytes received
* Operation timed out after 3001 milliseconds with 0 bytes received
* Closing connection 0
curl: (28) Operation timed out after 3001 milliseconds with 0 bytes received
* Operation timed out after 3001 milliseconds with 0 bytes received
* Closing connection 0
curl: (28) Operation timed out after 3001 milliseconds with 0 bytes received
* Operation timed out after 3000 milliseconds with 0 bytes received
* Closing connection 0
curl: (28) Operation timed out after 3000 milliseconds with 0 bytes received

Rails 側の出力は以下のようになりました。 5スレッド分のリクエストはサーバー側(Rails/Puma)の処理が行われましたが、残りの5リクエスト分はクライアント側でタイムアウトとなり、pumaのログには何も出力されませんでしたので、処理されずに終わったことになるかと思います。

Started GET "/samples" for 127.0.0.1 at 2024-04-28 02:51:09 +0000
  ActiveRecord::SchemaMigration Load (0.2ms)  SELECT "schema_migrations"."version" FROM "schema_migrations" ORDER BY "schema_migrations"."version" ASC
Processing by SamplesController#index as */*
Started to wait 61 second
waiting ends
Completed 200 OK in 61003ms (ActiveRecord: 0.0ms | Allocations: 1248)


Started GET "/samples" for 127.0.0.1 at 2024-04-28 02:56:03 +0000
Processing by SamplesController#index as */*
Started to wait 61 second
Started GET "/samples" for 127.0.0.1 at 2024-04-28 02:56:03 +0000
Processing by SamplesController#index as */*
Started to wait 61 second
Started GET "/samples" for 127.0.0.1 at 2024-04-28 02:56:03 +0000
Processing by SamplesController#index as */*
Started to wait 61 second
Started GET "/samples" for 127.0.0.1 at 2024-04-28 02:56:03 +0000
Processing by SamplesController#index as */*
Started to wait 61 second
Started GET "/samples" for 127.0.0.1 at 2024-04-28 02:56:03 +0000
Processing by SamplesController#index as */*
Started to wait 61 second


## --- 最初の5リクエスト分のサーバー側(Rails/Puma)の処理完了のログ ---

Finished waiting
Completed 200 OK in 61001ms (ActiveRecord: 0.0ms | Allocations: 4077)


Finished waiting
Completed 200 OK in 61001ms (ActiveRecord: 0.0ms | Allocations: 3329)


Finished waiting
Completed 200 OK in 61001ms (ActiveRecord: 0.0ms | Allocations: 2686)


Finished waiting
Completed 200 OK in 61000ms (ActiveRecord: 0.0ms | Allocations: 1931)


Finished waiting
Completed 200 OK in 61001ms (ActiveRecord: 0.0ms | Allocations: 1163)

クラスターモードの起動

クラスターモードの起動を試してみます。

config/puma.rb に以下を worker 数の指定を追記して puma を再度起動します。

workers 2

ワーカーが2つ起動して、Cluster モードになっていることが確認できます。

% bundle exec rails s
=> Booting Puma
=> Rails 7.1.3.2 application starting in development
=> Run `bin/rails server --help` for more startup options
[506579] Puma starting in cluster mode...
[506579] * Puma version: 6.4.2 (ruby 3.1.2-p20) ("The Eagle of Durango")
[506579] *  Min threads: 5
[506579] *  Max threads: 5
[506579] *  Environment: development
[506579] *   Master PID: 506579
[506579] *      Workers: 2
[506579] *     Restarts: (✔) hot (✔) phased
[506579] * Listening on http://127.0.0.1:3000
[506579] * Listening on http://[::1]:3000
[506579] Use Ctrl-C to stop
[506579] - Worker 0 (PID: 506582) booted in 0.0s, phase: 0
[506579] - Worker 1 (PID: 506585) booted in 0.0s, phase: 0

参考

Puma の内部構造やアーキテクチャを追う | バベルの図書館は完成しない