🤖
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秒」
-
再現手順
- unicornのワーカー数を1にする
- 数秒sleepするエンドポイントに対してcurlを2つ同時に実行
Discussion