The App Finished in 0.049s and the User Waited 7 Seconds

In one line

The app finished in 0.049 seconds but the user waited 7 seconds. The status code is 200 and the application log shows nothing wrong. This kind of incident leaves a trace only in nginx's buffer and connection settings.

Why this was needed

A 5xx at least shows. The dashboard turns red and the alerts ring. What really drags on is an incident where nobody seems to be at fault.

The user says "the report screen is slow". The development team digs through the app logs and answers, "We responded in 0.05 seconds." The infrastructure team brings up the CPU, memory and network graphs and answers, "The servers are idle." Both are true. And the user is telling the truth too. This meeting ends with no conclusion and is held again the next week in the same way.

The missing piece is inside nginx. The response spilled to disk, or the request body fell into a temporary file, or a new TCP connection is being created for every request. All three of these do not appear in the status code.

Buffering — the moment a response leaks to disk

proxy_buffering defaults to on, and for a good reason. nginx receives the upstream's response as fast as possible and releases the upstream connection, then nginx feeds it slowly to the slow client. Upstream threads are not held by slow users.

The problem comes when the response is larger than the buffers (proxy_buffer_size + proxy_buffers). Then nginx writes the remainder to a temporary file on disk. Here is a measured line.

[warn] an upstream response is buffered to a temporary file
  /var/lib/nginx/proxy/1/00/0000000001 while reading upstream,
  request: "GET /app/big?n=8000000 HTTP/1.1"

Two things deserve attention here.

First, the level is not [error] but [warn]. Most teams set error_log to the error level, or attach alerts only to the string [error]. Then this line never reaches anyone. Keeping it open at warn level is the only way to see this incident.

Second, the access log for the same request says 200. It is never visible through the status code.

These are the numbers measured by receiving the same 8MB response through a path with buffering on and a path with buffering off.

proxy_buffering on   →  ut=0.049  rt=4.173   + [warn] 임시 파일
proxy_buffering off  →  ut=3.188  rt=3.189   경고 없음

This table shows exactly what buffering is. When it is on, the upstream is held for only 0.049 seconds and nginx takes on the rest — at the cost of leaking to disk. When it is off, nothing leaks to disk, but the upstream is held until the client has received everything. The evidence is ut climbing up to rt.

So the judgment splits like this.

Large file and report downloads → leave buffering on. The value of releasing the upstream quickly is greater than the disk I/O. Instead, enlarge proxy_buffers to reduce the amount that leaks to temporary files.
SSE, long polling, real-time log streaming → turn buffering off. Here it is normal for the upstream to be held for a long time, and buffering may even bundle the data and harm real-time behavior.

But let us be honest. When we measured streaming that sends a chunk at 1-second intervals in this lab environment, the chunks arrived at 1-second intervals both with proxy_buffering on and off. nginx passes data along as it reads it, as long as the client can receive. The common explanation that "turning buffering on breaks streaming" did not reproduce, at least under these conditions. The real reasons to turn buffering off for streaming are closer to keeping the response from leaking to disk when it grows and deliberately keeping the upstream occupied.

Body size — the 413 the app never sees

The default of client_max_body_size is 1m. For an upload larger than this, nginx cuts it off directly with a 413.

[error] client intended to send too large body: 3000000 bytes,
  request: "POST /app/toobig HTTP/1.1"

This is the access log for the same request.

413 ut=- rt=0.002 us=- "POST /app/toobig HTTP/1.1"

ut and us are both dashes. It never went to the upstream. If you count the upstream server's log in the lab, it really is 0 entries. When the development team says "that request isn't in our log", it is not an excuse but an accurate fact.

There is one more setting attached to body size, and this one is less well known. A body larger than client_body_buffer_size (default 16k, 8k depending on the platform) goes not to memory but to disk.

[warn] a client request body is buffered to a temporary file
  /var/lib/nginx/body/0000000003, request: "POST /app/spill HTTP/1.1"

In a system that receives hundreds of 500KB form uploads per second, this line is logged hundreds of times per second, and that much is written to and deleted from disk. The status codes are all 200.

Connection reuse — all three lines must be present

Upstream Keep-Alive works only when three things are present at the same time. If even one is missing, it is silently off.

upstream app {
  server 127.0.0.1:9101;
  keepalive 16;                      # ①
}
location /app/ {
  proxy_http_version 1.1;            # ②
  proxy_set_header Connection "";    # ③
  proxy_pass http://app/;
}

We measured the number of TCP connections the upstream saw when sending the same 10 requests.

Setting	Connections seen by the upstream
None	10
① only	10
① + ②	10
① + ② + ③	1

Many people stop after adding only ②. They assume raising to HTTP/1.1 is enough, but the Connection header sent by the client is passed through to the upstream, and the connection is closed every time. ③ removes that header.

When connections are not reused, a new socket is opened and closed for every request and TIME_WAIT piles up. There are no symptoms normally, but the moment traffic crosses the threshold, port exhaustion makes everything blow up at once. And the symptom you see then is connect() failed — that is, a 502. The cause is connection settings, but the symptom looks like "the backend is dead". The theme of this course, that the symptom and the cause are in different places, repeats here too.

What you see in the field

Keep the error_log level open at warn. The two temporary-file warnings covered in this section are all [warn]. If you narrow it to error, these incidents cease to exist. If you worry about log volume, don't narrow the level; shorten the rotation interval.

Put $upstream_response_time and $request_time together in the log format. Without these two columns you cannot make the first branch, "is the app slow or the transfer slow?", and if you cannot make that branch, the meeting repeats.

Measure before you change a setting. Enlarging a buffer or turning buffering off is not free. If you don't write down in numbers what you gain and what you give up, six months later nobody can touch that value.

What you will do in the next lab

You receive the same 8MB response through a path with buffering on and a path with buffering off and compare the two numbers, prove through the upstream log that a 413 never even reaches the application, and measure connection reuse before and after the set of three. At the end you write an operations decision guide that contains those numbers.