Skip to content
Open
Show file tree
Hide file tree
Changes from 3 commits
Commits
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
7 changes: 7 additions & 0 deletions docs/developers-guide.md
Original file line number Diff line number Diff line change
Expand Up @@ -3455,6 +3455,13 @@ verbose mode is active. `should_force_text_task_updates` decides whether the
indicatif reporter emits textual task updates, forcing them for accessible
mode or non-TTY standard output.

`AccessibleReporter` and `VerboseTimingReporter` are each generic over a
`Write + Send` output sink that defaults to `io::Stderr`; tests inject a
`Vec<u8>` writer to capture status and timing lines without a global stderr
sink. `VerboseTimingReporter` writes its timing summary to that injected
sink while the wrapped reporter continues to own stage, task, and completion
lines.

`run_with_ninja_program` (in `src/runner/mod.rs`) constructs the run's
`StatusReporter` through `reporter::make_reporter` after resolving output mode
and reporter settings, then shares it via the `ExecutionContext` it passes to
Expand Down
8 changes: 6 additions & 2 deletions docs/execplans/3-9-3-per-stage-timing-metrics.md
Original file line number Diff line number Diff line change
Expand Up @@ -55,7 +55,10 @@ Total pipeline time: 50ms

The summary lines are emitted on `stderr` with other status output. `stdout`
continues to carry command artefacts (for example `manifest -` output) and is
not used for timing diagnostics.
not used for timing diagnostics. The summary sink is injectable:
`VerboseTimingReporter` is generic over a `Write + Send` writer that defaults
to `io::Stderr`, so tests can capture timing output without a global stderr
sink.

## Constraints

Expand Down Expand Up @@ -182,7 +185,8 @@ What shipped:
- Added `src/status_timing.rs` with:
- a deterministic stage-timing recorder,
- a duration formatter (`ns`/`us`/`ms`/`s`),
- `VerboseTimingReporter` wrapper with an injectable monotonic clock.
- `VerboseTimingReporter` wrapper with an injectable monotonic clock and an
injectable `Write + Send` output sink.
- Wired reporter selection in `src/runner/reporter.rs` so verbose mode
wraps the resolved base reporter (including silent progress mode).
- Added localized timing summary runtime strings and updated verbose help copy
Expand Down
34 changes: 31 additions & 3 deletions src/status_timing.rs
Original file line number Diff line number Diff line change
Expand Up @@ -69,11 +69,19 @@ impl TimingState {

/// Status reporter wrapper that emits per-stage timings on successful
/// completion.
pub struct VerboseTimingReporter {
///
/// The writer defaults to [`io::Stderr`]; tests can supply a `Vec<u8>`
/// via the test-only writer-and-clock constructor for output capture.
/// The summary sink is guarded by a [`Mutex`] and written while the guard is
/// held, serialising whole lines in call order; the reporting path never
/// re-enters the same writer, so the bounded lock scope cannot deadlock,
/// mirroring [`super::AccessibleReporter`].
pub struct VerboseTimingReporter<W: Write + Send = io::Stderr> {
inner: Box<dyn StatusReporter>,
prefs: OutputPrefs,
clock: Box<MonotonicClock>,
state: Mutex<TimingState>,
writer: Mutex<W>,
}

impl VerboseTimingReporter {
Expand All @@ -84,21 +92,37 @@ impl VerboseTimingReporter {
Self::with_clock(inner, prefs, Box::new(move || start.elapsed()))
}

/// Wrap an existing reporter with verbose timing summary support and an
/// injected monotonic clock.
fn with_clock(
inner: Box<dyn StatusReporter>,
prefs: OutputPrefs,
clock: Box<MonotonicClock>,
) -> Self {
Self::with_clock_and_writer(inner, prefs, clock, io::stderr())
}
}

impl<W: Write + Send> VerboseTimingReporter<W> {
/// Wrap an existing reporter with verbose timing summary support, an
/// injected monotonic clock, and an injected timing summary sink.
fn with_clock_and_writer(
inner: Box<dyn StatusReporter>,
prefs: OutputPrefs,
clock: Box<MonotonicClock>,
writer: W,
) -> Self {
Self {
inner,
prefs,
clock,
state: Mutex::new(TimingState::default()),
writer: Mutex::new(writer),
}
}
}

impl StatusReporter for VerboseTimingReporter {
impl<W: Write + Send> StatusReporter for VerboseTimingReporter<W> {
fn report_stage(&self, current: StageNumber, total: StageNumber, description: &str) {
let should_forward = {
let mut state = self
Expand Down Expand Up @@ -147,8 +171,12 @@ impl StatusReporter for VerboseTimingReporter {

self.inner.report_complete(tool_key);

let mut writer = self
.writer
.lock()
.unwrap_or_else(std::sync::PoisonError::into_inner);
for line in lines {
drop(writeln!(io::stderr(), "{line}"));
drop(writeln!(writer, "{line}"));
}
}
}
Expand Down
34 changes: 34 additions & 0 deletions src/status_timing_tests.rs
Original file line number Diff line number Diff line change
Expand Up @@ -269,6 +269,40 @@ fn verbose_timing_reporter_suppresses_progress_updates_after_complete(test_prefs
);
}

#[rstest]
fn verbose_timing_reporter_writes_summary_to_injected_sink(en_localizer: EnLocalizer) {
let _localizer = en_localizer;
let clock = Arc::new(FakeClock::from_millis(&[0, 12, 23]));
let injected_clock = Arc::clone(&clock);
let reporter = VerboseTimingReporter::with_clock_and_writer(
Box::new(crate::status::SilentReporter),
test_prefs(),
Box::new(move || injected_clock.now()),
Vec::new(),
);
reporter.report_stage(
StageNumber::new_unchecked(1),
StageNumber::new_unchecked(6),
"Reading manifest file",
);
reporter.report_stage(
StageNumber::new_unchecked(2),
StageNumber::new_unchecked(6),
"Parsing YAML document",
);
reporter.report_complete(LocalizationKey::new(keys::STATUS_TOOL_GENERATE));

let output = reporter
.writer
.lock()
.unwrap_or_else(std::sync::PoisonError::into_inner);
let rendered = normalize_fluent_isolates(&String::from_utf8_lossy(&output));
assert!(rendered.contains("Stage timing summary:"));
assert!(rendered.contains("Stage 1/6: Reading manifest file: 12ms"));
assert!(rendered.contains("Stage 2/6: Parsing YAML document: 11ms"));
assert!(rendered.contains("Total pipeline time: 23ms"));
}

#[rstest]
#[case::unicode(crate::theme::ThemePreference::Unicode, "timing_summary_unicode")]
#[case::ascii(crate::theme::ThemePreference::Ascii, "timing_summary_ascii")]
Expand Down
Loading