Apache reverse proxy delay in serving user request

Question

We have a problem with our system where users randomly experiencing delay. Our architecture is reasonably straightforward, where:

1. We have Apache 2.4.57 acting as a reverse proxy
2. We also have multiple backend system, lets say system A listens on port 9000, and system B listens on port 9085. Most user interactions are routed to system B. Both of these backend systems are running on Spring Boot.

What we can see from apache access log is that we have two different issues.

Issue A:

User request arrived at apache pretty quick, and at system B shortly after. System B also served the request within a few milliseconds (and I assume that the response is returned to apache very shortly after that). However, according to apache access log, the response time is quite big. Sometimes up to a minute.

Our apache log format:

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

and here is a snippet from apache access log:

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

The slow request was the one at 2023-11-14 21:15:53.922. That particular request arrived at system B at 2023-11-14 21:15:53,933, and system B took 3ms to serve the request. But for some unknown reason, it took 95925ms to complete the request (i assume that time includes the time it takes to write back to the client? It is the '%{ms}T' field from LogFormat). What could be the reason for this? Is there any way to debug this further?

Here are some OS settings on the box (Red Hat Enterprise Linux Server release 7.9 (Maipo), kernel is 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

and the limits for the user:

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

Here is the apache config (i've only included section which I think is relevant):

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:

While issue A is the delay on the way back to the user, issue B is the delay on the way in. i.e. user sent the request to the box (which should arrive at apache), but for some unknown reason, apache picked it up very late (sometimes up to a minute). But everything else down the pipeline is fast. We found this out by running wireshark on both ends (at user PC as well as tcpdump the server).

We noticed that:

1. User side receives ACK from the server as soon as it sent the request (and we can also see that from the tcpdump capture on the server side)
2. Something is causing Apache to not receive this request until a few moments later (based on the access log '%{%Y-%m-%d %T}t.%{msec_frac}t' entry )

To analyse this issue, I ran

ss -ntip '( sport = 4443 )

in the background, and I noticed that when user is experiencing delay due to issue B, the socket read queue for that particular user IP shows a non-zero value for a few seconds.

What does this mean? is Apache too busy? or is the backend (system B) too busy, which caused Apache not to bother to read from the socket read queue?

Should I increase the 'backlog' settings on Apache ? I've already increased the 'net.core.somaxconn' on the OS level (the default is 128).