Skip to content
Open
Show file tree
Hide file tree
Changes from all 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