varnish-dev Digest, Vol 96, Issue 14
Phil Stanhope
stanhope at gmail.com
Mon Mar 24 12:45:09 CET 2014
Having been doing a tremendous amount of timestamp related work recently
(outside of Varnish), I really like how Martin has done this.
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.
Alternatively, I could argue that all fixed with fields should be
sequential -- and the variable width label be the last field.
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.
-phil
On Mon, Mar 24, 2014 at 6:33 AM, <varnish-dev-request at varnish-cache.org>wrote:
> Send varnish-dev mailing list submissions to
> varnish-dev at varnish-cache.org
>
> To subscribe or unsubscribe via the World Wide Web, visit
> https://www.varnish-cache.org/lists/mailman/listinfo/varnish-dev
> or, via email, send a message with subject or body 'help' to
> varnish-dev-request at varnish-cache.org
>
> You can reach the person managing the list at
> varnish-dev-owner at varnish-cache.org
>
> When replying, please edit your Subject line so it is more specific
> than "Re: Contents of varnish-dev digest..."
>
>
> Today's Topics:
>
> 1. Re: ReqEnd (Varnish 4 timing information revisited)
> (Martin Blix Grydeland)
>
>
> ----------------------------------------------------------------------
>
> Message: 1
> Date: Mon, 24 Mar 2014 11:32:56 +0100
> From: Martin Blix Grydeland <martin at varnish-software.com>
> To: Varnish Development <varnish-dev at varnish-cache.org>
> Subject: Re: ReqEnd (Varnish 4 timing information revisited)
> Message-ID:
> <
> CANTn4cpyxEzzfU9bvXgD-U587zB7PSXbyo6EPq0mZPQjLpf4Eg at mail.gmail.com>
> Content-Type: text/plain; charset="iso-8859-1"
>
> After the discussions of the VDD, I have a revised suggestion (patch
> attached) for how to do timing information in Varnish.
>
> 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.
>
> 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.
>
> 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.
>
> Attached is a patch to implement this for the request side of things. The
> backend fetch side has not been done yet.
>
> 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.
>
> The documentation for the Timestamp log record (also showing the events
> being logged):
>
> Timestamp - Timing information
>
> Contains timing information for the Varnish worker threads.
>
> Time stamps are issued by Varnish on certain events, and show
> the absolute time of the event, the time spent since the start
> of the work unit, and the time spent since the last timestamp
> was logged.
>
> The format is:
>
> %s: %f %f %f
> | | | |
> | | | +- Time since last timestamp
> | | +---- Time since start of work unit
> | +------- Absolute time of event
> +----------- Event label
>
> Timestamps are logged automatically by Varnish, or through custom
> std.timestamp() calls from VCL. The following timestamps are
> automatically logged:
>
> start - The start of a worker task, e.g. request processing or
> backend fetch.
>
> reqheaders - Finished reading the client headers.
>
> reqbody - Finished reading the request body.
>
> waitinglist - Came off waitinglist.
>
> fetch - Fetch processing finished.
>
> process - Processing finished, ready to deliver.
>
> deliver - Delivery finished.
>
> restart - Performing request restart.
>
> pipe - Opened pipe to backend.
>
> pipesess - Pipe session finished.
>
>
>
> On 14 March 2014 15:35, Martin Blix Grydeland
> <martin at varnish-software.com>wrote:
>
> > Hi,
> >
> > 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
> > https://www.varnish-cache.org/trac/wiki/VDD13Q4).
> >
> > 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.
> >
> > 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.
> >
> > SLTM(ReqProc, 0, "Request processing timing",
> > "Contains timing information from the processing of the request.\n\n"
> > "The format is::\n\n"
> > "\t%f %f %f %f %f\n"
> > "\t| | | | |\n"
> > "\t| | | | +- Time spent processing and fetching\n"
> > "\t| | | +---- Time spent reading the request body\n"
> > "\t| | +------- Time spent on waiting lists\n"
> > "\t| +---------- Total time spent processing the request\n"
> > "\t+------------- Timestamp (since epoch) when vcl_recv was called\n"
> > "\n"
> > )
> >
> > 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.
> >
> > SLTM(ReqEnd, 0, "Client request end timing information",
> > "Marks the end of a client request. Contains timing information"
> > " from the complete handling of the request.\n\n"
> > "The format is::\n\n"
> > "\t%f %f %f %f %f\n"
> > "\t| | | | |\n"
> > "\t| | | | +- Time to transmit response (plus ESI processing)\n"
> > "\t| | | +---- Time to process request (sum of ReqProc)\n"
> > "\t| | +------- Total time to finish request handling\n"
> > "\t| +---------- Timestamp (since epoch) when the request ended\n"
> > "\t+------------- Timestamp (since epoch) when the request started\n"
> > "\n"
> > )
> >
> > Comments much appreciated.
> >
> > Martin
> >
> > --
> > <http://varnish-software.com>*Martin Blix Grydeland*
> > Senior Developer | Varnish Software AS
> > Cell: +47 21 98 92 60
> > We Make Websites Fly!
> >
>
>
>
> --
> <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/20140324/077887ef/attachment.html
> >
> -------------- next part --------------
> A non-text attachment was scrubbed...
> Name: 0001-Introduce-SLT_Timestamp-mechanism-for-request-handli.patch
> Type: text/x-patch
> Size: 16627 bytes
> Desc: not available
> URL: <
> https://www.varnish-cache.org/lists/pipermail/varnish-dev/attachments/20140324/077887ef/attachment.bin
> >
>
> ------------------------------
>
> _______________________________________________
> varnish-dev mailing list
> varnish-dev at varnish-cache.org
> https://www.varnish-cache.org/lists/mailman/listinfo/varnish-dev
>
> End of varnish-dev Digest, Vol 96, Issue 14
> *******************************************
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://www.varnish-cache.org/lists/pipermail/varnish-dev/attachments/20140324/9bf2886a/attachment.html>
More information about the varnish-dev
mailing list