Measuring the overhead¶
Observing a site costs something. This page states how that cost is measured here, so that any number published about it can be reproduced or contradicted. A percentage with no method behind it is not a measurement.
For what that cost buys, and whether it is worth paying, see Overhead cost. This page is the method, for anyone who wants to reproduce or contest a number; that one is for deciding whether to install the module.
What the number has to answer¶
There are two questions, and one answer does not serve both.
Does the visitor wait longer? This is response latency: the time between the request arriving and the response leaving.
How much machine does it cost? This is capacity: how much CPU a request consumes, and therefore how many requests per second the same hardware can still serve.
They do not coincide here, because of how this module writes. Observability rows are buffered
during the request and flushed on KernelEvents::TERMINATE, which Drupal fires after the
response has been sent to the client (see DeferredPersistenceFlushSubscriber). That flush
happens while the visitor is already reading the page, so it never shows up in a latency benchmark.
The figures below are one machine's, not yours
Every number on this page comes from runs on one development laptop. They illustrate the protocol and the proportions it reveals, not a result to expect elsewhere: the same command repeated on the same machine produced fixed costs ranging from 4.59 to 5.40 ms. Run it on your own server to get figures that describe it.
That is not most of the cost. Measured on this session's request-log census, front page,
warm-up request discarded, 20 requests, the module's own total was 6.253 ms per request, and
only 0.379 ms (6.1%) of it is that deferred flush. The remaining 5.874 ms (93.9%) runs
inside handle(), before the response is sent, and the visitor waits for all of it:
| ledger key | inside handle() |
share of the total |
|---|---|---|
execution.response |
1.80 ms | 28.8% |
span.trace_link |
1.30 ms | 20.8% |
cache.page |
0.80 ms | 12.8% |
trace.response |
0.80 ms | 12.8% |
cache.response |
0.72 ms | 11.5% |
terminate.flush |
0.38 ms | 6.1% (the only one after the response) |
These are the five largest of the fourteen keys the capture cost ledger censused for that run (see the generated table below for the full set of ledger keys); the rest is spread thinly across the remaining nine and does not change the 93.9/6.1 split.
The reasoning behind "invisible in latency" was correct about what deferral moves and incomplete
about how much: deferring the writes moves the writes out of the request. It does not move
execution.response's AJAX-correlation attachment, span.trace_link's trace-to-span linking,
cache.page's page-cache bookkeeping, or trace.response/cache.response themselves, because none
of those are writes in the first place: they are instrumentation that runs, and finishes, before the
response leaves. A benchmark that measures only response latency is not blind to this module's cost;
it sees the large majority of it.
Rule 1: compare two states of one site, not two sites¶
Uninstalling the module changes the service container, the routing table and the schema. Reinstalling it changes them back. Anything measured across that boundary includes the cost of the difference in the site, not only the cost of observing.
Toggle native_observability.settings:capture.enabled instead. It is the master switch read at
runtime by CaptureGate, and every observer consults it. The code is loaded in both states, the
services are built in both states, and the only difference is whether the work is done.
drush cset native_observability.settings capture.enabled 0 -y # off
drush cset native_observability.settings capture.enabled 1 -y # on
State plainly what this excludes: the fixed cost of the module being installed at all, which is container size and autoloading, not per-request work. The bundled command (below) does this toggling itself, for exactly this reason.
Rule 2: interleave the blocks, never run one state then the other¶
A machine does not perform identically for minutes at a stretch. Thermal state, other processes, page cache in the host, container scheduling: all of it drifts, and on a development laptop that drift can be larger than the effect being measured. A comparison that runs one long block with the module off and then one long block with it on cannot tell that drift apart from the module's own cost, and can report a negative number for a module that only ever adds work.
Run pairs. Inside each pair run both states, and alternate which state goes first from one pair to the next, so that any effect of ordering cancels as well.
Rule 3: paired differences, with a deterministic significance test¶
Do not subtract the mean of all the "on" blocks from the mean of all the "off" blocks. Compute the difference within each pair, then report the median of those differences.
The bundled command runs an exact two-sided sign test on the paired differences instead of a
bootstrap confidence interval: same input measurements, same reported p every time, with no
pseudo-random resampling anywhere in the calculation.
When the effect does not exceed the noise floor (below), the result is that the effect is below the noise floor of the measurement. That is a result, and it is publishable as such. It is not a failed run to be repeated until it comes out positive.
Rule 4: prove the two states are actually different¶
A configuration toggle that silently fails to take effect makes the harness measure the same state twice and report the difference as an effect. The output looks like a clean result.
The bundled command does this for you: it counts the rows written to the observability tables during every ON block and every OFF block, and reports both counts per workload. An OFF block that wrote a row, or an ON block on an HTTP route that wrote none, produces an explicit warning instead of a silently wrong number.
Rule 5: name the route and name the load¶
The percentage has a denominator, and the denominator is whatever the page was already doing. The same absolute cost is 1 percent of a page that takes 300 ms and 15 percent of a page that takes 20 ms. A percentage quoted without the route it was measured on cannot be checked and cannot be compared.
Use pages the site really serves, and record which ones. A front page with no content published on it understates the work, because the observers scale with the queries and the cache operations a page performs.
Rule 6: absolute first, percentage second¶
Publish milliseconds per request first. Publish the percentage after, never instead of it. The absolute figure survives being read on a different machine; the percentage does not.
Rule 7: discard the warm-up¶
The first requests after a configuration change run with a cold opcache and a cold container. The bundled command runs one extra pair before the measured ones and discards it, for exactly this reason: see the "Warmed Up" requirement in this change's spec.
Rule 8: declare what is not in the number¶
At minimum: the hardware and whether it is a development machine, the page cache setting, and the volume of data already in the observability tables. Insert cost grows with index size, so a run against empty tables reports a lower number than a site that has been collecting for a month. The command's own legend states, every time it prints, that the result is proportional to the machine it ran on and is not transferable to another installation.
Where the module touches the pipeline¶
| Point | Type | Target | Priority | Owner module | Cost-ledger keys |
|---|---|---|---|---|---|
GuzzleSpanMiddleware (Outbound HTTP span middleware) |
HTTP client middleware | native_observability_spans.guzzle_span_middleware |
n/a | native_observability_spans |
http.span |
GuzzleTraceMiddleware (Execution HTTP trace middleware) |
HTTP client middleware | native_observability_execution.guzzle_trace_middleware |
n/a | native_observability_execution |
http.trace |
ObservedCacheTagsInvalidator (Observed cache-tags invalidator) |
Tagged collection | cache_tags.invalidator |
n/a | native_observability_cache_observer |
cache.invalidate |
CachePageObserverMiddleware (Page-cache observer middleware) |
HTTP middleware | http_middleware |
210 | native_observability_cache_observer |
cache.page |
TraceSubscriber (Core trace subscriber) |
Event subscriber | kernel.response |
-100 | native_observability |
trace.request, trace.response, trace.exception |
CacheResponseObserverSubscriber (Cache response observer subscriber) |
Event subscriber | kernel.response |
-90 | native_observability_cache_observer |
cache.response |
RequestSummarySpanSubscriber (Request summary span subscriber) |
Event subscriber | kernel.response |
-95 | native_observability_spans |
span.request_summary |
ExecutionRequestSubscriber (Execution request subscriber) |
Event subscriber | kernel.request |
0 | native_observability_execution |
execution.request, execution.response |
OpenTelemetryTraceSubscriber (OpenTelemetry trace subscriber) |
Event subscriber | kernel.response |
-110 | native_observability_otel |
otel.response |
DatabaseQueryObserverSubscriber (Database query observer subscriber) |
Event subscriber | kernel.request |
1000 | native_observability_database_observer |
db.log_start, db.classify |
DatabaseSummarySpanSubscriber (Database summary span subscriber) |
Event subscriber | kernel.response |
-96 | native_observability_spans |
span.database_summary |
DeferredPersistenceFlushSubscriber (Deferred persistence flush subscriber) |
Event subscriber | kernel.terminate |
-100 | native_observability |
terminate.flush |
SpanTraceLinkSubscriber (Span trace-link subscriber) |
Event subscriber | kernel.response |
-1000 | native_observability_spans |
span.trace_link |
TracesDeletedSubscriber (Traces-deleted span cleanup subscriber) |
Event subscriber | native_observability.traces_deleted |
n/a | native_observability_spans |
none |
RequestLogExclusionSubscriber (Request log exclusion subscriber) |
Event subscriber | kernel.request |
1500 | native_observability |
none |
native_observability_execution_page_attachments() (Execution ajax-correlation page attachment) |
Hook | page_attachments |
n/a | native_observability_execution |
none |
Points that induce cost outside the module itself:
DatabaseQueryObserverSubscriber: Calls Database::startLog(), which arms core's per-statement logging path: every query issued for the rest of the request then pays a debug_backtrace(DEBUG_BACKTRACE_IGNORE_ARGS) inside Connection::findCallerFromDebugBacktrace() (Database.php:87 -> StatementBase.php:148 -> Connection.php:1628).
Writes, and the phase they happen in:
- Before the response is sent:
DatabaseTraceStorage::insert()writes one row tonative_observability_trace, invalidates a cache tag, and dispatches the TRACE_RECORDED event. - After the response is sent, on
KernelEvents::TERMINATE:DeferredPersistenceFlushSubscriberflushes three buffers of deferred events (cache, span and query) that were held during the request. Measured, this is 6.1% of the module's own per-request cost (see above), not most of it: the rest of the table above runs, and finishes, before the response leaves.
This module does not publish an overhead percentage as a constant. There is no number that applies across installations: the cost depends on the hardware, the database, the volume of data already collected, and which pages the site actually serves. What it publishes instead is the inventory above, and a supported way to measure the cost on a specific machine, described next.
What is not persisted¶
Not every observation the module makes becomes a database row.
DatabaseQueryObserverSubscriber keeps per-request query counts (total count, total time, count by
table) in memory for the whole request, and only writes the individual, per-query rows for queries
that exceed slow_query_threshold_ms (100 ms by default), up to max_stored_queries_per_request
rows per request (20 by default). Both are configuration keys on
native_observability_database_observer.settings, documented in
Database observer settings. A page that runs 200
fast queries produces zero query-detail rows from that page, not 200: the aggregate counts still feed
the database tab's totals, but the per-query text and timing only exist for the slow ones, and only
up to the cap.
This is not an alerting system: the module has none. Nothing pages an operator, fires a webhook, or
escalates when a query crosses the threshold. The threshold only decides what gets written to the
native_observability_database_query table for later inspection in the dashboard or an export.
Running it¶
The supported way to measure overhead on a given machine is the bundled Drush command. It runs the protocol above (paired blocks, alternating order, a discarded warm-up pair, a noise-floor control pass, deterministic statistics) without any external tooling, driving requests through Drupal's own HTTP kernel.
drush no:overhead:measure
drush no:overhead:measure --path=node:/node/1 --only=front-page,node
drush no:overhead:measure --no-control --format=json
drush no:overhead:measure --only=front-page --record=front-page
drush no:overhead:measure --ledger
drush no:overhead:clear
Options: --pairs (measured ON/OFF pairs per workload, on top of one discarded warm-up pair, default
7, the smallest count at which the exact sign test can reach p <= 0.05), --requests (sequential
requests per block for HTTP workloads, default 15), --unit-requests (sequential units per block for
CLI-only workloads, default 500), --induced-queries (queries per block for the database
statement-event induced-cost row, default 200), --path (adds or replaces an HTTP workload by
label:/path, repeatable), --control/--no-control (the noise-floor control pass, on by default),
--keep-rows (keeps rows written by ON blocks instead of deleting them), --only (comma-separated
workload labels; empty runs the whole catalog), --record=<label> (publishes that workload's row as
the measured overhead on the report, see Report,
with no default, because the cost depends on which page is measured), --ledger (turns on the
capture cost ledger for this run, attributing each block's delta to the ledger keys in the table
above), and --format for machine-readable output (json, yaml, csv, and the rest Drush's
formatter supports; only the table format prints the header, legend and per-pair breakdown, see the
"Machine Formats MUST NOT Be Polluted By Human Output" requirement).
Each request is built as a Request, passed to the HTTP kernel's handle(), then followed by
terminate() before the timer stops: skipping terminate() would measure only latency and leave out
the deferred flush described above. Latency (handle() alone) and worker occupancy (handle() plus
terminate()) are reported as two separate quantities, not summed into one.
Because it runs from the CLI, this measures the work the module does one request after another, not
response latency under real concurrency: a CLI process never calls fastcgi_finish_request(). For
latency and throughput under real concurrency, drive load against the actual web server instead.
The same protocol also runs from the administrative interface
(/admin/config/development/native-observability/overhead), as a batch: one measurement
block per batch operation, so a run of several minutes does not tie up a single PHP worker for its
whole duration. Both entry points call the same OverheadMeasurementRunner; see the "Both Entry
Points MUST Run The Same Measurement" requirement.
Recovering after an interrupted run¶
The command restores whatever capture.enabled was set to before it ran, even when a request inside
a block throws: OverheadCommands::measure() wraps the run in a try/catch, and
OverheadMeasurementRunner::abort() restores the toggle, flushes deferred buffers and cleans up
written rows before the exception is re-thrown. That covers every ordinary failure.
It does not cover the process being killed outright (SIGKILL, an out-of-memory kill, the host
rebooting): nothing runs in that case, by definition, so capture.enabled can be left in whichever
state the run happened to be in when it died. There is no automatic recovery for the CLI path. Check
and, if needed, restore it by hand:
drush cget native_observability.settings capture.enabled
drush cset native_observability.settings capture.enabled 1 -y # or 0, whichever the site should run with
The administrative-interface path has a narrower version of the same gap, and a guard against it.
Drupal's batch API only ever runs code in response to a request from the browser that started the
batch (_batch_process(), _batch_finished()); if that browser is closed or simply stops polling,
nothing server-side runs either: no shutdown function, no 'finished' callback. OverheadMeasurementGuard
records the run's original capture.enabled value and a deadline (the run's own estimated duration
plus a 300-second grace period) when the run starts, and checks it the next time anyone opens the
measurement form: past the deadline, it restores the toggle itself and logs a warning naming who
started the abandoned run and when. This is a best-effort recovery that fires on the next visit to
that form, not a guarantee that fires the instant the browser closes. Nothing can guarantee that,
for any Drupal batch.