vsthrottle.is_denied is triggering with less requests per second than configured.

[ClemOzil]

Hey Guillaume, hope you're doing well.

Varnish version : 7.7
Varnish-module version : 0.26.0

We're using the vsthrottle module to add a global overall RQPS limit on our Varnish cache :

sub vcl_recv {
    if (vsthrottle.is_denied("global", 5000, 1s)) {
        std.log("rate_limit");
        return (synth(503, "Service Unavailable"));
    } else {
        std.log("ratelimit remaining: " + vsthrottle.remaining("global", 5000, 1s));
    }
}

When I start a ~4000 rqps benchmark run :

varnishstat looks like :

NAME                                              CURRENT        CHANGE       AVERAGE        AVG_10       AVG_100      AVG_1000 
MAIN.client_req                                       3927754       4194.72       3677.67       4013.30       4010.94       4010.94

AVERAGE, AVG_10, AVG_100 and AVG_1000 never goes over 4050.

But when I do :

varnishstat -1 -f MAIN.client_req

MAIN.client_req         651137      2615.01 Good client requests received
MAIN.client_req         655773      2623.09 Good client requests received
MAIN.client_req         659421      2627.18 Good client requests received
MAIN.client_req         662447      2628.76 Good client requests received
MAIN.client_req         666296      2633.58 Good client requests received

Already we can see some discrepancies between the values, but not the issue here.

I know that I'm doing ~4000 rqps, because I have full control on the tool that I use to simulate players.

Then I do

varnishlog

-   VCL_Log        ratelimit remaining: 180
-   VCL_Log        ratelimit remaining: 177
-   VCL_Log        ratelimit remaining: 172

After a few minutes, the "ratelimit remaining" log keeps on getting smaller and smaller even though the RQPS from my benchmark tool is staying at ~4000.

-   VCL_Log        ratelimit remaining: 3
-   VCL_Log        ratelimit remaining: 5
-   VCL_Log        ratelimit remaining: 4

Then I hit the vsthrottle.isdenied limit and I start to see 503 - Service unavailable.
In this state the "ratelimit remaining" oscillate between 200 and 0.

Around 10% of my requests are blocked, so around 400/seconds.

So, basically :

• I use vsthrottle.is_denied("global", 5000, 1s)
• I generate 4000 requests per second with my benchmark tool
• varnishstat returns AVG_10,100,1000 = ~4000
• varnishstat -1 -f MAIN.client_req returns a much lower value.
• Around 10% of my requests end up being blocked even though I'm still kinda far from the limit.

After some testing, it feels like the higher the values (rqps and vsthrottle value), the more evident this issue is.
I hit a 100k rqps vsthrottle limit, with "only" ~75k real rqps.

Every exemple I've seen using this library has much much lower values, and is usually used to do a RQPS limit/client, not a global limit : https://docs.varnish-software.com/varnish-enterprise/vmods/vsthrottle/

Are you aware of such a limitation ?

[gquintard]

Hi!

varnishstat -1 -f MAIN.client_req

MAIN.client_req         651137      2615.01 Good client requests received
MAIN.client_req         655773      2623.09 Good client requests received
MAIN.client_req         659421      2627.18 Good client requests received
MAIN.client_req         662447      2628.76 Good client requests received
MAIN.client_req         666296      2633.58 Good client requests received

Careful, the average you see here is over the whole lifetime of varnishd

Most likely, there's a difference between how the rate is compute by the VCL and your tool. VCL will test as soon as it receive the full headers, but I have a feeling that requests may pile up on the client side, leading to some request to actually reach VCL in another window than the one that they were started in?

[ClemOzil]

Hi,

I'm not sure I understand correctly your question.

All of my requests have a global response time of less than 80-100 ms at most for the video segments, less than 5ms for manifests.
My benchmark run lasts for more than 30 minutes without latency issue at a very stable RQPS.
This specific server is capable of doing more than 100k rqps with the same configuration (Epyc 5 9655P CPU)

I don't think there is any pile-up of requests on the client side.

[dridi]

I think what @gquintard means is pipelining.

If you have a fixed number of HTTP/1 connections, and your load testing tool reuses connections to minimize TCP or TLS handshakes, then it may add new requests to connections that have not yet processed responses of ongoing requests. If for some reason something slows down in Varnish, despite your load testing tool adding requests at a fixed rate, they may show up "all at once" in Varnish (but they are still processed sequentially per connection).

Likewise for h2, even if streams are submitted at a constant rate, if a hiccup happens it may result in a spike of requests on the Varnish side.

I don't know your exact setup, as it looks like authorized requests will go to a backend, presumably fetching actual video segments. Pretty much anything could incur a slow down, allowing requests to pile up in a connection, like waiting list serialization (usually because of zero TTL and grace).

It's hard to tell without a complete view of your setup.

Maybe after 30m your benchmark runs into full storage and constant churn with new segments. Things can vary a lot between different workloads.

Are you seeing the same discrepancy in a benchmark where you either serve a synthetic 503 or a synthetic 200, never engaging with an origin server?