Home / server / Questions / 1084879
In Process
vezult
Asked: 2021-11-30 08:55:39 +0800 CST

Is rate limiting delay included in nginx $request_time?

  • 772

If requests are delayed by nginx rate limiting (rate limit exceeded, but within burst rate), is this delay included in the nginx $request_time total?

The nginx docs state that $request_time is "time elapsed since the first bytes were read from the client"

If a request is delayed, is that before or after request bytes are read from the client? I assume after, since rate limiting can be based on request headers, etc.

Is there a way to separate total request time and time spent specifically on sending/receiving network communication to/from the client?

Note: I am aware of $upstream_response_time, and am logging that. I specifically am concerned with differentiating specific operations within nginx (caching, rate limiting, etc), and client-side network communications.

http nginx

1 Answers

  1. So, in my testing, nginx $request_time logging does reflect delay due to rate limiting.

    Client:

    wrk --timeout 20s -d 20 -t 79 -c 80 https://zapazoid.vistashare.net/Static/jquery.jnotify-1.1.min.js

    Config:

    nodelay removed from static rate limiting, and rate limit to 1r/s, burst set to 80r/s.

    Test Results:

    ❯ wrk --timeout 20s -d 20 -t 79 -c 80 https://zapazoid.vistashare.net/Static/jquery.jnotify-1.1.min.js
Running 20s test @ https://zapazoid.vistashare.net/Static/jquery.jnotify-1.1.min.js
  79 threads and 80 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency     9.97s     5.97s   19.93s    56.10%
    Req/Sec     0.27      1.57    10.00     97.56%
  41 requests in 20.10s, 140.14KB read
Requests/sec:      2.04
Transfer/sec:      6.97KB

    Nginx logs showed requests being delayed:

    2021/11/29 15:40:23 [warn] 2608#2608: *355 delaying request, excess: 78.992, by zone "static-corp", client: 10.100.2.130, server: zapazoid.vistashare.net, request: "GET /Static/jquery.jnotify-1.1.min.js HTTP/1.1", host: "zapazoid.vistashare.net"

    Access logging was configured as:

        log_format apm '$remote_addr - $remote_user [$time_local] '             
                   '"$request" $status $body_bytes_sent '                   
                   '"$http_referer" "$http_user_agent" '                    
                   '$request_time $upstream_response_time '                 
                   '$upstream_cache_status';

    and access logs showed climbing $request_time values (3rd value from end), as requests were increasingly delayed to fall into the configured limit:

    10.100.2.130 - - [29/Nov/2021:15:46:51 -0500] "GET /Static/jquery.jnotify-1.1.min.js HTTP/1.1" 200 3098 "-" "-" 0.001 0.004 MISS
10.100.2.130 - - [29/Nov/2021:15:46:51 -0500] "GET /Static/jquery.jnotify-1.1.min.js HTTP/1.1" 200 3098 "-" "-" 0.496 0.000 MISS
10.100.2.130 - - [29/Nov/2021:15:46:52 -0500] "GET /Static/jquery.jnotify-1.1.min.js HTTP/1.1" 200 3098 "-" "-" 0.995 0.000 MISS
10.100.2.130 - - [29/Nov/2021:15:46:52 -0500] "GET /Static/jquery.jnotify-1.1.min.js HTTP/1.1" 200 3098 "-" "-" 1.495 0.000 MISS
10.100.2.130 - - [29/Nov/2021:15:46:53 -0500] "GET /Static/jquery.jnotify-1.1.min.js HTTP/1.1" 200 3098 "-" "-" 1.999 0.000 MISS
10.100.2.130 - - [29/Nov/2021:15:46:53 -0500] "GET /Static/jquery.jnotify-1.1.min.js HTTP/1.1" 200 3098 "-" "-" 2.495 0.004 MISS
...
10.100.2.130 - - [29/Nov/2021:15:47:02 -0500] "GET /Static/jquery.jnotify-1.1.min.js HTTP/1.1" 200 3098 "-" "-" 11.467 0.000 MISS
10.100.2.130 - - [29/Nov/2021:15:47:03 -0500] "GET /Static/jquery.jnotify-1.1.min.js HTTP/1.1" 200 3098 "-" "-" 11.964 0.000 MISS
10.100.2.130 - - [29/Nov/2021:15:47:03 -0500] "GET /Static/jquery.jnotify-1.1.min.js HTTP/1.1" 200 3098 "-" "-" 12.466 0.004 MISS
10.100.2.130 - - [29/Nov/2021:15:47:04 -0500] "GET /Static/jquery.jnotify-1.1.min.js HTTP/1.1" 200 3098 "-" "-" 12.963 0.000 MISS
10.100.2.130 - - [29/Nov/2021:15:47:04 -0500] "GET /Static/jquery.jnotify-1.1.min.js HTTP/1.1" 200 3098 "-" "-" 13.460 0.000 MISS
10.100.2.130 - - [29/Nov/2021:15:47:05 -0500] "GET /Static/jquery.jnotify-1.1.min.js HTTP/1.1" 200 3098 "-" "-" 13.961 0.000 MISS
10.100.2.130 - - [29/Nov/2021:15:47:05 -0500] "GET /Static/jquery.jnotify-1.1.min.js HTTP/1.1" 200 3098 "-" "-" 14.452 0.000 MISS
10.100.2.130 - - [29/Nov/2021:15:47:06 -0500] "GET /Static/jquery.jnotify-1.1.min.js HTTP/1.1" 200 3098 "-" "-" 14.946 0.000 MISS
10.100.2.130 - - [29/Nov/2021:15:47:06 -0500] "GET /Static/jquery.jnotify-1.1.min.js HTTP/1.1" 200 3098 "-" "-" 15.446 0.000 MISS
    • 0