<div dir="ltr">Having been doing a tremendous amount of timestamp related work recently (outside of Varnish), I really like how Martin has done this.<div><br></div><div>My feedback is that i think that the timestamp should always be first and the label second. The reason for me is that you have a natural sort ordering (particularly if the timestamp has 6 digits of precision). When scanning a streaming version of timestamps being emitted your eye can see the labels. But if things start shifting left/right because the labels are not of uniform length it gets very hard to absorb.</div>
<div><br></div><div>Alternatively, I could argue that all fixed with fields should be sequential -- and the variable width label be the last field. </div><div><br></div><div>The other thing that I've done is when serializing this type of information for debugging purposes to actually calculate and include the running delta -- even though it's obvious that it can calculated after the fact. Typically it will be .000003 -- very small number of micro seconds. It's when that delta gets big that it jumps out at you and don't have to do any math in your head -- instead focus on why that particular operation took as long as it did.</div>
<div><br></div><div>-phil</div><div><br></div></div><div class="gmail_extra"><br><br><div class="gmail_quote">On Mon, Mar 24, 2014 at 6:33 AM, <span dir="ltr"><<a href="mailto:varnish-dev-request@varnish-cache.org" target="_blank">varnish-dev-request@varnish-cache.org</a>></span> wrote:<br>
<blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex">Send varnish-dev mailing list submissions to<br>
<a href="mailto:varnish-dev@varnish-cache.org">varnish-dev@varnish-cache.org</a><br>
<br>
To subscribe or unsubscribe via the World Wide Web, visit<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>
or, via email, send a message with subject or body 'help' to<br>
<a href="mailto:varnish-dev-request@varnish-cache.org">varnish-dev-request@varnish-cache.org</a><br>
<br>
You can reach the person managing the list at<br>
<a href="mailto:varnish-dev-owner@varnish-cache.org">varnish-dev-owner@varnish-cache.org</a><br>
<br>
When replying, please edit your Subject line so it is more specific<br>
than "Re: Contents of varnish-dev digest..."<br>
<br>
<br>
Today's Topics:<br>
<br>
1. Re: ReqEnd (Varnish 4 timing information revisited)<br>
(Martin Blix Grydeland)<br>
<br>
<br>
----------------------------------------------------------------------<br>
<br>
Message: 1<br>
Date: Mon, 24 Mar 2014 11:32:56 +0100<br>
From: Martin Blix Grydeland <<a href="mailto:martin@varnish-software.com">martin@varnish-software.com</a>><br>
To: Varnish Development <<a href="mailto:varnish-dev@varnish-cache.org">varnish-dev@varnish-cache.org</a>><br>
Subject: Re: ReqEnd (Varnish 4 timing information revisited)<br>
Message-ID:<br>
<<a href="mailto:CANTn4cpyxEzzfU9bvXgD-U587zB7PSXbyo6EPq0mZPQjLpf4Eg@mail.gmail.com">CANTn4cpyxEzzfU9bvXgD-U587zB7PSXbyo6EPq0mZPQjLpf4Eg@mail.gmail.com</a>><br>
Content-Type: text/plain; charset="iso-8859-1"<br>
<br>
After the discussions of the VDD, I have a revised suggestion (patch<br>
attached) for how to do timing information in Varnish.<br>
<br>
The suggestion was given during the VDD that the timing in Varnish should<br>
be more general and extendable, instead of having fixed categories of<br>
timing. To achieve this, the timing will be based upon timestamps being<br>
logged at the time specific events finish. The timestamps logged all have<br>
the same information, showing an event label, the absolute time of the<br>
event itself, the time spent since the start of the work unit (e.g. request<br>
processing or backend fetch), and the time since the last timestamp was<br>
logged.<br>
<br>
Having a limited set of fields that are present on all timestamps makes it<br>
easier to remember the format of it and understand the information without<br>
having to consult the documentation every time. There will also be less<br>
information present in each log entry, making it easier to spot the<br>
different fields.<br>
<br>
Timestamps can also be logged from VCL through a<br>
std.timestamp("event-label") call. So e.g. calling this after your curl<br>
vmod call, you will be able to show (thorugh the time since last timestamp<br>
field) how long time your curl HTTP call took to process.<br>
<br>
Attached is a patch to implement this for the request side of things. The<br>
backend fetch side has not been done yet.<br>
<br>
Note also that to improve the timing information, the start of time has<br>
been moved from after the client headers have been read to before the<br>
client headers have been read.<br>
<br>
The documentation for the Timestamp log record (also showing the events<br>
being logged):<br>
<br>
Timestamp - Timing information<br>
<br>
Contains timing information for the Varnish worker threads.<br>
<br>
Time stamps are issued by Varnish on certain events, and show<br>
the absolute time of the event, the time spent since the start<br>
of the work unit, and the time spent since the last timestamp<br>
was logged.<br>
<br>
The format is:<br>
<br>
%s: %f %f %f<br>
| | | |<br>
| | | +- Time since last timestamp<br>
| | +---- Time since start of work unit<br>
| +------- Absolute time of event<br>
+----------- Event label<br>
<br>
Timestamps are logged automatically by Varnish, or through custom<br>
std.timestamp() calls from VCL. The following timestamps are<br>
automatically logged:<br>
<br>
start - The start of a worker task, e.g. request processing or<br>
backend fetch.<br>
<br>
reqheaders - Finished reading the client headers.<br>
<br>
reqbody - Finished reading the request body.<br>
<br>
waitinglist - Came off waitinglist.<br>
<br>
fetch - Fetch processing finished.<br>
<br>
process - Processing finished, ready to deliver.<br>
<br>
deliver - Delivery finished.<br>
<br>
restart - Performing request restart.<br>
<br>
pipe - Opened pipe to backend.<br>
<br>
pipesess - Pipe session finished.<br>
<br>
<br>
<br>
On 14 March 2014 15:35, Martin Blix Grydeland<br>
<<a href="mailto:martin@varnish-software.com">martin@varnish-software.com</a>>wrote:<br>
<br>
> Hi,<br>
><br>
> I'm working on a patch to improve the timing information in the VSL<br>
> records. Basis is the discussions of last VDD (which is summarized here<br>
> <a href="https://www.varnish-cache.org/trac/wiki/VDD13Q4" target="_blank">https://www.varnish-cache.org/trac/wiki/VDD13Q4</a>).<br>
><br>
> When doing this, I found that the ideas from there didn't sufficiently<br>
> take into account the complexity of restarts in VCL. A single request can<br>
> cause any number of objects to be fetched into the cache, and each of these<br>
> will have interesting timing information. From experience I know that<br>
> timing can be a very valuable debugging tool, and having good timing should<br>
> be a goal.<br>
><br>
> So instead of the single ReqEnd for all timing data, I believe that it<br>
> should be split into two records. Timing for anything up until the reply is<br>
> being sent will be in a new record tentatively named ReqProc (request<br>
> processing). The fields will include time spent on waiting lists, time<br>
> spent fetching the request body and time spent fetching objects. The<br>
> ReqProc record will be logged also on restarts, so the log will show the<br>
> intermediate timing of the processing happened until that time.<br>
><br>
> SLTM(ReqProc, 0, "Request processing timing",<br>
> "Contains timing information from the processing of the request.\n\n"<br>
> "The format is::\n\n"<br>
> "\t%f %f %f %f %f\n"<br>
> "\t| | | | |\n"<br>
> "\t| | | | +- Time spent processing and fetching\n"<br>
> "\t| | | +---- Time spent reading the request body\n"<br>
> "\t| | +------- Time spent on waiting lists\n"<br>
> "\t| +---------- Total time spent processing the request\n"<br>
> "\t+------------- Timestamp (since epoch) when vcl_recv was called\n"<br>
> "\n"<br>
> )<br>
><br>
> The ReqEnd will be output only once per request processed, and will only<br>
> be output from the log transaction that finishes the request handling<br>
> (restarts creates a new log transaction). It will contain the<br>
> time_to_first_byte (which is equal to the sum of the previous ReqProc<br>
> records), as well as the transmit time (which would include any ESI<br>
> processing or fetch time when streaming). The details of ESI processing<br>
> timing would be found in the ReqProc and ReqEnd log records of the ESI<br>
> subrequest transactions. Details of background fetch timing would be in the<br>
> BereqEnd record.<br>
><br>
> SLTM(ReqEnd, 0, "Client request end timing information",<br>
> "Marks the end of a client request. Contains timing information"<br>
> " from the complete handling of the request.\n\n"<br>
> "The format is::\n\n"<br>
> "\t%f %f %f %f %f\n"<br>
> "\t| | | | |\n"<br>
> "\t| | | | +- Time to transmit response (plus ESI processing)\n"<br>
> "\t| | | +---- Time to process request (sum of ReqProc)\n"<br>
> "\t| | +------- Total time to finish request handling\n"<br>
> "\t| +---------- Timestamp (since epoch) when the request ended\n"<br>
> "\t+------------- Timestamp (since epoch) when the request started\n"<br>
> "\n"<br>
> )<br>
><br>
> Comments much appreciated.<br>
><br>
> Martin<br>
><br>
> --<br>
> <<a href="http://varnish-software.com" target="_blank">http://varnish-software.com</a>>*Martin Blix Grydeland*<br>
> Senior Developer | Varnish Software AS<br>
> Cell: <a href="tel:%2B47%2021%2098%2092%2060" value="+4721989260">+47 21 98 92 60</a><br>
> We Make Websites Fly!<br>
><br>
<br>
<br>
<br>
--<br>
<<a href="http://varnish-software.com" target="_blank">http://varnish-software.com</a>>*Martin Blix Grydeland*<br>
Senior Developer | Varnish Software AS<br>
Cell: <a href="tel:%2B47%2021%2098%2092%2060" value="+4721989260">+47 21 98 92 60</a><br>
We Make Websites Fly!<br>
-------------- next part --------------<br>
An HTML attachment was scrubbed...<br>
URL: <<a href="https://www.varnish-cache.org/lists/pipermail/varnish-dev/attachments/20140324/077887ef/attachment.html" target="_blank">https://www.varnish-cache.org/lists/pipermail/varnish-dev/attachments/20140324/077887ef/attachment.html</a>><br>
-------------- next part --------------<br>
A non-text attachment was scrubbed...<br>
Name: 0001-Introduce-SLT_Timestamp-mechanism-for-request-handli.patch<br>
Type: text/x-patch<br>
Size: 16627 bytes<br>
Desc: not available<br>
URL: <<a href="https://www.varnish-cache.org/lists/pipermail/varnish-dev/attachments/20140324/077887ef/attachment.bin" target="_blank">https://www.varnish-cache.org/lists/pipermail/varnish-dev/attachments/20140324/077887ef/attachment.bin</a>><br>
<br>
------------------------------<br>
<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>
<br>
End of varnish-dev Digest, Vol 96, Issue 14<br>
*******************************************<br>
</blockquote></div><br></div>