Apacheのログに%T or %Dでリクエスト処理時間を載せることができます。%Tと%Dは内部的には同じ計算値で、単位が異なるだけです(%Tは秒、%Dはマイクロ秒)。

このリクエスト処理時間は、いつからいつまでの処理時間でしょうか。つまり計測時間の開始と終了はどのタイミングでしょうか。

終了はレスポンスデータをsend(2)し切ったタイミングです。

開始として思いつくのは次の3つのタイミングです。

1. listenキューに入ったタイミング(3wayハンドシェイクの最初のACKを受けたタイミング)
2. accept(2)が返ったタイミング(3wayハンドシェイクの最後のACKを受けたタイミング)
3. リクエストデータをrecv(2)する前

実はどれも間違いです。正解は、リクエストデータの1行目のリクエスト行を読み終わったタイミングです(ソースコードで言うと server/protocol.cのread_request_line()で r->request_time に値を設定している行です)。

上記3案のうち、aは少し不自然なタイミングです。しかも、通常のソケットプログラミングでは、このタイミングはpoll/selectによるポーリングでしか知りえません。

b.のタイミングで計測すると、ワーカースレッドの数が足りない場合にワーカースレッドを待つ時間が加算されることになります。状況によっては意図と異なる値です。

c.のタイミングで計測すると、HTTPクライアントが接続だけしてリクエストデータを送信してこない時の待ち時間が加算されることになります。

そんなわけで、リクエスト行を読み終わったタイミングから計測開始、ということなのでしょう。