Apache のログにリクエスト処理時間を記録したい場合、LogFormatで %D（マイクロ秒）、%T（秒）で指定する。
ログ出力
**.0.3.*** - - [29/Nov/2020:13:56:07 +0000] 260★マイクロ秒（%D） 0★秒（%T） "GET / HTTP/1.1" 403 3630 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_14_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/87.0.4280.67 Safari/537.36" **.0.3.*** - - [29/Nov/2020:13:56:07 +0000] 75 0 "GET /icons/apache_pb2.gif HTTP/1.1" 200 4234 "http://ec2-**-***-***-***.ap-northeast-1.compute.amazonaws.com/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_14_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/87.0.4280.67 Safari/537.36" **.0.3.*** - - [29/Nov/2020:13:56:07 +0000] 61 0 "GET /favicon.ico HTTP/1.1" 404 196 "http://ec2-**-***-***-***.ap-northeast-1.compute.amazonaws.com/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_14_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/87.0.4280.67 Safari/537.36" **.0.3.*** - - [29/Nov/2020:13:56:10 +0000] 175 0 "GET / HTTP/1.1" 403 3630 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_14_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/87.0.4280.67 Safari/537.36"
インストール・設定
- Apache インストール
$ sudo yum -y install httpd
<IfModule log_config_module>
#
# The following directives define some format nicknames for use with
# a CustomLog directive (see below).
#
LogFormat "%h %l %u %t %D %T \"%r\" %>s %b \"%{Referer}i\" \"%{User-Agent}i\"" combined # ★ %D と %T を追記
LogFormat "%h %l %u %t \"%r\" %>s %b" common
（中略）
#
# If you prefer a logfile with access, agent, and referer information
# (Combined Logfile Format) you can use the following directive.
#
CustomLog "logs/access_log" combined
</IfModule>
- 起動
$ sudo systemctl start httpd.service
- ステータス確認
$ sudo systemctl status httpd.service * httpd.service - The Apache HTTP Server Loaded: loaded (/usr/lib/systemd/system/httpd.service; disabled; vendor preset: disabled) Active: active (running) since Sun 2020-11-29 13:48:49 UTC; 1min 40s ago Docs: man:httpd.service(8) Main PID: 21146 (httpd) Status: "Total requests: 0; Idle/Busy workers 100/0;Requests/sec: 0; Bytes served/sec: 0 B/sec" CGroup: /system.slice/httpd.service |-21146 /usr/sbin/httpd -DFOREGROUND |-21147 /usr/sbin/httpd -DFOREGROUND |-21148 /usr/sbin/httpd -DFOREGROUND |-21153 /usr/sbin/httpd -DFOREGROUND |-21169 /usr/sbin/httpd -DFOREGROUND `-21179 /usr/sbin/httpd -DFOREGROUND Nov 29 13:48:49 ip-172-**-*-178.ap-northeast-1.compute.internal systemd[1]: Starting The Apache HTTP Server... Nov 29 13:48:49 ip-172-**-*-178.ap-northeast-1.compute.internal systemd[1]: Started The Apache HTTP Server.
参考
mod_log_config - Apache HTTP サーバ バージョン 2.2
フォーマット文字列 説明 %D リクエストを処理するのにかかった時間、マイクロ秒単位 %T リクエストを扱うのにかかった時間、秒単位
Apacheのログに%T or %Dでリクエスト処理時間を載せることができます。%Tと%Dは内部的には同じ計算値で、単位が異なるだけです(%Tは秒、%Dはマイクロ秒)。
このリクエスト処理時間は、いつからいつまでの処理時間でしょうか。つまり計測時間の開始と終了はどのタイミングでしょうか。
終了はレスポンスデータをsend(2)し切ったタイミングです。
開始として思いつくのは次の3つのタイミングです。
- listenキューに入ったタイミング(3wayハンドシェイクの最初のACKを受けたタイミング)
- accept(2)が返ったタイミング(3wayハンドシェイクの最後のACKを受けたタイミング)
- リクエストデータをrecv(2)する前
実はどれも間違いです。正解は、リクエストデータの1行目のリクエスト行を読み終わったタイミングです(ソースコードで言うと server/protocol.cのread_request_line()で r->request_time に値を設定している行です)。
上記3案のうち、aは少し不自然なタイミングです。しかも、通常のソケットプログラミングでは、このタイミングはpoll/selectによるポーリングでしか知りえません。
Apacheのリクエスト処理時間(%T or %D)は正確には何の時間か — ありえるえりあ
b.のタイミングで計測すると、ワーカースレッドの数が足りない場合にワーカースレッドを待つ時間が加算されることになります。状況によっては意図と異なる値です。
c.のタイミングで計測すると、HTTPクライアントが接続だけしてリクエストデータを送信してこない時の待ち時間が加算されることになります。
そんなわけで、リクエスト行を読み終わったタイミングから計測開始、ということなのでしょう。
