An nginx latency alert fires, yet the logs and metrics of the application server behind nginx can show the same requests finishing quickly. This happens when the application server stops entirely for a few seconds, for example during a full GC1, and connections that arrive in the meantime are kept waiting.

sequenceDiagram participant N as nginx participant K as Application server's kernel participant U as Application server Note over U: Stopped by a full GC or similar N->>K: SYN (open a connection) Note over K: The accept queue is full, so the SYN is dropped

The dropped SYN is resent every second and connects after the application server resumes. From nginx, these look like 200s that took about 1, 2, or 3 seconds to connect. The three lines below are from the nginx access log, which records $upstream_connect_time (the seconds nginx took to finish connecting to the application server) as uct. The columns are time, request ID, status, uct, $upstream_header_time (uht), $upstream_response_time (urt), and $request_time (rt). uht and urt are the seconds from when nginx starts connecting to the application server until it receives the start of the response, and until it has received the whole response. rt is the seconds from when nginx receives the request until it finishes sending the response.

1792402370.463 487aefe88a1328206a8e93c7c242399a 200 uct=1.002 uht=1.002 urt=1.002 rt=1.002 1792402370.464 cfdd11ceca67677e3601df796850a712 200 uct=2.067 uht=2.067 urt=2.067 rt=2.068 1792402371.040 dd774240d10448d9dc41bfcaaa7d8dfe 200 uct=3.054 uht=3.055 urt=3.055 rt=3.054

The application server receives the request ID that nginx assigned, and its log records time, request ID, and processing time in milliseconds. These are its lines for the same request IDs:

1792402370.463 487aefe88a1328206a8e93c7c242399a 0.092 1792402370.463 cfdd11ceca67677e3601df796850a712 0.104 1792402371.040 dd774240d10448d9dc41bfcaaa7d8dfe 0.084

Nearly all of the time went to connecting, and processing on the application server took about 0.1 ms. The application server starts timing only after it takes the connection off the queue, so the wait to connect does not appear in its logs or metrics.

The logs above were taken from an application server that receives 200 requests per second, stopped for 3 seconds2.

What is happening

When the application server stops, the accept queue fills up. SYNs that arrive after that are dropped, and connections are made through retransmissions by the nginx-side kernel.

The accept queue

The kernel carries out the exchange that sets up a TCP connection (the handshake). The connecting side sends a SYN to request a connection, the receiving side replies with a SYN-ACK to accept it, and the handshake completes when the connecting side sends an ACK. A completed connection waits in the kernel's accept queue until the server process takes it with the accept system call.

Even while the application server is stopped, the kernel on its side keeps completing handshakes and queuing the connections. Nothing takes connections off the queue during the stop, so the queue fills up.

sequenceDiagram participant N as nginx participant NK as nginx-side kernel participant UK as Application server's kernel participant U as Application server Note over U: Stopped N->>NK: Connect to the application server NK->>UK: SYN UK-->>NK: SYN-ACK NK->>UK: ACK NK-->>N: Connected Note over UK: Puts the connection in the accept queue Note over U: On resuming, takes connections off the queue in order

The maximum number of connections the queue can hold is the backlog. The application server passes the backlog to the kernel when it starts listening for connections (when it calls listen). The value comes from the runtime's or framework's default, or from configuration.

SYNs are dropped when the queue is full

When the number of connections in the queue exceeds the backlog, the application server's kernel drops newly arriving SYNs without replying3.

Retransmissions get through

When a SYN gets no reply, the nginx-side kernel waits and sends it again. This is SYN retransmission. If the nginx-side kernel is Linux 6.5 or later, the first few retransmissions go out at 1-second intervals4.

Retransmitted SYNs are dropped too while the queue is full. Once the application server resumes and the queue has room, the next retransmission gets a SYN-ACK and the connection is made. Depending on which retransmission gets through, $upstream_connect_time is about 1, 2, or 3 seconds. The three log lines at the top are these cases.

sequenceDiagram participant N as nginx participant NK as nginx-side kernel participant UK as Application server's kernel participant U as Application server Note over U: Stopped Note over UK: The accept queue is full N->>NK: Connect to the application server NK->>UK: SYN Note over UK: Drops it without replying loop Every second while the queue is full NK->>UK: Resend the SYN Note over UK: Drops it again end Note over U: Resumes and takes connections off the queue NK->>UK: Next retransmission UK-->>NK: SYN-ACK NK->>UK: ACK NK-->>N: Connected ($upstream_connect_time is about 1, 2, or 3 seconds)

Verification

I stopped the application server for 3 seconds to confirm this sequence. Requests that arrived during the stop split into those that connected immediately and those that connected after waiting about 1, 2, or 3 seconds.

Setup

nginx and the application server ran as containers on the same Docker network, and nginx was sent 200 requests per second for 15 seconds. Five seconds in, the application server process was stopped from outside with SIGSTOP, then resumed with SIGCONT 3 seconds later. This mimics a full GC stopping the whole process.

  • nginx is 1.30.6, with a single application server in the upstream block. proxy_connect_timeout (how long nginx waits to finish connecting to the application server) is left at its default of 60 seconds
  • The application server is an HTTP server that returns 200 immediately for every request, and listens with a backlog of 100

