問題
ウェブアプリケーションで処理に時間がかかることがあり、その調査を行っている。
その時、アクセスログをもとに原因を特定しているのだが、利用しているミドルウェアによってアクセスログに記録されている時刻が異なっていて混乱したので、その内容を示す。
利用しているアーキテクチャ
今回のアーキテクチャは CloudFront -> nginx -> Apache の構成になっていて、それぞれでアクセスログを出力している。
アクセスログ時刻の仕様
違いをまとめると以下の通り。 Apache は「受信時刻」だが、CloudFront/Nginx は「レスポンス完了時刻」を示すことが大きく違う。
| 項目 | CloudFront | Nginx | Apache |
|---|---|---|---|
| 時刻フィールド |
date + time
|
$time_local |
%t |
| ログの時刻の意味 | レスポンス完了時刻 | レスポンス完了時刻 | リクエスト受信時刻 |
| ログ出力のタイミング | レスポンス完了後 | レスポンス完了後 | レスポンス完了後 |
| 公式ドキュメント | CloudFront 標準ログ仕様 | Nginx $time_local | Apache ログファイル |
そのため、例えば
- クライアントからのリクエスト開始は
00:00:00 - Apache での処理に3秒程度かかる
-
クライアント - CLoudFront - Nginx - Apache間の通信のオーバーヘッドは考えないものとする
といった条件でログを記録した場合、ログの時刻記録は以下のようになる。
- CloudFront:
00:00:03(※time-taken などのリクエスト全体にかかった時間を知るための記録もあり、こちらには3秒が記録される） - Nginx :
00:00:03 - Apache:
00:00:00
この仕様を知らないと、ログ時刻を誤って読み取って異なる結論を導き出してしまうので注意すること。