ReqEnd (Varnish 4 timing information revisited)

[Martin Blix Grydeland]

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!
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://www.varnish-cache.org/lists/pipermail/varnish-dev/attachments/20140314/e237672a/attachment.html>