メトリクス可視化から始める Rails ウェブサーバーのチューニング Kaigi on Rails 2021 / 2021-10-23 / @s4ichi

@s4ichi ● Takamasa Saichi / 齋地 崇大 ○ s4ichi / s4ichi ● Ruby / Rails（2014~） ○ Ruby で JIT でメモリ割り付け最適化の研究 ○ 好きな gem は sigdump と stackprof ● クックパッド株式会社 技術部 ○ マイクロサービス化と巨大モノリスの基盤開発

毎日の料理を楽しみにする https://cookpad.jobs/

Rails を動かすウェブサーバー 何を使っています？

今日はそんなウェブサーバーの チューニングの話をしにきました

アジェンダ📝 ● ウェブサーバーの役割と特有の難しさについて ● ウェブサーバー特有のメトリクス収集と可視化 ○ ウェブサーバーの特性に応じたメトリクスの収集 ○ 収集したメトリクスを使って長期的な変化を可視化 ○ unicorn と puma を例に紹介 ● 可視化した情報を使ったチューニングの例 ○ メトリクスに基づいた監視とチューニングの事例を紹介

“ウェブサーバー” ● Rails, Sinatra, Hanami 等の裏側 ● unicorn, puma, WEBrick など ○ Rails 標準では puma が入ります ● HTTP で受けて Rack の handler を叩くソフトウェアを想定 $ bin/rails server => Booting Puma => Rails 6.1.4.1 application starting in development => Run `bin/rails server --help` for more startup options Puma starting in single mode... * Puma version: 5.4.0 (ruby 3.0.2-p107) ("Super Flight") * Min threads: 5 * Max threads: 5 * Environment: development * PID: 57130 * Listening on http://127.0.0.1:3000 * Listening on http://[::1]:3000 Use Ctrl-C to stop

“ウェブサーバー” の役割 ● クライアントや上段と http(s) でやり 取りするレイヤ ○ クライアントの http/https request を Ruby のオブジェクトに変換 ○ 処理結果の Ruby オブジェクトを http/https 形式の response に変換 unicorn/puma/WEBrick Rack Rails/Sinatra/Hanami client

unicorn - yhbt.net/unicorn ● prefork 型の multi process で動作するウェブサーバー実装 ○ 少し昔まで GitHub の 500 系エラーに表示されていましたね

unicorn の動作モデル ● master 1 : worker N のプロセスモデル ○ master から fork して worker を指定数分起動 ● 実装がシンプルであるがための制約 ○ keep-alive や pipeline の実装も存在しない ○ slow & high-latency client には nginx に任せる ○ ref: https://yhbt.net/unicorn/DESIGN.html nginx unicorn client

puma - github.com/puma/puma ● multi worker, multi thread で動作可能なウェブサーバー実装 ○ Rails 5 から development の rails server でも起動するように（以前は WEBrick）

puma の動作モデル ● worker M : thread N ○ cluster mode の場合 ○ worker process 毎に threadpool を保有 ● Receive Thread ○ worker ごとに request body を受け取る thread https://github.com/puma/puma/blob/56a25f709604240fb32310f15126d47d5a6541ca/docs/architecture.md

puma の動作モデル ● worker M : thread N ○ cluster mode の場合 ○ worker process 毎に threadpool を保有 ● Receive Thread ○ worker ごとに request body を受け取る thread https://github.com/puma/puma/blob/56a25f709604240fb32310f15126d47d5a6541ca/docs/architecture.md

ウェブサーバーで計算資源を極限まで使い倒す ● ウェブサーバーに与えられた計算資源を効率良く使いたい ○ 余剰な計算資源は削減してアプリケーションの運用コストを削減 ○ ウェブサーバー起因の無駄な待ち時間は削減にしてレスポンスタイムを改善 ● アプリケーションに適しているウェブサーバーの設定 ○ アプリケーションの実装やワークロードを基に適した設定を選ぶ ○ ウェブサーバー周辺のミドルウェアと合わせてチューニングをしていく

