[PATCH] Add the VSL tag BereqEnd

[Martin Blix Grydeland]

Thanks for the patch Geoff!

For the format and what is logged I have a couple of comments.

I am missing a Treq field, which is the time it took to send the request to
the backend in the first place. Would be used to search for network issues
(or slow piping of passed client request bodies).

Also I think we should have the total backend response time in seconds as a
separate field. This because that I guess will be the most frequently used
property of the record, and will be useful to query on in terms of finding
the ones that take a long time. I realize that the data is there as the sum
of Thdr and Tbody, but since the query lang can't test on the sum of two
fields it becomes not so usable. The question then becomes if we should add
a Tresp field, or replace Tbody with the Tresp (causing Tbody to be
calculable but not query-able). My vote goes to add the Tresp field.

Lastly, I think mimicking ReqEnd is a goal in itself, and to do that we
should think about the vxid that is present on ReqEnd. But in Varnish 4 the
vxid is part of every log record always, so here I believe we should remove
the vxid from ReqEnd instead.

So my suggestion on the fields present is:
BereqEnd <Tstart> <Tend> <dTreq> <dThdr> <dTbody> <dTresp>

Tstart: begin fetch processing (epoch)
Tend: end fetch processing (epoch)
dTreq: time to send the backend request
dThdr: time to receive the backend response headers
dTbody: time to receive the backend response body
dTresp: time to receive the backend response (dThdr + dTbody)

Regards,
Martin




On 10 October 2013 11:37, Geoff Simmons <geoff at uplex.de> wrote:

> Hello all,
>
> This patch adds the BereqEnd tag, always the last tag emitted for a
> bereq transaction before the End marker.
>
> The format is:
>
> BereqEnd <Tstart> <Tend> <Thdr> <Tbody>
>
> Tstart: begin fetch processing (epoch)
> Tend: end fetch processing (epoch)
> Thdr: time to receive response header
> Tbody: time to receive response body
>
> Thdr is approximately the delta from just after sending the backend
> request until just after receiving the header. Tbody is approximately
> the delta from just after receiving the response header until just after
> receiving the body.
>
> So for example:
>
> BereqEnd       1381335026.155810356 1381335026.268885612 0.112095833
> 0.000851154
>
> The deltas are approximate because the low-level fetch operations do
> some buffering, so the timings don't correspond strictly to reading the
> header and body off the network (see the comments in
> cache_http1_proto.c), but I think will for the most part reflect backend
> latencies well enough.
>
> The rationale is that I think backend timings will be useful for:
>
> - measuring backend performance, and in particular finding out which
> backends are slow
>
> - finding out how much time in a fetch is due to work done strictly in
> varnishd, and how much is due to latencies in systems beyond Varnish's
> control
>
> There is a bit of varnishd overhead in the Thdr and Tbody timings, but
> they are dominated by backend latencies. That does mean, however, that
> Tbody is always > 0, even if there is no response body.
>
> Probably most people won't be very interested in the difference between
> Thdr and Tbody (just Thdr+Tbody). We have to take a measurement after
> the header arrives anyway, since there might not be a body, so I thought
> we may as well log the delta. But maybe we just want the one value here,
> just Thdr+Tbody. Tell me what you think.
>
>
> Best,
> Geoff
> --
> ** * * UPLEX - Nils Goroll Systemoptimierung
>
> Scheffelstraße 32
> 22301 Hamburg
>
> Tel +49 40 2880 5731
> Mob +49 176 636 90917
> Fax +49 40 42949753
>
> http://uplex.de
>
> _______________________________________________
> varnish-dev mailing list
> varnish-dev at varnish-cache.org
> https://www.varnish-cache.org/lists/mailman/listinfo/varnish-dev
>



-- 
<http://varnish-software.com>*Martin Blix Grydeland*
Senior Developer | Varnish Software AS
Cell: +47 21 98 92 60
We Make Websites Fly!
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://www.varnish-cache.org/lists/pipermail/varnish-dev/attachments/20131015/a702dd25/attachment.html>