Profiling PHP-FPM Bottlenecks on a VPS: slowlog, strace, and Real Request Tracing

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.

Step 1: Turn On the PHP-FPM Slow Log

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.

# /etc/php/8.4/fpm/pool.d/www.conf
request_slowlog_timeout = 2s
slowlog = /var/log/php8.4-fpm-slow.log
request_terminate_timeout = 60s
request_slowlog_trace_depth = 30

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.

sudo systemctl reload php8.4-fpm
tail -f /var/log/php8.4-fpm-slow.log

A representative entry looks like this:

[20-Sep-2026 11:04:22]  [pool www] pid 41207
script_filename = /var/www/site/public/index.php
[0x00007f] curl_exec() /var/www/site/vendor/guzzle/src/Handler/CurlHandler.php:44
[0x00008a] sendAsyncRequest() /var/www/site/vendor/guzzle/src/Client.php:190
[0x000131] request() /var/www/site/app/Services/PricingApi.php:88
[0x0001c9] quote() /var/www/site/app/Http/ProductController.php:57

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() inside an outbound API call — no amount of PHP tuning will help. The fix is a timeout and a cache, not more workers.

Step 2: Classify the Bottleneck Before You Touch Config

Slow-log top frame	Class	Correct response
curl_exec, stream_socket_client	Network I/O wait	Timeout + cache; never add workers
PDOStatement::execute	Database latency	Index work, buffer pool sizing
file_get_contents, include	Disk I/O / missing opcache	Enable opcache, check realpath cache
sleep, flock, sem_acquire	Lock contention	Move sessions out of files, remove locks
Deep in your own application code	Genuine CPU	Profile with a sampling profiler

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.

Step 3: Confirm With strace on a Single PID

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 multiplies syscall overhead and will distort your own measurement.

# find a worker currently handling a request
pgrep -af 'php-fpm: pool www'

# trace it, showing only slow syscalls
sudo strace -f -T -e trace=network,read,write -p 41207 2>&1 | awk '{ if ($NF ~ /\./ ) print }'

The -T flag appends the duration of each syscall in seconds. A recvfrom() or poll() sitting at <1.2> 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.

When the slow-log frames point at PDOStatement::execute, the investigation moves to MySQL, and the arithmetic laid out in sizing the InnoDB buffer pool for a 1 GB VPS is the first thing to check, because a buffer pool smaller than the working set turns every read into a disk seek.

Step 4: A Minimal In-Process Timing Harness

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:

function timed(string $label, callable $fn) {
    $t0 = hrtime(true);
    $out = $fn();
    $ms = (hrtime(true) - $t0) / 1e6;
    error_log(sprintf('TIMING %-24s %8.2f ms', $label, $ms));
    return $out;
}

$rows = timed('db.products', fn() => $pdo->query('SELECT * FROM products')->fetchAll());
$rate = timed('http.pricing', fn() => $client->quote($id));

hrtime(true) returns nanoseconds from a monotonic clock and is unaffected by NTP steps — unlike microtime(), 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:

grep TIMING /var/log/php8.4-fpm.log \
  | awk '{sum[$3]+=$4; n[$3]++; if($4>max[$3])max[$3]=$4}
           END{for(k in sum) printf "%s mean=%.1fms max=%.1fms n=%d\n", k, sum[k]/n[k], max[k], n[k]}'

Step 5: Attack the Right Layer

• Network wait: wrap every external call in a 2 s timeout and a 60 s cache. A hung API must never hold a worker for 30 s.
• Database latency: fix the query or the buffer pool. Adding FPM workers while the DB is saturated simply moves the queue.
• Disk/opcache: verify opcache.enable=1 and opcache.validate_timestamps=0 in production, with a deploy hook to reload FPM.
• Lock contention: move sessions to Redis. File-based sessions serialise on the same inode and are a classic hidden stall.
• Genuine CPU: this is the only case where a larger instance or a faster core actually helps. Our VPS configuration and sizing pages cover what each tier delivers under sustained load.

One caution on profiling overhead: an always-on APM agent can add 5–15 percent CPU. On a single-core VPS that is real money. Start with the FPM slow log, escalate to strace for a single PID, and only install an agent once you have proven which class of bottleneck you are chasing.

The One-Line Summary

Idle CPU plus a slow page almost always means waiting, not computing. Measure what the process is waiting on before you change a single setting — and revisit the PHP-FPM pool sizing rules only after the wait is eliminated.