Skip to content

Commit

Permalink
log: Better heuristics to determine which command has terminated
Browse files Browse the repository at this point in the history 
This is still WIP: no unittest, probably missed corner cases, buggy unless merge are also
parsed/shown, etc. But it matches correctly the begining of my emerge.log (with lots of parallel
commands), and it seems good to commit as a snapshot.

UI-wise, `log` should have an option (maybe default) to display commands when they start rather than
when they stop, as it looks more natural. We could skip state tracking in that case.
  • Loading branch information
@vincentdephily
vincentdephily committed Nov 5, 2024
1 parent 411a40f commit 5220495
Show file tree
Hide file tree
Showing 3 changed files with 87 additions and 58 deletions.
64 changes: 52 additions & 12 deletions src/commands.rs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -3,37 +3,76 @@ use libc::pid_t;
use std::{collections::{BTreeMap, HashMap, HashSet},
io::{stdin, IsTerminal}};

/// Find the most likely terminated cmd
fn find_cmd(cmds: &mut Vec<(i64, String, u32, u32)>, ts: i64) -> (i64, String, u32, u32) {
if let Some(p) = cmds.iter().position(|&(_, _, nth, of)| of != 0 && nth == of) {
// Finished cmd
cmds.remove(p)
} else if let Some(p) = cmds.iter().position(|&(_, _, _, of)| of == 0) {
// Cmd without associated merge
cmds.remove(p)
} else if let Some(p) = cmds.iter().position(|_| true) {
// oldest cmd
cmds.remove(p)
} else {
// No cmd (should not happen unless --from)
warn!("No matching cmd at {ts} in {:?}", cmds);
(ts + 1, String::from("?"), 0, 0)
}
}

/// Update cmd with latest "(<N> of <M>)" merge state
fn update_cmd(cmds: &mut Vec<(i64, String, u32, u32)>, nth: u32, of: u32) {
if let Some(p) = cmds.iter().position(|&(_, _, _, cof)| nth == 1 && cof == 0) {
// Assign nth/of to new cmd
cmds[p].2 = nth;
cmds[p].3 = of;
} else if let Some(p) = cmds.iter().position(|&(_, _, _, cof)| of == cof) {
// update nth in previously amended cmd
cmds[p].2 = nth;
} else {
// TODO: there's probably other cases to handle, with --keep-going or --jobs
warn!("No matching cmd for {nth}/{of} in {:?}", cmds);
}
}

