varnishncsa bad Time taken to serve the request

[Bernard Gardner]

Hi Cesar,

I'm not sure if I've properly understood your question - you mention using %D as a format string for logging time taken to serve the request in varnishncsa, but I don't see that as one of the documented strings in the varnishncsa manual page. I do see %{Varnish:time_firstbyte}x - which is what I'm guessing you're looking at and which will only include the time taken for your backend to process the request and start to send the response, the network latency for varnish to receive that first packet and then start to send the response to the client (assuming a miss).

%D is a format string for the apache logs, and there it's showing you the time to the last byte, but that time doesn't include the network path to the client if varnish is serving the request.

Either of those would explain what you're seeing (and would likely be showing very similar values for the time in question if your backend and varnish instance are close on the network, or running on the same host).

I think that the time that you want (time to last byte from varnish) could be calculated from the fields in the ReqEnd tag in the varnish log - I don't think you'll be able to access it via varnishncsa directly, you may need to use some other logging client, or modify varnishncsa to do exactly what you want.

The fields in the ReqEnd tag are described here - https://www.varnish-cache.org/trac/wiki/Varnishlog

Hope that helps,
Bernard.

-------------- next part --------------
A non-text attachment was scrubbed...
Name: smime.p7s
Type: application/pkcs7-signature
Size: 4139 bytes
Desc: not available
URL: <https://www.varnish-cache.org/lists/pipermail/varnish-misc/attachments/20140811/95c3ab56/attachment.bin>