$ guides / varnish / varnish-slow-response-latency ▌

Operations Guides

Varnish slow responses: hit latency, miss latency, and why varnishstat has no timing

Users report slow responses through Varnish. You open varnishstat and look for a latency counter. There isn’t one. Varnish’s counter subsystem maintains event counts and gauges: cache_hit, cache_miss, threads, backend_fail. None of them measure how long a request took.

This is architectural. Varnish writes per-request timing into the shared memory log (VSL) as Timestamp tags with per-phase resolution. The tools to read them are varnishlog, varnishncsa, and varnishhist. If you are diagnosing slow responses using varnishstat alone, you have no timing data.

The second trap: tracking aggregate P99 across all requests. Cache miss latency is dominated by backend response time, typically orders of magnitude slower than cache hit latency. A regression in the hit path, where Varnish itself is the bottleneck, is invisible when miss latency dominates the tail. Measure hit and miss distributions separately.

Why varnishstat has no timing

varnishstat reads from Varnish’s counter subsystem, a region of shared memory optimized for high-frequency integer updates without per-event overhead. Adding per-request timing would require either a histogram (memory proportional to bucket count) or a running average (lossy and misleading for latency, which has a long tail).

Instead, Varnish writes per-request timing into the VSL as Timestamp tags. This gives full-resolution per-request data, but it lives in a circular buffer that wraps if consumers do not read fast enough. You get exact per-request timing, but only if you capture it in real time.

The Timestamp tag

Every request transaction includes a series of Timestamp tags:

Timestamp <label>: <absolute_seconds> <seconds_since_start> <seconds_since_previous>

The three fields after the label:

Wall-clock time when this point was reached
Cumulative seconds since the Start timestamp (total elapsed for this request)
Seconds since the previous Timestamp tag in this transaction

For total request processing time, the second field of Timestamp:Resp is the authoritative value.

A cache hit produces these tags (no Fetch):

Timestamp Start: ...
Timestamp Req: ...
Timestamp Process: ...
Timestamp Resp: 1606399284.176648 0.000388 0.000255

A cache miss adds a Fetch timestamp for the backend round trip:

Timestamp Start: ...
Timestamp Req: ...
Timestamp Fetch: ...
Timestamp Process: ...
Timestamp Resp: 1606398588.818609 0.007421 0.000178

The hit completed in 388 microseconds. The miss took 7.4 milliseconds, with most of the time in the Fetch phase (backend response). Process and Resp deltas are nearly identical between hit and miss. Varnish’s own overhead is sub-millisecond; miss latency is dominated by backend response time.

flowchart LR
    subgraph hit["Cache hit - no Fetch tag"]
        A1["Start"] --> A2["Req"] --> A3["Process"] --> A4["Resp"]
    end
    subgraph miss["Cache miss - includes Fetch"]
        B1["Start"] --> B2["Req"] --> B3["Fetch"] --> B4["Process"] --> B5["Resp"]
    end
    A4 -->|"Resp field 2 = total time"| R1["Hit latency: expect sub-ms"]
    B5 -->|"Resp field 2 = total time"| R2["Miss latency: includes backend fetch"]

Where to get timing data

Tool	Format or tag	Use case
varnishlog	`Timestamp` tags per request	Single-request forensic analysis, per-phase breakdown
varnishncsa	`%D` (microseconds), `%{Varnish:time_firstbyte}x` (TTFB in seconds)	Bulk logging to disk for percentile analysis
varnishhist	Live terminal histogram: response time and fetch time distributions	Real-time assessment during incidents

varnishhist is useful during an incident. The default profile shows two histograms: total response time for all requests, and fetch time for backend responses (misses only). If response time shifts right but fetch time does not, the hit path is getting slower. If only the fetch distribution moves, the backend is the problem.

What “slow” means for each path

Cache hits should be sub-millisecond. Consistently exceeding 10ms on hits indicates system-level contention: CPU scheduling delays, thread pool queuing, ban list lookup overhead, or workspace pressure. The hit path does almost no I/O. If it is slow, something inside Varnish or the OS is contending.

Cache miss latency is bounded by backend response time plus Varnish overhead. The overhead component should add less than 5ms. If miss latency increases but backend TTFB (visible in the Fetch timestamp delta) is unchanged, Varnish’s processing or queuing overhead is the problem. If backend TTFB has increased, the problem is downstream.

Common causes

