From 77b4ac2c5a2e1e5d50d5b6990f177672c2bdeee0 Mon Sep 17 00:00:00 2001 From: Kyle Pettigrew Date: Wed, 29 Jul 2026 08:56:57 +1000 Subject: [PATCH 1/2] Document the around_test instrumentation hook Inferno Core runs a whole test run in one call stack, so instrumentation applied around the runner, such as tracing of the background worker, covers the entire run rather than individual tests. Inferno::TestRunner#around_test provides a seam for per-test instrumentation. Add an Advanced Features page covering the hook: why run-scoped instrumentation is not useful for a long run, how to override the hook, the contract an override has to honour, and a worked OpenTelemetry example that produces one trace per test. Link to it from the debugging page, which covers the separate concern of investigating a single test interactively. --- docs/advanced-test-features/index.md | 8 +- .../instrumenting-test-execution.md | 142 ++++++++++++++++++ docs/getting-started/debugging.md | 9 +- 3 files changed, 157 insertions(+), 2 deletions(-) create mode 100644 docs/advanced-test-features/instrumenting-test-execution.md diff --git a/docs/advanced-test-features/index.md b/docs/advanced-test-features/index.md index 66505bc..33db71c 100644 --- a/docs/advanced-test-features/index.md +++ b/docs/advanced-test-features/index.md @@ -55,4 +55,10 @@ verifying and Inferno displays these associations to users within the ## [Scripting Suite Execution](/docs/advanced-test-features/scripting-execution.html) The Inferno CLI supports executing suites using a yaml configuration format -instead of the UI using the `inferno execute_script` command. \ No newline at end of file +instead of the UI using the `inferno execute_script` command. + +## [Instrumenting Test Execution](/docs/advanced-test-features/instrumenting-test-execution.html) +Inferno runs a whole test run in a single call stack, so instrumentation applied +around the runner covers the entire run rather than individual tests. This page +shows how to use the `around_test` hook to scope tracing, metrics, or logging to +one test at a time. \ No newline at end of file diff --git a/docs/advanced-test-features/instrumenting-test-execution.md b/docs/advanced-test-features/instrumenting-test-execution.md new file mode 100644 index 0000000..19563eb --- /dev/null +++ b/docs/advanced-test-features/instrumenting-test-execution.md @@ -0,0 +1,142 @@ +--- +title: Instrumenting Test Execution +nav_order: 10 +parent: Advanced Features +layout: docs +section: docs +--- +{:toc-skip: .h4 data-toc-skip=""} + +# Instrumenting Test Execution + +Inferno runs an entire test run inside a single call stack: the background job +that executes a run calls `Inferno::TestRunner#start`, which walks the suite and +calls `#run_test` once per test. That is convenient for running tests, but it +means anything that observes the run from the outside, such as a tracing library +that instruments the background worker, sees one long-lived operation rather than +one operation per test. + +`Inferno::TestRunner#around_test` is an extension point for attaching +instrumentation to each individual test. It receives the test about to be run and +yields to run it, so an override can start and finish a span, a trace, a timer, +or a log context around exactly one test. + +This is aimed at people deploying Inferno rather than at people writing tests. +Nothing about a suite or its tests changes, and no additional dependency is +required. If you are trying to work out why a specific test behaves the way it +does while you are writing it, see +[Debugging](/docs/getting-started/debugging.html) instead. + +## The Hook + +The default implementation simply yields: + +```ruby +def around_test(_test) + yield +end +``` + +Override it by prepending a module to `Inferno::TestRunner`: + +```ruby +module TestTiming + def around_test(test) + started_at = Process.clock_gettime(Process::CLOCK_MONOTONIC) + super + ensure + duration = Process.clock_gettime(Process::CLOCK_MONOTONIC) - started_at + Inferno::Application['logger'].info( + "test=#{test.id} test_run=#{test_run.id} duration=#{duration.round(3)}s" + ) + end +end + +Inferno::TestRunner.prepend(TestTiming) +``` + +Inside the override, `test` is the test class being run (an +`Inferno::Entities::Test` subclass, so `test.id`, `test.short_id`, and +`test.title` are all available), and the runner's own `test_run` and +`test_session` readers are available for correlating the test with the run it +belongs to. + +An override must run the test, so it has to: + +- **Call `super` (or `yield`) exactly once.** An override that never runs the + test silently skips it and records no result for it. An override that runs it + twice runs the test twice, including any HTTP requests it makes. +- **Return the value it gets back unchanged.** That value is the test's result, + and the runner uses it to roll up group and suite results. Using `ensure`, as + above, keeps the return value intact; assigning `super` to a variable and + returning something else does not. +- **Let exceptions propagate.** A failing test is recorded as a result rather + than raised, so an exception escaping the block is a failure of the test runner + itself. Swallowing it leaves the run in an inconsistent state. If the + instrumentation needs to record the exception, re-raise it afterwards. + +Put the override in a file that loads in every process that executes tests. A +file under your test kit's `lib` directory that is required from your test kit's +main file will be picked up by the web server, the background worker, and the +CLI. + +## Example: One Trace Per Test + +The motivating case for this hook is distributed tracing. If a deployment +instruments the background worker, for example with OpenTelemetry +auto-instrumentation of Sidekiq, then the span for the job becomes the root of +the trace, and every request made by every test in the run nests underneath it. +An entire run then arrives at the trace store as a single trace that can be many +minutes long and, in our case, tens of thousands of spans. That is a problem +regardless of which backend is used: + +- A trace is meant to represent one logical operation, and no trace UI renders a + multi-minute waterfall of thousands of spans in a way anyone can read. +- Trace stores cap the size of a single trace (for example, Grafana Tempo's + `max_bytes_per_trace` defaults to 5 MB) and drop spans past the limit, so + the end of a long run is lost. + +Detaching the context inside `around_test` gives one trace per test instead, +correlated by the test run id: + +```ruby +module PerTestTraceRoot + def around_test(test) + tracer = OpenTelemetry.tracer_provider.tracer('inferno') + + # Detach from the enclosing job span so that each test starts its own trace + # rather than becoming another branch of the run's trace. + OpenTelemetry::Context.with_current(OpenTelemetry::Context::ROOT) do + tracer.in_span( + "inferno.test #{test.id}", + attributes: { + 'inferno.test_run_id' => test_run.id, + 'inferno.test_id' => test.id, + 'inferno.test_session_id' => test_session.id + } + ) do + super + end + end + end +end + +Inferno::TestRunner.prepend(PerTestTraceRoot) +``` + +Each test is now a bounded trace on its own, and searching for +`inferno.test_run_id` returns every test in a run. OpenTelemetry is used here +only as an illustration; the hook has no knowledge of it, and the same shape +works for a metrics client, a timer, or a log context. + +## Other Uses + +The hook is not specific to tracing. It is also a reasonable place to: + +- emit a per-test duration metric, as in the first example above +- add the current test and run to a logging context, so that log lines emitted + while a test runs can be attributed to it +- report progress for long-running suites to something outside Inferno + +Because it wraps a single test rather than the whole run, none of these need to +know how the suite is structured or how the runner recurses through it. diff --git a/docs/getting-started/debugging.md b/docs/getting-started/debugging.md index 7098dec..7bbd766 100644 --- a/docs/getting-started/debugging.md +++ b/docs/getting-started/debugging.md @@ -142,4 +142,11 @@ You can also even see which test will be run first. ```ruby [3] pry(main)> suite.groups.first.tests => [#] -``` \ No newline at end of file +``` + +## Instrumenting a Deployment + +The techniques above are for investigating a single test interactively while you +write it. To observe test runs in a deployed instance instead, for example by +emitting a trace, a span, or a timing metric for each test that runs, see +[Instrumenting Test Execution](/docs/advanced-test-features/instrumenting-test-execution.html). \ No newline at end of file From e7faa741d412f10d43f12bf3ddf07cd4238d5ccf Mon Sep 17 00:00:00 2001 From: Kyle Pettigrew Date: Sat, 1 Aug 2026 09:04:12 +1000 Subject: [PATCH 2/2] Keep the test id out of the span name in the tracing example The worked example named each span after the test it wrapped. Tracing backends treat the span name as a low-cardinality dimension and generate metrics keyed on it, so that pattern produces one metric series per test, per suite, per suite version. Measured on a deployment of a large test kit it produced over 1,400 distinct span names, and every one of those series was useless by construction: a test emits a single span per run, so a per-test series holds one observation and rate() or increase() over it returns zero. Name the span with a constant and move identity into attributes, which carry no such constraint. Add the short id and title while there, since those are what a user reads back when reporting a slow test. Also note two things the example would otherwise leave a reader to discover: that an override recording the outcome should reserve error status for 'error' rather than 'fail', since a conformance failure is the expected outcome of testing a non-conformant system, and that the block covers persisting the result and its requests as well as executing the test. --- .../instrumenting-test-execution.md | 45 +++++++++++++++++-- 1 file changed, 42 insertions(+), 3 deletions(-) diff --git a/docs/advanced-test-features/instrumenting-test-execution.md b/docs/advanced-test-features/instrumenting-test-execution.md index 19563eb..b2b714b 100644 --- a/docs/advanced-test-features/instrumenting-test-execution.md +++ b/docs/advanced-test-features/instrumenting-test-execution.md @@ -101,6 +101,8 @@ correlated by the test run id: ```ruby module PerTestTraceRoot + SPAN_NAME = 'inferno.test'.freeze + def around_test(test) tracer = OpenTelemetry.tracer_provider.tracer('inferno') @@ -108,12 +110,14 @@ module PerTestTraceRoot # rather than becoming another branch of the run's trace. OpenTelemetry::Context.with_current(OpenTelemetry::Context::ROOT) do tracer.in_span( - "inferno.test #{test.id}", + SPAN_NAME, attributes: { 'inferno.test_run_id' => test_run.id, + 'inferno.test_session_id' => test_session.id, 'inferno.test_id' => test.id, - 'inferno.test_session_id' => test_session.id - } + 'inferno.test_short_id' => test.short_id, + 'inferno.test_title' => test.title + }.compact ) do super end @@ -129,6 +133,41 @@ Each test is now a bounded trace on its own, and searching for only as an illustration; the hook has no knowledge of it, and the same shape works for a metrics client, a timer, or a log context. +### Keep the test out of the span name + +Note that the span above is given a constant name and everything identifying it +is an attribute. This is worth doing deliberately, because the span name is not +just a label: tracing backends treat it as a low-cardinality dimension and +generate metrics keyed on it. Grafana Tempo's metrics generator, for example, +emits `traces_spanmetrics_*` series with the span name as a dimension. + +Naming the span after the test therefore creates one metric series per test, per +suite, per suite version. On one deployment of a large test kit that produced +over 1,400 distinct span names, and every one of those series was useless by +construction: a test emits a single span per run, so a per-test series holds one +observation and a `rate()` or `increase()` over it returns zero. Collapsing the +name to a constant removed all of that cardinality and, as a side effect, turned +the one remaining series into a genuinely useful one, total test execution time +across the deployment. + +Attributes have no such constraint. Filtering, grouping and table columns all +work on them, so nothing is lost by moving identity out of the name. + +A related point if the override records the outcome: reserve error status for +results of `'error'`. A test result of `'fail'` is the expected outcome of +testing a non-conformant system, so marking those spans as errors puts ordinary +conformance failures into error-rate panels and alerts. + +### What the block covers + +`around_test` wraps the whole of `#run_test`, which includes loading inputs, +constructing the test instance, running it, saving outputs, and persisting the +result along with its messages and requests. A duration measured with this hook +is therefore the wall time a user waited for that test, which is usually what you +want, but it is not purely the time spent executing the test body. For a test +that makes many HTTP requests, persisting them can be a substantial share of it. +If you need the two separated, instrument `#persist_result` as well. + ## Other Uses The hook is not specific to tracing. It is also a reasonable place to: