dotnet / runtime

.NET is a cross-platform runtime for cloud, mobile, desktop, and IoT apps.
https://docs.microsoft.com/dotnet/core/
MIT License
15.17k stars 4.72k forks source link

System.Threading.RateLimiting.FixedWindowRateLimiter sometimes doubles the configured rate #101612

Open alexwang1109 opened 6 months ago

alexwang1109 commented 6 months ago

Description

We are using FixedWindowRateLimiter to limit the number of API requests per second to our vendor API endpoint. Sometimes, the FixedWindowRateLimiter has unexpected behavior, e.g., it doubles the rate from the configuration at the very beginning.

Reproduction Steps

You can run the attached program, and reproduce the described issue. The program is NOT going to call the API. Instead, it is writing timestamp to console.

Program.txt

Expected behavior

The FixedWindowRateLimiter should only allow 6 requests based on the configuration to hit API endpoint within each second.

Actual behavior

At the beginning, the FixedWindowRateLimiter actually allows 12 requests to hit API endpoint within the first second. FixedWindowRateLimiter_API_log.txt FixedWindowRateLimiter_console_log.txt

Regression?

This issue persists in all .NET Frameworks. The example program is using .NET Framework 4.8.

Known Workarounds

We will have to implement retry mechanism when "429 too many requests" error occurs.

Configuration

.NET Framework 4.8 Microsoft Windows 10 Pro x64

Other information

No response

BrennanConroy commented 6 months ago

You are hitting the time window that resets the number of allowed requests. I'm guessing you're running on a slow machine, or under the debugger, so it's taking close to 1 second before you start acquiring permits.

So what is happening is that you acquire 6 permits, but then almost immediately reset the amount of allowed permits due to the 1 second timer being hit.

A better example of this (on a fast machine not under the debugger):

public static async Task Main(string[] args)
{
    Console.WriteLine($"Start {DateTime.Now.ToString("yyyy-MM-dd HH:mm:ss.fff")}");
    RateLimiter limiter = new FixedWindowRateLimiter(
                   new FixedWindowRateLimiterOptions
                   {
                       AutoReplenishment = true,
                       PermitLimit = 6,
                       QueueLimit = int.MaxValue,
                       QueueProcessingOrder = QueueProcessingOrder.OldestFirst,
                       Window = TimeSpan.FromSeconds(1),
                   });

    await Task.Delay(900); // get close to the 1 second reset window
    for (var i = 0; i < 13; i++)
    {
        using (RateLimitLease lease = await limiter.AcquireAsync(permitCount: 1))
        {
            Console.WriteLine(DateTime.Now.ToString("yyyy-MM-dd HH:mm:ss.fff"));
        } // lease
    }

    Console.ReadKey();
}

Results in:

Start 2024-04-26 19:48:58.923
2024-04-26 19:48:59.874
2024-04-26 19:48:59.883
2024-04-26 19:48:59.883
2024-04-26 19:48:59.883
2024-04-26 19:48:59.883
2024-04-26 19:48:59.883
2024-04-26 19:48:59.930 <-- 1 second window reset occurred
2024-04-26 19:48:59.930
2024-04-26 19:48:59.930
2024-04-26 19:48:59.930
2024-04-26 19:48:59.930
2024-04-26 19:48:59.930
2024-04-26 19:49:00.935

Which can look like it took twice the limit.

It might be nice to only start counting once the limiter becomes active so this wouldn't be possible at all.

alexwang1109 commented 6 months ago

This is definitely explaining what was going on. Now I understand this behavior. Thanks!

dotnet-policy-service[bot] commented 6 months ago

Tagging subscribers to this area: @mangod9 See info in area-owners.md if you want to be subscribed.