Re: seeking advice on using details in access_log to distinguish slow requests from slow repsonses

On Fri, Jan 3, 2025, 12:43 PM Brian Reichert <[email protected]> wrote:

> At $WORK, we're trying to instrument our Apache 2.4.51 server to
> diagnose latency issues.
>
> Among our goals is to instrument our logs to distinguish between
> clients taking too long to complete requests, and our server from
> taking too long to provide a response.
>
> Further, we want those logs to be terse, as disk space and log
> retention are important.
>
> I've been exploring combinations of:
>
>   from mod_logio:
>     LogIOTrackTTFB
>
>   from mod_log_config:
>     %D          The time taken to serve the request, in microseconds.
>     %^FB        Delay in microseconds between when the request
>                 arrived and the first byte of the response headers
>                 are written.
>    %{begin:%d/%b/%Y:%T}t.%{begin:usec_frac}t
>                 beginning of request processing, in microseconds.
>
> When I compare the recorded timestamps with a packet capture, and
> a purposely-slowed POST request, I see that both of these counters
> seem to start from when the first packet of the request comes in,
> not when the whole request has been received.
>
> As such, the timers describe the whole request/response cycle, and
> don't let us infer where the latency is.
>
> We've also explored info-level logging into our error_log, which
> does yield useful records:
>
>   when a TLS session has completed setup.
>   when the request was completely received.
>
> These are both great, and coupled with the details we can get in
> our access_log, we can better pinpoint latency.
>
> But, info-level logging yields a firehouse of data that floods the
> logs, hamper retention.
>
> Does anyone have any suggestions as to how to introduce a timestamp
> into the access log as to when the entire request was received?
>

Maybe a mod-lua script that runs in the post read request hook and just
logs a message. Note this does not count any request body.

>
> Or how to expose the details we see in the error_log, but in a way
> that's much more terse than all of info?
>
> Thanks for any pointers!
>
> --
> Brian Reichert                          <[email protected]>
> BSD admin/developer at large
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: [email protected]
> For additional commands, e-mail: [email protected]
>
>