Case study: a ban storm made Varnish slower than no cache

Field notes — a real production bug, project name withheld. Symptom → investigation → fix → lesson.

The symptom

The store put Varnish in front of Magento expecting the usual transformation: sub-100 ms cache hits, a 70-plus percent hit rate, origin traffic collapsing. Instead the site got slower. Time to first byte on category pages rose from ~600 ms (direct to Nginx, no Varnish) to ~1.2 seconds through Varnish, the hit rate hovered around 12 percent, and during the nightly product-feed import the site behaved as if there were no cache at all, with PHP-FPM saturated and customers queuing. Disabling Varnish and serving straight from the origin was measurably faster, which is the kind of result that makes a team question whether the cache layer is broken by design.

The ops dashboard added a stranger detail: Varnish memory usage grew steadily through the night and never fully came back down, while varnishstat showed the n_expired counter climbing into the millions. Restarting Varnish every morning "fixed" performance until midday, then the decay resumed. The Magento admin cache panel showed full-page cache as enabled and healthy, the VCL was the stock Magento-generated one with only small header tweaks, and curl -I on a freshly visited product page returned X-Magento-Cache-Debug: HIT exactly once before flipping back to MISS on the next request. A HIT that never repeats is not a cache, it is a rumor.

The feed import was the metronome. Every night at 01:00 a supplier feed touched 8,000-15,000 products (price and stock nudges, most of them trivial), and by 02:00 the hit rate was in single digits. Whatever the import did, it invalidated far more than the products it changed.

Investigation

The investigation started with the ban list, because Magento invalidates Varnish with BAN requests and a HIT that flips to MISS overnight smells like over-invalidation:

varnishadm ban.list

The list held tens of thousands of entries, most of them hours old, with patterns like these:

obj.http.X-Magento-Tags ~ (cat_p_48291|cat_p_48292|cat_p_48293|...hundreds more...)
obj.http.X-Magento-Tags ~ .*

Two pathologies in one screen. First, a third-party feed module issued one BAN per product it touched, each carrying a long alternation of product tags, instead of batching. Fifteen thousand product touches meant fifteen thousand BANs, each of which Varnish must evaluate against every cached object on lookup. Second, and far worse, the module's "cleanup" step after the import issued a catch-all ban matching .* against the tag header, intended as a safety net for anything the per-product bans missed. That single expression marked the entire cache as suspect in one stroke.

The varnishstat counters confirmed the mechanics:

varnishstat -1 -f MAIN.bans -f MAIN.bans_added -f MAIN.bans_completed \
  -f MAIN.bans_deleted -f MAIN.n_expired -f MAIN.cache_hit -f MAIN.cache_miss

bans_added grew by ~15,000 nightly while bans_completed lagged by hours. The ban_lurker thread, which tests old bans against objects in the background, could not keep up: bans_deleted crawled while the list grew. Every cache lookup had to walk the accumulated ban list (bans_tested in the hundreds of millions per day), which explained the TTFB regression directly. Varnish with 20,000 pending bans evaluates 20,000 regexes per object lookup before it may serve a HIT. At that point the cache layer costs more CPU than rendering the page in PHP, which is exactly why bypassing Varnish was faster. The n_expired millions were objects finally reaped after their bans completed, and the never-shrinking memory was the ban list itself plus the steady churn of MISS-rendered replacements for objects that should have stayed cached.

A look at the module code showed the root call. On every product save event it fired:

$this->purgeCache->sendPurgeRequest('.*');

buried behind an observer on catalog_product_save_after that the feed import triggered per row. The stock Magento invalidation path, which sends precise X-Magento-Tags-Pattern bans scoped to the changed entities, was bypassed entirely. Category pages carry the tags of every product listed on them, so one .* ban retired category pages, product pages, layered-navigation variants, and the homepage blocks in a single request. The nightly import effectively flushed the whole full-page cache and then spent the morning rebuilding it one MISS at a time under live traffic.

The morning-restart ritual masked all of this. Restarting Varnish clears the ban list, so post-restart lookups were fast until the next import rebuilt the pile. The team had mistaken ban-list amnesia for a healthy cache.

Fix

The fix replaced carpet-bomb invalidation with scoped purges, in three steps.

First, disable the module's ban logic the same night: a config flag the vendor had thoughtfully provided (feed/invalidate_cache: 0) stopped both the per-product BAN flood and the terminal .* ban. The import ran the next night with zero BANs issued, hit rate held at 78 percent through the import window, and morning TTFB dropped back under 200 ms on HITs. That single-flag test proved the bans were the whole disease before any code was rewritten.

Second, rewire invalidation to Magento's tag-scoped path. The observer was replaced with a collector that gathers affected product IDs during the import and issues one batched ban with an explicit tag pattern after the run:

# one BAN per import, scoped to changed tags only
BAN obj.http.X-Magento-Tags ~ "cat_p_(48291|48292|...)" 

In practice this went through Magento\CacheInvalidate\Model\PurgeCache::sendPurgeRequest() with the collected pattern, throttled to at most one BAN per five minutes during the import. Fifteen thousand BANs became one. The catch-all .* pattern was deleted from the codebase and blocked at review: any future pattern broader than a concrete tag prefix fails the pre-merge check.

Third, give Varnish room to breathe on the remaining invalidation. Grace and keep were set so a freshly banned object still serves stale-while-revalidate instead of stampeding the origin:

sub vcl_hit {
    if (obj.ttl >= 0s) { return (deliver); }
    if (obj.ttl + obj.grace > 0s) { return (deliver); }
}

with beresp.grace = 1h and beresp.keep = 24h in vcl_backend_response. The ban_lurker cadence was raised (ban_lurker_age = 60s, ban_lurker_batch = 10000) so the short scoped bans complete in seconds instead of lingering for hours. A varnishstat alert on bans count (page above 500 outstanding) now catches any regression before TTFB moves.

Verification was a full feed cycle: ban.list holding under 10 entries through the import, bans_tested flat, hit rate steady at 75-82 percent, origin PHP-FPM idle through a window that previously saturated it, and category TTFB p95 at 180 ms at 03:00 instead of 1.4 seconds.

Lesson

A cache that invalidates everything caches nothing, and Varnish charges per pending ban on every lookup. One BAN per imported row plus a trailing .* safety net turns the ban list into a second workload bigger than the traffic it fronts: tens of thousands of regex evaluations per HIT check will always lose to just rendering the page. Batch invalidation into a single tag-scoped BAN per run, never ship a .* pattern against X-Magento-Tags, and watch bans_added versus bans_completed the way you watch hit rate. When Varnish is slower than no Varnish, read ban.list first: the cache is probably fine, it is just being told to forget everything, nightly.

This case illustrates the cache architecture in /blog/magento2-cache-varnish-redis.