skip to content

In PHP, a request takes 900 ms of wall time but its getrusage() CPU time is only 60 ms; what does that gap mean?

level: middleimportance: should knowfreq 30%

answer

  1. waiting is not computing
  2. ru_utime plus ru_stime
  3. snapshot before and after, then subtract
  4. an FPM worker's counters span many requests
  5. database time is another process's CPU

basics

~20 s

Wall time is elapsed real time; CPU time is what the PHP process spent executing, from getrusage() as user plus system time. A 900 ms versus 60 ms gap means the request mostly waited on I/O.

solid answer

~40 s

Measure wall time with `hrtime(true)` deltas and CPU time with `getrusage()`, adding `ru_utime.tv_sec`/`ru_utime.tv_usec` (user mode) and `ru_stime.tv_sec`/`ru_stime.tv_usec` (kernel work on the process's behalf). The counters are cumulative for the whole process, and a PHP-FPM worker serves many requests, so take a snapshot at the start and at the end and subtract. 900 ms of wall time with 60 ms of CPU means over 90 % of the request was spent waiting: a slow query, an outbound HTTP call, a lock, a DNS lookup, a `sleep()`. The database's own work is on another process's CPU and never appears here. The next step is timing each I/O call, not tuning loops. When CPU time is close to wall time, PHP itself is burning the time, and a CPU profile of the code is the right tool.

code

php · 21 lines
php
<?php
declare(strict_types=1);

function cpuMicros(): int
{
    $u = getrusage();
    if ($u === false) {
        return 0;
    }
    return ($u['ru_utime.tv_sec'] + $u['ru_stime.tv_sec']) * 1_000_000
        + $u['ru_utime.tv_usec'] + $u['ru_stime.tv_usec'];
}

$wall0 = hrtime(true);
$cpu0 = cpuMicros();

handleRequest();

$wallMs = (hrtime(true) - $wall0) / 1e6;
$cpuMs = (cpuMicros() - $cpu0) / 1e3;
error_log(sprintf('wall=%.1fms cpu=%.1fms', $wallMs, $cpuMs));

go deeper

for a junior

Know the words: wall time is what the user waits, CPU time is what the process spent computing. PHP's getrusage() gives user and system CPU time.

for a middle

Explain the delta rule under PHP-FPM and how to add the seconds and microseconds fields. Interpret a low CPU-to-wall ratio as waiting on I/O and name the usual suspects.

for a senior

Use the ratio to choose the next tool: spans around I/O for waiting, a CPU profile for computing. Mention context switches and host saturation as ways the ratio can mislead.

for a principal

Argue for logging wall and CPU time per request by default, so every regression starts with a known split instead of an argument about whether the code or the database got slower.

## Two different questions **Wall time** (also called elapsed or real time) is what a stopwatch would show: from the moment the request started to the moment it finished. It is what the user waits for. **CPU time** is the time a processor core actually spent executing the process's instructions. It splits into two parts: - **user time**: executing the process's own code, which for PHP means the engine running your script, including internal functions like `preg_match()` or `json_encode()`; - **system time**: the kernel working on the process's behalf, such as copying bytes for `read()` and `write()` calls or managing memory. A single-threaded PHP request normally cannot use more CPU time than wall time, apart from measurement granularity, so the interesting number is the **ratio**. ## Reading getrusage() `getrusage(int $mode = 0): array|false` wraps the `getrusage(2)` system call. Mode `0` reports the calling process; mode `1` reports its terminated, waited-for child processes (`RUSAGE_CHILDREN`), for example commands started with `proc_open()`. The CPU fields are split into seconds and microseconds: | Key | Meaning | |---|---| | `ru_utime.tv_sec`, `ru_utime.tv_usec` | user CPU time | | `ru_stime.tv_sec`, `ru_stime.tv_usec` | system CPU time | | `ru_maxrss` | peak resident set size of the process | | `ru_nvcsw`, `ru_nivcsw` | voluntary and involuntary context switches | On Windows only the time fields and a couple of others are filled in. ## The delta rule The counters describe the **whole process since it started**, not the current request. Under the CLI that is roughly the script, but a PHP-FPM worker is forked once and then serves hundreds or thousands of requests. Reading `getrusage()` once at the end of a request reports the CPU time of every request that worker ever served. So: 1. Snapshot CPU time (and `hrtime(true)`) as early as possible in the request. 2. Snapshot both again at the end. 3. Subtract, and log the two numbers together with the route or request id. ## Interpreting the ratio | CPU / wall | What it usually means | Where to look next | |---|---|---| | low (under ~30 %) | the request is **waiting**: database, HTTP APIs, cache servers, file locks, DNS, `sleep()` | time each outbound call with `hrtime()` spans; count queries | | high (close to 100 %) | PHP is **computing**: rendering, large array transformations, regular expressions, hashing, serialization | a CPU-time profile of the PHP code | | mixed | both | split the request into phases first | For the 900 ms / 60 ms request, over 90 % is waiting. The database server did work too, but on its own CPU, in another process, so it counts as waiting from PHP's point of view. Micro-optimizing loops could shave a few of the 60 ms at most; finding the slow query or the new API call is where the 840 ms are. Another signal is **context switches**: a high count of voluntary switches (`ru_nvcsw`) means the process blocked many times, which fits many small I/O calls such as a query inside a loop. A process that is ready to run but is not getting a core, because the host is overloaded, also shows wall time well above CPU time, so check host load before blaming the code. ## When system time is high Most PHP requests are dominated by user time. A large **system** share is a clue of its own: the kernel is doing a lot on the process's behalf. Common PHP causes are: - many filesystem calls, such as `file_exists()` or `is_file()` checks repeated on every request; - reading or writing large files in small chunks; - many small network writes, for example logging each line to a remote socket; - allocating and freeing large amounts of memory. In each case the fix is fewer or larger system calls, not faster PHP code. ## Why it matters for profiling The same split decides which profiler view to trust. A **CPU-time** profile shows only where PHP burned cycles and hides a request that is slow because it waits; a **wall-time** profile includes the waiting and shows which call blocked. Deciding which one you need is the first step of any PHP performance investigation, and the `getrusage()` ratio answers it in two lines of code.

  • Why does getrusage() called only at the end of a request under PHP-FPM give absurdly large CPU numbers?
    Because it reports the process's cumulative usage since the worker started, and an FPM worker handles many requests before it is recycled. The number grows with every request it has served. Take a snapshot at the start of the request and subtract it from the one at the end.
  • The CPU-to-wall ratio is near 100 % but the host is also at 100 % CPU. Is the PHP code necessarily slow?
    Not necessarily. With a busy host the request may also wait in the run queue, which inflates wall time without adding CPU time, and heavy CPU per request may be normal work multiplied by high traffic. Compare CPU time per request against a baseline release, not against wall time alone, before deciding the code regressed.

saying these in an interview costs you the question

  • Reads getrusage() once at request end under FPM and treats it as that request's CPU.
  • Assumes the time a SQL query spends in the database shows up as PHP CPU time.
  • Responds to a wait-dominated request by micro-optimizing PHP loops.
  • Believes wall time and CPU time are always roughly equal for a PHP request.
  • Adds tv_sec and tv_usec together without converting units.