汎用的で最適な設定が無い問題 ● 設定の最適化の方針が具体化しすぎてシェアし難い ○ 各社・各プロジェクトの特性に応じるのでそれぞれサイロ化してしまう ● 複数の指標を組み合わせて適している設定を探していく ○ CPU 使用率 → I/O 待ちだったら CPU 使いませんよね 🤔 ○ メモリ使用率 → OOM しない程度に最大まで使ってほしい 🤔 ○ レスポンスタイム → アプリケーションの実装起因で変動しちゃいます 🤔 ● より具体的な指標があれば意思決定の材料になる

ウェブサーバー特有のメトリクスに着目 ● ソフトウェアの関心範囲のメトリクスを基準にする ○ e.g., 同時にいくつのリクエストを捌いているか , 機能 A の待ち行列はどのくらいか , 機能 B の処理時間は平均どれくらいかかっているか ● OS やクライアント視点での指標だけではわからないことも多い ○ ウェブサーバー特有のメトリクスと合わせる ○ “適した設定” の根拠をメトリクスの値とその変化で具体的に示す

メトリクスの長期的な観測📉📈 ● 瞬間的なメトリクスや一時的な監視では効果が図りにくい ○ ウェブサーバーのチューニング前後の変化の傾向を指標とする

どうやってメトリクスを可視化する？🤔

