From c5074e213bae93a9352396054b031991d884a0de Mon Sep 17 00:00:00 2001 From: Vincent de Phily Date: Wed, 15 Jan 2025 10:33:56 +0000 Subject: [PATCH 1/3] parse/stats: Follow package moves Keeps build time stats accross renames. See #60. This commit is an MVP, lacking tests and optimizations. Even then, parsing 80 update files takes 2-6ms on my system, so the cost of this double-parsing single-threaded implementation is already low. We get the list of update files from the mtimedb, which is nice because we already parse it and can yet again avoid locating the installed repos, but also lists (on my system) some non-existing files and files from an inactive repo. --- docs/COMPARISON.md | 2 +- src/commands.rs | 23 +++++++------ src/parse.rs | 2 +- src/parse/current.rs | 78 +++++++++++++++++++++++++++++++++++++++++++- 4 files changed, 92 insertions(+), 13 deletions(-) diff --git a/docs/COMPARISON.md b/docs/COMPARISON.md index 9ab9412..6cc8fc4 100644 --- a/docs/COMPARISON.md +++ b/docs/COMPARISON.md @@ -131,7 +131,7 @@ estimate the resulting speedup factor. | Global ETA format | total time | total time | total time, end date | | Estimation accuracy | ok | better | best, configurable | | Recognize binary emerges | no | no | yes | -| Follow package renames | yes | no | no | +| Follow package moves | no | no | yes | | Query gentoo.linuxhowtos.org for unknown packages | yes | no | no | ## Speed diff --git a/src/commands.rs b/src/commands.rs index f6b1df2..9fb86ef 100644 --- a/src/commands.rs +++ b/src/commands.rs @@ -179,6 +179,7 @@ impl ArgKind { /// Then we compute the stats per ebuild, and print that. pub fn cmd_stats(gc: Conf, sc: ConfStats) -> Result { let hist = get_hist(&gc.logfile, gc.from, gc.to, sc.show, &sc.search, sc.exact)?; + let moves = PkgMoves::new(); let h = [sc.group.name(), "Logged emerges", "Install/Update", "Unmerge/Clean", "Sync"]; let mut tblc = Table::new(&gc).margin(1, " ").header(h); let h = [sc.group.name(), "Repo", "Syncs", "Total time", "Predict time"]; @@ -237,7 +238,7 @@ pub fn cmd_stats(gc: Conf, sc: ConfStats) -> Result { *run_args.entry(ArgKind::new(&args)).or_insert(0) += 1; }, Hist::MergeStart { ts, key, .. } => { - merge_start.insert(key, (ts, false)); + merge_start.insert(moves.get(key), (ts, false)); }, Hist::MergeStep { kind, key, .. } => { if matches!(kind, MergeStep::MergeBinary) { @@ -247,9 +248,9 @@ pub fn cmd_stats(gc: Conf, sc: ConfStats) -> Result { } }, Hist::MergeStop { ts, ref key, .. } => { - if let Some((start_ts, bin)) = merge_start.remove(key) { + if let Some((start_ts, bin)) = merge_start.remove(moves.get_ref(key)) { let (tc, tb, _) = - pkg_time.entry(p.take_ebuild()) + pkg_time.entry(moves.get(p.take_ebuild())) .or_insert((Times::new(), Times::new(), Times::new())); if bin { tb.insert(ts - start_ts); @@ -259,12 +260,12 @@ pub fn cmd_stats(gc: Conf, sc: ConfStats) -> Result { } }, Hist::UnmergeStart { ts, key, .. } => { - unmerge_start.insert(key, ts); + unmerge_start.insert(moves.get(key), ts); }, Hist::UnmergeStop { ts, ref key, .. } => { - if let Some(start_ts) = unmerge_start.remove(key) { + if let Some(start_ts) = unmerge_start.remove(moves.get_ref(key)) { let (_, _, times) = - pkg_time.entry(p.take_ebuild()) + pkg_time.entry(moves.get(p.take_ebuild())) .or_insert((Times::new(), Times::new(), Times::new())); times.insert(ts - start_ts); } @@ -450,23 +451,25 @@ pub fn cmd_predict(gc: Conf, mut sc: ConfPred) -> Result { // Parse emerge log. let hist = get_hist(&gc.logfile, gc.from, gc.to, Show::m(), &vec![], false)?; + let moves = PkgMoves::new(); let mut started: BTreeMap = BTreeMap::new(); let mut times: HashMap<(String, bool), Times> = HashMap::new(); for p in hist { match p { Hist::MergeStart { ts, key, .. } => { - started.insert(key, (ts, false)); + started.insert(moves.get(key), (ts, false)); }, Hist::MergeStep { kind, key, .. } => { if matches!(kind, MergeStep::MergeBinary) { - if let Some((_, bin)) = started.get_mut(&key) { + if let Some((_, bin)) = started.get_mut(moves.get_ref(&key)) { *bin = true; } } }, Hist::MergeStop { ts, ref key, .. } => { - if let Some((start_ts, bin)) = started.remove(key.as_str()) { - let timevec = times.entry((p.take_ebuild(), bin)).or_insert(Times::new()); + if let Some((start_ts, bin)) = started.remove(moves.get_ref(key)) { + let timevec = + times.entry((moves.get(p.take_ebuild()), bin)).or_insert(Times::new()); timevec.insert(ts - start_ts); } }, diff --git a/src/parse.rs b/src/parse.rs index 54f61d3..7815cbb 100644 --- a/src/parse.rs +++ b/src/parse.rs @@ -4,7 +4,7 @@ mod history; mod proces; pub use ansi::{Ansi, AnsiStr, Theme}; -pub use current::{get_buildlog, get_emerge, get_pretend, get_resume, Pkg}; +pub use current::{get_buildlog, get_emerge, get_pretend, get_resume, Pkg, PkgMoves}; pub use history::{get_hist, Hist, MergeStep}; #[cfg(test)] pub use proces::tests::procs; diff --git a/src/parse/current.rs b/src/parse/current.rs index 6885108..531b1c0 100644 --- a/src/parse/current.rs +++ b/src/parse/current.rs @@ -7,7 +7,8 @@ use log::*; use regex::Regex; use serde::Deserialize; use serde_json::from_reader; -use std::{fs::File, +use std::{collections::HashMap, + fs::File, io::{BufRead, BufReader, Read}, path::PathBuf}; @@ -81,6 +82,7 @@ struct Resume { struct Mtimedb { resume: Option, resume_backup: Option, + updates: Option>, } /// Parse resume list from portage mtimedb @@ -111,6 +113,80 @@ fn get_resume_priv(kind: ResumeKind, file: &str) -> Option> { .collect()) } +pub struct PkgMoves(HashMap); +impl PkgMoves { + /// Parse package moves using file list from portagedb + pub fn new() -> Self { + let r = Self::load("/var/cache/edb/mtimedb").unwrap_or_default(); + trace!("Package moves: {r:?}"); + Self(r) + } + + pub fn get(&self, key: String) -> String { + self.0.get(&key).cloned().unwrap_or(key) + } + + pub fn get_ref<'a>(&'a self, key: &'a String) -> &'a String { + self.0.get(key).unwrap_or(key) + } + + fn load(file: &str) -> Option> { + let now = std::time::Instant::now(); + let reader = File::open(file).map_err(|e| warn!("Cannot open {file:?}: {e}")).ok()?; + let db: Mtimedb = + from_reader(reader).map_err(|e| warn!("Cannot parse {file:?}: {e}")).ok()?; + let mut moves = HashMap::new(); + if let Some(updates) = db.updates { + // Sort the files in reverse chronological order (compare year, then quarter) + let mut files: Vec<_> = updates.keys().collect(); + files.sort_by(|a, b| match (a.rsplit_once('/'), b.rsplit_once('/')) { + (Some((_, a)), Some((_, b))) if a.len() == 7 && b.len() == 7 => { + match a[3..].cmp(&b[3..]) { + std::cmp::Ordering::Equal => a[..3].cmp(&b[..3]), + o => o, + }.reverse() + }, + _ => { + warn!("Unexpected update file name {a}"); + a.cmp(b) + }, + }); + // + for f in files { + Self::parse(&mut moves, f); + } + debug!("Loaded {} package moves from {} files in {:?}", + moves.len(), + updates.len(), + now.elapsed()); + } + Some(moves) + } + + fn parse(moves: &mut HashMap, file: &str) -> Option<()> { + trace!("Parsing {file}"); + let f = File::open(file).map_err(|e| warn!("Cannot open {file:?}: {e}")).ok()?; + for line in + BufReader::new(f).lines().map_while(Result::ok).filter(|l| l.starts_with("move ")) + { + if let Some((from, to)) = line[5..].split_once(' ') { + // Portage rewrites each repo's update files so that entries point directly to the final + // name, but there can still be cross-repo chains, which we untangle here. Assumes the + // first name seen is the latest one. + if let Some(to_final) = moves.get(to) { + if from != to_final { + trace!("Pointing {from} to {to_final} instead of {to}"); + moves.insert(from.to_owned(), to_final.clone()); + } + } else { + moves.insert(from.to_owned(), to.to_owned()); + } + } + } + Some(()) + } +} + /// Retrieve summary info from the build log pub fn get_buildlog(pkg: &Pkg, portdirs: &Vec) -> Option { From 2cb555838cc7f450aeb6cb463a726965e908c06e Mon Sep 17 00:00:00 2001 From: Vincent de Phily Date: Thu, 16 Jan 2025 14:27:12 +0000 Subject: [PATCH 2/3] parse/qa: Avoid parsing mtimedb twice, refactor, add unittest A bit of a brain-teaser to find and cleanly document failure modes, but it found one bug (duplicates overwriting instead of being ignored), which gives some confidence in the test. --- src/commands.rs | 7 ++- src/parse.rs | 2 +- src/parse/current.rs | 136 ++++++++++++++++++++++++++---------------- tests/1Q-2024 | 7 +++ tests/4Q-2022 | 6 ++ tests/mtimedb.updates | 7 +++ 6 files changed, 111 insertions(+), 54 deletions(-) create mode 100644 tests/1Q-2024 create mode 100644 tests/4Q-2022 create mode 100644 tests/mtimedb.updates diff --git a/src/commands.rs b/src/commands.rs index 9fb86ef..dbfe686 100644 --- a/src/commands.rs +++ b/src/commands.rs @@ -179,7 +179,7 @@ impl ArgKind { /// Then we compute the stats per ebuild, and print that. pub fn cmd_stats(gc: Conf, sc: ConfStats) -> Result { let hist = get_hist(&gc.logfile, gc.from, gc.to, sc.show, &sc.search, sc.exact)?; - let moves = PkgMoves::new(); + let moves = PkgMoves::new(&Mtimedb::new()); let h = [sc.group.name(), "Logged emerges", "Install/Update", "Unmerge/Clean", "Sync"]; let mut tblc = Table::new(&gc).margin(1, " ").header(h); let h = [sc.group.name(), "Repo", "Syncs", "Total time", "Predict time"]; @@ -451,7 +451,8 @@ pub fn cmd_predict(gc: Conf, mut sc: ConfPred) -> Result { // Parse emerge log. let hist = get_hist(&gc.logfile, gc.from, gc.to, Show::m(), &vec![], false)?; - let moves = PkgMoves::new(); + let mdb = Mtimedb::new(); + let moves = PkgMoves::new(&mdb); let mut started: BTreeMap = BTreeMap::new(); let mut times: HashMap<(String, bool), Times> = HashMap::new(); for p in hist { @@ -480,7 +481,7 @@ pub fn cmd_predict(gc: Conf, mut sc: ConfPred) -> Result { // Build list of pending merges let pkgs: Vec = if std::io::stdin().is_terminal() { // From resume list - let mut r = get_resume(sc.resume); + let mut r = get_resume(sc.resume, &mdb); // Plus specific emerge processes for p in einfo.pkgs.iter() { if !r.contains(p) { diff --git a/src/parse.rs b/src/parse.rs index 7815cbb..460c29f 100644 --- a/src/parse.rs +++ b/src/parse.rs @@ -4,7 +4,7 @@ mod history; mod proces; pub use ansi::{Ansi, AnsiStr, Theme}; -pub use current::{get_buildlog, get_emerge, get_pretend, get_resume, Pkg, PkgMoves}; +pub use current::{get_buildlog, get_emerge, get_pretend, get_resume, Mtimedb, Pkg, PkgMoves}; pub use history::{get_hist, Hist, MergeStep}; #[cfg(test)] pub use proces::tests::procs; diff --git a/src/parse/current.rs b/src/parse/current.rs index 531b1c0..b34e4e4 100644 --- a/src/parse/current.rs +++ b/src/parse/current.rs @@ -74,36 +74,42 @@ pub fn get_pretend(reader: R, filename: &str) -> Vec { out } + #[derive(Deserialize)] struct Resume { mergelist: Vec>, } -#[derive(Deserialize)] -struct Mtimedb { +#[derive(Deserialize, Default)] +pub struct Mtimedb { resume: Option, resume_backup: Option, updates: Option>, } +impl Mtimedb { + pub fn new() -> Self { + Self::try_new("/var/cache/edb/mtimedb").unwrap_or_default() + } + fn try_new(file: &str) -> Option { + let reader = File::open(file).map_err(|e| warn!("Cannot open {file:?}: {e}")).ok()?; + from_reader(reader).map_err(|e| warn!("Cannot parse {file:?}: {e}")).ok() + } +} + /// Parse resume list from portage mtimedb -pub fn get_resume(kind: ResumeKind) -> Vec { - let r = get_resume_priv(kind, "/var/cache/edb/mtimedb").unwrap_or_default(); +pub fn get_resume(kind: ResumeKind, db: &Mtimedb) -> Vec { + let r = try_get_resume(kind, db).unwrap_or_default(); debug!("Loaded {kind:?} resume list: {r:?}"); r } -fn get_resume_priv(kind: ResumeKind, file: &str) -> Option> { - if matches!(kind, ResumeKind::No) { - return Some(vec![]); - } - let reader = File::open(file).map_err(|e| warn!("Cannot open {file:?}: {e}")).ok()?; - let db: Mtimedb = from_reader(reader).map_err(|e| warn!("Cannot parse {file:?}: {e}")).ok()?; +fn try_get_resume(kind: ResumeKind, db: &Mtimedb) -> Option> { let r = match kind { ResumeKind::Either | ResumeKind::Auto => { - db.resume.filter(|o| !o.mergelist.is_empty()).or(db.resume_backup)? + db.resume.as_ref().filter(|o| !o.mergelist.is_empty()).or(db.resume_backup.as_ref())? }, - ResumeKind::Main => db.resume?, - ResumeKind::Backup => db.resume_backup?, - ResumeKind::No => unreachable!(), + ResumeKind::Main => db.resume.as_ref()?, + ResumeKind::Backup => db.resume_backup.as_ref()?, + ResumeKind::No => return Some(vec![]), }; Some(r.mergelist .iter() @@ -113,11 +119,12 @@ fn get_resume_priv(kind: ResumeKind, file: &str) -> Option> { .collect()) } + pub struct PkgMoves(HashMap); impl PkgMoves { /// Parse package moves using file list from portagedb - pub fn new() -> Self { - let r = Self::load("/var/cache/edb/mtimedb").unwrap_or_default(); + pub fn new(db: &Mtimedb) -> Self { + let r = Self::try_new(db).unwrap_or_default(); trace!("Package moves: {r:?}"); Self(r) } @@ -130,36 +137,31 @@ impl PkgMoves { self.0.get(key).unwrap_or(key) } - fn load(file: &str) -> Option> { + fn try_new(db: &Mtimedb) -> Option> { let now = std::time::Instant::now(); - let reader = File::open(file).map_err(|e| warn!("Cannot open {file:?}: {e}")).ok()?; - let db: Mtimedb = - from_reader(reader).map_err(|e| warn!("Cannot parse {file:?}: {e}")).ok()?; + // Sort the files in reverse chronological order (compare year, then quarter) + let mut files: Vec<_> = db.updates.as_ref()?.keys().collect(); + files.sort_by(|a, b| match (a.rsplit_once('/'), b.rsplit_once('/')) { + (Some((_, a)), Some((_, b))) if a.len() == 7 && b.len() == 7 => { + match a[3..].cmp(&b[3..]) { + std::cmp::Ordering::Equal => a[..3].cmp(&b[..3]), + o => o, + }.reverse() + }, + _ => { + warn!("Using default sort for {a} <> {b}"); + a.cmp(b) + }, + }); + // Read each file to populate the result map let mut moves = HashMap::new(); - if let Some(updates) = db.updates { - // Sort the files in reverse chronological order (compare year, then quarter) - let mut files: Vec<_> = updates.keys().collect(); - files.sort_by(|a, b| match (a.rsplit_once('/'), b.rsplit_once('/')) { - (Some((_, a)), Some((_, b))) if a.len() == 7 && b.len() == 7 => { - match a[3..].cmp(&b[3..]) { - std::cmp::Ordering::Equal => a[..3].cmp(&b[..3]), - o => o, - }.reverse() - }, - _ => { - warn!("Unexpected update file name {a}"); - a.cmp(b) - }, - }); - // - for f in files { - Self::parse(&mut moves, f); - } - debug!("Loaded {} package moves from {} files in {:?}", - moves.len(), - updates.len(), - now.elapsed()); + for f in &files { + Self::parse(&mut moves, f); } + debug!("Loaded {} package moves from {} files in {:?}", + moves.len(), + files.len(), + now.elapsed()); Some(moves) } @@ -170,16 +172,19 @@ impl PkgMoves { BufReader::new(f).lines().map_while(Result::ok).filter(|l| l.starts_with("move ")) { if let Some((from, to)) = line[5..].split_once(' ') { - // Portage rewrites each repo's update files so that entries point directly to the final - // name, but there can still be cross-repo chains, which we untangle here. Assumes the - // first name seen is the latest one. + // Portage rewrites each repo's update files so that entries point directly to the + // final name, but there can still be cross-repo chains, which we untangle + // here. Assumes we're parsing files newest-first. if let Some(to_final) = moves.get(to) { if from != to_final { - trace!("Pointing {from} to {to_final} instead of {to}"); + trace!("Using move {from} -> {to_final} instead -> {to} in {file}"); moves.insert(from.to_owned(), to_final.clone()); + } else { + trace!("Ignoring move {from} -> {to} in {file}"); } } else { - moves.insert(from.to_owned(), to.to_owned()); + // TODO: MSRV 1.?? try_insert https://github.com/rust-lang/rust/issues/82766 + moves.entry(from.to_owned()).or_insert_with(|| to.to_owned()); } } } @@ -307,9 +312,9 @@ mod tests { /// Check that `get_resume()` has the expected output fn check_resume(kind: ResumeKind, file: &str, expect: Option<&[(&str, bool)]>) { - let expect_pkg = + let expect_pkg: Option> = expect.map(|o| o.into_iter().map(|(s, b)| Pkg::try_new(s, *b).unwrap()).collect()); - let res = get_resume_priv(kind, &format!("tests/{file}")); + let res = Mtimedb::try_new(&format!("tests/{file}")).and_then(|m| try_get_resume(kind, &m)); assert_eq!(expect_pkg, res, "Mismatch for {file}"); } @@ -367,4 +372,35 @@ mod tests { let einfo = get_emerge(&procs); assert_eq!(einfo.roots, vec![1, 5]); } + + #[test] + fn pkgmoves() { + // It's interesting to run this test with RUST_LOG=trace. Expect: + // * "Cannot open tests/notfound: No such file or directory" + // * "Using default sort ..." (depending on random hashmap seed) + // * "Using move chain/v1 -> chain/v3 instead -> chain/v2 in tests/4Q-2022" + // * "Ignoring move loop/final -> loop/from in tests/4Q-2022" + let _ = env_logger::try_init(); + let moves = PkgMoves::new(&Mtimedb::try_new("tests/mtimedb.updates").unwrap()); + for (have, want, why) in + [// Basic cases + ("app-doc/doxygen", "app-text/doxygen", "simple move in 2024"), + ("x11-libs/libva", "media-libs/libva", "simple move in 2022"), + ("notmoved", "notmoved", "unknown string should return original string"), + ("dev-haskell/extra", "dev-haskell/extra", "slotmoves should be ignored"), + // Multi-moves where portage updated the old file + ("dev-util/lldb", "llvm-core/lldb", "1st lldb rename"), + ("dev-debug/lldb", "llvm-core/lldb", "2nd lldb rename"), + // Weird cases + ("duplicate/bar", "foo/bar", "duplicate update should prefer newest (no trace)"), + ("conflict/foo", "foo/2024", "conflicting update should prefer newest (no trace)"), + ("loop/from", "loop/final", "loops should prefer newest (trace \"ignore move...\")"), + ("chain/v2", "chain/v3", "chain from new should be taken as-is (no trace)"), + ("chain/v1", + "chain/v3", + "chain from old should point to new (trace \"using move...\")")] + { + assert_eq!(moves.get(String::from(have)), String::from(want), "{why}"); + } + } } diff --git a/tests/1Q-2024 b/tests/1Q-2024 new file mode 100644 index 0000000..59319b5 --- /dev/null +++ b/tests/1Q-2024 @@ -0,0 +1,7 @@ +move app-doc/doxygen app-text/doxygen +slotmove dev-build/autoconf-dickey 2.52_p20210509 2.52 +move dev-debug/lldb llvm-core/lldb +move conflict/foo foo/2024 +move duplicate/bar foo/bar +move chain/v2 chain/v3 +move loop/from loop/final \ No newline at end of file diff --git a/tests/4Q-2022 b/tests/4Q-2022 new file mode 100644 index 0000000..c205b52 --- /dev/null +++ b/tests/4Q-2022 @@ -0,0 +1,6 @@ +move x11-libs/libva media-libs/libva +move dev-util/lldb llvm-core/lldb +move conflict/foo foo/2022 +move duplicate/bar foo/bar +move chain/v1 chain/v2 +move loop/final loop/from \ No newline at end of file diff --git a/tests/mtimedb.updates b/tests/mtimedb.updates new file mode 100644 index 0000000..0df7481 --- /dev/null +++ b/tests/mtimedb.updates @@ -0,0 +1,7 @@ +{ + "updates": { + "tests/notfound": 1640636550, + "tests/1Q-2024": 1669625966, + "tests/4Q-2022": 1640636540 + } +} \ No newline at end of file From db0606e57b4cc7a1cd1835f937c14c81be9eb784 Mon Sep 17 00:00:00 2001 From: Vincent de Phily Date: Thu, 16 Jan 2025 15:36:39 +0000 Subject: [PATCH 3/3] qa/docs: Update changelog, add timing logs, demote debugs to traces Interestingly, parsing the mtimedb json takes 3x as long as parsing 65 update files. --- CHANGELOG.md | 12 ++++++++++-- src/parse/current.rs | 10 +++++++--- src/parse/history.rs | 23 +++++++++++++---------- 3 files changed, 30 insertions(+), 15 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 4a76092..bca2584 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,11 +1,17 @@ # unreleased +Feature release: Binary merges, package moves, emerge arguments, process tree, configurable colors, +and other goodies. + ## New features * `log`, `stats` and `predict` now take binary merges into account - Track merge time stats separately - Display bin merges in a different color - The `unknown` config has been split into `unknownc` (compiled) and `unknownb` (binary) +* `stats` and `predict` now follow package moves + - Merge time predictions remain correct after a rename like `sys-devel/llvm` -> `llvm-core/llvm` + - `Stats` are aggregated using the latest name * `log` and `stat` can now show emerge (r)runs - Use `--show=r`/`-sr`/`-sa` to enable it - No duration given, as `emerge.log` doesn't provide enough info to make this reliable @@ -13,11 +19,12 @@ - New `command` keyword resolves to the time of the nth emerge command (`-fc` is roughly equivalent to qlop's `--lastmerge`) - A single span (`day`/`y`/`command`/etc) without a count now means that span with a count of 1 + (so `-fd` is equivalent to `-1d`) * `predict` now displays emerge proces tree instead of just top proces - - Bevahvior configurable with `--pdepth`, `--pwidth` + - Behavior configurable with `--pdepth`/`-D`/`--pwidth`/`-W` - Format is a bit nicer and more colorful - `--show=e` renamed `--show=r` (running emerge processes) for consistency -* Display a placeholder for skipped rows, configurable with `--showskip` +* Display a placeholder for skipped rows (`--first`/`--last`/`--pdepth`), configurable with `--showskip` * Colors are now configurable, to match your terminal's theme - Eg `theme = "count:0 duration:1;3;37"` in `emlop.toml` displays counts unstyled and durations in bright italic white. @@ -31,6 +38,7 @@ * Don't display child emerge processes as root ones * Fix off by one upper bound for some cli args * Allow alignment of wider columns +* Fix bright/dim terminal colors for stats counts # 0.7.1 2024-09-30 diff --git a/src/parse/current.rs b/src/parse/current.rs index b34e4e4..9b8875e 100644 --- a/src/parse/current.rs +++ b/src/parse/current.rs @@ -10,7 +10,8 @@ use serde_json::from_reader; use std::{collections::HashMap, fs::File, io::{BufRead, BufReader, Read}, - path::PathBuf}; + path::PathBuf, + time::Instant}; /// Package name and version #[derive(Debug, Clone, PartialEq, Eq, PartialOrd, Ord)] @@ -90,8 +91,11 @@ impl Mtimedb { Self::try_new("/var/cache/edb/mtimedb").unwrap_or_default() } fn try_new(file: &str) -> Option { + let now = Instant::now(); let reader = File::open(file).map_err(|e| warn!("Cannot open {file:?}: {e}")).ok()?; - from_reader(reader).map_err(|e| warn!("Cannot parse {file:?}: {e}")).ok() + let r = from_reader(reader).map_err(|e| warn!("Cannot parse {file:?}: {e}")).ok(); + debug!("Loaded {file} in {:?}", now.elapsed()); + r } } @@ -138,7 +142,7 @@ impl PkgMoves { } fn try_new(db: &Mtimedb) -> Option> { - let now = std::time::Instant::now(); + let now = Instant::now(); // Sort the files in reverse chronological order (compare year, then quarter) let mut files: Vec<_> = db.updates.as_ref()?.keys().collect(); files.sort_by(|a, b| match (a.rsplit_once('/'), b.rsplit_once('/')) { diff --git a/src/parse/history.rs b/src/parse/history.rs index b1da9f1..c07e0b8 100644 --- a/src/parse/history.rs +++ b/src/parse/history.rs @@ -11,7 +11,8 @@ use regex::{Regex, RegexBuilder, RegexSet, RegexSetBuilder}; use std::{fs::File, io::{BufRead, BufReader}, str::from_utf8, - thread}; + thread, + time::Instant}; /// Items sent on the channel returned by `new_hist()`. #[derive(Debug)] @@ -119,8 +120,9 @@ pub fn get_hist(file: &str, search_terms: &Vec, search_exact: bool) -> Result, Error> { - debug!("File: {file}"); - debug!("Show: {show}"); + trace!("Show: {show}"); + let now = Instant::now(); + let logfile = file.to_owned(); let (ts_min, ts_max) = filter_ts(file, min, max)?; let filter = FilterStr::try_new(search_terms, search_exact)?; let mut buf = open_any_buffered(file)?; @@ -139,7 +141,7 @@ pub fn get_hist(file: &str, Ok(_) => { if let Some((t, s)) = parse_ts(&line, ts_min, ts_max) { if prev_t > t { - warn!("logfile:{curline}: System clock jump: {} -> {}", + warn!("{logfile}:{curline}: System clock jump: {} -> {}", fmt_utctime(prev_t), fmt_utctime(t)); } @@ -181,11 +183,12 @@ pub fn get_hist(file: &str, } }, // Could be invalid UTF8, system read error... - Err(e) => warn!("logfile:{curline}: {e}"), + Err(e) => warn!("{logfile}:{curline}: {e}"), } line.clear(); curline += 1; } + debug!("Parsed {curline} {logfile} lines in {:?}", now.elapsed()); }); Ok(rx) } @@ -226,11 +229,11 @@ fn filter_ts(file: &str, min: TimeBound, max: TimeBound) -> Result<(i64, i64), E }; // Check and log bounds, return result match (min, max) { - (None, None) => debug!("Date: None"), - (Some(a), None) => debug!("Date: after {}", fmt_utctime(a)), - (None, Some(b)) => debug!("Date: before {}", fmt_utctime(b)), + (None, None) => trace!("Date: None"), + (Some(a), None) => trace!("Date: after {}", fmt_utctime(a)), + (None, Some(b)) => trace!("Date: before {}", fmt_utctime(b)), (Some(a), Some(b)) if a < b => { - debug!("Date: between {} and {}", fmt_utctime(a), fmt_utctime(b)) + trace!("Date: between {} and {}", fmt_utctime(a), fmt_utctime(b)) }, (Some(a), Some(b)) => { bail!("Invalid date filter: {} <= {}, did you swap --to and --from ?", @@ -250,7 +253,7 @@ enum FilterStr { } impl FilterStr { fn try_new(terms: &Vec, exact: bool) -> Result { - debug!("Search: {terms:?} {exact}"); + trace!("Search: {terms:?} {exact}"); Ok(match (terms.len(), exact) { (0, _) => Self::True, (_, true) => {