BAN - Memory consumption exploding under load

[Hugues Alary]

Hi there,

Re-opening this thread from 2016!

A few days ago, I ran into an issue where varnish (varnish-6.0.0 revision
a068361dff0d25a0d85cf82a6e5fdaf315e06a7d) became completely unresponsive.

While investigating, I noticed a lot of errors in varnishlog `VSL: store
overflow`, but most importantly, I noticed our BAN list was starting to
accumulate with somewhere around 130K BANs reported by varnishstat.

The load on the website was pretty low. Restarting Varnish fixed the issue. It
is possible I had been running some script generating a lot of BANs, but it
still seems weird it would generate so many BANs that varnish would become
unresponsive.

After restarting Varnish, I watched `varnishstat -1 | grep bans` and could
see MAIN.bans going up and down, but staying fairly stable on average.

Today, I decided to check again and I noticed:

MAIN.bans                     66863          .   Count of bans
MAIN.bans_completed           66834          .   Number of bans marked
'completed'
MAIN.bans_obj                 66849          .   Number of bans using obj.*
MAIN.bans_req                    14          .   Number of bans using req.*
MAIN.bans_added              170939         1.18 Bans added
MAIN.bans_deleted            104076         0.72 Bans deleted
MAIN.bans_tested            3767852        26.08 Bans tested against
objects (lookup)
MAIN.bans_obj_killed          62024         0.43 Objects killed by bans
(lookup)
MAIN.bans_lurker_tested   3344073359     23148.62 Bans tested against
objects (lurker)
MAIN.bans_tests_tested      94711644       655.62 Ban tests tested against
objects (lookup)
MAIN.bans_lurker_tests_tested   4573910595     31661.91 Ban tests tested
against objects (lurker)
MAIN.bans_lurker_obj_killed          16627         0.12 Objects killed by
bans (lurker)
MAIN.bans_lurker_obj_killed_cutoff            0         0.00 Objects killed
by bans for cutoff (lurker)
MAIN.bans_dups                           113845         0.79 Bans
superseded by other bans
MAIN.bans_lurker_contention                   3         0.00 Lurker gave
way for lookup
MAIN.bans_persisted_bytes             163879330          .   Bytes used by
the persisted ban lists
MAIN.bans_persisted_fragmentation     162795194          .   Extra bytes in
persisted ban lists due to fragmentation


1- MAIN.bans is almost at 70k and varnish has been running for 1 day 16
hours
2- MAIN.bans_req is > 0, but nowhere in my configuration do I ever submit
bans using req.*

So I have 3 questions:

- is 70k+ bans un-reasonable and should I find a way to reduce them?
- why am I seeing 14 MAIN.bans_req when my config doesn't ever emit such
bans?

Thanks,
-Hugues

On Thu, Nov 3, 2016 at 3:04 AM, Dridi Boukelmoune <dridi at varni.sh> wrote:

> On Thu, Oct 27, 2016 at 6:02 PM, Nils Goroll <slink at schokola.de> wrote:
> > Hi,
> >
> > we've added a bunch of ban and ban lurker improvements which did not get
> > backported to 4.1.3
> >
> > Please upgrade to 5.0 or master.
>
> Hi Nils,
>
> I was thinking (against the too-many-knobs trend) that maybe we should
> have some sort of ban_queue_limit parameter to avoid piling up too
> many bans. It would also play nice with your std.ban() initiative
> where hitting the queue limit could be one of the reasons returned by
> the function when it fails.
>
> The default could be 0 for unlimited, or a fairly large number.
>
> Dridi
>
> _______________________________________________
> varnish-misc mailing list
> varnish-misc at varnish-cache.org
> https://www.varnish-cache.org/lists/mailman/listinfo/varnish-misc
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://www.varnish-cache.org/lists/pipermail/varnish-misc/attachments/20180531/d8a53e26/attachment.html>