これが私の production.log のスニペットです。
Started GET "/product/514034/754240" for XX.XX.202.138 at 2012-06-21 11:52:28 -0700
Started GET "/product/614409/666897" for XX.XX.228.38 at 2012-06-21 11:52:28 -0700
Processing by ProductsController#show as HTML
Parameters: {"category_id"=>"514034", "product_id"=>"754240"}
Processing by ProductsController#show as HTML
Parameters: {"category_id"=>"614409", "product_id"=>"666897"}
Logged in 2940659 via auth cookie
Logged in 585210 via auth cookie
[e3e3fc56bb6bd137741b269ee397683c] [2940659] Read fragment views/global-caches/header (0.7ms)
[e3e3fc56bb6bd137741b269ee397683c] [2940659] Rendered shared/_email_form.html.haml (0.7ms)
[d81bb986be5acc0277c0c9e11b414249] [585210] Read fragment views/global-caches/sharebar-message (0.7ms)
[d81bb986be5acc0277c0c9e11b414249] [585210] Rendered shared/_email_form.html.haml (0.7ms)
...
ご覧のとおり、2 人の異なるユーザーの 2 つの同時セッションが同じログ ファイルに同時に記録されています。これにより、ログを解析して、各種類のページの生成にかかった時間などを判断することができなくなります。これは、エントリが次の順序で予期されていないためです。
Started GET "/URL/BLAH" for IP at DATE
... stuff...
Completed 200 OK in XXms (ActiveRecord: YY.Yms)
代わりに、次のような予測できないインターリーブされたログを取得します。
Started GET "/URL/BLAH" for IP at DATE
Started GET "/URL/BLAH" for IP at DATE
... stuff...
Completed 200 OK in XXms (ActiveRecord: YY.Yms)
...stuff...
Completed 200 OK in XXms (ActiveRecord: YY.Yms)
したがって、「完了」と「開始」を一致させることは不可能です。
私が望むのは、各子プロセスが独自のログなどに書き込む方法です。または、各ページビューのログをアトミックに書き込む方法が可能である場合、それは不可能または困難であるか、パフォーマンスが低下する可能性があります。