From def6d4215267d0575519a96a7d956c25d7267173 Mon Sep 17 00:00:00 2001 From: Vincent de Phily Date: Wed, 6 Nov 2024 15:54:17 +0000 Subject: [PATCH] log: WIP/postmortem improving command termination heuristic At this stage, with the current emerge.log format, I'm afraid there's no reliable way to find when an emerge command ends. There are just too many triping hazards, between missing termination logs, interspersed emerge commands, and resetting merge counters. Fix one case and break the others. Maybe if portage logged the emerge pids, but it might be hard to convince upstream nd I'd still need a fallback for old logs. It might be interesting to look at pqlop code to see how it detects failed merges. I suspect it's also a fragile heuristic, even though the problem is much simpler for (un)merge events. I'm not comfortable releasing a feature based on complex shaky heuristics, so I'm abandoning this branch. But I'll start a new one that only looks at CmdStart events, there are still interesting features to build around that. --- src/commands.rs | 93 ++++++++++++++++++++++++++++++++----------------- 1 file changed, 62 insertions(+), 31 deletions(-) diff --git a/src/commands.rs b/src/commands.rs index 32a8ffe..fc29661 100644 --- a/src/commands.rs +++ b/src/commands.rs @@ -3,33 +3,57 @@ use libc::pid_t; use std::{collections::{BTreeMap, HashMap, HashSet}, io::{stdin, IsTerminal}}; +#[derive(Debug)] +struct CmdState { + ts: i64, + args: String, + pkgs: bool, + nth: u32, + of: u32, +} +impl CmdState { + fn new(ts: i64, args: String) -> Self { + let pkgs = args.split_ascii_whitespace().any(|s| !s.starts_with('-') || s == "--clean"); + Self { ts, args, pkgs, nth: 0, of: 0 } + } +} + /// 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) +fn find_cmd(cmds: &mut Vec, ts: i64) -> (i64, String, String) { + if let Some(p) = cmds.iter().rev().position(|s| s.of != 0 && s.nth == s.of) { + // Newest finished cmd + let s = cmds.remove(p); + (s.ts, s.args, format!("finished cmd {p}/{} at {}/{}", cmds.len() + 1, s.nth, s.of)) + } else if let Some(p) = cmds.iter().rev().position(|s| s.of > 0) { + // Newest cmd without associated merge + let s = cmds.remove(p); + (s.ts, s.args, format!("associated cmd {p}/{}", cmds.len() + 1)) + } else if let Some(s) = cmds.pop() {//iter().rev().position(|s| s.of == 0) { + // Newest cmd without associated merge + //let s = cmds.remove(p); + (s.ts, s.args, format!("unassociated cmd {0}/{0}", cmds.len() + 1)) + //} else if let Some(p) = cmds.iter().position(|&(_, _, nth, of)| of != 0 && nth != of) { + // newest cmd (oldest might be missing its "terminating" log) not matched by other cases + // cmds.remove(p) + //} else if !cmds.is_empty() {//let Some(p) = cmds.iter().position(|_| true) { + // newest cmd (oldest might be missing its "terminating" log) + // cmds.pop().unwrap() } else { // No cmd (should not happen unless --from) warn!("No matching cmd at {ts} in {:?}", cmds); - (ts + 1, String::from("?"), 0, 0) + (ts + 1, String::from("?"), format!("fallback out of {} cmds", cmds.len())) } } /// Update cmd with latest "( of )" 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) { +fn update_cmd(cmds: &mut Vec, nth: u32, of: u32) { + if let Some(p) = cmds.iter().rev().position(|s| nth == 1 && s.of == 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) { + cmds[p].nth = nth; + cmds[p].of = of; + } else if let Some(p) = cmds.iter().rev().position(|s| of == s.of) { // update nth in previously amended cmd - cmds[p].2 = nth; + cmds[p].nth = nth; } else { // TODO: there's probably other cases to handle, with --keep-going or --jobs warn!("No matching cmd for {nth}/{of} in {:?}", cmds); @@ -41,7 +65,7 @@ fn update_cmd(cmds: &mut Vec<(i64, String, u32, u32)>, nth: u32, of: u32) { /// 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 { let hist = get_hist(&gc.logfile, gc.from, gc.to, sc.show, &sc.search, sc.exact)?; - let mut cmds: Vec<(i64, String, u32, u32)> = vec![]; + let mut cmds: Vec = vec![]; let mut merges: HashMap = HashMap::new(); let mut unmerges: HashMap = HashMap::new(); let mut syncs: Option = None; @@ -52,27 +76,34 @@ pub fn cmd_log(gc: Conf, sc: ConfLog) -> Result { for p in hist { match p { Hist::CmdStart { ts, args, .. } => { - cmds.push((ts, args, 0, 0)); + found += 1; + if found <= sc.first { + tbl.row([&[&FmtDate(ts)], &[], &[&"Emerge ", &args]]); + } + cmds.push(CmdState::new(ts, args)); }, Hist::CmdStop { ts, .. } => { found += 1; - let (started, args, nth, of) = find_cmd(&mut cmds, ts); + let (started, args, reason) = find_cmd(&mut cmds, ts); if found <= sc.first { - 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]]); - } + //if nth > 0 { + tbl.row([&[&FmtDate(if sc.starttime { started } else { ts })], + &[&FmtDur(ts - started), &gc.clr], + &[&"Emerge ", &args, &" ", &gc.cnt, &reason]]); + //} else { + // tbl.row([&[&FmtDate(if sc.starttime { started } else { ts })], + // &[&FmtDur(ts - started), &gc.clr], + // &[&"Emerge ", &args]]); + //} } }, - Hist::MergeStart { ts, key, nth, of, .. } => { + Hist::MergeStart { ts, ref key, nth, of, .. } => { if sc.show.merge { // This'll overwrite any previous entry, if a merge started but never finished - merges.insert(key, ts); + merges.insert(key.clone(), ts); + //tbl.row([&[&FmtDate(ts)], + // &[], + // &[&gc.cnt, &nth, &"/", &of, &" ", &cmds.len()]]); } update_cmd(&mut cmds, nth, of); },