
リクエストが nginx のレート制限によって遅延された場合 (レート制限を超えたが、バースト レート内)、この遅延は nginx の$request_time
合計に含まれますか?
nginxのドキュメントには次$request_time
のように書かれています「クライアントから最初のバイトが読み取られてから経過した時間」
リクエストが遅れる場合、それはクライアントからリクエストバイトが読み込まれる前ですか、それとも後ですか?後レート制限はリクエスト ヘッダーなどに基づいて設定できるためです。
合計リクエスト時間と、クライアントとのネットワーク通信の送受信に特に費やされた時間を分離する方法はありますか?
注記: 私は を認識しており$upstream_response_time
、それをログに記録しています。特に、nginx 内の特定の操作 (キャッシュ、レート制限など) とクライアント側のネットワーク通信を区別することに関心があります。
答え1
私のテストでは、nginxの$request_time
ログ記録するレート制限による遅延を反映します。
クライアント:
wrk --timeout 20s -d 20 -t 79 -c 80 https://zapazoid.vistashare.net/Static/jquery.jnotify-1.1.min.js
設定:
nodelay
静的レート制限から削除され、レート制限は1r/s
、バーストは に設定されました80r/s
。
試験結果:
❯ 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 ログにはリクエストが遅延していることが示されていました:
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"
アクセス ログは次のように構成されました。
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';
アクセス ログでは、$request_time
リクエストが設定された制限内に収まるように遅延が進むにつれて、値が上昇していることが示されました (最後から 3 番目の値)。
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