# FPM pool monitoring Retrospective telemetry for the two PHP-FPM pools. Built after the 2026-08-13/14 investigation, where every interesting question — *was the pool saturated at 08:35? is worker RSS growing? which client held the workers?* — turned out to be unanswerable, because the only records were high-water counters that reset on every reload. Two data sources, because neither alone is sufficient: | Source | Answers | Blind to | |---|---|---| | `pm.status_path` (`fpm-sample.sh`) | occupancy, worker memory | *which* request — `ProxyPassMatch` rewrites the long pool's URI to `/index.php` before FPM sees it — and queue depth, which FPM reports as 0 on any UNIX socket | | `ss -lx` (`fpm-sample.sh`, `sockq`) | real accept-queue depth, configured backlog | everything else; it is one number per socket | | Apache access log (`pool-traffic-report.pl`) | per-route duration, status, true concurrency, cost by user agent | anything Apache never logged, e.g. requests the ALB cut at its 600s idle timeout; and client IPs, which are deliberately not collected | | `traffic-YYYY-MM-DD.json` (`fpm-traffic-snapshot --json`) | the same per-route and per-pool figures for any past day, kept forever | sub-hour detail — it is one document per day | | `rollup-YYYY-MM-DD.json` (`fpm-daily-rollup`) | the hourly shape of any past day, kept forever | anything finer than an hour — the raw ticks behind it are gone after 45 days | ## Install ```bash # 1. Sampler sudo install -m 0755 deploy/monitoring/fpm-sample.sh /usr/local/bin/fpm-sample.sh sudo install -m 0644 deploy/monitoring/fpm-pool-metrics.service \ /etc/systemd/system/fpm-pool-metrics.service sudo mkdir -p /var/log/php8.3-fpm/metrics sudo systemctl daemon-reload sudo systemctl enable --now fpm-pool-metrics.service # 2. Retention, and the nightly traffic snapshot (request durations exist only in # Apache's access log, which logrotate discards well before 45 days) sudo install -m 0755 deploy/monitoring/fpm-metrics-prune /etc/cron.daily/fpm-metrics-prune sudo install -m 0755 deploy/monitoring/fpm-traffic-snapshot /etc/cron.daily/fpm-traffic-snapshot # 2b. Permanent hourly archive. Raw ticks are deleted at 45 days; this keeps the # hourly shape of every day forever at ~14 MB/year. Named to sort BEFORE # fpm-metrics-prune ("d" < "m") so a rollup that has fallen behind is never # outrun by the delete. The first run BACKFILLS every day already on disk, so # the archive starts with the full 45 days rather than empty. sudo install -m 0755 deploy/monitoring/fpm-daily-rollup /etc/cron.daily/fpm-daily-rollup sudo /etc/cron.daily/fpm-daily-rollup && ls /var/log/php8.3-fpm/metrics/rollup-*.json | wc -l # 3. Analysis tools (run on demand, not scheduled) sudo install -m 0755 deploy/monitoring/pool-traffic-report.pl /usr/local/bin/ sudo install -m 0755 deploy/monitoring/pool-metrics-summary.pl /usr/local/bin/ # 4. Confirm sleep 40 && sudo tail -2 /var/log/php8.3-fpm/metrics/pool-$(date -u +%F).jsonl ``` Requires `libfcgi-bin` for `cgi-fcgi` (already present on this host) and both pools to keep `pm.status_path = /fpm-status`. ## Use ```bash # Hourly occupancy and memory, both pools sudo pool-metrics-summary.pl /var/log/php8.3-fpm/metrics/pool-$(date -u +%F).jsonl # Several days at once sudo sh -c 'zcat -f /var/log/php8.3-fpm/metrics/pool-*.jsonl* | pool-metrics-summary.pl' # What the long pool ran, with true concurrency sudo pool-traffic-report.pl /var/log/apache2/access.log # Narrow to an incident sudo pool-traffic-report.pl --since '26-08-14 08:30' --until '26-08-14 09:00' \ /var/log/apache2/access.log # The fast pool's traffic too (--all drops the long-pool filter) sudo pool-traffic-report.pl --all /var/log/apache2/access.log # Machine-readable, for the portal monitoring UI. Carries per-pool concurrency, the # ">= N for X seconds" ladder, per-route percentiles and status classes, and both the # requested window and the actual extent -- --until filters on request START, so a # request arriving at 23:59:58 is counted in full and the data runs past midnight. sudo pool-traffic-report.pl --all --json /var/log/apache2/access.log | python3 -m json.tool ``` ## Reading the output without repeating our mistakes **Never multiply `rss_peak_mb` or `rss_avg_mb` by worker count.** Forked workers share most pages copy-on-write, so summed RSS badly overstates real usage — during the investigation 36 workers were added and `used` went *down* 257 MB. `pss_total_mb` is the only field safe to read as a pool total; it is sampled every 20th tick because it costs a page-table walk per worker. `mem_avail_mb` is the ground truth. **Counters reset on reload.** `max_active`, `max_children_reached`, `max_listen_q` and `slow_requests` are cumulative since the pool last started. `pool-metrics-summary.pl` detects a reload by `start_since` going backwards, prints `RELOAD` on that hour and excludes the boundary from its deltas. In the raw JSONL, diffing across a reload yields nonsense. **Between-sample spikes.** The `peak` column is the highest `active` value *sampled*, so a spike shorter than `INTERVAL` can be missed. FPM's own `max_active` field is a high-water mark that cannot miss one — if `peak` looks implausibly low, check `max_active` in the raw JSONL. **`swap_used_mb` is not evidence of swapping.** It stayed at ~1.4 GB while the box was idle, being pages parked during an old peak and never faulted back. The `swout` column (a `pswpout` delta) is what shows active swapping. **Static assets are counted separately, and must be.** Apache serves `/resources/*` and anything with an asset extension from disk without ever reaching PHP. On 2026-08-19 those were 1,521 requests holding 2.9 seconds in total, yet they peaked at 50 simultaneous -- a single page load. Folding them into the non-pool bucket put its peak at 51; excluding them gives 7, which is exactly what the FPM sampler independently reported for `[www]`. The report shows them on their own line, outside every pool. **Concurrency, not request count, sizes `pm.max_children`.** `pool-traffic-report.pl` reconstructs each request's interval as `[timestamp, timestamp + duration]` — Apache's `%t` is the time the request was **received**, not written. The script had this backwards until 2026-08-17 and inflated every peak it reported; if you are reading a concurrency figure quoted from before that, distrust it. The `>= N for X s` lines are the ones to size against: a peak lasting 71 seconds a day is not worth provisioning 40 extra permanent workers for. **Apache is the outer ceiling, not the pool.** `mpm_event` with `MaxRequestWorkers 150` caps the whole host — every vhost together — at 150 concurrent requests, and the 2026-08-13/14 bursts reached 148. No `pm.max_children` above that can do anything, and a reporting burst at that level starves portal and devportal too. This is also why `request_terminate_timeout` matters beyond FPM: a request running 3583s holds one of those 150 Apache threads for the whole hour. **Do not parse the access log positionally.** Field 9 is the duration in ms and field 11 is the status. `awk '$9==502'` selects requests that took 502 *milliseconds*; using it once produced an entirely fabricated error profile. `X-Forwarded-For` also arrives as `ip1, ip2` from the ALB, shifting every later column. Both scripts anchor on the quoted request instead. ## Why the fast pool is sampled too Cheap — one more socket per tick — and it earns it twice over: - **It serves three applications.** `php-fpm-handler.conf` is Included by the solutions, portal and devportal vhosts, so all three share `[www]`'s worker count and limits. When something degrades, per-pool history is the only way to tell which app caused it. This is not hypothetical: all 10 entries in `www-slow.log` were portal's `EmbedLaunch` sitting in `sleep()`, not businessmap-sa at all. - **`/healthcheck.php` runs there.** If the ALB ever marks this instance unhealthy, the question is whether the fast pool was saturated at that second. The one asymmetry: for `[www]` the per-worker request URI **is** meaningful, because `SetHandler` passes the real URI through. So when the fast pool crosses `SATURATION_PCT` busy, the sampler dumps `?full` to `www-saturation-.log` — which names the URI and the script filename, and therefore the application. The long pool gets nothing equivalent; its attribution has to come from the access log. ## Which setting each measurement argues about The point of collecting this is to stop guessing at pool limits. What supports what: | Setting | Evidence | Where | |---|---|---| | `pm.max_children` (both pools) | `peak`, `sockq` (`full` is always 0 on a static pool) | sampler | | `pm.max_requests` | `rsspk` / `pss` correlated with `oldest_s` | sampler | | `memory_limit` | `oom` — nothing else sees a killed request | sampler (FPM log) | | `pm.start_servers`, `pm.min/max_spare_servers` | `busy` | sampler (FPM log) | | `listen.backlog` | `bklog` confirms it took effect, `sockq` how much of it is used, plus 503s in the Apache log | sampler + snapshot | | `request_terminate_timeout` | p95/p99/max duration per route | **snapshot only** | | long-pool route membership | per-route duration and concurrency | **snapshot only** | The last two are why `fpm-traffic-snapshot` matters: the status page exposes no request durations whatsoever, so without the nightly snapshot every timeout and routing decision is limited to whatever is still in `access.log`. Two things this still cannot see, by construction: requests the **ALB** cut at its 600s idle timeout (they are in no local log — that needs ALB access logs), and `max_execution_time` being CPU-time on Linux, so `tmo` staying at 0 does not mean no request ran long. ## The permanent hourly archive `fpm-daily-rollup` folds each finished day into hourly rows and keeps them indefinitely, because `fpm-metrics-prune` deletes the raw ticks at 45 days. ```bash # what a past day looked like, hour by hour, at any age python3 -c 'import json;d=json.load(open("/var/log/php8.3-fpm/metrics/rollup-2026-08-17.json")); [print(h["pool"], h["hour"], h["reqs"], h["active_max"], h["sockq_max"], h["oom"]) for h in d["hours"]]' # the same aggregation on demand, for today or any range zcat -f /var/log/php8.3-fpm/metrics/pool-2026-08-1*.jsonl* | pool-metrics-summary.pl --json - ``` It is `pool-metrics-summary.pl --json`, not a separate implementation — the counter-reset and reload semantics in that script are subtle enough that a second copy would drift from the table everyone reads by eye. Three fields exist only in the rollup and are worth knowing about: | Field | Why it is there | |---|---| | `real_reqs` | `reqs` minus the sampler's own `/fpm-status` polls (one per tick per pool). **`real_reqs ≈ 0` on a pool that has routes means the pool is not receiving them.** `[reporting]` sat unrouted from 2026-08-14 to 08-17 looking perfectly healthy, because "up and idle" and "up and unreachable" are the same picture without this | | `pss_suspect` | true on any hour containing a reload. Both worker generations are alive during a graceful reload and both are counted, so `pss_total_mb` is roughly doubled — reading it as a real total there produced one wrong conclusion already | | `cfg_changed` | true when `max_children`, `memory_limit`, `terminate_timeout` or `pm` changed inside the hour. Occupancy is not comparable across such an hour, and a dashboard drawing its capacity rule at a stale value made a saturated pool look quiet on 2026-08-14 | Counts (`reqs`, `oom`, `slow`, `signal`, …) are always numbers, never null — "no delta recorded" is genuinely zero events. Gauges (`pss_total_mb`, `active_mean`, `oldest_s`, …) are null when absent, so a chart breaks the line instead of plotting a false zero; `pss_total_mb` is legitimately absent on 19 of every 20 ticks by design. Two guards keep the archive alive, and **both should stay**: rollups are named `.json` rather than `.jsonl` so they fall outside `fpm-metrics-prune`'s globs, *and* that script excludes `rollup-*` explicitly. Either one alone is a silent data-loss bug waiting for somebody to rename a file. ## Reading speed, measured Why the raw files are still read directly for recent ranges, rather than everything going through the rollup. PHP streaming these files with `gzopen`/`gzgets` and aggregating into hourly buckets, on the real 32-field line shape: | Range | Lines | Time | Peak memory | |---|---|---|---| | 1 day, raw | 17,280 | 54 ms | 2.0 MB | | 1 day, gzipped | 17,280 | 66 ms | 2.0 MB | | 7 days | 120,960 | 392 ms | 2.0 MB | | 45 days, 45 gz files | 794,880 | 3.16 s | 2.0 MB | Memory is flat because it streams; there is no range wide enough to exhaust `memory_limit`. So raw is comfortably interactive up to a week, the rollup is what makes a multi-month range instant, and `gzopen` reads plain files too so one code path handles both. ## Disk usage Bounded, and small. Measured against a generated day at `INTERVAL=15`: | | | |---|---| | line length | ~590 bytes (grew with the config and socket fields) | | lines/day | 17,280 (3 pools × 5,760 ticks) | | raw | ~10.2 MB/day | | gzipped | ~0.21 MB/day (48:1 — the keys repeat every line) | | **steady state at 45-day retention** | **~30 MB total** (2 days raw + 43 gzipped) | | rollups | 550 B per pool-hour → 39 KB/day → **~14 MB/year, kept forever** | | traffic JSON | ~1 KB per distinct route per day → single-digit MB/year, kept forever | A year of hourly history therefore costs less than a day and a half of raw ticks. That is a ceiling, not a trend: `fpm-metrics-prune` gzips past 2 days and deletes past 45, so the total stops growing after day 45. Without retention it would be ~1.5 GB/year. To halve it, set `Environment=INTERVAL=30` in the unit — at the cost of being twice as likely to miss a spike between samples. `www-saturation-.log` is written only when the fast pool is at least `SATURATION_PCT` busy, which has never been observed (peak has been 6–9 of 40, or 15–22%). A `?full` table runs ~500 bytes per worker, so ~21 KB per dump at 40 workers; `SATURATION_COOLDOWN` caps it at one dump a minute, bounding a sustained incident at ~30 MB/day instead of ~124 MB/day. The same prune job covers it. **The FPM slowlogs need their own stanza.** `long-slow.log` and `www-slow.log` live in the same directory but are written by FPM, not the sampler — and the packaged `/etc/logrotate.d/php8.3-fpm` covers only `/var/log/php8.3-fpm.log`, so they matched nothing and grew unbounded. `www-slow.log` fires at 30s and writes a full backtrace each time. Install the stanza: ```bash sudo install -m 0644 deploy/monitoring/logrotate-php8.3-fpm-slowlog \ /etc/logrotate.d/php8.3-fpm-slowlog sudo logrotate -d /etc/logrotate.d/php8.3-fpm-slowlog # dry run, then drop -d ``` It is a separate file so a `php8.3-fpm` package upgrade does not prompt about a modified conffile, and it is scoped to `*-slow.log` so it can never touch `metrics/`. ## Not covered here - **ALB access logs (S3).** The single biggest remaining blind spot. The 502s that started this whole investigation appear *nowhere* in Apache's log — ~224k requests, zero 502s — because the ALB generated them itself after its 600s idle timeout fired on requests still queued behind a saturated pool. Only ALB access logs record those. Costs S3 storage and needs a bucket policy. - **CloudWatch alarms.** `HTTPCode_ELB_5XX_Count`, `UnHealthyHostCount` and `TargetConnectionErrorCount` are already emitted by the ALB at no extra cost; they just have no alarms attached. That is the cheapest alerting available here. - **Prometheus / Grafana.** Deliberately avoided. On a 2-vCPU box already running Apache and two pools for three applications, an exporter plus a scraper costs more than it returns for a single instance.