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

Kaigi on Rails 2021 の登壇資料です。
https://kaigionrails.org/2021/talks/s4ichi/

Transcript

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

   View Slide

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

   View Slide

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

   View Slide

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

   View Slide

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

   View Slide

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

   View Slide

7. “ウェブサーバー”
   ● 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
   

   View Slide

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

   View Slide

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

   View Slide

10. 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
    

    View Slide

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

    View Slide

12. 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
    

    View Slide

13. 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
    

    View Slide

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

    View Slide

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

    View Slide

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

    View Slide

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

    View Slide

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

    View Slide

19. `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
    

    View Slide

20. `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 数
    

    View Slide

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

    View Slide

22. ● メトリクスを右に抜粋
    ○ 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
    

    View Slide

23. ● メトリクスを右に抜粋
    ○ 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
    

    View Slide

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

    View Slide

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

    View Slide

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

    View Slide

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

    View Slide

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

    View Slide

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

    View Slide

30. 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、つまり偏りを示唆する結果
    

    View Slide

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

    View Slide

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

    View Slide

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

    View Slide

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

    View Slide

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

    View Slide

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

    View Slide

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

    View Slide

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

    View Slide

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

    View Slide

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

    View Slide

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

    View Slide