skip to content

How do PHP-FPM's request_slowlog_timeout and slowlog work, and what does a slow-log entry show?

level: middleimportance: should knowfreq 38%

answer

  1. off by default: 0
  2. slowlog file is mandatory with it
  3. backtrace of a still-running request
  4. 20 frames by default
  5. master pauses the worker to read it

basics

~20 s

When a request has run longer than request_slowlog_timeout, the FPM master pauses that worker, reads its PHP call stack and appends it, with the script path, to the pool's slowlog file; the request then continues. It is off by default and needs slowlog set.

solid answer

~50 s

`request_slowlog_timeout` (default `0`, off; units `s`, `m`, `h`, `d`) and `slowlog` are per-pool settings, and FPM refuses to start the pool if the timeout is set without a `slowlog` file. When a request has been executing longer than the timeout, the master logs a WARNING (`executing too slow (… sec), logging`), briefly stops the worker — with `ptrace` where available — reads its PHP call stack from memory and appends it to the slow log: a timestamp, pool and PID, `script_filename`, then up to `request_slowlog_trace_depth` (default 20) frames, innermost first, each as `[address] function() file:line`. The request is not killed and is logged only once. The status page's `slow requests` counter counts these events. The timeout must not exceed `request_terminate_timeout` when that is set. It shows where a request **is** at that moment, not a full profile, so a few samples of the same line are the signal.

code

ini · 7 lines
ini
[shop]
slowlog = /var/log/php-fpm/$pool.slow.log
; trace any request still running after 3 seconds
request_slowlog_timeout = 3s
request_slowlog_trace_depth = 20
; kill after 30 seconds; must not be below the slowlog timeout
request_terminate_timeout = 30s

go deeper

for a junior

Recall that the FPM slow log records a stack trace of requests running longer than request_slowlog_timeout, and that it is off by default.

for a middle

Explain the settings and their validation, how the master pauses a worker to read its stack, and how to read the frames from innermost out.

for a senior

Use slow-log samples as evidence: pick a threshold above normal latency, look for repeated top frames, and know the ptrace limitation in containers.

for a principal

Decide which production tripwires stay always on — slow log, status metrics — and when a full profiler is justified.

## What the slow log is for A pool of PHP-FPM workers can be saturated by a handful of requests that take far longer than normal. The **slow log** answers *"what are those requests doing right now?"* without a profiler or a debugger: FPM takes a snapshot of the PHP call stack of any request that has been running longer than a threshold and writes it to a file. ## Configuration | Directive | Default | Notes | |---|---|---| | `request_slowlog_timeout` | `0` (off) | Units `s` (default), `m`, `h`, `d` | | `slowlog` | not set | **Mandatory** when the timeout is set | | `request_slowlog_trace_depth` | `20` | Maximum number of frames written | FPM validates these when it starts: a timeout without a `slowlog` file is an error (`'slowlog' must be specified for use with 'request_slowlog_timeout'`), and a slowlog timeout greater than a non-zero `request_terminate_timeout` is also rejected, because the request would be killed before it could be logged. On platforms without the tracing support, FPM warns that the timeout is not supported and ignores it. ```ini [shop] slowlog = /var/log/php-fpm/$pool.slow.log request_slowlog_timeout = 3s request_slowlog_trace_depth = 20 ``` ## What happens when a request crosses the threshold 1. The master checks running requests periodically. When one has been in the executing stage longer than `request_slowlog_timeout`, it logs a WARNING to the FPM error log: `[pool shop] child 8812, script '/srv/shop/public/index.php' (request: "POST /checkout/confirm") executing too slow (3.004163 sec), logging` 2. It **pauses** the worker — through `ptrace` on systems that have it, otherwise by stopping it with a signal and reading its memory — and walks the PHP engine's chain of call frames. 3. It appends an entry to the slow log and lets the worker continue. The request is **not** terminated. 4. Each request is logged **once**, however long it runs, and the pool's `slow requests` counter on the status page increases. ## Reading an entry ```text [29-Sep-2026 14:02:11] [pool shop] pid 8812 script_filename = /srv/shop/public/index.php [0x00007f3a1c0145a0] curl_exec() /srv/shop/src/Payment/GatewayClient.php:88 [0x00007f3a1c014480] charge() /srv/shop/src/Checkout/ConfirmOrder.php:41 [0x00007f3a1c014300] __invoke() /srv/shop/src/Http/Kernel.php:120 [0x00007f3a1c014200] handle() /srv/shop/public/index.php:14 ``` - The **first frame** is the innermost call — here a `curl_exec()` waiting on the payment provider. - Each line gives the function name and the **file and line** where it was called; class names are not printed, so the file tells you which class. - Include and eval frames appear as `[INCLUDE_OR_EVAL]()`. ## Interpreting it well - **A snapshot, not a profile.** It shows where the request is at the moment of the check. One entry proves little; twenty entries all ending in `curl_exec()` in the same client prove a pattern. - **Waiting shows up clearly.** Database calls, HTTP calls, `sleep()`, session and file locks — anything blocking — sits at the top of the trace. - **CPU-heavy loops** show up as user functions at the top, and the same line recurring across entries. - **Choose the threshold** above normal response times (for example two to three times the 95th percentile), or the log fills with noise. ## Worked reading: three entries from one incident Suppose the slow log collects 40 entries in two minutes during an incident. Grouping them by their **top frame** gives the picture quickly: 1. 31 entries start with `curl_exec()` called from `GatewayClient.php:88` — requests waiting on the payment provider. 2. 6 entries start with `execute()` called from the stock repository's file — database statements waiting on a row lock. 3. 3 entries show different user functions — ordinary noise. The fix follows the majority: a timeout and circuit breaker on the payment call. Counting top frames is the whole technique; a shell one-liner over the log is usually enough. ## Operational notes - The pause is short, but it happens to a real request; keep the threshold high enough that only outliers are traced. - In containers, the tracing step can be refused if the runtime forbids `ptrace`; the FPM error log then reports a failure to attach to the child, and the slow log stays empty. - The slow log file is opened by the master, so it must be writable by the user that runs the master. - For systematic performance work, a profiler gives complete cost data; the slow log is the always-on production tripwire.

  • The slow log is configured but stays empty inside a container, and the FPM log mentions failing to attach to a child. Why?
    To read a slow request's stack, the FPM master attaches to the worker with `ptrace` where the platform supports it. Container runtimes can forbid `ptrace`, so the attach fails and nothing is written. Allowing it for the FPM container restores the slow log; without it, you only get the 'executing too slow' warning in the FPM error log.
  • Does a request that appears in the slow log get stopped?
    No. The master pauses the worker only long enough to read its stack, then lets it continue; each request is logged once. Stopping long requests is the job of `request_terminate_timeout`, which kills the worker, and FPM requires the slowlog timeout not to exceed it so a request can be logged before it is killed.

saying these in an interview costs you the question

  • The slow log is written by PHP when the script finishes
  • request_slowlog_timeout kills requests that exceed it
  • The slow log shows how much time each function took
  • A request is logged again every time the timeout elapses
  • request_slowlog_timeout is enabled by default