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

@@ -1,23 +1,30 @@
 # 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
 * `--from` and `--to` now accept more values
   - 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
 

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<Self> {
+        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<HashMap<String, String>> {
-        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('/')) {

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<String>,
                 search_exact: bool)
                 -> Result<Receiver<Hist>, 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<String>, exact: bool) -> Result<Self, regex::Error> {
-        debug!("Search: {terms:?} {exact}");
+        trace!("Search: {terms:?} {exact}");
         Ok(match (terms.len(), exact) {
             (0, _) => Self::True,
             (_, true) => {