问题 A：

用户请求很快到达 Apache，不久之后到达系统 B。系统 B 也在几毫秒内处理了请求（我假设响应在那之后不久就会返回给 Apache）。但是，根据 Apache 访问日志，响应时间相当大。有时长达一分钟。

我们的 Apache 日志格式：

LogFormat "%{%Y-%m-%d %T}t.%{msec_frac}t %m %U %>s %b %{ms}T %H %h %k"

这是Apache访问日志中的片段：

2023-11-14 21:10:37.375 GET /api/backend/sales/ticket/refresh/ 200 - 67 HTTP/2.0 a.b.c.d 1 
2023-11-14 21:10:37.522 GET /api/backend/user/full 200 4054 98 HTTP/2.0 a.b.c.d 1 
2023-11-14 21:10:37.621 PUT /api/backend/user/preferences 200 - 1054 HTTP/2.0 a.b.c.d 1 
2023-11-14 21:14:45.634 GET /api/backend/tickets 200 12461 18 HTTP/2.0 a.b.c.d 0            
2023-11-14 21:10:36.890 GET /api/backend/system/websocket 101 - 300712 HTTP/1.1 a.b.c.d 0   # finished at 21:15:36 (21:10:36.890 + 300712ms)
2023-11-14 21:15:53.054 GET /api/backend/sales/ticket/refresh/ 200 - 730 HTTP/2.0 a.b.c.d 1 # finished at 21:15:53 (21:15:53.054 + 730ms)
2023-11-14 21:11:20.953 GET /api/backend/pricestream 101 - 300110 HTTP/1.1 a.b.c.d 0        # finished at 21:16:20 (21:11:20.953 + 300110ms)
2023-11-14 21:15:53.922 GET /api/backend/user/full 200 4054 95925 HTTP/2.0 a.b.c.d 1        # finished at 21:17:20 (21:15:53.922 + 95925ms)
2023-11-14 21:17:31.437 PUT /api/backend/user/preferences 200 - 8910 HTTP/2.0 a.b.c.d 1     # arrived at 21:17:31.437
2023-11-14 21:18:46.013 GET /api/backend/user/full 200 4054 14 HTTP/2.0 a.b.c.d 0
2023-11-14 21:18:46.014 GET /api/backend/ndf-pairs 200 241 42 HTTP/2.0 a.b.c.d 1

慢速请求是 2023-11-14 21：15：53.922 的请求。该特定请求于 2023-11-14 21：15：53,933 到达系统 B，系统 B 需要 3 毫秒来处理该请求。

但是由于某种未知原因，完成请求需要 95925 毫秒（我假设时间包括写回客户端所需的时间？它是 LogFormat 中的“%{ms}T”字段。这可能是什么原因？有什么方法可以进一步调试吗？

以下是包装盒上的一些操作系统设置（Red Hat Enterprise Linux Server release 7.9 （Maipo），内核为 3.10.0-1160.92.1.el7.x86_64。

net.core.somaxconn = 4096
net.ipv4.tcp_rmem = 10240   87380   67108864
net.ipv4.tcp_wmem = 10240   87380   67108864
fs.inotify.max_user_instances=8192
fs.inotify.max_user_watches=1048576
net.ipv4.tcp_keepalive_time = 1800
net.core.rmem_max = 67108864
net.core.wmem_max = 67108864
net.core.netdev_max_backlog = 30000
net.ipv4.tcp_congestion_control=htcp
net.ipv4.ip_forward = 0
net.ipv4.tcp_window_scaling = 1

以及用户的限制：

cat /etc/security/limits.d/username.conf
username soft nofile 49152
username hard nofile 49152
username soft nproc 327680
username hard nproc 327680
username soft stack 20480
username hard stack 20480

这是Apache配置（我只包含了我认为相关的部分）：

SSLSessionCache        "shmcb:/app/myapp/runtimes/apache2/logs/ssl_scache(512000)"
ExtendedStatus On

<VirtualHost _default_:4443>
    SSLSessionTickets off
    SSLSessionCacheTimeout  300
    ProxyTimeout 300
    Protocols h2 http/1.1

    H2OutputBuffering off

    MaxKeepAliveRequests 1000
    KeepAlive On

    KeepAliveTimeout 1

    SSLEngine on
    SSLProxyEngine on

    ProxyRequests Off

    RewriteEngine On
    RewriteCond %{HTTP:Upgrade} websocket [NC]
    RequestHeader set Upgrade websocket
    RewriteRule /api/system/(.*) wss://backendapi.apps.com:9000/system/$1 [P,L]
    <LocationMatch "^/api/(.*)">
        ProxyPass "https://backendapi.apps.com:9000/$1" connectiontimeout=5 timeout=300
        ProxyPassReverse "https://backendapi.apps.com:9000/$1"
        Order allow,deny
        Allow from all
    </LocationMatch>

    RewriteEngine On
    RewriteCond %{HTTP:Upgrade} websocket [NC]
    RequestHeader set Upgrade websocket
    RewriteRule /api/backend/(.*) wss://backendapi.apps.com:9085/$1 [P,L]
    <LocationMatch "^/api/backend/(.*)">
       ProxyPassMatch "https://backendapi.apps.com:9085/$1" connectiontimeout=5 timeout=300
       ProxyPassReverse "https://backendapi.apps.com:9085/$1"
       Order allow,deny
       Allow from all
    </LocationMatch>
</VirtualHost>

<IfModule mpm_event_module>
    StartServers             3
    MinSpareThreads         75
    MaxSpareThreads        250
    ThreadsPerChild         25
    MaxRequestWorkers     2500
    ServerLimit            100
    MaxConnectionsPerChild   0
</IfModule>

问题 B：

问题 A 是返回给用户的途中的延迟，而问题 B 是返回到用户途中的延迟。即用户将请求发送到盒子（它应该到达 Apache），但由于某种未知原因，Apache 很晚才收到它（有时长达一分钟）。

但接下来的一切都很快。我们通过在两端（在用户 PC 以及 tcpdump 服务器）上运行 Wireshark 来发现这一点。我们注意到：

用户端在发送请求后立即收到来自服务器的 ACK（我们也可以从服务器端的 tcpdump 捕获中看到这一点）
某些东西导致Apache直到片刻后才收到此请求（基于访问日志'%{%Y-%m-%d %T}t.%{msec_frac}t'条目）

为了分析这个问题，我运行了

ss -ntip '( sport = 4443 )

在后台，我注意到当用户由于问题 B 而遇到延迟时，该特定用户 IP 的套接字读取队列会在几秒钟内显示非零值。

这是什么意思？Apache太忙了吗？还是后端（系统 B）太忙，导致 Apache 懒得从套接字读取队列中读取？

我应该增加 Apache 上的“积压工作”设置吗？我已经在操作系统级别增加了“net.core.somaxconn”（默认值为 128）。

Linux Apache 套接字反向代理 HTTP2

Apache 反向代理延迟处理用户请求 [已关闭]

Apache reverse proxy delay in serving user request [closed]

问题 A：

问题 B：

评论