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..b2b714b --- /dev/null +++ b/docs/advanced-test-features/instrumenting-test-execution.md @@ -0,0 +1,181 @@ +--- +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 + SPAN_NAME = 'inferno.test'.freeze + + 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( + SPAN_NAME, + attributes: { + 'inferno.test_run_id' => test_run.id, + 'inferno.test_session_id' => test_session.id, + 'inferno.test_id' => test.id, + 'inferno.test_short_id' => test.short_id, + 'inferno.test_title' => test.title + }.compact + ) 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. + +### 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: + +- 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