[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    |
----------------------+--------------------

Comment (by RyanS):

 Our Varnish 4.0.3 installation probably suffers from the same problem.

 We use Varnish 4.0.3 for out website and serve a lot of pages with semi-
 unlimited (i.e. 1 year) TTL. When content gets changed, we ban te cache
 object through special http headers. Please note that there can be
 250.000+ new bans per day.

 Our problem is that page load times turn out to be slower and slower the
 longer Varnish runs. When checking with "varnishstat -1" it seems that
 band never get deleted. MAIN.bans_deleted is always 0.

 When i login to varnishadm and type the ban.list command I see a long list
 of bans with status "C" for "Completed". Varnishstat -1 shows me that
 there can be hundreds of thousands of them. They never get deleted.

 ---

 Here are the important part from our VCL:

 sub vcl_recv {

   if (req.method == "BAN") {
     if (!client.ip ~ purgers) {
       return (synth(405, "Not allowed"));
     }

     if (req.http.X-Cache-Tags) {
       ban("obj.http.X-Cache-Tags ~ " + req.http.X-Cache-Tags);
       return (synth(200, "Banned"));
     }

     if (req.http.X-Url) {
       ban("obj.http.x-origurl ~ " + req.http.X-Url);
       return (synth(200, "Banned"));
     }

     return (synth(405, "No cache tags provided"));
   }

 ...
 }

 sub vcl_backend_response {
   set beresp.http.x-origurl = bereq.url;
 ...
 }

 ---

 Here's an example of the ban.list output from varnishadm:

 1428440119.975700    20 C
 1428440119.875178    21 C
 1428440119.775048     0 C
 1428440119.675068     1 C
 1428440119.575059     0 C
 1428440119.474236     0 C
 1428440119.374664     1 C
 1428440119.275055     0 C
 1428440119.173203     1 C
 1428440119.070568     1 C
 1428440118.968622     0 C
 1428440118.867101     0 C
 1428440118.767099     2 C
 1428440118.665274     3 C
 1428440118.565995     2 C
 1428440118.463959     4 C
 1428440118.360379     3 C
 1428440118.259975     4 C
 1428440118.157665     4 C
 1428440118.054391     8 C
 1428440117.953973     3 C
 1428440117.851816    16 C
 1428440117.749820     7 C
 1428440117.647959     8 C
 1428440117.546431     2 C
 1428440117.446593     2 C
 1428440117.345096     1 C
 1428440117.245096     0 C
 1428440117.143993     0 C
 1428440117.!

 ---

 Here's output from varnishstat -1 a couple of hours after restart:

 MAIN.bans                     148860          .   Count of bans
 MAIN.bans_completed           148137          .   Number of bans marked
 'completed'
 MAIN.bans_obj                 148859          .   Number of bans using
 obj.*
 MAIN.bans_req                      0          .   Number of bans using
 req.*
 MAIN.bans_added               148860         3.93 Bans added
 MAIN.bans_deleted                  0         0.00 Bans deleted
 MAIN.bans_tested             2792056        73.77 Bans tested against
 objects (lookup)
 MAIN.bans_obj_killed             168         0.00 Objects killed by bans
 (lookup)
 MAIN.bans_lurker_tested  32706072512    864097.03 Bans tested against
 objects (lurker)
 MAIN.bans_tests_tested     347445702      9179.54 Ban tests tested against
 objects (lookup)
 MAIN.bans_lurker_tests_tested  32706072533    864097.03 Ban tests tested
 against objects (lurker)
 MAIN.bans_lurker_obj_killed         132363         3.50 Objects killed by
 bans (lurker)
 MAIN.bans_dups                          58         0.00 Bans superseded by
 other bans
 MAIN.bans_lurker_contention           1303         0.03 Lurker gave way
 for lookup
 MAIN.bans_persisted_bytes         24958452          .   Bytes used by the
 persisted ban lists
 MAIN.bans_persisted_fragmentation     22912281          .   Extra bytes in
 persisted ban lists due to fragmentation

 As you can see, MAIN.bans_deleted is 0.

 --

 I've already increased ban_lurker_batch to 100.000 and decreased
 ban_lurker_sleep to 0.001 sec, with no effect.

 If you need more information, please let me know.

-- 
Ticket URL: <https://www.varnish-cache.org/trac/ticket/1635#comment:4>
Varnish <https://varnish-cache.org/>
The Varnish HTTP Accelerator