`Puma.stats` { "started_at": "2021-01-14T07:09:17Z", "workers": 2, "phase": 0, "booted_workers": 2, "old_workers": 0, "worker_status": [ { "started_at": "2021-01-14T07:09:24Z", "pid": 64136, "index": 0, "phase": 0, "booted": true, "last_checkin": "2021-01-14T07:11:09Z", "last_status": { "backlog": 0, "running": 5, "pool_capacity": 5, "max_threads": 5, "requests_count": 2 } }, { "started_at": "2021-01-14T07:09:24Z", "pid": 64137, "index": 1, "phase": 0, "booted": true, "last_checkin": "2021-01-14T07:11:09Z", "last_status": { "backlog": 0, "running": 5, "pool_capacity": 5, "max_threads": 5, "requests_count": 1 } } ] ● puma の状態を出力するインターフェー スは標準で搭載されている ● 必要なメトリクスをここから用意 ○ 総 worker 数 ○ worker 毎の thread pool stats ■ active な thread 数 ■ backlog の request 数 https://github.com/puma/puma/blob/56a25f709604240fb3231 0f15126d47d5a6541ca/docs/stats.md

`Raindrops::Linux. tcp_listener_stats` address = '0.0.0.0:8080' stat = Raindrops::Linux. tcp_listener_stats([address]) stat[address].to_h # =>{:active=>0, :queued=>0} ● unicorn には標準で提供している stats 出力機能は存在しない ● 直接 socket から取得するしかない ○ OS の汎用的な仕組みなどを介して取得 ● 例: raindrops gem を介して取得 ○ active な worker 数 ○ queue にある request 数

prometheus_exporter - github.com/discourse/prometheus_exporter ● 今回の発表では prometheus_exporter gem を活用します ○ puma と unicorn の integration を使って stats を出力

● メトリクスを右に抜粋 ○ Prometheus 形式の Gauge 値 ○ https://github.com/discourse/prometh eus_exporter#puma-metrics ● worker と thread に関する値 ○ puma の stats から取得した情報 ○ `puma -w 2 -t 16:16` で起動した場合 puma のメトリクス出力 # HELP ruby_puma_workers_total Number of puma workers. # TYPE ruby_puma_workers_total gauge ruby_puma_workers_total{phase="0"} 2 # HELP ruby_puma_booted_workers_total Number of puma workers booted. # TYPE ruby_puma_booted_workers_total gauge ruby_puma_booted_workers_total{phase="0"} 2 # HELP ruby_puma_old_workers_total Number of old puma workers. # TYPE ruby_puma_old_workers_total gauge ruby_puma_old_workers_total{phase="0"} 0 # HELP ruby_puma_running_threads_total Number of puma threads currently running. # TYPE ruby_puma_running_threads_total gauge ruby_puma_running_threads_total{phase="0"} 32 # HELP ruby_puma_request_backlog_total Number of requests waiting to be processed by a puma thread. # TYPE ruby_puma_request_backlog_total gauge ruby_puma_request_backlog_total{phase="0"} 0 # HELP ruby_puma_thread_pool_capacity_total Number of puma threads available at current scale. # TYPE ruby_puma_thread_pool_capacity_total gauge ruby_puma_thread_pool_capacity_total{phase="0"} 32 # HELP ruby_puma_max_threads_total Number of puma threads at available at max scale. # TYPE ruby_puma_max_threads_total gauge ruby_puma_max_threads_total{phase="0"} 32

● メトリクスを右に抜粋 ○ Prometheus 形式の Gauge 値 ○ https://github.com/discourse/prometh eus_exporter#unicorn-process-metrics ● raindrops から取得した情報 ○ `worker_processes 4` で設定した場合 ○ “backlog” は処理待ちで queue に入れらて いるリクエストの数 unicorn のメトリクス出力 # HELP ruby_unicorn_workers_total Number of unicorn workers. # TYPE ruby_unicorn_workers_total gauge ruby_unicorn_workers_total 4 # HELP ruby_unicorn_active_workers_total Number of active unicorn workers # TYPE ruby_unicorn_active_workers_total gauge ruby_unicorn_active_workers_total 0 # HELP ruby_unicorn_request_backlog_total Number of requests waiting to be processed by a unicorn worker. # TYPE ruby_unicorn_request_backlog_total gauge ruby_unicorn_request_backlog_total 0

stats の収集と可視化 ● 今回は Prometheus で収集した stats を Grafana で可視化 ○ もしくは netdata などで Prometheus 形式の出力を一括で収集 & 可視化も便利

例: N台あるウェブサーバー（unicorn）の active な worker（最大/平均）, worker 設定値, backlog の値（最大/平均）

例: N台あるウェブサーバー（unicorn）の総 worker 数と active な worker 数, backlog とサーバー台数も表示

可視化したメトリクスを使ったチューニング ● メトリクスから安直に推察するだけでも色々得られる ○ active な worker が常時少なく余りまくっている → 与えられているリソースが過剰すぎるかもしれない ○ backlog が常に一定数以上存在している → worker を増やして待ち時間を削減できるかも知れない ○ 用意した worker がほぼ全て active であるが backlog が無い → 資源効率は良いがスパイクアクセスに耐えられないかも？

可視化 → 改善の事例を紹介

事例①：時間帯でアクセス傾向が変化するサービス ● 特定の時間帯に向けてリクエスト数が緩やかに増加 ● 増加するリクエスト数に応じてスケールアウトする構成 ○ AWS ECS タスク上で unicorn を使って Rails アプリケーションを起動 ○ スケールアウトのしきい値は CPU 使用率が N% を維持する設定 ● prometheus_exporter の導入とメトリクスの可視化 ○ CPU/Memory, nginx 等の既存メトリクスと合わせて状況を把握 ○ ウェブサーバー含めて設定を見直していった例を紹介 👉

Load Balancing の偏りの観測 ● active な worker の最大と平均に大きな差が発生 ○ API ごとにレスポンスタイムに差があり遅いエンドポイントが集中している …？ 事例①：時間帯でアクセス傾向が変化するサービス ➔ max workers: 8 で固定（unicorn の設定値） ➔ active(max): 5 ~ 8 で推移 ➔ active(avg): 2 ~ 3 で推移 ➔ active(max) と active(avg) の差が大きい ➔ worker が捌けている unicorn と worker が暇になっ ている unicorn、つまり偏りを示唆する結果

Load Balancing の偏りを改善 ● Slow Endpoint ばかり叩かれた unicorn の active(max) が高い仮説 ○ Load Balancing のアルゴリズムを RoundRobin から LeastConn へ変更で改善 ○ たびたび発生する backlog のスパイクもほぼ見られなくなった 🎉 事例①：時間帯でアクセス傾向が変化するサービス 変更前 変更後

スケールアウトの閾値を調整 ● LB の偏り改善により worker が以前よりも空く傾向へ ○ 余裕がある分スケールアウトの閾値を上げて最終的に週平均 30 ECS タスクを削減🎉 ○ LB による偏りが削減され特定のタスクで backlog がスパイクしなくなったため 事例①：時間帯でアクセス傾向が変化するサービス 変更前 変更後

prefork する worker 数を増やす調整 ● unicorn の worker 数を調整して必要なキャパシティ分増やす ○ 平時でもスパイクが見込まれるためリソースの空き分を worker に充て余裕を保たせる 事例①：時間帯でアクセス傾向が変化するサービス 変更前 変更後 変更前 変更後

事例②：アクセス数がスパイクするサービス - Push 通知に起因してアクセス数が何倍にもスパイク - 大規模な一斉配信で瞬間的な負荷の増加が見込まれるため事前に増強が必要 - 同じく AWS ECS タスク上に unicorn を使って Rails アプリケーションを起動 - worker の状況を可視化して見積もりや傾向を観測 - レスポンスタイムの悪化を出来る限り削減したい - 悪化時の原因の切り分けもしたい - e.g.) unicorn の詰まり, DB のキャパシティを超えた , キャッシュの eviction 増加

