まとめ

nginxのaccess.logに書かれる時間はリクエストを受けた時間だとずっと思っていましたが、実はリクエストを処理した後にログに書かれる時間だったというお話です。

経緯

# cat /var/log/nginx/access.log
127.0.0.1 - - [02/Feb/2016:10:56:06 +0000] "GET /sleep.php HTTP/1.1" 200 29 "-" "curl/7.40.0" "-"

4カラム目の時間、アクセス時間と説明してあるWebがよくあります。で、当初そういうものなんだろうとおもっていましたが、確認してみるとどうやら違うようでした。ということで確認してみました。

確認方法

簡単なPHPプログラムをつくってみました。時間を表示して、10秒sleep、さらに時間を表示します。

# cat  /usr/share/nginx/html/sleep.php

そして実行

# date; curl http://test:8080/sleep.php ; date
Tue Feb  2 10:55:56 UTC 2016
10:55:56
10:56:06
Tue Feb  2 10:56:06 UTC 2016

curlの実行にはほぼ時間はかかっておらず、実行前が10:55:56、実行後が10:56:06になっています。そしてアクセスログ確認

# cat /var/log/nginx/access.log
127.0.0.1 - - [02/Feb/2016:10:56:06 +0000] "GET /sleep.php HTTP/1.1" 200 29 "-" "curl/7.40.0" "-"

実行後の時間が記録されていることがわかります。

Apacheの場合は、アクセス時間が記録される

論より証拠、同じ方法でためしてみましょう。nginxのかわりにapache2を起動します。

# service nginx stop
Stopping nginx:                                            [  OK  ]
# service httpd start
Starting httpd:                                            [  OK  ]

アクセスしてみます。

# date; curl http://test/sleep.php ; date
Tue Feb  2 11:05:52 UTC 2016
11:05:52
11:06:02
Tue Feb  2 11:06:02 UTC 2016
# cat /var/log/httpd/access_log
127.0.0.1 - - [02/Feb/2016:11:05:52 +0000] "GET /sleep.php HTTP/1.1" 200 18 "-" "curl/7.40.0"

アクセス直後の時間が表示されていますね。ということで時間がかかる処理をしている方はご注意ください。

元記事はこちら

nginxのaccess.logに記録される時間はログに書きこまれた時間