Keep how-far in the library's production dependencies and the tracker and diagnostics in dev-dependencies. Use the 0.1 versions in the dependency setup and tested integration guide.

Test what the library reports

Run each operation twice: once with how_far::NoPulse and once with a PulseTree, and check that the output is identical. Then assert on the tree the library left behind. Finish the root yourself; the library never does.

use how_far::{prelude::*, Outcome, Total, Unstoppable};
use how_far_along::{Phase, PulseTree, Status};
use how_far_example_codec::Mode;
use how_far_example_pipeline::convert;

let tree = PulseTree::new(Phase::new("encode", Total::Unknown), Unstoppable);
let observer = tree.observer();
let result = convert(&[1, 2], &tree, Mode::Fast, false).finish_phase(tree);
assert_eq!(result, convert(&[1, 2], &how_far::NoPulse, Mode::Fast, false));
let root = observer.snapshot();
assert_eq!(root.status, Status::Finished(Outcome::Succeeded));
// Check stage names, units, totals, completed counts and outcomes:
// assert_eq!(root.children[0].name, "decode");
// assert_eq!(root.children[0].completed, rows);

Worth a test each:

  • Cancellation at an exact point. Give the tree a stop policy that trips when a snapshot reaches a chosen count, and assert that the active stage is Cancelled, later stages are NotRun, and completed work up to the stop is still counted.
  • Failure versus cancellation. Feed corrupt input and assert Failed, not Cancelled. Stages::run_classified needs a correct is_stop.
  • Calling another library. Run the library inside a stage of an outer plan, the way an application's pipeline would, and assert both levels finish.
  • Parallel work. Run under a Rayon pool of 1, 2, 4 and 8 threads, and assert that a stage shared by workers counts each unit once.

The repository's scenario tests do all of these against a pretend codec and a pipeline built on it, across crates, scoped and spawned threads, Rayon, and Tokio.

Measure checkpoint cadence

DiagnosticPulse measures a library without changing its signature. Wrap the tree, pass the wrapper, and finish the wrapper:

use how_far::{prelude::*, Total, Unstoppable};
use how_far_along::{Phase, PulseTree};
use how_far_example_codec::Mode;
use how_far_example_pipeline::convert;
use how_far_really::diagnostics::{DiagnosticPulse, Options};
use how_far_really::profile::{Profiler, StdClock};

let profiler = Profiler::new(StdClock::new(), 512);
let tree = PulseTree::new(Phase::new("encode", Total::Unknown), Unstoppable);
let measured = DiagnosticPulse::new(tree, &profiler);
let observer = measured.observer();
let result = convert(&[1, 2], &measured, Mode::Fast, false).finish_phase(measured);
profiler.operation_returned();
assert!(result.is_ok());
let trace = profiler.snapshot().with_progress(observer.snapshot());
for finding in trace.diagnose(&Options::default()) {
    eprintln!("{finding}");
}

Every phase the library plans gets its own span, tied to its node in the tree. A stage of a sequential plan is timed from when the previous stage finished, so work done before a stage's first checkpoint is measured, and a stage that never checks at all still gets a span. Other phases start at their first check or report. A phase that splits ends its own span there; a sequential stage then records a Wait span while it coordinates its children, so its timing runs from entry to exit without treating the children's work as its own silence.

Workers that share one phase share its span, so one busy worker can hide another's long silence. When that matters, give each worker its own profiler.span(node, "chunk 3", SpanKind::Work) and pass span.instrument(stop_or_sink) to that worker. Finish spans and join workers before taking the trace, and give the profiler enough capacity for every span; the trace reports anything dropped or still running.

DiagnosticPulse returns true from may_stop() and may_report(), so a library that skips checkpoints for no-op pulses still makes the calls being measured.

Checks inside code that owns its stop

