feat: summarize G1 pause counts and durations

README.md

@@ -4,15 +4,15 @@ JVMDelta is a Rust project for comparing JVM performance measurements before and
 
 ## Current status
 
-The current CLI inspects a narrow subset of G1 Unified GC pause summaries. It counts supported young, full, remark, and cleanup pauses, unrelated entries, and unknown pause categories. The core library exposes parsed events with exact units and source-line provenance. Invalid supported summaries fail with a line-numbered error. See [supported syntax and limitations](docs/GC_LOG_SUPPORT.md).
+The current CLI inspects a narrow subset of G1 Unified GC pause summaries. It counts supported young, full, remark, and cleanup pauses, unrelated entries, and unknown pause categories. It also reports exact total, minimum, maximum, and nanosecond-rounded-down mean pause durations per category and overall. The core library exposes parsed events with exact units and source-line provenance. Invalid supported summaries fail with a line-numbered error. See [supported syntax and limitations](docs/GC_LOG_SUPPORT.md).
 
 Comparison, regression detection, JFR parsing, JSON/HTML reports, and a GitHub Action are **planned**, not implemented.
 
 ## Architecture
 
-- `crates/jvmdelta-core`: bounded streaming GC parser and small domain modules for future metrics, comparison, regression, and reports.
+- `crates/jvmdelta-core`: bounded streaming GC parser and constant-size pause statistics; small domain modules reserve comparison, regression, and report concepts.
 - `crates/jvmdelta-cli`: Clap executable, file access, counts, and exit status.
-- `tests/fixtures`: synthetic JDK 17/21-style examples and selected real JDK 25 G1 output.
+- `tests/fixtures`: synthetic edge cases and selected real Temurin 17/21 and OpenJDK 25 G1 output.
 - `docs`: [architecture](docs/ARCHITECTURE.md), [format support](docs/GC_LOG_SUPPORT.md), [development](docs/DEVELOPMENT.md), and [roadmap](docs/ROADMAP.md).
 
 ## Build and use
@@ -24,6 +24,7 @@ cargo build --workspace
 cargo run -p jvmdelta-cli -- --help
 cargo run -p jvmdelta-cli -- --version
 cargo run -p jvmdelta-cli -- gc inspect tests/fixtures/jdk25-g1-real.log
