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

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つ同時に実行