Time to connect

In the 3 seconds between the stop and the resume, 600 requests reached nginx, and all of them returned 200. The counts by $upstream_connect_time are:

$upstream_connect_time Requests
0 seconds (connected immediately) 102
About 1 second 204
About 2 seconds 205
About 3 seconds 89

This holds beyond the three lines at the top: for all 600 requests, the processing time in the application server's log was under 1 ms.

Which row a request falls into depends on when it arrived. The queue was full about 0.5 seconds after the stop. Connections that arrived before that went into the queue and connected immediately. Connections that arrived later had their SYNs dropped, the nginx-side kernel resent them every second, and they connected on the first retransmission after the application server resumed. The earlier a connection arrived, the more times its SYN was resent and the longer it waited.

Spotting it in your own logs

To tell whether the accept queue overflowed, match the nginx access log against the application server's log. The access log shows that SYNs were dropped and the connections were made by retransmission. The application server's log shows that the application server was stopped.

Access log

In the access log, look at $upstream_connect_time on the 200 lines from when the alert fired. If the values cluster around 1, 2, and 3 seconds, SYNs were dropped and the connections were made by retransmission.

$upstream_connect_time is not part of the default combined format, so add it with log_format5. The verification used this format:

log_format lab '$msec $request_id $status uct=$upstream_connect_time uht=$upstream_header_time urt=$upstream_response_time rt=$request_time';

Application server log

In the application server's log, find the lines with the same IDs as the requests whose $upstream_connect_time came in 1-second steps, and look at how the lines are spaced around that time. If those requests finished quickly and the lines stop for a while around that time, the application server was stopped. The lines after the gap are bunched at the time it resumed.

To match the two logs, pass the ID that nginx assigns to each request ($request_id) to the application server. On the nginx side, this takes one line:

proxy_set_header X-Request-Id $request_id;

On the application server side, its access log needs to be configured to include the received X-Request-Id header.

Fix

If the application server's backlog is set larger than the number of requests that arrive during a stop (requests per second × seconds stopped), the queue does not overflow6. With a backlog of 4096, the 200s of about 1, 2, and 3 seconds no longer appear.

The default backlogs of JVM servers, which can stop for a full GC, are:

  • Tomcat and Spring Boot: 1007
  • Jetty: 508

Even without an overflow, requests that arrive during a stop wait in the queue until the application server resumes. That wait shows up in $upstream_header_time, so 200s slowed by the length of the stop remain.

How this varies by environment

With a shortened connect timeout

If proxy_connect_timeout is shorter than the stop, nginx gives up on connections whose retransmissions have not gotten through in time and returns 504.

When the stop is not 3 seconds

A stop of a different length should change the values $upstream_connect_time clusters around. This article tests a 3-second stop.

Kernels older than 6.5

If the nginx-side kernel is older than 6.5, $upstream_connect_time clusters around 1 and 3 seconds, and about 2 seconds does not appear. This is because the retransmission interval doubles each time: after 1 second, then 2 seconds after that, then 4 seconds after that.

The stock kernel of Ubuntu 24.04 (6.8) is 6.5 or later. Those of Ubuntu 22.04 (5.15), Debian 12 (6.1), and RHEL 9 (5.14) are older. Whether a distribution has backported this change into its own kernel has not been checked.

With a proxy in front of the application server

If a proxy that accepts connections first sits between nginx and the application server (Docker's userland-proxy, which handles published ports, or a sidecar proxy), that proxy answers the SYNs from nginx. Even if the application server's queue overflows, no retransmissions happen on the nginx side, so the method in this article should not apply. This article does not verify this case.

  1. Ordinary GC pauses are not this long. The JVM's G1 collector has a default pause-time goal of 200 ms (G1Arguments::initialize() in JDK 25). Pauses of several seconds come from things like a full GC under heap pressure, which this article does not verify. ↩

  2. The results are here, and the code is in show-your-work. It ran on GitHub Actions ubuntu-24.04 (x86_64, kernel 6.17) with Docker 28.0.4. ↩

  3. In the Linux 6.17 source, tcp_conn_request() drops the SYN when the queue is full. sk_acceptq_is_full() decides whether it is full, and treats the queue as full when the number of connections in it is greater than (>) the backlog. ↩

  4. The number of retransmissions sent at 1-second intervals is set by net.ipv4.tcp_syn_linear_timeouts (default 4; see the Linux 6.17 documentation). ↩

  5. Adding variables with log_format is covered in nginx request_time is fast, but users say it's slow. ↩

  6. To go above 4096, also raise net.core.somaxconn in the application server's kernel. The kernel caps the backlog at somaxconn (__sys_listen_socket() in Linux 6.17), and its default is 4096 (preinit_net_sysctl(), documentation). ↩

  7. The Tomcat 11 documentation on HTTP connector configuration, and TomcatServerProperties in the Spring Boot 4.1.1 source. ↩

  8. Jetty passes 0, and the JDK replaces it with 50. The default is 0 in ServerConnector in the Jetty 12.1.14 source, and ServerSocketChannelImpl in the JDK 25 source turns any value below 1 into 50. ↩