nginx - nginx upstream_response_time 比 web app 大

Question

QPS 5000/s时，最小的nginx响应时间是88ms，最大的nginx响应时间是1844ms，但是web app响应时间几乎在1ms，不知道为什么

这是 nginx 配置

    worker_processes 32;
    worker_rlimit_nofile 65535;


    # define event
    events {
        use epoll;
        worker_connections 65535;
        multi_accept on;
    }

    http {
        sendfile            on;
    tcp_nopush          on;
    tcp_nodelay         on;
    log_format  main  '$remote_addr - $remote_user [$time_local] "$request" '
                      '$status $body_bytes_sent "$http_referer" '
                      '"$http_user_agent" "$http_x_forwarded_for "|$request_time|$upstream_response_time';
    upstream natee{
        server 127.0.0.1:8000;
        server 127.0.0.1:8001;
        server 127.0.0.1:8002;
        server 127.0.0.1:8003;
        server 127.0.0.1:8004;
        server 127.0.0.1:8005;
        server 127.0.0.1:8006;
        server 127.0.0.1:8007;
        server 127.0.0.1:8008;
        server 127.0.0.1:8009;
        server 127.0.0.1:8010;
        server 127.0.0.1:8011;
        server 127.0.0.1:8012;
        server 127.0.0.1:8013;
        server 127.0.0.1:8014;
        server 127.0.0.1:8015;
        server 127.0.0.1:8016;
        server 127.0.0.1:8017;
        server 127.0.0.1:8018;
        server 127.0.0.1:8019;
        server 127.0.0.1:8020;
    }
    server {
        proxy_http_version 1.1; 
        listen 9000;
        proxy_ignore_client_abort on;
        proxy_read_timeout 300s;
        server_name localhost;
        access_log  /root/nginx/access.log main;
        error_log  /root/nginx/error.log debug;
        location / {
            proxy_pass http://natee;
            proxy_http_version 1.1;
            proxy_connect_timeout 60000;
            proxy_read_timeout 60000;
            proxy_send_timeout 60000;
        }
    }

}

我使用日志格式记录 request_time 和 upstream_reponse_time，

这是网络响应时间

[I 211008 11:30:39 web:2243] 200 POST /test (127.0.0.1) 0.32ms
[I 211008 11:30:39 web:2243] 200 POST /test (127.0.0.1) 0.32ms
[I 211008 11:30:39 web:2243] 200 POST /test (127.0.0.1) 0.31ms
[I 211008 11:30:39 web:2243] 200 POST /test (127.0.0.1) 0.34ms
[I 211008 11:30:39 web:2243] 200 POST /test (127.0.0.1) 0.34ms
[I 211008 11:30:39 web:2243] 200 POST /test (127.0.0.1) 0.36ms
[I 211008 11:30:39 web:2243] 200 POST /test (127.0.0.1) 0.38ms
[I 211008 11:30:39 web:2243] 200 POST /test (127.0.0.1) 0.34ms

这是 nginx access.log

    172.19.3.130 - - [08/Oct/2021:11:30:40 +0800] "POST /test HTTP/1.1" 200 2 "-" "Go-http-client/1.1" "- "|0.652|0.592
    172.19.3.130 - - [08/Oct/2021:11:30:40 +0800] "POST /test HTTP/1.1" 200 2 "-" "Go-http-client/1.1" "- "|0.652|0.592
    172.19.3.130 - - [08/Oct/2021:11:30:40 +0800] "POST /test HTTP/1.1" 200 2 "-" "Go-http-client/1.1" "- "|0.652|0.592
    172.19.3.130 - - [08/Oct/2021:11:30:40 +0800] "POST /test HTTP/1.1" 200 2 "-" "Go-http-client/1.1" "- "|0.652|0.592
    172.19.3.130 - - [08/Oct/2021:11:30:40 +0800] "POST /test HTTP/1.1" 200 2 "-" "Go-http-client/1.1" "- "|0.652|0.592
    172.19.3.130 - - [08/Oct/2021:11:30:40 +0800] "POST /test HTTP/1.1" 200 2 "-" "Go-http-client/1.1" "- "|0.652|0.592
    172.19.3.130 - - [08/Oct/2021:11:30:40 +0800] "POST /test HTTP/1.1" 200 2 "-" "Go-http-client/1.1" "- "|0.652|0.592
    172.19.3.130 - - [08/Oct/2021:11:30:40 +0800] "POST /test HTTP/1.1" 200 2 "-" "Go-http-client/1.1" "- "|0.652|0.592