+cargo run -p jvmdelta-cli -- gc inspect tests/fixtures/jdk17-g1-real.log
 ```
 
 The installed executable is named `jvmdelta`. `gc inspect` uses strict parsing: unreadable files and malformed supported summaries exit nonzero with an error on stderr.

crates/jvmdelta-cli/src/main.rs

@@ -1,5 +1,6 @@
 use clap::{Parser, Subcommand};
 use jvmdelta_core::gc_log::{EventKind, GcLogParser, Record, SkipReason};
+use jvmdelta_core::metrics::{GcSummary, PauseStats};
 use std::error::Error;
 use std::fs::File;
 use std::io::BufReader;
@@ -51,31 +52,55 @@ fn run() -> Result<(), Box<dyn Error>> {
 fn inspect(path: PathBuf) -> Result<(), Box<dyn Error>> {
     let file =
         File::open(&path).map_err(|error| format!("cannot open {}: {error}", path.display()))?;
-    let mut counts = [0_u64; 4];
+    let mut summary = GcSummary::default();
     let mut skipped = 0_u64;
     let mut unsupported = 0_u64;
     for record in GcLogParser::new(BufReader::new(file)) {
         match record? {
-            Record::Event(event) => {
-                let index = match event.kind {
-                    EventKind::Young => 0,
-                    EventKind::Full => 1,
-                    EventKind::Remark => 2,
-                    EventKind::Cleanup => 3,
-                };
-                counts[index] += 1;
-            }
+            Record::Event(event) => summary.record(&event)?,
             Record::Skipped(SkipReason::Unrelated) => skipped += 1,
             Record::Skipped(SkipReason::UnsupportedEvent) => unsupported += 1,
         }
     }
     println!("File: {}", path.display());
-    println!("Supported events: {}", counts.iter().sum::<u64>());
-    println!("Young: {}", counts[0]);
-    println!("Full: {}", counts[1]);
-    println!("Remark: {}", counts[2]);
-    println!("Cleanup: {}", counts[3]);
+    println!("Supported events: {}", summary.all().count());
+    for (name, kind) in categories() {
+        println!("{name}: {}", summary.category(kind).count());
+    }
     println!("Unrelated entries skipped: {skipped}");
     println!("Unsupported pause types skipped: {unsupported}");
+    println!("Pause durations (ms; mean rounded down to 1 ns):");
+    print_duration_stats("All", summary.all());
+    for (name, kind) in categories() {
+        print_duration_stats(name, summary.category(kind));
+    }
     Ok(())
 }
+
+fn categories() -> [(&'static str, EventKind); 4] {
+    [
+        ("Young", EventKind::Young),
+        ("Full", EventKind::Full),
+        ("Remark", EventKind::Remark),
+        ("Cleanup", EventKind::Cleanup),
+    ]
+}
+
+fn print_duration_stats(name: &str, stats: &PauseStats) {
+    let min = stats.min_ns().map(|value| format_ms(u128::from(value)));
+    let mean = stats
+        .mean_ns_floor()
+        .map(|value| format_ms(u128::from(value)));
+    let max = stats.max_ns().map(|value| format_ms(u128::from(value)));
+    println!(
+        "  {name}: total={} min={} mean={} max={}",
+        format_ms(stats.total_ns()),
+        min.as_deref().unwrap_or("n/a"),
+        mean.as_deref().unwrap_or("n/a"),
+        max.as_deref().unwrap_or("n/a")
+    );
+}
+
+fn format_ms(ns: u128) -> String {
+    format!("{}.{:06}", ns / 1_000_000, ns % 1_000_000)
+}

crates/jvmdelta-cli/tests/cli.rs

@@ -57,12 +57,18 @@ fn inspect_valid_and_empty_files() {
     assert!(stdout.contains("Young: 1"));
     assert!(stdout.contains("Full: 1"));
     assert!(stdout.contains("Unrelated entries skipped: 4"));
+    assert!(stdout.contains("All: total=22.970000 min=10.235000 mean=11.485000 max=12.735000"));
+    assert!(stdout.contains("Remark: total=0.000000 min=n/a mean=n/a max=n/a"));
 
     let empty = tempfile_path("empty");
     std::fs::write(&empty, "").expect("write empty file");
     let output = inspect(empty.to_str().expect("UTF-8 path"));
     assert!(output.status.success());
     assert!(String::from_utf8_lossy(&output.stdout).contains("Supported events: 0"));
+    assert!(
+        String::from_utf8_lossy(&output.stdout)
+            .contains("All: total=0.000000 min=n/a mean=n/a max=n/a")
+    );
     std::fs::remove_file(empty).expect("remove temp file");
 }
 
@@ -81,6 +87,25 @@ fn inspect_rejects_missing_and_malformed_files() {
     assert!(String::from_utf8_lossy(&output.stderr).contains("line 2"));
 }
 
+#[test]
+fn inspect_real_jdk17_and_21_excerpts() {
+    for version in [17, 21] {
+        let path = format!(
+            "{}/../../tests/fixtures/jdk{version}-g1-real.log",
+            env!("CARGO_MANIFEST_DIR")
+        );
+        let output = inspect(&path);
+        assert!(
+            output.status.success(),
+            "JDK {version}: {}",
+            String::from_utf8_lossy(&output.stderr)
+        );
+        let stdout = String::from_utf8_lossy(&output.stdout);
+        assert!(stdout.contains("Supported events: 2"));
+        assert!(stdout.contains("Unrelated entries skipped: 3"));
+    }
+}
+
 fn tempfile_path(suffix: &str) -> std::path::PathBuf {
     std::env::temp_dir().join(format!("jvmdelta-cli-{}-{suffix}.log", std::process::id()))
 }

crates/jvmdelta-core/src/metrics.rs

@@ -1,9 +1,162 @@
-//! Performance measurement definitions.
+//! Exact, incremental measurements over validated GC pause events.
 
-/// Units supported by future measurements.
+use crate::gc_log::{EventKind, GcEvent};
+use std::fmt;
+
+/// Units used by core measurements.
 #[derive(Debug, Clone, Copy, PartialEq, Eq)]
 pub enum Unit {
     Nanoseconds,
     Bytes,
     Count,
 }
+
+/// Counts and duration statistics for pause summary records.
+///
+/// `count` counts records, not distinct GC IDs or collection cycles. `total_ns`
+/// uses `u128` so it can represent sums larger than a single `u64` duration.
+#[derive(Debug, Default, Clone, Copy, PartialEq, Eq)]
+pub struct PauseStats {
+    count: u64,
+    total_ns: u128,
+    min_ns: Option<u64>,
+    max_ns: Option<u64>,
+}
+
+impl PauseStats {
+    /// Number of pause summary records observed.
+    pub fn count(&self) -> u64 {
+        self.count
+    }
+
+    /// Exact sum of pause durations in nanoseconds; zero when empty.
+    pub fn total_ns(&self) -> u128 {
+        self.total_ns
+    }
+
+    /// Shortest pause in nanoseconds, or `None` when empty.
+    pub fn min_ns(&self) -> Option<u64> {
+        self.min_ns
+    }
+
+    /// Longest pause in nanoseconds, or `None` when empty.
+    pub fn max_ns(&self) -> Option<u64> {
+        self.max_ns
+    }
+
+    /// Arithmetic mean, rounded down to a whole nanosecond; `None` when empty.
+    pub fn mean_ns_floor(&self) -> Option<u64> {
+        if self.count == 0 {
+            return None;
+        }
+        // A mean of u64 inputs cannot exceed u64::MAX.
+        u64::try_from(self.total_ns / u128::from(self.count)).ok()
+    }
+
+    fn with_duration(self, duration_ns: u64) -> Result<Self, SummaryError> {
+        let count = self
+            .count
+            .checked_add(1)
+            .ok_or(SummaryError::CountOverflow)?;
+        let total_ns = self
+            .total_ns
+            .checked_add(u128::from(duration_ns))
+            .ok_or(SummaryError::DurationOverflow)?;
+        Ok(Self {
+            count,
+            total_ns,
+            min_ns: Some(
+                self.min_ns
+                    .map_or(duration_ns, |value| value.min(duration_ns)),
+            ),
+            max_ns: Some(
+                self.max_ns
+                    .map_or(duration_ns, |value| value.max(duration_ns)),
+            ),
+        })
+    }
+}
+
+/// Exact pause summaries for all events and each supported category.
+#[derive(Debug, Default, Clone, PartialEq, Eq)]
+pub struct GcSummary {
+    all: PauseStats,
+    young: PauseStats,
+    full: PauseStats,
+    remark: PauseStats,
+    cleanup: PauseStats,
+}
+
+impl GcSummary {
+    /// Add one validated GC pause event. If an overflow occurs, the summary is unchanged.
+    pub fn record(&mut self, event: &GcEvent) -> Result<(), SummaryError> {
+        let next_all = self.all.with_duration(event.duration_ns)?;
+        let category = match event.kind {
+            EventKind::Young => &mut self.young,
+            EventKind::Full => &mut self.full,
+            EventKind::Remark => &mut self.remark,
+            EventKind::Cleanup => &mut self.cleanup,
+        };
+        let next_category = category.with_duration(event.duration_ns)?;
+        self.all = next_all;
+        *category = next_category;
+        Ok(())
+    }
+
+    /// Statistics over every supported pause summary record.
+    pub fn all(&self) -> &PauseStats {
+        &self.all
+    }
+
+    /// Statistics for one supported pause category.
+    pub fn category(&self, kind: EventKind) -> &PauseStats {
+        match kind {
+            EventKind::Young => &self.young,
+            EventKind::Full => &self.full,
+            EventKind::Remark => &self.remark,
+            EventKind::Cleanup => &self.cleanup,
+        }
+    }
+}
+
+/// An arithmetic limit was reached while accumulating events.
+#[derive(Debug, Clone, Copy, PartialEq, Eq)]
+pub enum SummaryError {
+    CountOverflow,
+    DurationOverflow,
+}
+
+impl fmt::Display for SummaryError {
+    fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
+        match self {
+            Self::CountOverflow => write!(f, "GC pause count exceeds u64"),
+            Self::DurationOverflow => write!(f, "total GC pause duration exceeds u128 nanoseconds"),
+        }
+    }
+}
+
+impl std::error::Error for SummaryError {}
+
+#[cfg(test)]
+mod tests {
+    use super::{PauseStats, SummaryError};
+
+    #[test]
+    fn count_overflow_is_explicit() {
+        let stats = PauseStats {
+            count: u64::MAX,
+            ..PauseStats::default()
+        };
+        assert_eq!(stats.with_duration(1), Err(SummaryError::CountOverflow));
+    }
+
+    #[test]
+    fn total_overflow_is_explicit() {
+        let stats = PauseStats {
+            count: 1,
+            total_ns: u128::MAX,
+            ..PauseStats::default()
+        };
+        assert_eq!(stats.with_duration(1), Err(SummaryError::DurationOverflow));
+    }
+}

crates/jvmdelta-core/tests/metrics_summary.rs

@@ -0,0 +1,78 @@
+use jvmdelta_core::gc_log::{EventKind, GcEvent, GcLogParser, Record};
+use jvmdelta_core::metrics::GcSummary;
+use std::io::Cursor;
+
+fn summarize(input: &str) -> GcSummary {
+    let mut summary = GcSummary::default();
+    for record in GcLogParser::new(Cursor::new(input)) {
+        if let Record::Event(event) = record.expect("fixture parses") {
+            summary.record(&event).expect("sample fits in summary");
+        }
+    }
+    summary
+}
+
+#[test]
+fn empty_summary_has_no_extrema_or_mean() {
+    let summary = summarize("");
+    assert_eq!(summary.all().count(), 0);
+    assert_eq!(summary.all().total_ns(), 0);
+    assert_eq!(summary.all().min_ns(), None);
+    assert_eq!(summary.all().max_ns(), None);
+    assert_eq!(summary.all().mean_ns_floor(), None);
+    assert_eq!(summary.category(EventKind::Full).mean_ns_floor(), None);
+}
+
+#[test]
+fn category_and_overall_durations_are_exact() {
+    let input = include_str!("../../../tests/fixtures/jdk17-g1-synthetic.log");
+    let summary = summarize(input);
+    assert_eq!(summary.all().count(), 4);
+    assert_eq!(summary.all().total_ns(), 10_877_000);
+    assert_eq!(summary.all().min_ns(), Some(50_000));
+    assert_eq!(summary.all().max_ns(), Some(6_250_000));
+    assert_eq!(summary.all().mean_ns_floor(), Some(2_719_250));
+    assert_eq!(summary.category(EventKind::Young).count(), 1);
+    assert_eq!(summary.category(EventKind::Young).total_ns(), 3_452_000);
+    assert_eq!(summary.category(EventKind::Full).total_ns(), 6_250_000);
+    assert_eq!(summary.category(EventKind::Remark).total_ns(), 1_125_000);
+    assert_eq!(summary.category(EventKind::Cleanup).total_ns(), 50_000);
+}
+
+#[test]
+fn mean_rounds_down_to_nanosecond_and_ids_are_not_deduplicated() {
+    let mut summary = GcSummary::default();
+    for duration in [1, 2] {
+        summary
+            .record(&GcEvent {
+                source_line: 1,
+                gc_id: 7,
+                kind: EventKind::Remark,
+                description: String::new(),
+                heap: None,
+                duration_ns: duration,
+                uptime_ns: None,
+                source: String::new(),
+            })
+            .expect("fits");
+    }
+    assert_eq!(summary.category(EventKind::Remark).count(), 2);
+    assert_eq!(summary.category(EventKind::Remark).total_ns(), 3);
+    assert_eq!(summary.category(EventKind::Remark).mean_ns_floor(), Some(1));
+    assert_eq!(summary.category(EventKind::Full).min_ns(), None);
+}
+
+#[test]
+fn real_jdk17_and_21_samples_parse_and_aggregate() {
+    let jdk17 = summarize(include_str!("../../../tests/fixtures/jdk17-g1-real.log"));
+    assert_eq!(jdk17.all().count(), 2);
+    assert_eq!(jdk17.category(EventKind::Young).total_ns(), 1_420_000);
+    assert_eq!(jdk17.category(EventKind::Full).total_ns(), 2_327_000);
+    assert_eq!(jdk17.all().total_ns(), 3_747_000);
+
+    let jdk21 = summarize(include_str!("../../../tests/fixtures/jdk21-g1-real.log"));
+    assert_eq!(jdk21.all().count(), 2);
+    assert_eq!(jdk21.category(EventKind::Young).total_ns(), 1_456_000);
+    assert_eq!(jdk21.category(EventKind::Full).total_ns(), 3_257_000);
+    assert_eq!(jdk21.all().total_ns(), 4_713_000);
+}