=== VSL

Varnish Shared Memory Logging

:Manual section: 7

OVERVIEW

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.

VSL tags


.. include:: ../include/vsl-tags.rst

TIMESTAMPS
==========

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

Start The start of request processing (first byte received or restart).

Req Complete client request received.

ReqBody Client request body processed (discarded, cached or passed to the backend).

Waitinglist Came off waitinglist.

Fetch Fetch processing finished (completely fetched or ready for streaming).

Process Processing finished, ready to deliver the client response.

Resp Delivery of response to the client finished.

Restart Client request is being restarted.

Reset The client closed its connection, reset its stream or caused a stream error that forced Varnish to reset the stream. Request processing is interrupted and considered failed, with a 408 "Request Timeout" status code.

Pipe handling timestamps


The following timestamps are client timestamps specific to pipe transactions:

Pipe
	Opened a pipe to the backend and forwarded the request.

PipeSess
	The pipe session has finished.

The following timestamps change meaning in a pipe transaction:

Process
	Processing finished, ready to begin the pipe delivery.

Backend fetch timestamps

Start Start of the backend fetch processing.

Fetch Came off vcl_backend_fetch ready to send the backend request.

Connected Successfully established a backend connection, or selected a recycled connection from the pool.

Bereq Backend request sent.

Beresp Backend response headers received.

Process Processing finished, ready to fetch the response body.

BerespBody Backend response body received.

Retry Backend request is being retried.

Error Backend request failed to vcl_backend_error.

NOTICE MESSAGES

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.


HISTORY
=======

This document was initially written by Poul-Henning Kamp, and later updated by
Martin Blix Grydeland.


SEE ALSO
========

* :ref:`varnishhist(1)`
* :ref:`varnishlog(1)`
* :ref:`varnishncsa(1)`
* :ref:`varnishtop(1)`

COPYRIGHT
=========

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