<div dir="ltr">After the discussions of the VDD, I have a revised suggestion (patch attached) for how to do timing information in Varnish.<div><br></div><div>The suggestion was given during the VDD that the timing in Varnish should be more general and extendable, instead of having fixed categories of timing. To achieve this, the timing will be based upon timestamps being logged at the time specific events finish. The timestamps logged all have the same information, showing an event label, the absolute time of the event itself, the time spent since the start of the work unit (e.g. request processing or backend fetch), and the time since the last timestamp was logged.</div>
<div><br></div><div>Having a limited set of fields that are present on all timestamps makes it easier to remember the format of it and understand the information without having to consult the documentation every time. There will also be less information present in each log entry, making it easier to spot the different fields.</div>
<div><br></div><div>Timestamps can also be logged from VCL through a std.timestamp("event-label") call. So e.g. calling this after your curl vmod call, you will be able to show (thorugh the time since last timestamp field) how long time your curl HTTP call took to process.</div>
<div><br></div><div>Attached is a patch to implement this for the request side of things. The backend fetch side has not been done yet.</div><div><br></div><div>Note also that to improve the timing information, the start of time has been moved from after the client headers have been read to before the client headers have been read.</div>
<div><br></div><div>The documentation for the Timestamp log record (also showing the events being logged):</div><div><br></div><div><div><font face="courier new, monospace">Timestamp - Timing information</font></div><div>
<font face="courier new, monospace"><br></font></div><div><font face="courier new, monospace">Contains timing information for the Varnish worker threads.</font></div><div><font face="courier new, monospace"><br></font></div>
<div><font face="courier new, monospace">Time stamps are issued by Varnish on certain events, and show</font></div><div><font face="courier new, monospace">the absolute time of the event, the time spent since the start</font></div>
<div><font face="courier new, monospace">of the work unit, and the time spent since the last timestamp</font></div><div><font face="courier new, monospace">was logged.</font></div><div><font face="courier new, monospace"><br>
</font></div><div><font face="courier new, monospace">The format is:</font></div><div><font face="courier new, monospace"><br></font></div><div><font face="courier new, monospace">%s: %f %f %f</font></div><div><font face="courier new, monospace">| | | |</font></div>
<div><font face="courier new, monospace">| | | +- Time since last timestamp</font></div><div><font face="courier new, monospace">| | +---- Time since start of work unit</font></div><div><font face="courier new, monospace">| +------- Absolute time of event</font></div>
<div><font face="courier new, monospace">+----------- Event label</font></div><div><font face="courier new, monospace"><br></font></div><div><font face="courier new, monospace">Timestamps are logged automatically by Varnish, or through custom</font></div>
<div><font face="courier new, monospace">std.timestamp() calls from VCL. The following timestamps are</font></div><div><font face="courier new, monospace">automatically logged:</font></div><div><font face="courier new, monospace"><br>
</font></div><div><font face="courier new, monospace">start - The start of a worker task, e.g. request processing or</font></div><div><font face="courier new, monospace">backend fetch.</font></div><div><font face="courier new, monospace"><br>
</font></div><div><font face="courier new, monospace">reqheaders - Finished reading the client headers.</font></div><div><font face="courier new, monospace"><br></font></div><div><font face="courier new, monospace">reqbody - Finished reading the request body.</font></div>
<div><font face="courier new, monospace"><br></font></div><div><font face="courier new, monospace">waitinglist - Came off waitinglist.</font></div><div><font face="courier new, monospace"><br></font></div><div><font face="courier new, monospace">fetch - Fetch processing finished.</font></div>
<div><font face="courier new, monospace"><br></font></div><div><font face="courier new, monospace">process - Processing finished, ready to deliver.</font></div><div><font face="courier new, monospace"><br></font></div><div>
<font face="courier new, monospace">deliver - Delivery finished.</font></div><div><font face="courier new, monospace"><br></font></div><div><font face="courier new, monospace">restart - Performing request restart.</font></div>
<div><font face="courier new, monospace"><br></font></div><div><font face="courier new, monospace">pipe - Opened pipe to backend.</font></div><div><font face="courier new, monospace"><br></font></div><div><font face="courier new, monospace">pipesess - Pipe session finished.</font></div>
</div><div><br></div></div><div class="gmail_extra"><br><br><div class="gmail_quote">On 14 March 2014 15:35, Martin Blix Grydeland <span dir="ltr"><<a href="mailto:martin@varnish-software.com" target="_blank">martin@varnish-software.com</a>></span> wrote:<br>
<blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><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" target="_blank">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 style="white-space:pre-wrap"> </span>"Contains timing information from the processing of the request.\n\n"</font></div>
<div><font face="courier new, monospace"><span style="white-space:pre-wrap"> </span>"The format is::\n\n"</font></div><div><font face="courier new, monospace"><span style="white-space:pre-wrap"> </span>"\t%f %f %f %f %f\n"</font></div>
<div><font face="courier new, monospace"><span style="white-space:pre-wrap"> </span>"\t| | | | |\n"</font></div><div><font face="courier new, monospace"><span style="white-space:pre-wrap"> </span>"\t| | | | +- Time spent processing and fetching\n"</font></div>
<div><font face="courier new, monospace"><span style="white-space:pre-wrap"> </span>"\t| | | +---- Time spent reading the request body\n"</font></div><div><font face="courier new, monospace"><span style="white-space:pre-wrap"> </span>"\t| | +------- Time spent on waiting lists\n"</font></div>
<div><font face="courier new, monospace"><span style="white-space:pre-wrap"> </span>"\t| +---------- Total time spent processing the request\n"</font></div><div><font face="courier new, monospace"><span style="white-space:pre-wrap"> </span>"\t+------------- Timestamp (since epoch) when vcl_recv was called\n"</font></div>
<div><font face="courier new, monospace"><span style="white-space:pre-wrap"> </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 style="white-space:pre-wrap"> </span>"Marks the end of a client request. Contains timing information"</font></div>
<div><font face="courier new, monospace"><span style="white-space:pre-wrap"> </span>" from the complete handling of the request.\n\n"</font></div><div><font face="courier new, monospace"><span style="white-space:pre-wrap"> </span>"The format is::\n\n"</font></div>
<div><font face="courier new, monospace"><span style="white-space:pre-wrap"> </span>"\t%f %f %f %f %f\n"</font></div><div><font face="courier new, monospace"><span style="white-space:pre-wrap"> </span>"\t| | | | |\n"</font></div>
<div><font face="courier new, monospace"><span style="white-space:pre-wrap"> </span>"\t| | | | +- Time to transmit response (plus ESI processing)\n"</font></div><div><font face="courier new, monospace"><span style="white-space:pre-wrap"> </span>"\t| | | +---- Time to process request (sum of ReqProc)\n"</font></div>
<div><font face="courier new, monospace"><span style="white-space:pre-wrap"> </span>"\t| | +------- Total time to finish request handling\n"</font></div><div><font face="courier new, monospace"><span style="white-space:pre-wrap"> </span>"\t| +---------- Timestamp (since epoch) when the request ended\n"</font></div>
<div><font face="courier new, monospace"><span style="white-space:pre-wrap"> </span>"\t+------------- Timestamp (since epoch) when the request started\n"</font></div><div><font face="courier new, monospace"><span style="white-space:pre-wrap"> </span>"\n"</font></div>
<div><font face="courier new, monospace">)</font></div></div><div><br></div><div>Comments much appreciated.</div><span class="HOEnZb"><font color="#888888"><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: <a href="tel:%2B47%2021%2098%2092%2060" value="+4721989260" target="_blank">+47 21 98 92 60</a><br><span style="font-weight:bold">We Make Websites Fly!</span></td></tr></tbody></table>
</div>
</div></font></span></div>
</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>