[Varnish] #1635: Completed bans keep accumulating

[Varnish]

#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