This document describes the format and content of all the Varnish shared memory logging tags. These tags are used by the varnishlog(1), varnishtop(1), etc. logging tools supplied with Varnish.
Timestamps are inserted in the log on completing certain events during the worker thread's task handling. The timestamps has a label showing which event was completed. The reported fields show the absolute time of the event, the time spent since the start of the task and the time spent since the last timestamp was logged.
The timestamps logged automatically by Varnish are inserted after completing events that are expected to have delays (e.g. network IO or spending time on a waitinglist). Timestamps can also be inserted from VCL using the std.timestamp() function. If one is doing time consuming tasks in the VCL configuration, it's a good idea to log a timestamp after completing that task. This keeps the timing information in subsequent timestamps from including the time spent on the VCL event.
Request handling timestamps
The start of request processing (first byte received or restart).
Complete client request received.
Client request body processed (discarded, cached or passed to the backend).
Came off waitinglist.
Fetch processing finished (completely fetched or ready for streaming).
Processing finished, ready to deliver the client response.
Delivery of response to the client finished.
Client request is being restarted.
Pipe handling timestamps
Opened a pipe to the backend and forwarded the request.
The pipe session has finished.
Backend fetch timestamps
Start of the backend fetch processing.
Came off vcl_backend_fetch ready to send the backend request.
Successfully established a backend connection, or selected a recycled connection from the pool.
Backend request sent.
Backend response headers received.
Processing finished, ready to fetch the response body.
Backend response body received.
Backend request is being retried.
Backend request failed to vcl_backend_error.
Notice messages contain informational messages about the handling of a request. These can be exceptional circumstances encountered that causes deviation from the normal handling. The messages are prefixed with vsl: for core Varnish generated messages, and VMOD authors are encouraged to use vmod_<name>: for their own notice messages. This matches the name of the manual page where detailed descriptions of notice messages are expected.
The core messages are described below.
Conditional fetch wait for streaming object
The backend answered 304 Not Modified on a conditional fetch using an object that has not yet been fully fetched as the stale template object. This can only happen when the TTL of the object is less than the time it takes to fetch it. The fetch is halted until the stale object is fully fetched, upon which the new object is created as normal. While waiting, any grace time on the stale object will be in effect.
High number of variants
Objects are primarily looked up from an index using the hash key computed from the hash_data() VCL function. When variants are involved, that is to say when a backend response was stored with a Vary header, a secondary lookup is performed but it is not indexed. As the number of variants for a given key increases, this can slow cache lookups down, and since this happens under a lock, this can greatly increase lock contention, even more so for frequently requested objects. Variants should therefore be used sparingly on cacheable responses, but since they can originate from either VCL or origin servers, this notice should help identify problematic resources.
This document was initially written by Poul-Henning Kamp, and later updated by Martin Blix Grydeland.
This document is licensed under the same licence as Varnish itself. See LICENCE for details.
- Copyright (c) 2006 Verdens Gang AS
- Copyright (c) 2006-2015 Varnish Software AS
varnishd(1), varnishhist(1), varnishlog(1), varnishncsa(1), vmod_blob(3), vmod_proxy(3), vmod_std(3).