☰

Apache 反向代理在处理用户请求时出现延迟

tag-icon • tag-icon linux networking apache-http-server reverse-proxy
Apache 反向代理在处理用户请求时出现延迟

我们的系统存在一个问题，用户会随机遇到延迟。我们的架构相当简单，其中：

  1. 我们有 Apache 2.4.57 作为反向代理
  2. 我们还有多个后端系统，假设系统 A 监听端口 9000，系统 B 监听端口 9085。大多数用户交互都路由到系统 B。这两个后端系统都在 Spring Boot 上运行。

从 apache 访问日志中我们可以看到有两个不同的问题。

问题 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/refreshSales 200 - 67 HTTP/2.0 a.b.c.d 1 
2023-11-14 21:10:37.522 GET /api/backend/userInfo 200 4054 98 HTTP/2.0 a.b.c.d 1 
2023-11-14 21:10:37.621 PUT /api/backend/userPreferences 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/websocketCall 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/refreshSales 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/userInfo 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/userPreferences 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/userInfo 200 4054 14 HTTP/2.0 a.b.c.d 0
2023-11-14 21:18:46.014 GET /api/backend/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 版本 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 发现了这一点。

我们注意到：

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

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

ss -ntip '( sport = 4443 )

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

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

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

相关内容