<div dir="ltr">Hi,<div><br></div><div>I'm working on a patch to improve the timing information in the VSL records. Basis is the discussions of last VDD (which is summarized here <a href="https://www.varnish-cache.org/trac/wiki/VDD13Q4">https://www.varnish-cache.org/trac/wiki/VDD13Q4</a>).</div>
<div><br></div><div>When doing this, I found that the ideas from there didn't sufficiently take into account the complexity of restarts in VCL. A single request can cause any number of objects to be fetched into the cache, and each of these will have interesting timing information. From experience I know that timing can be a very valuable debugging tool, and having good timing should be a goal.</div>
<div><br></div><div>So instead of the single ReqEnd for all timing data, I believe that it should be split into two records. Timing for anything up until the reply is being sent will be in a new record tentatively named ReqProc (request processing). The fields will include time spent on waiting lists, time spent fetching the request body and time spent fetching objects. The ReqProc record will be logged also on restarts, so the log will show the intermediate timing of the processing happened until that time.</div>
<div><br></div><div><div><font face="courier new, monospace">SLTM(ReqProc, 0, "Request processing timing",</font></div><div><font face="courier new, monospace"><span class="" style="white-space:pre"> </span>"Contains timing information from the processing of the request.\n\n"</font></div>
<div><font face="courier new, monospace"><span class="" style="white-space:pre"> </span>"The format is::\n\n"</font></div><div><font face="courier new, monospace"><span class="" style="white-space:pre"> </span>"\t%f %f %f %f %f\n"</font></div>
<div><font face="courier new, monospace"><span class="" style="white-space:pre"> </span>"\t| | | | |\n"</font></div><div><font face="courier new, monospace"><span class="" style="white-space:pre"> </span>"\t| | | | +- Time spent processing and fetching\n"</font></div>
<div><font face="courier new, monospace"><span class="" style="white-space:pre"> </span>"\t| | | +---- Time spent reading the request body\n"</font></div><div><font face="courier new, monospace"><span class="" style="white-space:pre"> </span>"\t| | +------- Time spent on waiting lists\n"</font></div>
<div><font face="courier new, monospace"><span class="" style="white-space:pre"> </span>"\t| +---------- Total time spent processing the request\n"</font></div><div><font face="courier new, monospace"><span class="" style="white-space:pre"> </span>"\t+------------- Timestamp (since epoch) when vcl_recv was called\n"</font></div>
<div><font face="courier new, monospace"><span class="" style="white-space:pre"> </span>"\n"</font></div><div><font face="courier new, monospace">)</font></div></div><div><br></div><div>The ReqEnd will be output only once per request processed, and will only be output from the log transaction that finishes the request handling (restarts creates a new log transaction). It will contain the time_to_first_byte (which is equal to the sum of the previous ReqProc records), as well as the transmit time (which would include any ESI processing or fetch time when streaming). The details of ESI processing timing would be found in the ReqProc and ReqEnd log records of the ESI subrequest transactions. Details of background fetch timing would be in the BereqEnd record.</div>
<div><br></div><div><div><font face="courier new, monospace">SLTM(ReqEnd, 0, "Client request end timing information",</font></div><div><font face="courier new, monospace"><span class="" style="white-space:pre"> </span>"Marks the end of a client request. Contains timing information"</font></div>
<div><font face="courier new, monospace"><span class="" style="white-space:pre"> </span>" from the complete handling of the request.\n\n"</font></div><div><font face="courier new, monospace"><span class="" style="white-space:pre"> </span>"The format is::\n\n"</font></div>
<div><font face="courier new, monospace"><span class="" style="white-space:pre"> </span>"\t%f %f %f %f %f\n"</font></div><div><font face="courier new, monospace"><span class="" style="white-space:pre"> </span>"\t| | | | |\n"</font></div>
<div><font face="courier new, monospace"><span class="" style="white-space:pre"> </span>"\t| | | | +- Time to transmit response (plus ESI processing)\n"</font></div><div><font face="courier new, monospace"><span class="" style="white-space:pre"> </span>"\t| | | +---- Time to process request (sum of ReqProc)\n"</font></div>
<div><font face="courier new, monospace"><span class="" style="white-space:pre"> </span>"\t| | +------- Total time to finish request handling\n"</font></div><div><font face="courier new, monospace"><span class="" style="white-space:pre"> </span>"\t| +---------- Timestamp (since epoch) when the request ended\n"</font></div>
<div><font face="courier new, monospace"><span class="" style="white-space:pre"> </span>"\t+------------- Timestamp (since epoch) when the request started\n"</font></div><div><font face="courier new, monospace"><span class="" style="white-space:pre"> </span>"\n"</font></div>
<div><font face="courier new, monospace">)</font></div></div><div><br></div><div>Comments much appreciated.</div><div><br></div><div>Martin</div><div><br></div><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></div>