スパイク時の worker 状況を観測 ● 改善前のメトリクスでは backlog が爆発する状態 ● レスポンスタイムの上昇によって一時的なサービスの提供が滞る 事例②：アクセス数がスパイクするサービス

原因の切り分け / 次回の見積もり ● backlog が爆発した原因を調査 ○ worker の不足ではなくアプリケーション・ DB が原因 ■ 結果アプリケーション側のレスポンスタイム上昇 ■ レスポンスタイムに応じた見積もりをした worker 数では足りない事態 ● worker 不足が原因か、それ以外が原因か ○ worker の必要総数はレスポンスタイムやリクエスト数から程度予測可能 ■ アプリケーション・DB が十分に負荷に耐えうる状態であることが前提 事例②：アクセス数がスパイクするサービス

アプリケーション・DB の見直しと改善 ● 初日の Leonard Chin さんの発表で改善のアプローチが紹介👇 事例②：アクセス数がスパイクするサービス https://speakerdeck.com/lchin/performance-as-a-product-feature

スパイク時の worker 状況を改善 事例②：アクセス数がスパイクするサービス

事例③：限られた資源上でのチューニング ● ISUCON - https://isucon.net/ ○ 与えられたサーバー上でアプリケーションをチューニングしてスコアを競う ○ 高速化すればするほど単位時間あたりのリクエスト数は増加 ● 近年の ISUCON は CPU 2 core, Memory 4GB が 3 台 ○ いかにボトルネックを可視化してチューニングできるかが重要 ○ prometheus_exporter で出力して netdata 上に出力 ■ アプリケーション特性に応じて puma の設定を改善🚀

まとめ: 可視化 → 改善 ● ウェブサーバーに特有のメトリクスを収集して可視化 ○ 適切な設定の根拠や交渉材料としてメトリクスを集める ○ 長期的な監視によって異常値や不適な状態を見つける ● 問題発生時の切り分けをより正確に ○ 例えばレスポンスタイムの悪化はあくまでクライアントの目線 ○ 実際何に時間がかかっているのかを推測ではなく数値で判断

毎日の料理を楽しみにする https://cookpad.jobs/