[Varnish] #1635: Completed bans keep accumulating
Varnish
varnish-bugs at varnish-cache.org
Thu Nov 27 11:48:51 CET 2014
#1635: Completed bans keep accumulating
----------------------+--------------------
Reporter: Sesse | Owner:
Type: defect | Status: new
Priority: normal | Milestone:
Component: varnishd | Version: trunk
Severity: normal | Resolution:
Keywords: lurker |
----------------------+--------------------
Description changed by lkarsten:
Old description:
> Hi,
>
> I have a site where almost every backend response (vcl_backend_response)
> produces a new ban, of the form:
>
> ban ( "obj.http.x-analysis == 1 && obj.http.x-rglm != " +
> beresp.http.x-rglm );
>
> Pretty soon, these bans go into completed state. However, for some reason
> the ban lurker doesn't manage to delete them, even though there are no
> req.* bans. This seems to go on and on until I have hundreds of thousands
> of bans, and BAN_Insert and ban_lurker both take significant amounts of
> CPU time. Making the ban lurker wake up more often does not seem to help
> anything; the ban count still goes up and never seems to go down (at
> all).
>
> If I stop the backend entirely, so no requests ever go through, it seems
> to actually reduce the count after a while. Start it again, and the count
> increases. It's 100% reproducible for me.
>
> Relevant parts of varnishstat -1:
>
> MAIN.bans 507 . Count of bans
> MAIN.bans_completed 505 . Number of bans marked
> 'completed'
> MAIN.bans_obj 507 . Number of bans using
> obj.*
> MAIN.bans_req 0 . Number of bans using
> req.*
> MAIN.bans_added 25714 0.18 Bans added
> MAIN.bans_deleted 25207 0.18 Bans deleted
> MAIN.bans_tested 19528 0.14 Bans tested against
> objects (lookup)
> MAIN.bans_obj_killed 8168 0.06 Objects killed by bans
> (lookup)
> MAIN.bans_lurker_tested 20704629 147.19 Bans tested against
> objects (lurker)
> MAIN.bans_tests_tested 67431 0.48 Ban tests tested
> against objects (lookup)
> MAIN.bans_lurker_tests_tested 20721896 147.31 Ban tests tested
> against objects (lurker)
> MAIN.bans_lurker_obj_killed 13909 0.10 Objects killed by
> bans (lurker)
> MAIN.bans_dups 15323 0.11 Bans superseded
> by other bans
> MAIN.bans_lurker_contention 0 0.00 Lurker gave way
> for lookup
> MAIN.bans_persisted_bytes 1619932 . Bytes used by the
> persisted ban lists
> MAIN.bans_persisted_fragmentation 1613241 . Extra bytes
> in persisted ban lists due to
> fragmentation
>
> Relevant parts of my VCL:
>
> http://git.sesse.net/?p=remoteglot;a=blob;f=default.vcl;h=38631cb4f1d3c6f399dd4fb1378dec993339aa32;hb=HEAD
>
> This is Varnish from git, 7746e30e2c53cf55f0f2525bb3f49c9ee83e9611.
New description:
Hi,
I have a site where almost every backend response (vcl_backend_response)
produces a new ban, of the form:
ban ( "obj.http.x-analysis == 1 && obj.http.x-rglm != " +
beresp.http.x-rglm );
Pretty soon, these bans go into completed state. However, for some reason
the ban lurker doesn't manage to delete them, even though there are no
req.* bans. This seems to go on and on until I have hundreds of thousands
of bans, and BAN_Insert and ban_lurker both take significant amounts of
CPU time. Making the ban lurker wake up more often does not seem to help
anything; the ban count still goes up and never seems to go down (at all).
If I stop the backend entirely, so no requests ever go through, it seems
to actually reduce the count after a while. Start it again, and the count
increases. It's 100% reproducible for me.
Relevant parts of varnishstat -1:
{{{
MAIN.bans 507 . Count of bans
MAIN.bans_completed 505 . Number of bans marked
'completed'
MAIN.bans_obj 507 . Number of bans using
obj.*
MAIN.bans_req 0 . Number of bans using
req.*
MAIN.bans_added 25714 0.18 Bans added
MAIN.bans_deleted 25207 0.18 Bans deleted
MAIN.bans_tested 19528 0.14 Bans tested against
objects (lookup)
MAIN.bans_obj_killed 8168 0.06 Objects killed by bans
(lookup)
MAIN.bans_lurker_tested 20704629 147.19 Bans tested against
objects (lurker)
MAIN.bans_tests_tested 67431 0.48 Ban tests tested against
objects (lookup)
MAIN.bans_lurker_tests_tested 20721896 147.31 Ban tests tested
against objects (lurker)
MAIN.bans_lurker_obj_killed 13909 0.10 Objects killed by
bans (lurker)
MAIN.bans_dups 15323 0.11 Bans superseded by
other bans
MAIN.bans_lurker_contention 0 0.00 Lurker gave way
for lookup
MAIN.bans_persisted_bytes 1619932 . Bytes used by the
persisted ban lists
MAIN.bans_persisted_fragmentation 1613241 . Extra bytes in
persisted ban lists due to
fragmentation
}}}
Relevant parts of my VCL:
http://git.sesse.net/?p=remoteglot;a=blob;f=default.vcl;h=38631cb4f1d3c6f399dd4fb1378dec993339aa32;hb=HEAD
This is Varnish from git, 7746e30e2c53cf55f0f2525bb3f49c9ee83e9611.
--
--
Ticket URL: <https://www.varnish-cache.org/trac/ticket/1635#comment:1>
Varnish <https://varnish-cache.org/>
The Varnish HTTP Accelerator
More information about the varnish-bugs
mailing list