From 61e1b382ca76a2175d78a07cd82929de8bc1cd20 Mon Sep 17 00:00:00 2001 From: Rain Date: Fri, 30 Aug 2024 14:43:55 -0700 Subject: [PATCH] [4/n] [update-engine] line displays can now compute offsets from a start time (#6487) The update engine doesn't track the start time because some of its uses don't have a reliable way to get that. But we're also adding the update engine to the blueprint executor background task, which does have the start time available. Use that. --- Cargo.lock | 1 + update-engine/Cargo.toml | 1 + update-engine/src/display/group_display.rs | 9 +- update-engine/src/display/line_display.rs | 11 ++ .../src/display/line_display_shared.rs | 185 +++++++++++++----- 5 files changed, 161 insertions(+), 46 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index fa32990d8c..75336496e9 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -11508,6 +11508,7 @@ dependencies = [ "camino", "camino-tempfile", "cancel-safe-futures", + "chrono", "clap", "debug-ignore", "derive-where", diff --git a/update-engine/Cargo.toml b/update-engine/Cargo.toml index 5c8343a432..76e912b87e 100644 --- a/update-engine/Cargo.toml +++ b/update-engine/Cargo.toml @@ -10,6 +10,7 @@ workspace = true [dependencies] anyhow.workspace = true cancel-safe-futures.workspace = true +chrono.workspace = true debug-ignore.workspace = true derive-where.workspace = true either.workspace = true diff --git a/update-engine/src/display/group_display.rs b/update-engine/src/display/group_display.rs index 9e75b64757..7d99150a9f 100644 --- a/update-engine/src/display/group_display.rs +++ b/update-engine/src/display/group_display.rs @@ -184,8 +184,13 @@ impl GroupDisplay { pub fn write_stats(&mut self, header: &str) -> std::io::Result<()> { // Add a blank prefix which is equal to the maximum width of known prefixes. let prefix = " ".repeat(self.max_width); - let mut line = - self.formatter.start_line(&prefix, Some(self.start_sw.elapsed())); + let mut line = self.formatter.start_line( + &prefix, + // TODO: we don't currently support setting a start time for group + // displays. We should do that at some point. + None, + Some(self.start_sw.elapsed()), + ); self.stats.format_line(&mut line, header, &self.formatter); writeln!(self.writer, "{line}") } diff --git a/update-engine/src/display/line_display.rs b/update-engine/src/display/line_display.rs index 5321ec017c..f6005a9f9e 100644 --- a/update-engine/src/display/line_display.rs +++ b/update-engine/src/display/line_display.rs @@ -4,6 +4,7 @@ // Copyright 2023 Oxide Computer Company +use chrono::{DateTime, Utc}; use debug_ignore::DebugIgnore; use derive_where::derive_where; use owo_colors::Style; @@ -50,6 +51,16 @@ impl LineDisplay { self.formatter.set_styles(styles); } + /// Sets the start time for all future lines. + /// + /// If the start time is set, then the progress display will be relative to + /// that time. Otherwise, only the offset from the start of the job will be + /// displayed. + #[inline] + pub fn set_start_time(&mut self, start_time: DateTime) { + self.shared.set_start_time(start_time); + } + /// Sets the amount of time before the next progress event is shown. #[inline] pub fn set_progress_interval(&mut self, interval: Duration) { diff --git a/update-engine/src/display/line_display_shared.rs b/update-engine/src/display/line_display_shared.rs index e31d36dcd7..73a0e44e19 100644 --- a/update-engine/src/display/line_display_shared.rs +++ b/update-engine/src/display/line_display_shared.rs @@ -9,9 +9,11 @@ use std::{ collections::HashMap, fmt::{self, Write as _}, + sync::LazyLock, time::Duration, }; +use chrono::{DateTime, Utc}; use owo_colors::OwoColorize; use swrite::{swrite, SWrite as _}; @@ -33,6 +35,8 @@ pub(super) const HEADER_WIDTH: usize = 9; #[derive(Debug, Default)] pub(super) struct LineDisplayShared { + // The start time, if provided. + start_time: Option>, // This is a map from root execution ID to data about it. execution_data: HashMap, } @@ -45,6 +49,10 @@ impl LineDisplayShared { ) -> LineDisplaySharedContext<'a> { LineDisplaySharedContext { shared: self, prefix, formatter } } + + pub(super) fn set_start_time(&mut self, start_time: DateTime) { + self.start_time = Some(start_time); + } } #[derive(Debug)] @@ -60,7 +68,11 @@ impl<'a> LineDisplaySharedContext<'a> { /// This line does not have a trailing newline; adding one is the caller's /// responsibility. pub(super) fn format_generic(&self, message: &str) -> String { - let mut line = self.formatter.start_line(self.prefix, None); + let mut line = self.formatter.start_line( + self.prefix, + self.shared.start_time, + None, + ); line.push_str(message); line } @@ -134,9 +146,11 @@ impl<'a> LineDisplaySharedContext<'a> { ) { match &step_event.kind { StepEventKind::NoStepsDefined => { - let mut line = self - .formatter - .start_line(self.prefix, Some(step_event.total_elapsed)); + let mut line = self.formatter.start_line( + self.prefix, + self.shared.start_time, + Some(step_event.total_elapsed), + ); swrite!( line, "{}", @@ -152,9 +166,11 @@ impl<'a> LineDisplaySharedContext<'a> { &first_step.info, &nest_data, ); - let mut line = self - .formatter - .start_line(self.prefix, Some(root_total_elapsed)); + let mut line = self.formatter.start_line( + self.prefix, + self.shared.start_time, + Some(root_total_elapsed), + ); swrite!( line, @@ -178,9 +194,11 @@ impl<'a> LineDisplaySharedContext<'a> { &nest_data, ); - let mut line = self - .formatter - .start_line(self.prefix, Some(root_total_elapsed)); + let mut line = self.formatter.start_line( + self.prefix, + self.shared.start_time, + Some(root_total_elapsed), + ); swrite!( line, @@ -224,9 +242,11 @@ impl<'a> LineDisplaySharedContext<'a> { &nest_data, ); - let mut line = self - .formatter - .start_line(self.prefix, Some(root_total_elapsed)); + let mut line = self.formatter.start_line( + self.prefix, + self.shared.start_time, + Some(root_total_elapsed), + ); swrite!( line, @@ -270,9 +290,11 @@ impl<'a> LineDisplaySharedContext<'a> { &step.info, &nest_data, ); - let mut line = self - .formatter - .start_line(self.prefix, Some(root_total_elapsed)); + let mut line = self.formatter.start_line( + self.prefix, + self.shared.start_time, + Some(root_total_elapsed), + ); self.formatter.add_completion_and_step_info( &mut line, @@ -293,9 +315,11 @@ impl<'a> LineDisplaySharedContext<'a> { &nest_data, ); - let mut line = self - .formatter - .start_line(self.prefix, Some(root_total_elapsed)); + let mut line = self.formatter.start_line( + self.prefix, + self.shared.start_time, + Some(root_total_elapsed), + ); self.format_step_running(&mut line, ld_step_info); @@ -315,9 +339,11 @@ impl<'a> LineDisplaySharedContext<'a> { &nest_data, ); - let mut line = self - .formatter - .start_line(self.prefix, Some(root_total_elapsed)); + let mut line = self.formatter.start_line( + self.prefix, + self.shared.start_time, + Some(root_total_elapsed), + ); self.formatter.add_completion_and_step_info( &mut line, @@ -344,9 +370,11 @@ impl<'a> LineDisplaySharedContext<'a> { &nest_data, ); - let mut line = self - .formatter - .start_line(self.prefix, Some(root_total_elapsed)); + let mut line = self.formatter.start_line( + self.prefix, + self.shared.start_time, + Some(root_total_elapsed), + ); // The prefix is used for "Caused by" lines below. Add // the requisite amount of spacing here. let mut caused_by_prefix = line.clone(); @@ -387,9 +415,11 @@ impl<'a> LineDisplaySharedContext<'a> { &nest_data, ); - let mut line = self - .formatter - .start_line(self.prefix, Some(root_total_elapsed)); + let mut line = self.formatter.start_line( + self.prefix, + self.shared.start_time, + Some(root_total_elapsed), + ); swrite!( line, @@ -463,8 +493,11 @@ impl<'a> LineDisplaySharedContext<'a> { &self, info: &ExecutionTerminalInfo, ) -> String { - let mut line = - self.formatter.start_line(self.prefix, info.leaf_total_elapsed); + let mut line = self.formatter.start_line( + self.prefix, + self.shared.start_time, + info.leaf_total_elapsed, + ); match info.kind { TerminalKind::Completed => { swrite!( @@ -540,9 +573,11 @@ impl<'a> LineDisplaySharedContext<'a> { nest_data: &nest_data, }; - let mut line = self - .formatter - .start_line(self.prefix, Some(root_total_elapsed)); + let mut line = self.formatter.start_line( + self.prefix, + self.shared.start_time, + Some(root_total_elapsed), + ); let (before, after) = match progress { Some(counter) => { @@ -685,6 +720,7 @@ impl LineDisplayFormatter { pub(super) fn start_line( &self, prefix: &str, + start_time: Option>, total_elapsed: Option, ) -> String { let mut line = format!("[{}", prefix.style(self.styles.prefix_style)); @@ -694,17 +730,31 @@ impl LineDisplayFormatter { } // Show total elapsed time in an hh:mm:ss format. - if let Some(total_elapsed) = total_elapsed { - let total_elapsed_secs = total_elapsed.as_secs(); - let hours = total_elapsed_secs / 3600; - let minutes = (total_elapsed_secs % 3600) / 60; - let seconds = total_elapsed_secs % 60; - swrite!(line, "{:02}:{:02}:{:02}", hours, minutes, seconds); - // To show total_elapsed more accurately, use: - // swrite!(line, "{:.2?}", total_elapsed); - } else { - // Add 8 spaces to align with hh:mm:ss. - line.push_str(" "); + match (start_time, total_elapsed) { + (Some(start_time), Some(total_elapsed)) => { + // Add the offset from the start time. + let current_time = start_time + total_elapsed; + swrite!( + line, + "{}", + current_time.format_with_items(DATETIME_FORMAT.iter()) + ); + } + (None, Some(total_elapsed)) => { + let total_elapsed_secs = total_elapsed.as_secs(); + let hours = total_elapsed_secs / 3600; + let minutes = (total_elapsed_secs % 3600) / 60; + let seconds = total_elapsed_secs % 60; + swrite!(line, "{:02}:{:02}:{:02}", hours, minutes, seconds); + // To show total_elapsed more accurately, use: + // swrite!(line, "{:.2?}", total_elapsed); + } + (Some(_), None) => { + line.push_str(DATETIME_FORMAT_INDENT); + } + (None, None) => { + line.push_str(ELAPSED_FORMAT_INDENT); + } } line.push_str("] "); @@ -874,6 +924,23 @@ impl LineDisplayFormatter { } } +static DATETIME_FORMAT: LazyLock>> = + LazyLock::new(|| { + // The format is "Jan 01 00:00:00". + // + // We can add customization in the future, but we want to restrict + // formats to fixed-width so we know how to align them. + chrono::format::StrftimeItems::new("%b %d %H:%M:%S") + .parse() + .expect("datetime format is valid") + }); + +// "Jan 01 00:00:00" is 15 characters wide. +const DATETIME_FORMAT_INDENT: &str = " "; + +// "00:00:00" is 8 characters wide. +const ELAPSED_FORMAT_INDENT: &str = " "; + #[derive(Clone, Debug)] pub(super) struct LineDisplayOutput { lines: Vec, @@ -989,6 +1056,8 @@ impl fmt::Display for AsLetters { #[cfg(test)] mod tests { + use chrono::TimeZone; + use super::*; #[test] @@ -1010,4 +1079,32 @@ mod tests { ); } } + + #[test] + fn test_start_line() { + let formatter = LineDisplayFormatter::new(); + let prefix = "prefix"; + let start_time = Utc.with_ymd_and_hms(2023, 2, 8, 3, 40, 56).unwrap(); + + assert_eq!( + formatter.start_line(prefix, None, None), + "[prefix ] ", + ); + assert_eq!( + formatter.start_line(prefix, None, Some(Duration::from_secs(5))), + "[prefix 00:00:05] ", + ); + assert_eq!( + formatter.start_line(prefix, Some(start_time), None), + "[prefix ] ", + ); + assert_eq!( + formatter.start_line( + prefix, + Some(start_time), + Some(Duration::from_secs(3600)), + ), + "[prefix Feb 08 04:40:56] ", + ); + } }