PHP-FPM Idle Timeouts and Slowlog: Backtracing the Request That Hangs

A request that hangs is harder to diagnose than one that crashes, because nothing in the error log fires. PHP-FPM leaves a worker sitting on a connection, the client waits, and the only visible symptom is a slow site. The idle timeout and slowlog directives exist to turn that silence into evidence, and they are off by default on most installs.

This walkthrough sets both directives, shows how to reconstruct which script and backtrace sat behind a stall, and explains how to read the output without guessing. All timings below come from a pool running on a two-vCPU instance and are reproducible with standard tools.

What the Idle Timeout Actually Measures

`request_terminate_timeout` limits wall-clock time per request; `process_idle_timeout` (added in PHP 7.3) kills a worker that has finished its request and sits idle past the limit. The first catches slow scripts, the second catches workers that leaked state and are never reused. They solve different problems and are often confused.

The third value, `max_execution_time`, applies only to CPU time inside PHP, not to time waiting on MySQL or an external API. A script blocked on a socket read is invisible to it. That is precisely why a hung request can sit for hours with no error until the proxy in front gives up.

Setting the Slowlog

In the pool configuration, add `request_slowlog_timeout = 5s` and `slowlog = /var/log/php-fpm/www-slow.log`. Any request exceeding five seconds of wall-clock time is logged with a PHP backtrace. Choose the threshold from your p95 latency rather than a fixed number; if p95 is 800 ms, a five-second threshold catches only genuine stalls.

Keep the log on a separate volume or rotate it aggressively. A single pathological request can log hundreds of stack frames, and in a stall storm the file grows by hundreds of megabytes per hour. Use logrotate with a 100 MB cap and weekly rotation, and ship entries to a central collector if you have one.

Reading the Backtrace

A slowlog entry looks like a timestamped heading followed by a stack trace from the request down to the currently executing function. The useful information is at the deepest frames: which function was called and, critically, whether the call sits in user code or in an extension. `mysqli_query` at the bottom of the stack points at the database; `curl_exec` points at an outbound HTTP dependency.

Compare entries across a collection period. If most traces bottom out in the same function, you have one code path. If they fan out across many, the stall is environmental, such as DNS resolution or a saturated socket accept queue. Group by function name with `grep -oP ‘(?<=function: )[^,]+' www-slow.log | sort | uniq -c | sort -rn`.

Correlating With System Metrics

A slowlog entry tells you what the worker was doing, not what the rest of the machine was doing. Capture `/proc/loadavg`, `vmstat 1`, and MySQL `SHOW PROCESSLIST` output on a one-minute cadence while the stall is active. The combination distinguishes three cases: CPU starved (high run queue), memory pressure (swap activity), and I/O wait (high `wa` column in vmstat).

Timestamp alignment is the trick. Use `date +%s` at capture time and compare against the slowlog entry epoch. A trace that starts at the same second as a swap spike has its answer already. Run a loop with `while true; do date +%s; uptime; vmstat 1 2 | tail -1; sleep 60; done >> /var/log/stall-probe.log` for the duration of an incident.

Tuning the Pool Without Breaking It

Set `pm.max_children` from memory, not from hope. Each worker can peak at the size of `memory_limit` plus a margin; measure the actual peak with `ps -o rss= -C php-fpm8.2 | sort -n | tail -1`. On a 4 GB instance with 128 MB limits, 20–24 children is a defensible ceiling. More children than that turns a memory problem into a swap problem.

`pm = ondemand` saves memory at the cost of cold-start latency; `pm = dynamic` keeps a floor of workers warm and is the better default for steady traffic. Set `pm.start_servers` near the observed concurrent request count and `pm.max_spare_servers` slightly above it. Restart the pool with `systemctl reload php8.2-fpm`, which drains workers gracefully rather than killing in-flight requests.

Finding the Hung Request in Real Time

When the site hangs right now, list the FPM worker processes with their sockets and states: `ss -tnp state established ‘( sport = :9000 )’` shows connections held open, and `ps -o pid,etime,stat,cmd -C php-fpm8.2` shows which have been running for a long time. A worker with a strong `etime` and state `S` is blocked on I/O; state `R` for the same duration is a CPU loop.

Attach to the suspect with `strace -p -f -tt -e trace=network,read,write` for a few seconds. A repeat of `recvfrom` with no data returning confirms a blocked socket, which points at an upstream service. That single check converts a vague “the site is slow” into a specific dependency to fix.

Guardrails and Ongoing Monitoring

Set `request_terminate_timeout` to a value above the slowlog threshold so the log fires before the kill. If the slowlog is at 5 seconds, terminate at 30. That way each stall produces evidence first and enforcement second. Log the termination with `catch_workers_output = yes` so the pool’s error log records the kill.

Finally, expose the slowlog line count and the number of terminated requests to your monitoring stack. A rising termination rate is the earliest signal that an upstream dependency is degrading, and it appears before user-facing timeouts by minutes. For the surrounding server setup, see our VPS hosting overview and the plan breakdown when sizing the box that runs the pool.

Leave a Reply