diff --git a/docs/progress-logging.md b/docs/progress-logging.md new file mode 100644 index 0000000..d477870 --- /dev/null +++ b/docs/progress-logging.md @@ -0,0 +1,16 @@ +# Progress Logging + +Progress logging is enabled by default and runs in a dedicated sleeping thread. Set `PROGRESS_LOG=0` to disable the logger and all additional stage timers. Set `PROGRESS_LOG_INTERVAL_SECS` to a positive integer number of seconds; the default is `30`. + +The logger prints `generation started` before workers launch, then emits time-based reports containing: + +- Generated, committed, and overall progress as exact counts and percentages. +- Interval and whole-run generation and commit rates in seeds/second. +- Elapsed time and channel occupancy. +- Aggregate worker and writer-pipeline durations. Writer-pipeline time includes connection, channel receive, COPY, and commit time; use the independent runtime-diagnostics branch when those database stages must be separated. While threads remain active, time is estimated as elapsed time per active thread; final values are measured. +- Active and completed worker/writer counts, dominant aggregate thread-time stage, and a queue-based likely bottleneck. +- Linux process RSS, peak RSS, bytes read, and bytes written from `/proc`; unsupported platforms report `n/a`. + +Aggregate stage durations are thread time, so overlapping workers or writers can produce totals larger than wall-clock elapsed time. `likely_bottleneck` is a queue-based diagnostic: at least `80%` occupancy indicates database pressure, at most `20%` indicates generation pressure, and an empty generation phase with outstanding commits indicates database drain. + +Instrumentation does not add a timer or branch to each generation pass. Timing occurs once per worker or writer lifetime, and process/resource collection runs only in the monitor thread at the configured interval. diff --git a/inserter/src/main.rs b/inserter/src/main.rs index 27b08dd..01f8db5 100644 --- a/inserter/src/main.rs +++ b/inserter/src/main.rs @@ -5,12 +5,14 @@ mod logging; mod metrics; mod misc; mod threads; +mod progress; use crate::{ checkpoint::{load_workloads, write_checkpoints}, misc::{check_db_connection, get_env_interval, Timer}, metrics::write_metrics, - threads::* + progress::{commit_thread, worker_thread}, + threads::*, }; use anyhow::{anyhow, Context, Result}; use crossbeam_channel::{bounded, Receiver, Sender}; @@ -163,6 +165,8 @@ fn run() -> Result<()> { } } + let planned_seeds = workloads.iter().map(|workload| workload.len() as u64).sum(); + let progress_logger = progress::ProgressLogger::start(planned_seeds, entry_reciever.clone())?; log_info!("Starting main thread loop"); // Main thread takes checkpoints and displays metrics to the terminal if *TUI_MODE != TUIMode::Off { @@ -232,6 +236,9 @@ fn run() -> Result<()> { .map_err(|_| anyhow!("writer thread panicked"))? .context("writer thread failed")?; } + if let Some(logger) = progress_logger { + logger.finish()?; + } let elapsed = start.elapsed(); let per_second = (*END_SEED - *START_SEED) as f64 / elapsed.as_secs_f64(); diff --git a/inserter/src/progress.rs b/inserter/src/progress.rs new file mode 100644 index 0000000..c334d91 --- /dev/null +++ b/inserter/src/progress.rs @@ -0,0 +1,381 @@ +use crate::{ + BENCHMARK, CHANNEL_SIZE, COMMITTED_SEEDS, COMMIT_COUNT, WORKER_THREADS, WRITER_THREADS, +}; +use anyhow::{Context, Result}; +use crossbeam_channel::{Receiver, Sender}; +use std::fs; +use std::ops::Range; +use std::sync::atomic::{AtomicU64, Ordering::Relaxed}; +use std::sync::{Arc, Condvar, LazyLock, Mutex}; +use std::thread::{self, JoinHandle}; +use std::time::{Duration, Instant}; + +static ENABLED: LazyLock = LazyLock::new(|| { + !matches!( + std::env::var("PROGRESS_LOG") + .unwrap_or_else(|_| "1".to_string()) + .to_ascii_lowercase() + .as_str(), + "0" | "false" | "no" | "off" + ) +}); + +static WORKER_TIME_NS: AtomicU64 = AtomicU64::new(0); +static WORKERS_FINISHED: AtomicU64 = AtomicU64::new(0); +static ACTIVE_WORKERS: AtomicU64 = AtomicU64::new(0); +static WRITER_TIME_NS: AtomicU64 = AtomicU64::new(0); +static WRITERS_FINISHED: AtomicU64 = AtomicU64::new(0); +static ACTIVE_WRITERS: AtomicU64 = AtomicU64::new(0); + +pub fn enabled() -> bool { + *ENABLED +} + +fn add_duration(counter: &AtomicU64, duration: Duration) { + counter.fetch_add(duration.as_nanos().min(u64::MAX as u128) as u64, Relaxed); +} + +pub fn worker_thread(seeds: Range, sender: Sender<(String, String)>, id: usize) -> Result<()> { + if !enabled() { + return crate::threads::worker_thread(seeds, sender, id); + } + ACTIVE_WORKERS.fetch_add(1, Relaxed); + let started = Instant::now(); + let result = crate::threads::worker_thread(seeds, sender, id); + add_duration(&WORKER_TIME_NS, started.elapsed()); + WORKERS_FINISHED.fetch_add(1, Relaxed); + ACTIVE_WORKERS.fetch_sub(1, Relaxed); + result +} + +pub fn commit_thread(receiver: Receiver<(String, String)>) -> Result<()> { + if !enabled() { + return crate::threads::commit_thread(receiver); + } + ACTIVE_WRITERS.fetch_add(1, Relaxed); + let started = Instant::now(); + let result = crate::threads::commit_thread(receiver); + add_duration(&WRITER_TIME_NS, started.elapsed()); + WRITERS_FINISHED.fetch_add(1, Relaxed); + ACTIVE_WRITERS.fetch_sub(1, Relaxed); + result +} + +struct Snapshot { + at: Instant, + generated: u64, + committed: u64, +} + +struct ProcessStats { + rss_kib: Option, + peak_rss_kib: Option, + read_bytes: Option, + write_bytes: Option, +} + +pub struct ProgressLogger { + stop: Arc<(Mutex, Condvar)>, + handle: Option>, +} + +impl ProgressLogger { + pub fn start(planned_seeds: u64, receiver: Receiver<(String, String)>) -> Result> { + if !enabled() { + return Ok(None); + } + + let interval_seconds = std::env::var("PROGRESS_LOG_INTERVAL_SECS") + .unwrap_or_else(|_| "30".to_string()) + .parse::() + .context("PROGRESS_LOG_INTERVAL_SECS must be a positive integer")?; + if interval_seconds == 0 { + anyhow::bail!("PROGRESS_LOG_INTERVAL_SECS must be greater than 0"); + } + let interval = Duration::from_secs(interval_seconds); + eprintln!( + "[progress] generation started: seeds={} workers={} writers={} commit_count={} interval={}s benchmark={}", + planned_seeds, + *WORKER_THREADS, + *WRITER_THREADS, + *COMMIT_COUNT, + interval_seconds, + *BENCHMARK + ); + + let stop = Arc::new((Mutex::new(false), Condvar::new())); + let thread_stop = Arc::clone(&stop); + let handle = thread::Builder::new() + .name("progress_logger".to_string()) + .spawn(move || monitor(planned_seeds, receiver, interval, thread_stop)) + .context("failed to spawn progress logger")?; + + Ok(Some(Self { + stop, + handle: Some(handle), + })) + } + + pub fn finish(mut self) -> Result<()> { + self.signal_stop(); + if let Some(handle) = self.handle.take() { + handle + .join() + .map_err(|_| anyhow::anyhow!("progress logger panicked"))?; + } + Ok(()) + } + + fn signal_stop(&self) { + let (lock, condition) = &*self.stop; + if let Ok(mut stopped) = lock.lock() { + *stopped = true; + condition.notify_one(); + } + } +} + +impl Drop for ProgressLogger { + fn drop(&mut self) { + self.signal_stop(); + } +} + +fn monitor( + planned_seeds: u64, + receiver: Receiver<(String, String)>, + interval: Duration, + stop: Arc<(Mutex, Condvar)>, +) { + let started = Instant::now(); + let mut previous = Snapshot { + at: started, + generated: generated_seeds(), + committed: committed_seeds(), + }; + + loop { + let (lock, condition) = &*stop; + let stopped = match lock.lock() { + Ok(stopped) => stopped, + Err(_) => return, + }; + let (stopped, timeout) = match condition.wait_timeout(stopped, interval) { + Ok(result) => result, + Err(_) => return, + }; + if *stopped { + break; + } + if timeout.timed_out() { + previous = report(started, previous, planned_seeds, receiver.len(), false); + } + } + + report(started, previous, planned_seeds, receiver.len(), true); +} + +fn report( + started: Instant, + previous: Snapshot, + planned_seeds: u64, + queue: usize, + complete: bool, +) -> Snapshot { + let now = Instant::now(); + let generated = generated_seeds(); + let committed = committed_seeds(); + let elapsed = now.duration_since(started); + let period = now + .duration_since(previous.at) + .as_secs_f64() + .max(f64::EPSILON); + let generated_rate = generated.saturating_sub(previous.generated) as f64 / period; + let committed_rate = committed.saturating_sub(previous.committed) as f64 / period; + let average_generated_rate = generated as f64 / elapsed.as_secs_f64().max(f64::EPSILON); + let average_committed_rate = committed as f64 / elapsed.as_secs_f64().max(f64::EPSILON); + let generated_percent = percent(generated, planned_seeds); + let committed_percent = percent(committed, planned_seeds); + let overall = if *BENCHMARK { generated } else { committed }; + let status = if complete { "complete" } else { "running" }; + let generation_time = estimated_thread_time(&WORKER_TIME_NS, &ACTIVE_WORKERS, elapsed); + let writer_time = estimated_thread_time(&WRITER_TIME_NS, &ACTIVE_WRITERS, elapsed); + + eprintln!( + "[progress] status={} elapsed={} progress={}/{} ({:.2}%) generated={}/{} ({:.2}%) committed={}/{} ({:.2}%) queue={}/{}", + status, + format_duration(elapsed), + overall, + planned_seeds, + percent(overall, planned_seeds), + generated, + planned_seeds, + generated_percent, + committed, + planned_seeds, + committed_percent, + queue, + *CHANNEL_SIZE + ); + eprintln!( + "[progress] rates: generated_interval={:.3}/s generated_average={:.3}/s committed_interval={:.3}/s committed_average={:.3}/s", + generated_rate, + average_generated_rate, + committed_rate, + average_committed_rate + ); + eprintln!( + "[progress] timing: generation_worker={} writer_pipeline={} workers_active={} workers_finished={}/{} writers_active={} writers_finished={}/{} dominant_thread_time={} likely_bottleneck={}", + format_nanos(generation_time), + format_nanos(writer_time), + ACTIVE_WORKERS.load(Relaxed), + WORKERS_FINISHED.load(Relaxed), + *WORKER_THREADS, + ACTIVE_WRITERS.load(Relaxed), + WRITERS_FINISHED.load(Relaxed), + if *BENCHMARK { 0 } else { *WRITER_THREADS as u64 }, + dominant_stage(generation_time, writer_time), + likely_bottleneck(generated, committed, planned_seeds, queue) + ); + print_process_stats(read_process_stats()); + + Snapshot { + at: now, + generated, + committed, + } +} + +fn generated_seeds() -> u64 { + crate::PROGRESS_WORKERS + .iter() + .take(*WORKER_THREADS as usize) + .map(|progress| progress.load(Relaxed).max(0) as u64) + .sum() +} + +fn committed_seeds() -> u64 { + COMMITTED_SEEDS.load(Relaxed).max(0) as u64 +} + +fn percent(value: u64, total: u64) -> f64 { + if total == 0 { + 100.0 + } else { + value.min(total) as f64 / total as f64 * 100.0 + } +} + +fn estimated_thread_time(completed: &AtomicU64, active: &AtomicU64, elapsed: Duration) -> u64 { + let active_time = elapsed + .as_nanos() + .saturating_mul(active.load(Relaxed) as u128) + .min(u64::MAX as u128) as u64; + completed.load(Relaxed).saturating_add(active_time) +} + +fn dominant_stage(generation_time: u64, writer_time: u64) -> &'static str { + let stages = [ + ("generation", generation_time), + ("writer_pipeline", writer_time), + ]; + stages + .into_iter() + .max_by_key(|(_, duration)| *duration) + .filter(|(_, duration)| *duration > 0) + .map(|(stage, _)| stage) + .unwrap_or("warming_up") +} + +fn likely_bottleneck( + generated: u64, + committed: u64, + planned_seeds: u64, + queue: usize, +) -> &'static str { + if *BENCHMARK { + return "generation"; + } + if generated >= planned_seeds && committed < planned_seeds { + return "database_drain"; + } + if *CHANNEL_SIZE > 0 && queue.saturating_mul(100) >= *CHANNEL_SIZE * 80 { + return "database"; + } + if *CHANNEL_SIZE == 0 || queue.saturating_mul(100) <= *CHANNEL_SIZE * 20 { + return "generation"; + } + "balanced_or_inconclusive" +} + +fn format_nanos(nanos: u64) -> String { + format_duration(Duration::from_nanos(nanos)) +} + +fn format_duration(duration: Duration) -> String { + let seconds = duration.as_secs_f64(); + if seconds >= 60.0 { + format!("{}m{:.3}s", duration.as_secs() / 60, seconds % 60.0) + } else { + format!("{:.3}s", seconds) + } +} + +fn read_process_stats() -> ProcessStats { + let status = fs::read_to_string("/proc/self/status").unwrap_or_default(); + let io = fs::read_to_string("/proc/self/io").unwrap_or_default(); + ProcessStats { + rss_kib: parse_value(&status, "VmRSS:"), + peak_rss_kib: parse_value(&status, "VmHWM:"), + read_bytes: parse_value(&io, "read_bytes:"), + write_bytes: parse_value(&io, "write_bytes:"), + } +} + +fn parse_value(contents: &str, key: &str) -> Option { + contents + .lines() + .find(|line| line.starts_with(key)) + .and_then(|line| line.split_whitespace().nth(1)) + .and_then(|value| value.parse().ok()) +} + +fn print_process_stats(stats: ProcessStats) { + eprintln!( + "[progress] resources: rss_mib={} peak_rss_mib={} process_read_mib={} process_write_mib={}", + format_mib(stats.rss_kib.map(|value| value * 1024)), + format_mib(stats.peak_rss_kib.map(|value| value * 1024)), + format_mib(stats.read_bytes), + format_mib(stats.write_bytes) + ); +} + +fn format_mib(bytes: Option) -> String { + bytes + .map(|value| format!("{:.3}", value as f64 / 1_048_576.0)) + .unwrap_or_else(|| "n/a".to_string()) +} + +#[cfg(test)] +mod tests { + use super::{format_duration, parse_value, percent}; + use std::time::Duration; + + #[test] + fn formats_short_and_long_durations() { + assert_eq!(format_duration(Duration::from_millis(1250)), "1.250s"); + assert_eq!(format_duration(Duration::from_millis(61_250)), "1m1.250s"); + } + + #[test] + fn percentage_is_bounded() { + assert_eq!(percent(50, 100), 50.0); + assert_eq!(percent(200, 100), 100.0); + } + + #[test] + fn parses_proc_values() { + assert_eq!(parse_value("VmRSS:\t2048 kB\n", "VmRSS:"), Some(2048)); + assert_eq!(parse_value("read_bytes: 4096\n", "read_bytes:"), Some(4096)); + } +} diff --git a/inserter/src/threads.rs b/inserter/src/threads.rs index ecc4f61..28e97fc 100644 --- a/inserter/src/threads.rs +++ b/inserter/src/threads.rs @@ -65,4 +65,4 @@ pub fn writer_sink(rec: Receiver<(String, String)>) -> Result<()> { } } Ok(()) -} \ No newline at end of file +}