まとめ
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"
アクセス直後の時間が表示されていますね。ということで時間がかかる処理をしている方はご注意ください。
