From cc0ae2a893e4ad850bc6e10a0d0dc8a535cce35c Mon Sep 17 00:00:00 2001 From: Akihito Koriyama Date: Sat, 12 Sep 2026 00:10:01 +0900 Subject: [PATCH] docs(performance): separate pre-#354 cold baseline from warm post-fix measurement Label the existing production-scale table as a historical, pre-fix, cold single-run observation. Add a distinct section for the ray-di/Ray.Di#354 unserialize() lazy-Reflection fix measured under warm OPcache SHM with a paired before/after comparison and a same-conditions three-way rerun, so cold and warm numbers are never mixed into the same table or ratio. Refs ray-di/Ray.Compiler#135, ray-di/Ray.Di#354 --- docs/performance.md | 121 +++++++++++++++++++++++++++++++++++++++----- 1 file changed, 107 insertions(+), 14 deletions(-) diff --git a/docs/performance.md b/docs/performance.md index 829045d8..1ed5a25a 100644 --- a/docs/performance.md +++ b/docs/performance.md @@ -14,10 +14,12 @@ and a `serialize()`d injector. | Strategy | What runs per object graph | Runtime cost | Notes | |---|---|---|---| -| **reflection** (`Ray\Di\Injector`) | Build the whole `Container` from the module (annotation reading, binding resolution, AOP weaving), then instantiate via reflection | Container build is **hundreds of ms** for a large app, paid **every process** | Dev only. Untenable for shared-nothing (php-fpm). | -| **serialize** (`serialize()` the injector, `unserialize()` per request) | `unserialize()` reconstructs the `Container` object graph, then instantiate via reflection | Dominated by **`unserialize()`** — paid **every process** (a blob is data; it cannot live in shared OPcache) | Scales linearly with the binding set. | +| **reflection** (`Ray\Di\Injector`) | Build the whole `Container` from the module (annotation reading, binding resolution, AOP weaving), then instantiate via reflection | Container build is **hundreds of ms** for a large app, paid **every request** | Dev only. Untenable for shared-nothing (php-fpm). | +| **serialize** (`serialize()` the injector, `unserialize()` per request) | `unserialize()` reconstructs the `Container` object graph, then instantiate via reflection | Dominated by **`unserialize()`** — paid **every request** (a blob is data; it cannot live in shared OPcache) | Scales linearly with the binding set. | | **compiled** (`CompiledInjector`) | `require` the few pre-generated scripts the graph touches, run flat `new`/setter code | **Lazy** — only the needed scripts; opcodes served from OPcache | Scripts/classes can be **preloaded** into shared memory across php-fpm workers. | +php-fpm resets all object state between requests; only long-lived workers (Swoole, RoadRunner) amortize this. + Key consequence: the heavy work (annotation reading, AOP class generation, binding analysis) is done **once at compile/serialize time** for both `serialize` and `compiled`. What remains at runtime is instantiation. `compiled` wins because flat, OPcache-cached opcodes beat reflection's dynamic @@ -68,7 +70,11 @@ tell a valid run from a bogus one**. Pitfalls it (and you) must control for: **not** work on the CLI — OPcache's age check uses the request start time, not wall-clock. Always confirm the benchmark reports `(valid)` / a non-zero cached-script count; if it prints `INVALID`, the numbers are re-parsing artifacts. -2. **Disable Xdebug** (`-d xdebug.mode=off`) — it inflates everything. +2. **Disable Xdebug and verify it actually took effect** (`-d xdebug.mode=off`) — it inflates + everything, but the setting alone is not proof: assert `xdebug_info('mode') === []` in the + benchmarked process itself. `ini_get('xdebug.mode')` is not sufficient — it can report `''` + while Xdebug is still active in another mode (e.g. a php-fpm pool config not honored at + runtime). 3. **Watch for a stale global `opcache.preload`** in your `php.ini` — it pollutes shared memory and can emit startup errors. Override it with an empty preload file. 4. **Class-autoload warmth** — the first object graph in a process autoloads all its classes (a @@ -98,11 +104,13 @@ Run it yourself: php -d xdebug.mode=off -d opcache.enable_cli=1 -d opcache.validate_timestamps=0 demo/benchmark/di_benchmark.php ``` -## Measured at production scale +## Measured at production scale (historical baseline, pre-[#354](https://github.com/ray-di/Ray.Di/pull/354), cold single-run) -The fixture above is small. These numbers are from a large production BEAR.Sunday application -(~600 compiled DI scripts; PHP 8.3, OPcache on, Xdebug off), measuring the per-process cost to -acquire the application root — i.e. one cold php-fpm request [#135]: +These numbers are a single cold-process observation from a large production BEAR.Sunday +application (~600 compiled DI scripts; PHP 8.3, OPcache on, Xdebug off), captured before +[ray-di/Ray.Di#354](https://github.com/ray-di/Ray.Di/pull/354)'s `unserialize()` fix, measuring the per-process cost to acquire the +application root — i.e. one cold php-fpm request ([#135](https://github.com/ray-di/Ray.Compiler/issues/135)). This is a single indicative data +point, not a controlled before/after comparison — see the warm, paired measurement below for that. | Strategy | Cost | Breakdown | |---|---|---| @@ -110,17 +118,102 @@ acquire the application root — i.e. one cold php-fpm request [#135]: | serialize | **~29 ms** | ≈ `unserialize()` of the whole Container (~25 ms, mostly class autoload) + build (~4 ms); blob ~0.5 MB | | compiled | **~5 ms** | lazy `require` of only the scripts the root touches (~30 of ~600); offline compile ~0.5 s | -- **reflection** rebuilds the entire Container every process — untenable for shared-nothing. This is - the cost the other two exist to avoid. +- **reflection** rebuilds the entire Container every request (php-fpm resets object state between + requests) — untenable for shared-nothing. This is the cost the other two exist to avoid. - **serialize** scales ~linearly with the binding set, and the blob cannot live in shared OPcache — - it is re-`unserialize()`d per process. + it is re-`unserialize()`d every request. - **compiled** loads only what a request needs — cost tracks the scripts a request touches, not the total binding set — and its scripts can be preloaded into shared OPcache across workers. -In a warm worker `unserialize()` drops to ~1–2 ms (classes already loaded), so warm serialize and -compiled both land in the low-millisecond range; the dramatic gap is the cold first request and how -the per-request work scales. These are indicative single-run figures on one machine — warm steady -state was not cleanly isolated — so treat warm numbers as approximate. +The measurements below share the same runtime configuration and object graph (this app's +federated-import feature disabled to isolate its own object-graph cost, PHP 8.5.10, php-fpm +started with `-d xdebug.mode=off` and `XDEBUG_MODE=off`, `xdebug_info('mode') === []` asserted on +every recorded sample, `opcache.validate_timestamps=0`, php-fpm `pm.max_requests=1` fresh process +per request) but follow separate protocols — don't merge their numbers into one table or ratio. + +## Measured after [ray-di/Ray.Di#354](https://github.com/ray-di/Ray.Di/pull/354) (warm OPcache SHM, same app) + +An earlier version of this section reported numbers measured while Xdebug was actually running in +`develop` mode despite the php-fpm pool's `xdebug.mode=off` setting — Xdebug did not honor it, and +the per-sample check at the time only verified `ini_get('xdebug.mode')` (always `''`) instead of +`xdebug_info('mode')` (which reported `['develop']`). The headline claim itself changed, not just +`reflection`'s number: paired total diff median was reported as -7.86 ms (29.1% reduction); +corrected value is -5.14 ms (33.9% reduction). The numbers below are a corrected re-measurement +asserting `xdebug_info('mode') === []` on every sample; see +[ray-di/Ray.Compiler#135](https://github.com/ray-di/Ray.Compiler/issues/135#issuecomment-5636446726) +for the retraction — the invalid data is no longer published, but remains visible in the +[gist](https://gist.github.com/koriym/db1c3b8bccd8c7c6bc18d4a2a51c622c)'s revision history. + +**Three-way comparison** (n=20 rotations, fixed order reflection → serialize → compiled, one +php-fpm restart, one warmup request per endpoint discarded before rotations began — relevant +bytecode was warmed before recorded samples): + +| Strategy | Median | IQR | +|---|---|---| +| reflection | 311.27 ms | [310.88, 312.21] | +| serialize | 7.93 ms | [7.65, 8.11] | +| compiled | 1.34 ms | [1.24, 1.36] | + +This table's `serialize` row and the paired comparison below time the identical +`serve_serialize()` region (blob read, `unserialize()`, `SchemeCollectionInterface`, +`AppInterface`) — same code, same graph; `reflection`/`compiled` here use separate endpoint +scripts. This batch's `serialize` median (7.93 ms) is lower than the paired run's after-arm +`total_ms` median below (9.95 ms) by about 25%, and it's a directional, explainable gap rather +than symmetric noise: `fpm_restart` fully stops and restarts the php-fpm master, which tears down +and rebuilds OPcache's shared memory. This table restarts the master once for the whole +60-request batch (1 warmup per endpoint, then 20 rotations) — its `serialize` row runs on OPcache +SHM that has also been populated by up to 19 prior `reflection`/`compiled` rotations (plus that +rotation's own `reflection` hit). The paired run +restarts the master before every single recorded sample (3 discarded warmups each, 40 restarts +total), so its `serialize` measurements never get that cross-endpoint SHM warmth. The three-way +`serialize` number is biased low relative to the paired run for this reason, not measurement +error. + +Ratios within this table only (same batch): reflection/serialize 39.2×, reflection/compiled +231.7× (per-rotation median, IQR [228.3, 253.6]), serialize/compiled 5.9×. + +**[PR #354](https://github.com/ray-di/Ray.Di/pull/354)'s effect on the serialize strategy** — paired before/after (n=20 pairs; a full php-fpm +master restart and 3 discarded warmup requests between each swap of `vendor/ray/di`, a separate +protocol from the three-way run above): + +| Phase | Median diff (after − before) | IQR | +|---|---|---| +| `unserialize()` only | -5.63 ms | [-5.91, -4.98] | +| Total root acquisition | -5.14 ms | [-5.50, -4.56] | + +All 20/20 pairs improved (33.9% median reduction in total root-acquisition cost; 41.6% on +`unserialize()` alone, 40.3% when the tiny blob-read step is folded in as "read+unserialize"). The +~0.49 ms gap between the `unserialize()`-only row and the total is downstream first-touch +`ReflectionParameter` rebuild cost. It doesn't split evenly across the medians of the two +downstream phases shown below (medians aren't additive) — the mean reconciliation is exact +instead: -5.461 ms (`unserialize()`) + 0.053 ms (`SchemeCollectionInterface`) + 0.337 ms +(remaining `AppInterface` resolution) = -5.071 ms (total mean). Classes declared during +resolution rise from 39 to 68 as bindings untouched by the old eager rebuild get built lazily +instead. What changes is how many classes +`unserialize()` actually needs to declare in the first place (710 → 61), by deferring +`ReflectionParameter` rebuilding in `Argument`/`InjectionPoint` until a dependency is actually +used. Full phase breakdown, commit +SHAs, and raw per-cycle data: +[ray-di/Ray.Compiler#135](https://github.com/ray-di/Ray.Compiler/issues/135#issuecomment-5636446726) +(comment; raw data: +[gist](https://gist.github.com/koriym/db1c3b8bccd8c7c6bc18d4a2a51c622c)). + +**Single first-hit observations, supplementary only, not used in either table above**: +reflection's first hit after the php-fpm restart was 482.62 ms — a genuinely cold observation, +above its warm median. serialize's first hit was 9.11 ms and compiled's was 4.71 ms, but neither +is a clean cold measurement — each ran in its own fresh process (`pm.max_requests=1`), but +reflection's hit had already populated shared OPcache, so only compiled's own script bytecode was +still uncompiled. + +Separately, from the paired run's own first request after each restart — the first of the three +discarded warmup requests, not the three-way batch above (a different protocol) — paired, n=20: +total diff median -83.76 ms (IQR [-84.27, -82.75]), 20/20 negative — the deferred rebuild +also removes a large share of the true cold path's bytecode-compilation load. + +Neither table above is comparable to the historical cold single-run table above it (different +app-federation state and pre-fix code). Both tables share the same caveats as the linked issue +comment: single machine, single app, no formal significance testing, no CPU/throughput +measurement. The structure behind these numbers: `compiled` moves work from request time to build time, makes the runtime cost proportional to what a request actually uses rather than to the total binding set, and