<div dir="ltr">Thanks for the patch Geoff!<div><br></div><div>For the format and what is logged I have a couple of comments.</div><div><br></div><div>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).</div>
<div><br></div><div>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.</div>
<div><br></div><div>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.</div>
<div><br></div><div>So my suggestion on the fields present is:</div><div>BereqEnd <Tstart> <Tend> <dTreq> <dThdr> <dTbody> <dTresp></div><div><br></div><div>Tstart: begin fetch processing (epoch)</div>
<div>Tend: end fetch processing (epoch)</div><div>dTreq: time to send the backend request</div><div>dThdr: time to receive the backend response headers</div><div>dTbody: time to receive the backend response body</div><div>
dTresp: time to receive the backend response (dThdr + dTbody)</div><div><br></div><div>Regards,</div><div>Martin</div><div><br></div><div><br></div></div><div class="gmail_extra"><br><br><div class="gmail_quote">On 10 October 2013 11:37, Geoff Simmons <span dir="ltr"><<a href="mailto:geoff@uplex.de" target="_blank">geoff@uplex.de</a>></span> wrote:<br>
<blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex">Hello all,<br>
<br>
This patch adds the BereqEnd tag, always the last tag emitted for a<br>
bereq transaction before the End marker.<br>
<br>
The format is:<br>
<br>
BereqEnd <Tstart> <Tend> <Thdr> <Tbody><br>
<br>
Tstart: begin fetch processing (epoch)<br>
Tend: end fetch processing (epoch)<br>
Thdr: time to receive response header<br>
Tbody: time to receive response body<br>
<br>
Thdr is approximately the delta from just after sending the backend<br>
request until just after receiving the header. Tbody is approximately<br>
the delta from just after receiving the response header until just after<br>
receiving the body.<br>
<br>
So for example:<br>
<br>
BereqEnd 1381335026.155810356 1381335026.268885612 0.112095833<br>
0.000851154<br>
<br>
The deltas are approximate because the low-level fetch operations do<br>
some buffering, so the timings don't correspond strictly to reading the<br>
header and body off the network (see the comments in<br>
cache_http1_proto.c), but I think will for the most part reflect backend<br>
latencies well enough.<br>
<br>
The rationale is that I think backend timings will be useful for:<br>
<br>
- measuring backend performance, and in particular finding out which<br>
backends are slow<br>
<br>
- finding out how much time in a fetch is due to work done strictly in<br>
varnishd, and how much is due to latencies in systems beyond Varnish's<br>
control<br>
<br>
There is a bit of varnishd overhead in the Thdr and Tbody timings, but<br>
they are dominated by backend latencies. That does mean, however, that<br>
Tbody is always > 0, even if there is no response body.<br>
<br>
Probably most people won't be very interested in the difference between<br>
Thdr and Tbody (just Thdr+Tbody). We have to take a measurement after<br>
the header arrives anyway, since there might not be a body, so I thought<br>
we may as well log the delta. But maybe we just want the one value here,<br>
just Thdr+Tbody. Tell me what you think.<br>
<br>
<br>
Best,<br>
Geoff<br>
<span class="HOEnZb"><font color="#888888">--<br>
** * * UPLEX - Nils Goroll Systemoptimierung<br>
<br>
Scheffelstraße 32<br>
22301 Hamburg<br>
<br>
Tel <a href="tel:%2B49%2040%202880%205731" value="+494028805731">+49 40 2880 5731</a><br>
Mob <a href="tel:%2B49%20176%20636%2090917" value="+4917663690917">+49 176 636 90917</a><br>
Fax <a href="tel:%2B49%2040%2042949753" value="+494042949753">+49 40 42949753</a><br>
<br>
<a href="http://uplex.de" target="_blank">http://uplex.de</a><br>
</font></span><br>_______________________________________________<br>
varnish-dev mailing list<br>
<a href="mailto:varnish-dev@varnish-cache.org">varnish-dev@varnish-cache.org</a><br>
<a href="https://www.varnish-cache.org/lists/mailman/listinfo/varnish-dev" target="_blank">https://www.varnish-cache.org/lists/mailman/listinfo/varnish-dev</a><br></blockquote></div><br><br clear="all"><div><br></div>-- <br>
<div><table border="0" cellpadding="0" cellspacing="0" style="font-size:12px;line-height:1.5em;font-family:'Helvetica Neue',Arial,sans-serif;color:rgb(102,102,102);width:550px;border-top-width:1px;border-top-style:solid;border-top-color:rgb(238,238,238);border-bottom-width:1px;border-bottom-style:solid;border-bottom-color:rgb(238,238,238);margin-top:20px;padding-top:5px;padding-bottom:5px">
<tbody><tr><td width="100"><a href="http://varnish-software.com" target="_blank"><img src="http://www.varnish-software.com/static/media/logo-email.png"></a><span></span><span></span></td><td><strong style="font-size:14px;color:rgb(34,34,34)">Martin Blix Grydeland</strong><br>
Senior Developer | Varnish Software AS<br>Cell: +47 21 98 92 60<br><span style="font-weight:bold">We Make Websites Fly!</span></td></tr></tbody></table></div>
</div>