Varnishlog tag explanation
The intention of this page is to explain what the different tags varnishlog outputs mean.
Format
830 ReqEnd c 877345549 1233949945.075706005 1233949945.075754881 0.017112017 0.000022888 0.000025988
- 830 is identifies the transaction, it will be assigned to only one transaction between a ReqStart? and ReqEnd? tag
- ReqEnd? is the tag, which tells you what kind of log line this is.
- c means client. b is backend. - is none or unknown
- The rest of the line is the contents of the log line.
ReqEnd
Typically, this looks like
830 ReqEnd c 877345549 1233949945.075706005 1233949945.075754881 0.017112017 0.000022888 0.000025988
The first number (877345549) is the XID, which you'll find in the X-Varnish header sent to the client.
The second number (1233949945.075706005) is the time when we start processing a request. It is decimal seconds since epoch.
The third number (1233949945.075754881) is the time when the request is completed. It is decimal seconds since epoch.
The fourth number (0.017112017) is the time elapsed between the start of the request processing and it actually being accept(2)-ed. Keep in mind that sessions are only accept()ed once, so this is time from the initial request was accepted until the current request begun processing (in other words: other requests from the same client/session could have been processed in the meanwhile).
The fifth number (0.000022888) is the time elapsed from the start of the request processing until we start delivering the object to the client.
The sixth and last number (0.000025988) is the time from we start delivering the object until the request completes.
