ReqEnd (Varnish 4 timing information revisited)

[Martin Blix Grydeland]

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-0001.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-0001.bin>