/// Straightforward display of merge events
///
/// We store the start times in a hashmap to compute/print the duration when we reach a stop event.
pub fn cmd_log(gc: Conf, sc: ConfLog) -> Result<bool, Error> {
let hist = get_hist(&gc.logfile, gc.from, gc.to, sc.show, &sc.search, sc.exact)?;
let mut cmd_start: Option<(i64, String)> = None;
let mut cmds: Vec<(i64, String, u32, u32)> = vec![];
let mut merges: HashMap<String, i64> = HashMap::new();
let mut unmerges: HashMap<String, i64> = HashMap::new();
let mut syncs: Option<i64> = None;
let mut found = 0;
let mut sync_start: Option<i64> = None;
let h = ["Date", "Duration", "Package/Repo"];
let mut tbl =
Table::new(&gc).align_left(0).align_left(2).margin(2, " ").last(sc.last).header(h);
for p in hist {
match p {
Hist::CmdStart { ts, args, .. } => {
// This'll overwrite any previous entry, if a cmd stops abruptly or multiple cmds run in parallel
cmd_start = Some((ts, args));
cmds.push((ts, args, 0, 0));
},
Hist::CmdStop { ts, .. } => {
found += 1;
let (started, args) = cmd_start.take().unwrap_or((ts + 1, String::from("?")));
let (started, args, nth, of) = find_cmd(&mut cmds, ts);
if found <= sc.first {
tbl.row([&[&FmtDate(if sc.starttime { started } else { ts })],
&[&FmtDur(ts - started), &gc.clr],
&[&"Emerge ", &args]]);
if nth > 0 {
tbl.row([&[&FmtDate(if sc.starttime { started } else { ts })],
&[&FmtDur(ts - started), &gc.clr],
&[&"Emerge ", &args, &" ", &gc.cnt, &nth, &"/", &of]]);
} else {
tbl.row([&[&FmtDate(if sc.starttime { started } else { ts })],
&[&FmtDur(ts - started), &gc.clr],
&[&"Emerge ", &args]]);
}
}
},
Hist::MergeStart { ts, key, .. } => {
Hist::MergeStart { ts, key, nth, of, .. } => {
// This'll overwrite any previous entry, if a merge started but never finished
merges.insert(key, ts);
update_cmd(&mut cmds, nth, of);
},
Hist::MergeStop { ts, ref key, .. } => {
found += 1;
Expand All @@ -59,11 +98,11 @@ pub fn cmd_log(gc: Conf, sc: ConfLog) -> Result<bool, Error> {
},
Hist::SyncStart { ts } => {
// Some sync starts have multiple entries in old logs
sync_start = Some(ts);
syncs = Some(ts);
},
Hist::SyncStop { ts, repo } => {
found += 1;
let started = sync_start.take().unwrap_or(ts + 1);
let started = syncs.take().unwrap_or(ts + 1);
if found <= sc.first {
tbl.row([&[&FmtDate(if sc.starttime { started } else { ts })],
&[&FmtDur(ts - started)],
Expand Down Expand Up @@ -155,7 +194,8 @@ impl Times {
///
/// First loop is like cmd_list but we store the merge time for each ebuild instead of printing it.
/// Then we compute the stats per ebuild, and print that.
pub fn cmd_stats(gc: Conf, sc: ConfStats) -> Result<bool, Error> {
pub fn cmd_stats(gc: Conf, mut sc: ConfStats) -> Result<bool, Error> {
sc.show.cmd = false;
let hist = get_hist(&gc.logfile, gc.from, gc.to, sc.show, &sc.search, sc.exact)?;
let h = [sc.group.name(), "Repo", "Syncs", "Total time", "Predict time"];
let mut tbls = Table::new(&gc).align_left(0).align_left(1).margin(1, " ").header(h);
Expand Down
62 changes: 23 additions & 39 deletions src/parse/history.rs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -16,46 +16,22 @@ use std::{fs::File,
/// Items sent on the channel returned by `new_hist()`.
#[derive(Debug)]
pub enum Hist {
CmdStart {
ts: i64,
args: String,
},
CmdStop {
ts: i64,
},
/// Command started (might never complete).
CmdStart { ts: i64, args: String },
/// Command completed
CmdStop { ts: i64 },
/// Merge started (might never complete).
MergeStart {
ts: i64,
key: String,
pos: usize,
},
MergeStart { ts: i64, key: String, pos: usize, nth: u32, of: u32 },
/// Merge completed.
MergeStop {
ts: i64,
key: String,
pos: usize,
},
MergeStop { ts: i64, key: String, pos: usize },
/// Unmerge started (might never complete).
UnmergeStart {
ts: i64,
key: String,
pos: usize,
},
UnmergeStart { ts: i64, key: String, pos: usize },
/// Unmerge completed.
UnmergeStop {
ts: i64,
key: String,
pos: usize,
},
UnmergeStop { ts: i64, key: String, pos: usize },
/// Sync started (might never complete).
SyncStart {
ts: i64,
},
SyncStart { ts: i64 },
/// Sync completed.
SyncStop {
ts: i64,
repo: String,
},
SyncStop { ts: i64, repo: String },
}
impl Hist {
pub fn ebuild(&self) -> &str {
Expand Down Expand Up @@ -267,7 +243,7 @@ fn find_version(atom: &str, filter: &FilterStr) -> Option<usize> {
}

/// Parse and filter timestamp
// TODO from_utf8(s.trim_ascii_start()) https://github.com/rust-lang/rust/issues/94035
// TODO MSRV 1.80: from_utf8(s.trim_ascii_start())
fn parse_ts(line: &[u8], min: i64, max: i64) -> Option<(i64, &[u8])> {
use atoi::FromRadix10;
match i64::from_radix_10(line) {
Expand All @@ -290,6 +266,9 @@ fn parse_cmdstart(enabled: bool, ts: i64, line: &[u8]) -> Option<Hist> {
}

fn parse_cmdstop(enabled: bool, ts: i64, line: &[u8]) -> Option<Hist> {
// It would be nice to match "exiting (un)successfully" lines instead (to give more
// information), but sometimes we only have the "terminating" line, so we'd need a stateful
// parser to handle this.
(enabled && line.starts_with(b"*** terminating")).then_some(Hist::CmdStop { ts })
}

Expand All @@ -298,9 +277,11 @@ fn parse_mergestart(enabled: bool, ts: i64, line: &[u8], filter: &FilterStr) ->
return None;
}
let mut tokens = from_utf8(line).ok()?.split_ascii_whitespace();
let t6 = tokens.nth(5)?;
let pos = find_version(t6, filter)?;
Some(Hist::MergeStart { ts, key: t6.to_owned(), pos })
let nth = atoi::atoi(tokens.nth(2)?.trim_start_matches('(').as_bytes())?;
let of = atoi::atoi(tokens.nth(1)?.trim_end_matches(')').as_bytes())?;
let key = tokens.next()?;
let pos = find_version(key, filter)?;
Some(Hist::MergeStart { ts, key: key.to_owned(), pos, nth, of })
}

fn parse_mergestop(enabled: bool, ts: i64, line: &[u8], filter: &FilterStr) -> Option<Hist> {
Expand Down Expand Up @@ -396,7 +377,8 @@ mod tests {
let hist = get_hist(&format!("tests/emerge.{}.log", file),
filter_mints,
filter_maxts,
Show { pkg: false,
Show { cmd: false,
pkg: false,
tot: false,
sync: parse_sync,
merge: parse_merge,
Expand All @@ -410,6 +392,8 @@ mod tests {
// Check that all items look valid
for p in hist {
let (kind, ts, ebuild, version) = match p {
Hist::CmdStart { ts, .. } => ("CStart", ts, "c/e", "1"),
Hist::CmdStop { ts, .. } => ("CStop", ts, "c/e", "1"),
Hist::MergeStart { ts, .. } => ("MStart", ts, p.ebuild(), p.version()),
Hist::MergeStop { ts, .. } => ("MStop", ts, p.ebuild(), p.version()),
Hist::UnmergeStart { ts, .. } => ("UStart", ts, p.ebuild(), p.version()),
Expand Down
19 changes: 12 additions & 7 deletions tests/commands.rs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -100,13 +100,18 @@ fn log() {
2020-06-18 16:21:56 1 Sync moltonel\n"),
// Check output of all events
("%F10000.log l --show a --from 2018-03-07T10:42:00 --to 2018-03-07T14:00:00 -oc",
"2018-03-07 10:43:10 14 >>> sys-apps/the_silver_searcher-2.0.0\n\
2018-03-07 11:37:05 38 Sync gentoo\n\
2018-03-07 12:49:09 2 <<< sys-apps/util-linux-2.30.2\n\
2018-03-07 12:49:13 1:01 >>> sys-apps/util-linux-2.30.2-r1\n\
2018-03-07 13:56:09 40 Sync gentoo\n\
2018-03-07 13:59:38 2 <<< dev-libs/nspr-4.17\n\
2018-03-07 13:59:41 24 >>> dev-libs/nspr-4.18\n"),
"2018-03-07 10:43:10 14 >>> sys-apps/the_silver_searcher-2.0.0\n\
2018-03-07 10:43:11 20 Emerge --backtrack=100 --quiet-build=y sys-apps/the_silver_searcher 1/1\n\
2018-03-07 11:37:05 38 Sync gentoo\n\
2018-03-07 11:37:06 39 Emerge --quiet-build=y --sync\n\
2018-03-07 12:49:09 2 <<< sys-apps/util-linux-2.30.2\n\
2018-03-07 12:49:13 1:01 >>> sys-apps/util-linux-2.30.2-r1\n\
2018-03-07 12:49:14 1:10:45 Emerge --deep --backtrack=100 --quiet-build=y --ask --update --jobs=2 --newuse --verbose world 1/1\n\
2018-03-07 13:56:09 40 Sync gentoo\n\
2018-03-07 13:56:09 40 Emerge --quiet-build=y --sync\n\
2018-03-07 13:57:53 22 Emerge --update --jobs=2 --backtrack=100 --ask --quiet-build=y --verbose --deep --newuse world\n\
2018-03-07 13:59:38 2 <<< dev-libs/nspr-4.17\n\
2018-03-07 13:59:41 24 >>> dev-libs/nspr-4.18\n"),
// skip first
("%F10000.log l client -oc --first 2",
"2018-02-04 04:55:19 35:46 >>> mail-client/thunderbird-52.6.0\n\
Expand Down

0 comments on commit 5220495

Please sign in to comment.