Skip to content

docs(performance): separate pre-#354 cold baseline from warm post-fix measurement #145

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Open
koriym wants to merge 1 commit into
base: 1.x
Choose a base branch
from
Open

docs(performance): separate pre-#354 cold baseline from warm post-fix measurement #145

Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
121 changes: 107 additions & 14 deletions docs/performance.md
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down Expand Up @@ -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
Expand Down Expand Up @@ -98,29 +104,116 @@ 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 |
|---|---|---|
| reflection | **~0.4–0.6 s** | Container build (annotation reading + binding analysis + AOP weaving) dominates |
| 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
Expand Down
Loading