Cause	What it looks like	First thing to check
Backend slowness	Miss latency elevated, hit latency normal	varnishlog Timestamp:Fetch delta
Ban list growth	Hit latency creeping up, backend req rate stable	`varnishstat -1 -f MAIN.bans`
Thread pool contention	All requests slow, queue length > 0	`varnishstat -1 -f MAIN.thread_queue_len`
VCL processing overhead	Hit latency elevated on specific URL patterns	varnishlog Timestamp:Process delta per request
Workspace pressure	Intermittent slow hits plus 500 errors	`varnishstat -1 -f 'MAIN.ws_*_overflow'`

Quick checks

# Live latency histogram (row 1 = all requests, row 2 = backend fetches)
varnishhist

# Log request duration in microseconds with hit/miss tag
varnishncsa -F '%D %s %{Varnish:hitmiss}x %U' -q 'ReqMethod ne "PURGE"'

# Per-phase timing for recent successful requests
varnishlog -i Timestamp -g request -q 'RespStatus == 200' | head -40

# Backend fetch time from Varnish's perspective
varnishlog -g request -i Timestamp -q 'BerespStatus gt 0'

# Check ban list length and lurker health
varnishstat -1 -f 'MAIN.bans*'

# Check thread pool saturation
varnishstat -1 -f MAIN.threads -f MAIN.thread_queue_len -f MAIN.threads_limited

# Check workspace overflow
varnishstat -1 -f 'MAIN.ws_*_overflow' -f MAIN.client_resp_500

The varnishncsa command tags each line with “hit” or “miss” via %{Varnish:hitmiss}x, letting you pipe through awk or sort for separate latency distributions. This is the fastest way to build a hit-vs-miss latency split from production traffic.

How to diagnose it

Establish whether the problem is hit latency or miss latency. Run varnishhist. Two histograms appear: response time for all requests and fetch time for backend responses. If response time has shifted past 1ms but fetch time has not, the hit path is slow. If only fetch time has shifted, the backend is slow.
If miss latency is the problem, measure backend TTFB. Extract Fetch-phase timing:
```
varnishlog -g request -i Timestamp -q 'BerespStatus gt 0'
```
Compare the Fetch timestamp delta to your backend’s expected response time. If backend TTFB has increased, the problem is downstream of Varnish. See Varnish fetch_failed: backend connected but the fetch broke and Varnish backend connection reuse low: keepalive not working and slow TTFB for related patterns.
If hit latency is the problem, check the ban list. Every cache lookup tests the object against all outstanding bans. A large ban list makes each lookup O(n):
```
varnishstat -1 -f MAIN.bans -f MAIN.bans_completed -f MAIN.bans_lurker_contention
```
If MAIN.bans is high (hundreds or thousands) and growing while bans_completed lags, ban evaluation is adding milliseconds to every hit. See Varnish ban list growing: O(n) lookups and the lurker falling behind for the full diagnostic.
Check thread pool saturation. Even cache hits need a worker thread. If the pool is full and the queue is backing up, requests wait before processing starts. This inflates Timestamp:Resp without showing up in Timestamp:Process:
```
varnishstat -1 -f MAIN.threads -f MAIN.thread_queue_len -f MAIN.threads_limited
```
Check for VCL overhead. Complex regex in vcl_recv or vcl_hash, heavy header manipulation, or VMOD calls add processing time visible in the Process delta:
```
varnishlog -i Timestamp -g request | grep 'Timestamp: Process'
```
Check workspace pressure. If workspace is nearly exhausted, Varnish may produce 500 errors or spend extra cycles on memory management:
```
varnishstat -1 -f 'MAIN.ws_*_overflow' -f MAIN.client_resp_500 -f MAIN.losthdr
```

Metrics and signals to monitor

Signal	Why it matters	Warning sign
Hit latency (varnishncsa %D, filtered by hit)	Isolates Varnish’s own processing overhead from backend time	Consistent >10ms on hits that were sub-ms before
Miss latency (varnishncsa %D, filtered by miss)	Backend response time as seen by Varnish	P99 above 2x baseline
MAIN.bans	O(n) lookup overhead on every cache lookup	Growing trend, lurker not keeping up
MAIN.thread_queue_len	Requests waiting for worker threads	Any sustained nonzero value
MAIN.ws_*_overflow	Workspace exhaustion causing 500s or overhead	Any nonzero rate
Backend TTFB (varnishlog Timestamp:Fetch)	External dependency dominating miss latency	Increasing trend
varnishhist distribution shape	Real-time view of response vs fetch latency shift	Response column shifting right without fetch column

