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!
_______________________________________________ varnish-dev mailing list varnish-dev@varnish-cache.org https://www.varnish-cache.org/lists/mailman/listinfo/varnish-dev