Codecs often keep their stop policy in a context object: an encoder built with with_stop(impl Stop + 'static) checks deep inside each frame. A borrowed pulse cannot be stored there directly; an owned view from stage.share() can, and under DiagnosticPulse that handle is instrumented. Checks the encoder makes through it count toward the stage that handed it out. Borrowed stop adapters cannot become owned views; use scoped workers or an owned stop source. Handle sharing failure explicitly: the sketch below assumes the enclosing library error represents its chosen response to NotShareable, rather than requiring every library error to convert all planning errors:

let stage = stages.begin(encode);
let result = match stage.share() {
    Ok(owned) => encoder.with_stop(owned).encode(input),
    Err(error) => Err(error.into()), // handle unsupported ownership explicitly
};
let output = stage.complete_classified(result, Error::is_stop)?;

If the encoder's Stop trait comes from a different version of enough, a four-line adapter bridges them. Stop::check is declared #[track_caller], so the adapter keeps the encoder's call sites without an attribute of its own.

A coarse report or missing checks?

A ReportGap finding says how long a task went without reporting, and also how many cancellation checks it made inside that stretch and the longest gap between them:

  • Frequent checks inside: the finding calls it a progress-granularity seam. The library's smallest reportable unit, such as a frame, takes that long; more checks would not help. Report smaller units, split the stage, or accept the coarse bar.
  • No checks inside: it is a cancellation gap too, and a StopGap finding names the line where the gap ended.

Checks made by another span on the same profiler count when that span ran across at least 90% of the gap; the evidence names it. A separate Profiler has its own clock epoch and cannot be correlated.

Stage weights

When a sequential plan finished and every stage has a span, diagnostics compares measured wall time with the declared weights and prints a PhaseSpec::new(...) sketch. Treat it as one run's candidate: wall time includes waits and changes with input, hardware and configuration. A stage that took less than Options::negligible_stage_share (2% by default) is too small to calibrate from one run (a flush that is trivial for this input may not be for the next), so it keeps its declared weight and cannot trigger advice on its own, unless the stages held this way would together own more than half the bar. Fork-join plans, failed stages, incomplete traces and overlapping spans get no weight advice.

Units that change pace

An UnevenPace finding says a task's units took very different times in different parts of its run: each span records how long each quarter of its reported units took (Stats::unit_pace), and the finding appears when the slowest quarter took at least Options::uneven_pace_ratio (4 by default) times as long as the fastest, over at least 8 reports and minimum_stage_wall. The tree's fraction, and any smoothing of it between reports, assume a phase's units cost about the same, so such a phase's bar runs fast and then stalls, or the reverse. If the change comes from the work itself, split the phase into stages where it changes and weight them by the measured times; if it comes from the input, report a unit that tracks cost, such as bytes or pixels. The first quarter runs from the span's start: sequence entry for a sequential stage, otherwise its first check or report. Setup after sequence entry counts; work before a non-sequential phase's first activity is not observed. A quarter whose reports all landed in one clock reading counts as the fastest possible, not as missing evidence. A report that read the clock before reports already recorded (a worker preempted on the way) still counts in its quarter.

Stages a phase could declare

Each span records, per source location, the time of the intervals that ended there and when it was first and last called (SiteStats::time and SiteStats::active; reports count only with report timing on). With the experimental-stage-suggestions feature, a SuggestedStages finding appears when a leaf phase, or code measured without a progress tree such as a codec's Stop checks, ran its checkpoints in separate stretches. Locations are taken in order of how long they were active, shortest first. Timing changes can change their order and the resulting groups across runs. One whose calls overlap a single stretch joins it. One overlapping several merges them if it carries more time than they do (the main work around short steps), and otherwise is an outer loop around them and is left out. The time after the last retained timed check or report becomes a stage of its own, named after that location. This is an interval without recorded checkpoint activity, not proof that the library cannot check there. A stretch under Options::negligible_stage_share of the time joins its neighbor. The sample code lists one PhaseSpec per stretch, named by the file and line of its busiest location, weighted by its share of the time, with the units it reported (or its checks) as an estimated total. Time ending at an outer loop's location is spread over the stretches in proportion, and the evidence says how much. Each comment's range is when the stretch's locations were called: the intervals its weight counts end at those calls, so a stage's work starts before its range, as setup before a first check does. The final stage starts at the last timed check or report. Locations that alternate inside one loop form a single stretch, so they never suggest a split. One run gives candidates; check the weights across inputs.

Defaults and cost

The default targets are 10 ms between cancellation checks, 50 ms between reports, 10 ms per callback, and 10 ms between runs of one callback. All are fields of Options. A high call rate alone does not prove waste, so check and report rates have separate thresholds.

Measuring costs time: an instrumented check reads the clock twice, and with report timing on (which DiagnosticPulse enables) a report reads it once. Compare against an uninstrumented run before changing a hot loop.

Callbacks

Wrap a callback's body to measure it, including any snapshot it builds:

poller.subscribe(move |event| {
    profiler.measure_callback("render", || render(event.snapshot()));
});

Findings report the slowest and 95th-percentile callback time, and the longest interval between two runs. A report does not schedule a UI update; how smooth a display looks depends on how often the application polls.

Run the examples

cargo test -p how-far-really --test diagnostics
cargo test -p how-far-example-app
cargo run -p how-far-really --example diagnostics
cargo run -p how-far-example-app