Fixes

Backend slowness (miss latency)

If miss latency is the problem, the backend is the root cause. Options:

Fix the backend. Profile the origin application. Varnish adds microseconds; backends add milliseconds.
Increase grace. Serve stale content while background fetches refresh objects, masking transient backend slowness. Without grace, any backend hiccup immediately produces 503s on all cache misses.
Increase thread_pool_max as a stopgap. If slow backends are holding threads and causing contention, a larger pool buys runway but does not fix the backend.

Ban list growth (hit latency)

Bans are being injected faster than the lurker processes them. Options, in order of preference:

Switch from req-based bans to obj-based bans. The ban lurker processes obj-based bans proactively. Req-based bans persist until every cached object is tested at lookup time, so every hit pays the full ban-list scan cost.
Use xkey VMOD or hash-based purging instead of regex bans. These invalidate by cache key without appending to the ban list.
Reduce ban_lurker_sleep to make the lurker more aggressive.
On Varnish 7.7+, tune ban_any_variant. This parameter (default 10000 in 7.7, changed to 0 in 8.0+) caps the number of possibly non-matching variants evaluated against the ban list during lookups. Setting it to 0 changes behavior to consider only matching objects, which reduces lookup overhead when many variants exist. See Varnish ban lurker not keeping up: contention and ban_lurker_sleep.

Thread pool contention (hit latency)

If all requests are slow because threads are queued:

Increase thread_pool_max via varnishadm param.set thread_pool_max N. Takes effect immediately. Calculate memory cost first: each thread consumes stack space (typically 64KB-512KB depending on OS and thread_pool_stack).
Check thread_pool_add_delay. If set too high, threads ramp up too slowly under load spikes and the queue backs up.
Investigate why threads are being held. Slow backends are the usual root cause. See Varnish backend is sick: health probes, all-backends-sick, and grace.

VCL overhead (hit latency)

If Process-phase timing is elevated on certain paths:

Compare Timestamp deltas across requests hitting different subroutines to isolate expensive VCL paths.
Simplify regex patterns in vcl_recv and vcl_hash. Regex evaluation is CPU-bound and runs on every request.
Audit VMOD calls for blocking operations (DNS lookups, external HTTP calls). These hold the worker thread for the entire call duration.

Workspace pressure (hit latency)

If workspace overflow counters are nonzero:

Increase workspace_client and workspace_backend. Costs more memory per connection. Calculate the cost: workspace size times max threads across all pools.
Identify oversized headers. Large Cookie headers are the most common cause.
Strip unnecessary request headers in vcl_recv before they consume workspace.

Prevention

Always run varnishncsa writing to persistent storage with %D and %{Varnish:hitmiss}x. Without this, you have no historical latency data when an incident occurs. The VSL is a circular buffer; unlogged data is gone.
Monitor hit and miss latency as separate distributions. Aggregate P99 hides hit-path regressions behind the miss tail.
Alert on MAIN.bans growth. The ban list is the most common cause of gradual hit latency degradation that goes unnoticed because hit rate is unchanged.
Monitor thread_queue_len at high frequency. It is a point-in-time gauge that oscillates rapidly. Sampling at 1-second intervals can miss sub-second spikes.
Track process RSS separately from configured storage size. The delta is transient storage plus overhead; unbounded growth leads to OOM with no warning from varnishstat.

How Netdata helps

Netdata’s Varnish collector surfaces the counter-level signals that correlate with latency regressions at per-second resolution:

Thread pool saturation (threads, thread_queue_len, threads_limited, threads_failed) is collected every second, making the exact moment contention begins visible before it cascades into dropped sessions.
Ban list counters (bans, bans_completed, bans_lurker_contention) are tracked as gauges and rates, so gradual accumulation is visible over hours or days.
Backend health and connection metrics (backend_fail, backend_unhealthy, backend_busy, backend_reuse) correlate with miss latency changes, helping distinguish a backend regression from a Varnish-side problem.
Storage and eviction signals (n_lru_nuked, g_bytes, g_space) reveal when cache pressure drives increased miss rates.
Workspace overflow counters (ws_*_overflow, losthdr) surface the failure mode where oversized headers cause intermittent 500s.
Anomaly detection on all Varnish counters flags unusual patterns without requiring static thresholds.

For per-request latency itself, Netdata’s strength is correlation: when hit latency increases, the ban list, thread pool, and workspace signals that explain why are already collected at per-second resolution, ready to overlay on the same timeline.