{"id":1179,"date":"2026-09-19T22:01:59","date_gmt":"2026-09-19T22:01:59","guid":{"rendered":"https:\/\/virtualserversvps.com\/blog\/profiling-php-fpm-slowlog-strace-bottlenecks\/"},"modified":"2026-09-19T22:01:59","modified_gmt":"2026-09-19T22:01:59","slug":"profiling-php-fpm-slowlog-strace-bottlenecks","status":"publish","type":"post","link":"https:\/\/virtualserversvps.com\/blog\/profiling-php-fpm-slowlog-strace-bottlenecks\/","title":{"rendered":"Profiling PHP-FPM Bottlenecks on a VPS: slowlog, strace, and Real Request Tracing"},"content":{"rendered":"\n

When a page takes 1.8 seconds and CPU sits at 40 percent, the problem is not capacity — it is latency somewhere in the request path. Guessing at it means changing PHP settings randomly and hoping. Profiling means measuring which of the three possible causes is real: an external call (DNS, HTTP, database), a lock\/blocking wait, or genuine CPU work. This deep dive walks through the tooling on a 2026 Ubuntu 24.04 VPS running PHP 8.4-FPM.<\/p>\n\n\n\n

Step 1: Turn On the PHP-FPM Slow Log<\/h2>\n\n\n\n

The slow log records the full PHP stack of any request exceeding a threshold. It costs a negligible amount when idle and is the single highest-value diagnostic setting available.<\/p>\n\n\n\n

# \/etc\/php\/8.4\/fpm\/pool.d\/www.conf\nrequest_slowlog_timeout = 2s\nslowlog = \/var\/log\/php8.4-fpm-slow.log\nrequest_terminate_timeout = 60s\nrequest_slowlog_trace_depth = 30<\/code><\/pre>\n\n\n\n
Set the threshold at roughly 3× your p95 response time. On a site whose p95 is 400 ms, a 2 s threshold captures only genuinely pathological requests instead of flooding the log.<\/p>\n\n\n\n
sudo systemctl reload php8.4-fpm\ntail -f \/var\/log\/php8.4-fpm-slow.log<\/code><\/pre>\n\n\n\n
A representative entry looks like this:<\/p>\n\n\n\n
[20-Sep-2026 11:04:22]  [pool www] pid 41207\nscript_filename = \/var\/www\/site\/public\/index.php\n[0x00007f] curl_exec() \/var\/www\/site\/vendor\/guzzle\/src\/Handler\/CurlHandler.php:44\n[0x00008a] sendAsyncRequest() \/var\/www\/site\/vendor\/guzzle\/src\/Client.php:190\n[0x000131] request() \/var\/www\/site\/app\/Services\/PricingApi.php:88\n[0x0001c9] quote() \/var\/www\/site\/app\/Http\/ProductController.php:57<\/code><\/pre>\n\n\n\n
Read it bottom-up. The framework entry point is the controller; the deepest frame is where time is being burned. Here it is curl_exec()<\/code> inside an outbound API call — no amount of PHP tuning will help. The fix is a timeout and a cache, not more workers.<\/p>\n\n\n\n
Step 2: Classify the Bottleneck Before You Touch Config<\/h2>\n\n\n\n
Slow-log top frame<\/th>Class<\/th>Correct response<\/th><\/tr><\/thead>
curl_exec<\/code>, stream_socket_client<\/code><\/td>Network I\/O wait<\/td>Timeout + cache; never add workers<\/td><\/tr>
PDOStatement::execute<\/code><\/td>Database latency<\/td>Index work, buffer pool sizing<\/td><\/tr>
file_get_contents<\/code>, include<\/code><\/td>Disk I\/O \/ missing opcache<\/td>Enable opcache, check realpath cache<\/td><\/tr>
sleep<\/code>, flock<\/code>, sem_acquire<\/code><\/td>Lock contention<\/td>Move sessions out of files, remove locks<\/td><\/tr>
Deep in your own application code<\/td>Genuine CPU<\/td>Profile with a sampling profiler<\/td><\/tr><\/tbody><\/table><\/figure>\n\n\n\n
This table is the whole diagnostic method. Four of the five classes look identical from the outside — a slow page and idle CPU — but only the last one is fixed by tuning PHP itself.<\/p>\n\n\n\n
Step 3: Confirm With strace on a Single PID<\/h2>\n\n\n\n
To prove a network wait, attach to one FPM worker and look at the syscall timing. Never run this on all workers at once — strace<\/code> multiplies syscall overhead and will distort your own measurement.<\/p>\n\n\n\n
# find a worker currently handling a request\npgrep -af 'php-fpm: pool www'\n\n# trace it, showing only slow syscalls\nsudo strace -f -T -e trace=network,read,write -p 41207 2>&1 | awk '{ if ($NF ~ \/\\.\/ ) print }'<\/code><\/pre>\n\n\n\n
The -T<\/code> flag appends the duration of each syscall in seconds. A recvfrom()<\/code> or poll()<\/code> sitting at <1.2><\/code> while the socket is idle is conclusive proof of remote latency. If instead you see a high volume of fast syscalls, the process is genuinely CPU-bound.<\/p>\n\n\n\n
When the slow-log frames point at PDOStatement::execute<\/code>, the investigation moves to MySQL, and the arithmetic laid out in sizing the InnoDB buffer pool for a 1 GB VPS<\/a> is the first thing to check, because a buffer pool smaller than the working set turns every read into a disk seek.<\/p>\n\n\n\n
Step 4: A Minimal In-Process Timing Harness<\/h2>\n\n\n\n
Slow logs give you the worst offenders. To get a distribution you need something in-process. A 20-line wrapper is often more useful than a full APM install on a small VPS:<\/p>\n\n\n\n
function timed(string $label, callable $fn) {\n    $t0 = hrtime(true);\n    $out = $fn();\n    $ms = (hrtime(true) - $t0) \/ 1e6;\n    error_log(sprintf('TIMING %-24s %8.2f ms', $label, $ms));\n    return $out;\n}\n\n$rows = timed('db.products', fn() => $pdo->query('SELECT * FROM products')->fetchAll());\n$rate = timed('http.pricing', fn() => $client->quote($id));<\/code><\/pre>\n\n\n\n
hrtime(true)<\/code> returns nanoseconds from a monotonic clock and is unaffected by NTP steps — unlike microtime()<\/code>, it cannot produce a negative duration when chrony slews the clock. Aggregate the log lines with a one-liner to get mean and p95 per label:<\/p>\n\n\n\n
grep TIMING \/var\/log\/php8.4-fpm.log \\\n  | awk '{sum[$3]+=$4; n[$3]++; if($4>max[$3])max[$3]=$4}\n           END{for(k in sum) printf \"%s mean=%.1fms max=%.1fms n=%d\\n\", k, sum[k]\/n[k], max[k], n[k]}'<\/code><\/pre>\n\n\n\n
Step 5: Attack the Right Layer<\/h2>\n\n\n\n