Apache 2.4.57反向代理两类用户请求延迟问题排查求助

各位好，我们的系统最近遇到了用户随机遭遇请求延迟的问题，架构不算复杂：用Apache 2.4.57做反向代理，后端是两个Spring Boot服务——系统A监听9000端口，系统B监听9085端口，大部分用户交互请求都会路由到系统B。

我们从Apache的访问日志里发现了两类不同的异常情况，下面详细说明，希望大家能帮忙分析原因，或者给出进一步排查的思路。

Issue A：后端响应快，但Apache记录的总响应时长异常长 #

用户请求很快到达Apache，紧接着就转发到了系统B，系统B也只用了几毫秒就处理完成（按理说响应应该很快回传给Apache），但Apache访问日志里记录的总响应时间却特别长，有时候甚至能到一分钟。

我们的Apache日志格式配置如下：

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

下面是日志片段，其中标记了几个异常请求的时间线：

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的GET /api/backend/userInfo请求：系统B在21:15:53.933就收到了请求，仅用3ms就处理完成，但Apache记录的总时长（也就是%{ms}T字段，代表从请求到达Apache到响应发送完成的总时间）却高达95925ms。

我猜测会不会是Apache把响应写回客户端的时候卡住了？但不确定具体原因。想请教大家：

• 这种现象可能是什么原因导致的？
• 有没有进一步调试排查的方法？

当前服务器配置信息 #

我们的服务器是Red Hat Enterprise Linux Server release 7.9 (Maipo)，内核版本3.10.0-1160.92.1.el7.x86_64，相关OS内核参数如下：

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

运行Apache的用户的limits配置：

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>

Issue B：请求已到达服务器，但Apache很久才处理 #

和Issue A不同，这个问题是请求在“进来”的阶段就延迟了：用户发送请求后，服务器很快就返回了ACK（客户端和服务器端的抓包都能验证这一点），但Apache的访问日志里记录的请求到达时间却晚了好几分钟，而后续的后端处理速度是正常的。

为了分析这个问题，我在后台持续运行了ss -ntip '( sport = 4443 )'命令监控，发现当用户遇到这类延迟时，对应用户IP的socket读队列会出现非零值，并且持续几秒。

我有几个疑问：

• 这个socket读队列非零的现象意味着什么？是Apache太忙来不及处理请求？还是后端系统B太忙，导致Apache不愿意去读socket队列？
• 我已经把OS层面的net.core.somaxconn从默认的128调到了4096，要不要再调整Apache的backlog相关设置？

备注：内容来源于stack exchange，提问作者caffeine_inquisitor