这是 nginx error.log

    2021/10/08 11:30:38 [debug] 3142#3142: accept on 0.0.0.0:9000, ready: 1
    2021/10/08 11:30:38 [debug] 3143#3143: accept on 0.0.0.0:9000, ready: 1
    2021/10/08 11:30:38 [debug] 3145#3145: accept on 0.0.0.0:9000, ready: 1
    2021/10/08 11:30:38 [debug] 3142#3142: posix_memalign: 000055F731876F30:512 @16
    2021/10/08 11:30:38 [debug] 3143#3143: posix_memalign: 000055F730E02410:512 @16
    2021/10/08 11:30:38 [debug] 3142#3142: *148769 accept: 172.19.3.130:52354 fd:9
    2021/10/08 11:30:38 [debug] 3143#3143: *148770 accept: 172.19.3.130:52356 fd:9
    2021/10/08 11:30:38 [debug] 3145#3145: posix_memalign: 000055F730BF0250:512 @16
    2021/10/08 11:30:38 [debug] 3142#3142: *148769 event timer add: 9: 60000:152402669
    2021/10/08 11:30:38 [debug] 3145#3145: *148771 accept: 172.19.3.130:52358 fd:9
    2021/10/08 11:30:38 [debug] 3142#3142: *148769 reusable connection: 1
    2021/10/08 11:30:38 [debug] 3145#3145: *148771 event timer add: 9: 60000:152402669
    2021/10/08 11:30:38 [debug] 3142#3142: *148769 epoll add event: fd:9 op:1 ev:80002001
    2021/10/08 11:30:38 [debug] 3145#3145: *148771 reusable connection: 1
    2021/10/08 11:30:38 [debug] 3145#3145: *148771 epoll add event: fd:9 op:1 ev:80002001
    2021/10/08 11:30:38 [debug] 3142#3142: posix_memalign: 000055F730E2EB10:512 @16
    2021/10/08 11:30:38 [debug] 3145#3145: accept() not ready (11: Resource temporarily unavailable)
    2021/10/08 11:30:38 [debug] 3142#3142: *148772 accept: 172.19.3.130:52360 fd:11
    2021/10/08 11:30:38 [debug] 3143#3143: *148770 event timer add: 9: 60000:152402669
    2021/10/08 11:30:38 [debug] 3142#3142: *148772 event timer add: 11: 60000:152402669
    2021/10/08 11:30:38 [debug] 3143#3143: *148770 reusable connection: 1
    2021/10/08 11:30:38 [debug] 3142#3142: *148772 reusable connection: 1
    2021/10/08 11:30:38 [debug] 3143#3143: *148770 epoll add event: fd:9 op:1 ev:80002001
    2021/10/08 11:30:38 [debug] 3142#3142: *148772 epoll add event: fd:11 op:1 ev:80002001
    2021/10/08 11:30:38 [debug] 3142#3142: accept() not ready (11: Resource temporarily unavailable)
    2021/10/08 11:30:38 [debug] 3143#3143: accept() not ready (11: Resource temporarily unavailable)
    2021/10/08 11:30:38 [debug] 3142#3142: accept on 0.0.0.0:9000, ready: 1
    2021/10/08 11:30:38 [debug] 3142#3142: posix_memalign: 000055F73187CB40:512 @16
    2021/10/08 11:30:38 [debug] 3142#3142: *148773 accept: 172.19.3.130:52362 fd:13
    2021/10/08 11:30:38 [debug] 3142#3142: *148773 event timer add: 13: 60000:152402669
    2021/10/08 11:30:38 [debug] 3142#3142: *148773 reusable connection: 1
    2021/10/08 11:30:38 [debug] 3143#3143: accept on 0.0.0.0:9000, ready: 1
    2021/10/08 11:30:38 [debug] 3142#3142: *148773 epoll add event: fd:13 op:1 ev:80002001
    2021/10/08 11:30:38 [debug] 3143#3143: posix_memalign: 000055F730CC8B20:512 @16
    2021/10/08 11:30:38 [debug] 3143#3143: *148774 accept: 172.19.3.130:52364 fd:11
    2021/10/08 11:30:38 [debug] 3142#3142: accept() not ready (11: Resource temporarily unavailable)
    2021/10/08 11:30:38 [debug] 3143#3143: *148774 event timer add: 11: 60000:152402669

标签： nginx