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

まとめ

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
<?php
   echo date('h:i:s') . "\n";
   sleep(10);
   echo date('h:i:s') . "\n";
?>

そして実行

# 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"

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