Zenn
🤖

unicornのワーカーがすべて処理中になった時のnginx/Railsログ

2021/12/29に公開
Rails
nginx
#
unicorn
tech

nginx -> unicorn の間で待ちが発生すると思うがログにはどうでるんだろう？と思って整理してみた。
考えてみるととても当たり前。でも、もう考えたくないのでまとめておく。

結論

  • nginxの $time_iso8601 はリクエストが完了した時刻
  • Railsのログに Started GET xxxx が記録されるのは unicorn のワーカにリクエストが到達して処理が開始されたタイミング
    • まぁ当たり前か
  • unicornが枯渇していてリクエストがワーカーに割り当てるまでの待ち時間は Railsの Completed のログに含まれない

状況

  • 2021-02-19 10:00:00 にリクエストが2つ同時にnginxに到達
  • Rails側で、1リクエストを処理するのに10秒かかる

どう記載されるか？

先に到達した方のリクエスト

  • nginx
    • $time_iso8601 は 2021-02-19 10:00:10
    • $request_time は 10秒
    • $upstream_response_time は 10秒
  • Rails
    • Started GET "/hoge" ... のログの時刻は 2021-02-19 10:00:00
    • Completed 200 OK in xxx ms ... のログの時刻は 2021-02-19 10:00:10。 ms の所はほぼ10秒」

後に到達した方のリクエスト

ワーカーがすべて処理中なので10秒間待たされる。

  • nginx
    • $time_iso8601 は 2021-02-19 10:00:20
    • $request_time は 10秒
    • $upstream_response_time は 10秒
  • Rails
    • Started GET "/hoge" ... のログの時刻は 2021-02-19 10:00:10
    • Completed 200 OK in xxx ms ... のログの時刻は 2021-02-19 10:00:20。 ms の所はほぼ10秒」

再現手順

  1. unicornのワーカー数を1にする
  2. 数秒sleepするエンドポイントに対してcurlを2つ同時に実行

Discussion