feat: integrate tracing and enhance bit matrix operations

Add the `tracing` crate to `obidebruinj`, `obisys`, and resolve it in `Cargo.lock`. Replace `eprintln!` statements with structured `debug!` and `info!` macros. Introduce a `TracedBar` wrapper for progress bars and enhance the `Stage` lifecycle to emit structured events for timing, memory metrics, and swap warnings. Add a progress spinner for unitig degree computation. Extend `PersistentBitMatrix` with columnar bit-vector operations and parallel distance methods, enabling uniform distance computations across all storage layouts while replacing previous panics with dimension-based fallbacks.

src/obisys/Cargo.toml

@@ -7,3 +7,4 @@ edition = "2024"
 libc      = "0.2"
 sysinfo   = "0.33"
 indicatif = "0.17"
+tracing   = "0.1"

src/obisys/src/lib.rs

@@ -1,13 +1,79 @@
 use std::fmt;
+use std::sync::atomic::{AtomicU64, Ordering};
 use std::time::{Duration, Instant};
 
 use indicatif::{ProgressBar, ProgressStyle};
+use tracing::{info, warn};
 
 const BRAILLE: &[&str] = &["⠋", "⠙", "⠹", "⠸", "⠼", "⠴", "⠦", "⠧", "⠇", "⠏"];
 
+// ── TracedBar ──────────────────────────────────────────────────────────────────
+
+/// Wrapper around `ProgressBar` that emits `tracing` events when stderr is not
+/// a TTY (e.g. HPC job logs): every 10% for bounded bars, every ~10 s for
+/// spinners (throttled on `set_message`).
+pub struct TracedBar {
+    pb:          ProgressBar,
+    label:       String,
+    unit:        String,
+    total:       u64,        // 0 for spinners
+    start:       Instant,    // creation time, for spinner throttling
+    last_pct:    AtomicU64,  // last emitted 10%-bucket (1..=10), 0 = none yet
+    last_log_ms: AtomicU64,  // ms since `start` at last spinner log
+}
+
+impl TracedBar {
+    pub fn inc(&self, delta: u64) {
+        self.pb.inc(delta);
+        if self.pb.is_hidden() && self.total > 0 {
+            let pos   = self.pb.position();
+            let pct10 = (pos * 10) / self.total; // 0..=10
+            let last  = self.last_pct.load(Ordering::Relaxed);
+            if pct10 > last
+                && self.last_pct
+                    .compare_exchange(last, pct10, Ordering::Relaxed, Ordering::Relaxed)
+                    .is_ok()
+            {
+                info!(
+                    stage    = %self.label,
+                    progress = format_args!("{}%", pct10 * 10),
+                    "{}/{} {}",
+                    pos, self.total, self.unit
+                );
+            }
+        }
+    }
+
+    pub fn set_message(&self, msg: impl Into<String>) {
+        let msg = msg.into();
+        if self.pb.is_hidden() {
+            if self.total > 0 {
+                // bounded bar: always log (already rate-limited by 10% threshold in inc)
+                info!(stage = %self.label, "{msg}");
+            } else {
+                // spinner: throttle to ~10 s
+                let now_ms = self.start.elapsed().as_millis() as u64;
+                let last   = self.last_log_ms.load(Ordering::Relaxed);
+                if now_ms >= last + 10_000
+                    && self.last_log_ms
+                        .compare_exchange(last, now_ms, Ordering::Relaxed, Ordering::Relaxed)
+                        .is_ok()
+                {
+                    info!(stage = %self.label, "{msg}");
+                }
+            }
+        }
+        self.pb.set_message(msg);
+    }
+
+    pub fn finish_and_clear(&self) {
+        self.pb.finish_and_clear();
+    }
+}
+
 /// Spinner with the standard project look: `⠋ label — msg  0s`.
 /// Caller updates the message with `pb.set_message(...)`.
-pub fn spinner(label: &str) -> ProgressBar {
+pub fn spinner(label: &str) -> TracedBar {
     let pb = ProgressBar::new_spinner();
     pb.set_style(
         ProgressStyle::with_template(&format!("{{spinner}} {label} — {{msg}}  {{elapsed}}"))
@@ -15,12 +81,15 @@ pub fn spinner(label: &str) -> ProgressBar {
             .tick_strings(BRAILLE),
     );
     pb.enable_steady_tick(Duration::from_millis(100));
-    pb
+    TracedBar {
+        pb, label: label.to_string(), unit: String::new(), total: 0,
+        start: Instant::now(), last_pct: AtomicU64::new(0), last_log_ms: AtomicU64::new(0),
+    }
 }
 
 /// Progress bar with the standard project look:
 /// `⠋ label — [████░░░░] pos/len unit  elapsed`.
-pub fn progress_bar(label: &str, n: u64, unit: &str) -> ProgressBar {
+pub fn progress_bar(label: &str, n: u64, unit: &str) -> TracedBar {
     let pb = ProgressBar::new(n);
     pb.set_style(
         ProgressStyle::with_template(&format!(
@@ -30,7 +99,10 @@ pub fn progress_bar(label: &str, n: u64, unit: &str) -> ProgressBar {
         .tick_strings(BRAILLE),
     );
     pb.enable_steady_tick(Duration::from_millis(100));
-    pb
+    TracedBar {
+        pb, label: label.to_string(), unit: unit.to_string(), total: n,
+        start: Instant::now(), last_pct: AtomicU64::new(0), last_log_ms: AtomicU64::new(0),
+    }
 }
 
 use libc::{RUSAGE_SELF, getrusage, rusage, timeval};
@@ -83,13 +155,15 @@ pub struct Stage {
 
 impl Stage {
     pub fn start(label: impl Into<String>) -> Self {
-        Self { label: label.into(), wall: Instant::now(), ru: get_rusage() }
+        let label = label.into();
+        info!(stage = %label, "started");
+        Self { label, wall: Instant::now(), ru: get_rusage() }
     }
 
     pub fn stop(self) -> StageStats {
         let wall_secs = self.wall.elapsed().as_secs_f64();
         let end = get_rusage();
-        StageStats {
+        let stats = StageStats {
             label:         self.label,
             wall_secs,
             user_secs:     tv_to_secs(end.ru_utime) - tv_to_secs(self.ru.ru_utime),
@@ -102,7 +176,22 @@ impl Stage {
             in_blocks:     delta(end.ru_inblock as i64, self.ru.ru_inblock as i64),
             out_blocks:    delta(end.ru_oublock as i64, self.ru.ru_oublock as i64),
             swaps:         delta(end.ru_nswap   as i64, self.ru.ru_nswap   as i64),
+        };
+        info!(
+            stage      = %stats.label,
+            wall_secs  = format_args!("{:.3}", stats.wall_secs),
+            rss        = %fmt_bytes(stats.max_rss_bytes),
+            swaps      = stats.swaps,
+            "done"
+        );
+        if stats.swaps > 0 {
+            warn!(
+                stage = %stats.label,
+                swaps = stats.swaps,
+                "working set exceeds available RAM"
+            );
         }
+        stats
     }
 }