diff --git a/.gitignore b/.gitignore index e2e4678..920e96c 100644 --- a/.gitignore +++ b/.gitignore @@ -4,3 +4,4 @@ /.env.* !.env.example *.log +!tests/fixtures/*.log diff --git a/README.md b/README.md index 77b89c9..88715d0 100644 --- a/README.md +++ b/README.md @@ -1,45 +1,34 @@ # JVMDelta -JVMDelta is a Rust project for comparing JVM performance measurements before and after a software change. The goal is to make regressions visible in local development and CI without requiring a JVM to analyze recorded data. - -Performance evidence is often spread across GC logs and JFR recordings. Comparing runs by hand is slow and makes it easy to overlook a change in pause time or allocation. JVMDelta aims to ingest those recordings, compare a baseline with a candidate, and produce clear reports. +JVMDelta is a Rust project for comparing JVM performance measurements before and after a software change. GC logs and JFR recordings can contain evidence that is tedious to inspect by hand. JVMDelta aims to make those measurements accessible locally and in CI without needing a JVM for analysis. ## Current status -Day 1 is a foundation release. The `jvmdelta` executable provides `--help` and `--version`. It does **not** parse recordings, compare runs, detect regressions, or produce reports yet. Unsupported commands fail with a nonzero exit status. - -## Architecture - -- `crates/jvmdelta-core`: reusable library with small domain modules for GC logs, metrics, comparisons, regression rules, and reports. Its current types define vocabulary only. -- `crates/jvmdelta-cli`: Clap based executable. CLI presentation stays outside the core library. -- `tests/fixtures`: reserved for representative, licensed input files as parsers are implemented. -- `docs`: architecture, development guidance, and the implementation roadmap. +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). -See [architecture](docs/ARCHITECTURE.md) for the intended data flow and boundaries. +Comparison, regression detection, JFR parsing, JSON/HTML reports, and a GitHub Action are **planned**, not implemented. -## Planned features - -- Parse JVM Unified GC logs and JFR recordings. -- Compute supported pause, memory, and allocation metrics. -- Compare baseline and candidate measurements and detect configured regressions. -- Render terminal, JSON, and HTML reports. -- Supply a GitHub Action for CI use. +## Architecture -These features are planned; no analysis command is available today. +- `crates/jvmdelta-core`: bounded streaming GC parser and small domain modules for future metrics, comparison, regression, and reports. +- `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. +- `docs`: [architecture](docs/ARCHITECTURE.md), [format support](docs/GC_LOG_SUPPORT.md), [development](docs/DEVELOPMENT.md), and [roadmap](docs/ROADMAP.md). ## Build and use -Requires stable Rust 1.85 or newer. No JVM is needed for the current CLI. +Requires stable Rust 1.85 or newer. Java is not required to build, test, or inspect a log. ```sh 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 ``` -The installed binary is named `jvmdelta`; for example, `jvmdelta --help`. +The installed executable is named `jvmdelta`. `gc inspect` uses strict parsing: unreadable files and malformed supported summaries exit nonzero with an error on stderr. -## Development +## Development and contributing ```sh cargo fmt --all -- --check @@ -48,8 +37,4 @@ cargo test --workspace cargo build --workspace --release ``` -See [development guidance](docs/DEVELOPMENT.md) for test and contribution practices. - -## Contributing - -Issues and focused pull requests are welcome. Discuss input format choices and regression semantics before implementing a parser or detector. Add representative fixtures and tests for behavior, keep parser errors explicit, and run the checks above. Contributions are licensed under [Apache-2.0](LICENSE). +Focused issues and pull requests are welcome. Discuss new GC variants or comparison semantics before extending support. Add representative, redistributable fixtures and tests, keep errors explicit, and document limitations. Contributions are licensed under [Apache-2.0](LICENSE). diff --git a/crates/jvmdelta-cli/src/main.rs b/crates/jvmdelta-cli/src/main.rs index 95257f1..c28968c 100644 --- a/crates/jvmdelta-cli/src/main.rs +++ b/crates/jvmdelta-cli/src/main.rs @@ -1,15 +1,81 @@ -use clap::Parser; +use clap::{Parser, Subcommand}; +use jvmdelta_core::gc_log::{EventKind, GcLogParser, Record, SkipReason}; +use std::error::Error; +use std::fs::File; +use std::io::BufReader; +use std::path::PathBuf; -/// JVM performance regression analysis (analysis commands are planned). +/// Inspect JVM GC logs. Comparison and regression analysis are planned. #[derive(Debug, Parser)] -#[command( - name = "jvmdelta", - version, - about = "JVM performance regression analysis; analysis commands are planned", - long_about = None -)] -struct Cli {} +#[command(name = "jvmdelta", version, about = "Inspect JVM GC logs; comparison and regression analysis are planned", long_about = None)] +struct Cli { + #[command(subcommand)] + command: Option, +} + +#[derive(Debug, Subcommand)] +enum Command { + /// Inspect supported G1 Unified GC pause summaries. + Gc { + #[command(subcommand)] + command: GcCommand, + }, +} + +#[derive(Debug, Subcommand)] +enum GcCommand { + /// Count and classify pause summaries in a GC log. + Inspect { + /// Path to a UTF-8 JVM Unified GC log. + path: PathBuf, + }, +} fn main() { - Cli::parse(); + if let Err(error) = run() { + eprintln!("jvmdelta: {error}"); + std::process::exit(1); + } +} + +fn run() -> Result<(), Box> { + let cli = Cli::parse(); + match cli.command { + Some(Command::Gc { + command: GcCommand::Inspect { path }, + }) => inspect(path), + None => Ok(()), + } +} + +fn inspect(path: PathBuf) -> Result<(), Box> { + let file = + File::open(&path).map_err(|error| format!("cannot open {}: {error}", path.display()))?; + let mut counts = [0_u64; 4]; + 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::Skipped(SkipReason::Unrelated) => skipped += 1, + Record::Skipped(SkipReason::UnsupportedEvent) => unsupported += 1, + } + } + println!("File: {}", path.display()); + println!("Supported events: {}", counts.iter().sum::()); + println!("Young: {}", counts[0]); + println!("Full: {}", counts[1]); + println!("Remark: {}", counts[2]); + println!("Cleanup: {}", counts[3]); + println!("Unrelated entries skipped: {skipped}"); + println!("Unsupported pause types skipped: {unsupported}"); + Ok(()) } diff --git a/crates/jvmdelta-cli/tests/cli.rs b/crates/jvmdelta-cli/tests/cli.rs index 8b3f5bc..ddc2636 100644 --- a/crates/jvmdelta-cli/tests/cli.rs +++ b/crates/jvmdelta-cli/tests/cli.rs @@ -13,8 +13,9 @@ fn help_describes_current_scope() { let output = run("--help"); assert!(output.status.success()); let stdout = String::from_utf8_lossy(&output.stdout); - assert!(stdout.contains("JVM performance regression analysis")); - assert!(stdout.contains("analysis commands are planned")); + assert!(stdout.contains("Inspect JVM GC logs")); + assert!(stdout.contains("comparison and regression analysis are planned")); + assert!(stdout.contains("gc")); assert!(stdout.contains("--version")); } @@ -32,5 +33,54 @@ fn version_reports_package_version() { fn unsupported_command_fails() { let output = run("compare"); assert!(!output.status.success()); - assert!(String::from_utf8_lossy(&output.stderr).contains("unexpected argument")); + assert!(String::from_utf8_lossy(&output.stderr).contains("unrecognized subcommand")); +} + +fn inspect(path: &str) -> std::process::Output { + Command::new(env!("CARGO_BIN_EXE_jvmdelta")) + .args(["gc", "inspect", path]) + .output() + .unwrap_or_else(|error| panic!("failed to run CLI: {error}")) +} + +#[test] +fn inspect_valid_and_empty_files() { + let root = concat!(env!("CARGO_MANIFEST_DIR"), "/../../tests/fixtures/"); + let output = inspect(&format!("{root}jdk25-g1-real.log")); + assert!( + output.status.success(), + "{}", + String::from_utf8_lossy(&output.stderr) + ); + let stdout = String::from_utf8_lossy(&output.stdout); + assert!(stdout.contains("Supported events: 2")); + assert!(stdout.contains("Young: 1")); + assert!(stdout.contains("Full: 1")); + assert!(stdout.contains("Unrelated entries skipped: 4")); + + 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")); + std::fs::remove_file(empty).expect("remove temp file"); +} + +#[test] +fn inspect_rejects_missing_and_malformed_files() { + let missing = tempfile_path("missing"); + let output = inspect(missing.to_str().expect("UTF-8 path")); + assert!(!output.status.success()); + assert!(String::from_utf8_lossy(&output.stderr).contains("cannot open")); + let path = concat!( + env!("CARGO_MANIFEST_DIR"), + "/../../tests/fixtures/malformed-g1-synthetic.log" + ); + let output = inspect(path); + assert!(!output.status.success()); + assert!(String::from_utf8_lossy(&output.stderr).contains("line 2")); +} + +fn tempfile_path(suffix: &str) -> std::path::PathBuf { + std::env::temp_dir().join(format!("jvmdelta-cli-{}-{suffix}.log", std::process::id())) } diff --git a/crates/jvmdelta-core/src/gc_log.rs b/crates/jvmdelta-core/src/gc_log.rs index 613bc4a..1efd646 100644 --- a/crates/jvmdelta-core/src/gc_log.rs +++ b/crates/jvmdelta-core/src/gc_log.rs @@ -1,4 +1,11 @@ -//! JVM Unified GC log parsing domain. +//! Streaming parser for a narrow subset of G1 Unified GC pause summaries. +//! See `docs/GC_LOG_SUPPORT.md` for the accepted syntax and error policy. + +use std::fmt; +use std::io::{self, BufRead, Read}; + +/// Maximum accepted line length in bytes, including its line ending. +pub const MAX_LINE_BYTES: u64 = 64 * 1024; /// A single raw log line, retained with its one-based source line number. #[derive(Debug, Clone, PartialEq, Eq)] @@ -17,13 +24,421 @@ impl<'a> SourceLine<'a> { } } -#[cfg(test)] -mod tests { - use super::SourceLine; +/// Supported stop-the-world G1 pause categories. +#[derive(Debug, Clone, Copy, PartialEq, Eq)] +pub enum EventKind { + Young, + Full, + Remark, + Cleanup, +} + +/// Heap usage in bytes. K, M, and G use powers of 1024. +#[derive(Debug, Clone, Copy, PartialEq, Eq)] +pub struct HeapUsage { + pub before_bytes: u64, + pub after_bytes: u64, + pub capacity_bytes: u64, +} + +/// A validated pause summary. Durations and uptime are exact nanoseconds. +#[derive(Debug, Clone, PartialEq, Eq)] +pub struct GcEvent { + pub source_line: usize, + pub gc_id: u64, + pub kind: EventKind, + /// Text between the pause category and optional heap summary, without trimming inner text. + pub description: String, + pub heap: Option, + pub duration_ns: u64, + pub uptime_ns: Option, + /// Original log line without the line ending. + pub source: String, +} + +/// Why a line did not produce a supported pause event. +#[derive(Debug, Clone, Copy, PartialEq, Eq)] +pub enum SkipReason { + Unrelated, + UnsupportedEvent, +} + +/// One classified input line. +#[derive(Debug, Clone, PartialEq, Eq)] +pub enum Record { + Event(GcEvent), + Skipped(SkipReason), +} + +/// A structured parser failure. +#[derive(Debug)] +pub struct ParseError { + pub line: usize, + pub kind: ParseErrorKind, +} + +/// Categories of parser failure. An I/O error terminates iteration. +#[derive(Debug)] +pub enum ParseErrorKind { + Io(io::Error), + LineTooLong, + InvalidUtf8, + Malformed(&'static str), + InvalidNumber(&'static str), + Overflow(&'static str), +} + +impl fmt::Display for ParseError { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + write!(f, "line {}: ", self.line)?; + match &self.kind { + ParseErrorKind::Io(error) => write!(f, "I/O error: {error}"), + ParseErrorKind::LineTooLong => write!(f, "line exceeds {MAX_LINE_BYTES} bytes"), + ParseErrorKind::InvalidUtf8 => write!(f, "invalid UTF-8"), + ParseErrorKind::Malformed(message) => write!(f, "malformed GC pause: {message}"), + ParseErrorKind::InvalidNumber(field) => write!(f, "invalid {field}"), + ParseErrorKind::Overflow(field) => { + write!(f, "{field} overflows u64 nanoseconds or bytes") + } + } + } +} + +impl std::error::Error for ParseError { + fn source(&self) -> Option<&(dyn std::error::Error + 'static)> { + match &self.kind { + ParseErrorKind::Io(error) => Some(error), + _ => None, + } + } +} + +/// Parses a `BufRead` stream one bounded line at a time. +/// +/// Each line yields an event, a skip reason, or an error. Malformed lines do not +/// end iteration; I/O, invalid UTF-8, and overlong lines do. Callers choose strict +/// or permissive behavior by stopping or continuing after malformed lines. +/// No file path, CLI type, or entire-log buffer is required. +pub struct GcLogParser { + reader: R, + line: usize, + finished: bool, + buffer: Vec, +} + +impl GcLogParser { + pub fn new(reader: R) -> Self { + Self { + reader, + line: 0, + finished: false, + buffer: Vec::new(), + } + } +} + +impl Iterator for GcLogParser { + type Item = Result; + + fn next(&mut self) -> Option { + if self.finished { + return None; + } + self.buffer.clear(); + let read = self + .reader + .by_ref() + .take(MAX_LINE_BYTES + 1) + .read_until(b'\n', &mut self.buffer); + let line = match self.line.checked_add(1) { + Some(line) => line, + None => { + self.finished = true; + return Some(Err(ParseError { + line: self.line, + kind: ParseErrorKind::Overflow("source line number"), + })); + } + }; + self.line = line; + match read { + Ok(0) => { + self.finished = true; + None + } + Err(error) => { + self.finished = true; + Some(Err(ParseError { + line, + kind: ParseErrorKind::Io(error), + })) + } + Ok(_) if self.buffer.len() as u64 > MAX_LINE_BYTES => { + self.finished = true; + Some(Err(ParseError { + line, + kind: ParseErrorKind::LineTooLong, + })) + } + Ok(_) => { + let bytes = self.buffer.strip_suffix(b"\n").unwrap_or(&self.buffer); + let bytes = bytes.strip_suffix(b"\r").unwrap_or(bytes); + match std::str::from_utf8(bytes) { + Ok(text) => Some(parse_line(text, line)), + Err(_) => { + self.finished = true; + Some(Err(ParseError { + line, + kind: ParseErrorKind::InvalidUtf8, + })) + } + } + } + } + } +} + +fn error(line: usize, kind: ParseErrorKind) -> ParseError { + ParseError { line, kind } +} + +fn parse_line(source: &str, line: usize) -> Result { + let mut rest = source; + let mut uptime_ns = None; + let mut level = None; + let mut tags = None; + let mut decorations = 0; + while let Some(after_open) = rest.strip_prefix('[') { + let Some((decoration, after_close)) = after_open.split_once(']') else { + return if source.contains("GC(") || source.contains("Pause ") { + Err(error( + line, + ParseErrorKind::Malformed("unterminated decoration"), + )) + } else { + Ok(Record::Skipped(SkipReason::Unrelated)) + }; + }; + decorations += 1; + if decorations > 8 { + return Err(error( + line, + ParseErrorKind::Malformed("too many decorations"), + )); + } + let decoration = decoration.trim(); + if decoration == "info" + || decoration == "debug" + || decoration == "trace" + || decoration == "warning" + || decoration == "error" + { + level = Some(decoration); + } else if decoration == "gc" || decoration.starts_with("gc,") { + tags = Some(decoration); + } else if decoration.ends_with('s') + && decoration[..decoration.len() - 1] + .bytes() + .all(|b| b.is_ascii_digit() || b == b'.') + { + uptime_ns = Some(decimal_to_scaled( + &decoration[..decoration.len() - 1], + 9, + "uptime", + line, + )?); + } else if decoration.contains('T') && decoration.contains(':') { + // Wall-clock `time` decoration is accepted but not interpreted. + } else if source.contains("GC(") || source.contains("Pause ") { + return Err(error( + line, + ParseErrorKind::Malformed("unsupported decoration"), + )); + } + rest = after_close; + } + if decorations > 0 && (!rest.starts_with(' ') || level.is_none() || tags.is_none()) { + return if source.contains("GC(") || source.contains("Pause ") { + Err(error( + line, + ParseErrorKind::Malformed("expected level, GC tags, and space after decorations"), + )) + } else { + Ok(Record::Skipped(SkipReason::Unrelated)) + }; + } + if decorations > 0 { + rest = rest.trim_start(); + } + if decorations > 0 && (tags != Some("gc") || level != Some("info")) { + return Ok(Record::Skipped(SkipReason::Unrelated)); + } + if !rest.starts_with("GC") { + return if rest.starts_with("Pause ") { + Err(error(line, ParseErrorKind::Malformed("missing GC ID"))) + } else { + Ok(Record::Skipped(SkipReason::Unrelated)) + }; + } + let Some(after_id_open) = rest.strip_prefix("GC(") else { + return if rest.contains("Pause ") { + Err(error(line, ParseErrorKind::Malformed("missing GC ID"))) + } else { + Ok(Record::Skipped(SkipReason::Unrelated)) + }; + }; + let Some((id_text, message)) = after_id_open.split_once(')') else { + return Err(error(line, ParseErrorKind::Malformed("unterminated GC ID"))); + }; + let gc_id = id_text + .parse::() + .map_err(|_| error(line, ParseErrorKind::InvalidNumber("GC ID")))?; + let Some(message) = message.strip_prefix(' ') else { + return Err(error( + line, + ParseErrorKind::Malformed("missing space after GC ID"), + )); + }; + let kind = if message.starts_with("Pause Young") { + EventKind::Young + } else if message.starts_with("Pause Full") { + EventKind::Full + } else if message.starts_with("Pause Remark") { + EventKind::Remark + } else if message.starts_with("Pause Cleanup") { + EventKind::Cleanup + } else { + return Ok(Record::Skipped(if message.starts_with("Pause ") { + SkipReason::UnsupportedEvent + } else { + SkipReason::Unrelated + })); + }; + let prefix = match kind { + EventKind::Young => "Pause Young", + EventKind::Full => "Pause Full", + EventKind::Remark => "Pause Remark", + EventKind::Cleanup => "Pause Cleanup", + }; + let tail = message.strip_prefix(prefix).unwrap_or(""); + if !tail.is_empty() && !tail.starts_with(' ') { + return Ok(Record::Skipped(SkipReason::UnsupportedEvent)); + } + let tail = tail.trim(); + let (body, duration_text) = tail.rsplit_once(' ').unwrap_or(("", tail)); + let Some(duration_text) = duration_text.strip_suffix("ms") else { + return Err(error( + line, + ParseErrorKind::Malformed("expected duration in ms"), + )); + }; + let duration_ns = decimal_to_scaled(duration_text, 6, "pause duration", line)?; + let (description, heap) = match body.rsplit_once(' ') { + Some((description, token)) if token.contains("->") => { + (description.trim(), Some(parse_heap(token, line)?)) + } + _ if body.contains("->") => ("", Some(parse_heap(body, line)?)), + _ => (body.trim(), None), + }; + if matches!(kind, EventKind::Young | EventKind::Full) && heap.is_none() { + return Err(error( + line, + ParseErrorKind::Malformed("young/full pause requires heap summary"), + )); + } + Ok(Record::Event(GcEvent { + source_line: line, + gc_id, + kind, + description: description.to_owned(), + heap, + duration_ns, + uptime_ns, + source: source.to_owned(), + })) +} + +fn parse_heap(text: &str, line: usize) -> Result { + let Some((before, rest)) = text.split_once("->") else { + return Err(error( + line, + ParseErrorKind::Malformed("expected heap before->after(capacity)"), + )); + }; + let Some((after, capacity)) = rest.split_once('(') else { + return Err(error( + line, + ParseErrorKind::Malformed("missing heap capacity"), + )); + }; + let Some(capacity) = capacity.strip_suffix(')') else { + return Err(error( + line, + ParseErrorKind::Malformed("unterminated heap capacity"), + )); + }; + Ok(HeapUsage { + before_bytes: parse_size(before, line)?, + after_bytes: parse_size(after, line)?, + capacity_bytes: parse_size(capacity, line)?, + }) +} + +fn parse_size(text: &str, line: usize) -> Result { + let Some(unit) = text.as_bytes().last().copied() else { + return Err(error(line, ParseErrorKind::InvalidNumber("heap size"))); + }; + let multiplier: u64 = match unit { + b'B' => 1, + b'K' => 1024, + b'M' => 1024_u64.pow(2), + b'G' => 1024_u64.pow(3), + _ => { + return Err(error( + line, + ParseErrorKind::InvalidNumber("heap unit (expected B, K, M, G)"), + )); + } + }; + let number = text[..text.len() - 1] + .parse::() + .map_err(|_| error(line, ParseErrorKind::InvalidNumber("heap size")))?; + number + .checked_mul(multiplier) + .ok_or_else(|| error(line, ParseErrorKind::Overflow("heap size"))) +} - #[test] - fn source_lines_require_one_based_numbers() { - assert!(SourceLine::new(0, "line").is_err()); - assert_eq!(SourceLine::new(1, "line").map(|line| line.number), Ok(1)); +fn decimal_to_scaled( + text: &str, + fractional_digits: usize, + field: &'static str, + line: usize, +) -> Result { + let (whole, fraction) = text.split_once('.').unwrap_or((text, "")); + if whole.is_empty() + || !whole.bytes().all(|b| b.is_ascii_digit()) + || !fraction.bytes().all(|b| b.is_ascii_digit()) + || fraction.len() > fractional_digits + || text.ends_with('.') + { + return Err(error(line, ParseErrorKind::InvalidNumber(field))); } + let scale = 10_u64.pow(fractional_digits as u32); + let whole = whole + .parse::() + .map_err(|_| error(line, ParseErrorKind::Overflow(field)))?; + let fraction_len = fraction.len(); + let fraction = if fraction.is_empty() { + 0 + } else { + fraction + .parse::() + .map_err(|_| error(line, ParseErrorKind::Overflow(field)))? + }; + whole + .checked_mul(scale) + .and_then(|n| { + n.checked_add(fraction * 10_u64.pow((fractional_digits - fraction_len) as u32)) + }) + .ok_or_else(|| error(line, ParseErrorKind::Overflow(field))) } diff --git a/crates/jvmdelta-core/src/lib.rs b/crates/jvmdelta-core/src/lib.rs index e6e1207..dacfc84 100644 --- a/crates/jvmdelta-core/src/lib.rs +++ b/crates/jvmdelta-core/src/lib.rs @@ -1,7 +1,4 @@ -//! Core types for JVM performance regression analysis. -//! -//! Parsing and analysis APIs will be added as their formats and behavior are -//! defined. No analysis is performed by this crate yet. +//! JVM performance analysis core. GC pause parsing is implemented; comparison and reporting are planned. pub mod comparison; pub mod gc_log; diff --git a/crates/jvmdelta-core/tests/gc_parser.rs b/crates/jvmdelta-core/tests/gc_parser.rs new file mode 100644 index 0000000..b7e8bbd --- /dev/null +++ b/crates/jvmdelta-core/tests/gc_parser.rs @@ -0,0 +1,163 @@ +use jvmdelta_core::gc_log::{EventKind, GcLogParser, ParseErrorKind, Record, SkipReason}; +use std::io::Cursor; + +fn events(input: &str) -> Vec { + GcLogParser::new(Cursor::new(input)) + .filter_map(|record| match record.expect("fixture must parse") { + Record::Event(event) => Some(event), + Record::Skipped(_) => None, + }) + .collect() +} + +#[test] +fn jdk17_synthetic_categories_and_exact_values() { + let input = include_str!("../../../tests/fixtures/jdk17-g1-synthetic.log"); + let parsed = events(input); + assert_eq!(parsed.len(), 4); + let young = &parsed[0]; + assert_eq!(young.source_line, 1); + assert_eq!(young.gc_id, 0); + assert_eq!(young.kind, EventKind::Young); + assert_eq!(young.description, "(Normal) (G1 Evacuation Pause)"); + assert_eq!(young.uptime_ns, Some(123_000_000)); + assert_eq!(young.duration_ns, 3_452_000); + let heap = young.heap.expect("young pause has heap"); + assert_eq!(heap.before_bytes, 20 * 1024 * 1024); + assert_eq!(heap.after_bytes, 8 * 1024 * 1024); + assert_eq!(heap.capacity_bytes, 128 * 1024 * 1024); + assert_eq!(parsed[1].kind, EventKind::Full); + assert_eq!(parsed[1].source_line, 3); + assert_eq!(parsed[2].kind, EventKind::Remark); + assert_eq!(parsed[2].heap, None); + assert_eq!(parsed[3].kind, EventKind::Cleanup); +} + +#[test] +fn jdk21_synthetic_and_real_jdk25_details() { + let input = include_str!("../../../tests/fixtures/jdk21-g1-synthetic.log"); + let parsed = events(input); + assert_eq!(parsed.len(), 2); + assert_eq!(parsed[0].gc_id, 12); + assert_eq!(parsed[0].duration_ns, 125_000); + assert_eq!(parsed[0].heap.expect("heap").before_bytes, 1024 * 1024); + assert_eq!( + parsed[1].heap.expect("heap").capacity_bytes, + 2 * 1024 * 1024 * 1024 + ); + let real = include_str!("../../../tests/fixtures/jdk25-g1-real.log"); + let records: Vec<_> = GcLogParser::new(Cursor::new(real)) + .collect::>() + .expect("real log parses"); + assert_eq!( + records + .iter() + .filter(|r| matches!(r, Record::Event(_))) + .count(), + 2 + ); + assert_eq!( + records + .iter() + .filter(|r| matches!(r, Record::Skipped(SkipReason::Unrelated))) + .count(), + 4 + ); +} + +#[test] +fn empty_and_bare_lines() { + assert_eq!(GcLogParser::new(Cursor::new("")).count(), 0); + let parsed = events("GC(4) Pause Young (Normal) (G1 Evacuation Pause) 1B->0B(2B) 0.000001ms\n"); + assert_eq!(parsed[0].duration_ns, 1); + assert_eq!(parsed[0].uptime_ns, None); +} + +#[test] +fn malformed_supported_lines_are_errors_with_provenance() { + let cases = [ + "[0.1s][info][gc] GC() Pause Young (Normal) 1M->0M(2M) 1ms", + "[0.1s][info][gc] GC(abc) Pause Young (Normal) 1M->0M(2M) 1ms", + "[0.1s][info][gc] GC(1 Pause Young (Normal) 1M->0M(2M) 1ms", + "[0.1s][info][gc] GC(1) Pause Young (Normal) 1T->0M(2M) 1ms", + "[0.1s][info][gc] GC(1) Pause Young (Normal) 18446744073709551615G->0M(2M) 1ms", + "[0.1s][info][gc] GC(1) Pause Young (Normal) 1M->0M(2M) -1ms", + "[0.1s][info][gc] GC(1) Pause Young (Normal) 1M->0M(2M) NaNms", + "[0.1s][info][gc] GC(1) Pause Young (Normal) 1M->0M(2M)", + "[0.1s][info][gc] GC(1) Pause Young (Normal) 1M->0M(2M) 18446744073709551615ms", + "[0.1s][info][gc] GC(1) Pause Young (Normal) 1M->0M(2M) 1.1234567ms", + "[0.1s][info][gc] GC(1) Pause Young (Normal) 1M->0M(2M) 1ms [truncated", + "[nonsense][info][gc] GC(1) Pause Young (Normal) 1M->0M(2M) 1ms", + ]; + for line in cases { + let input = format!("unrelated\n{line}\n"); + let error = GcLogParser::new(Cursor::new(input)) + .nth(1) + .expect("second line") + .expect_err(line); + assert_eq!(error.line, 2, "{line}"); + } +} + +#[test] +fn unsupported_and_detail_records_are_distinct() { + let input = "[0.1s][info][gc,phases] GC(1) Pause Young phase 1ms\n[0.1s][info][gc] GC(1) Pause Future 1ms\n[0.1s][info][gc] GC(1) Concurrent Mark 1ms\nplain message\n"; + let records: Vec<_> = GcLogParser::new(Cursor::new(input)) + .collect::>() + .expect("classified"); + assert_eq!( + records, + vec![ + Record::Skipped(SkipReason::Unrelated), + Record::Skipped(SkipReason::UnsupportedEvent), + Record::Skipped(SkipReason::Unrelated), + Record::Skipped(SkipReason::Unrelated) + ] + ); +} + +#[test] +fn sdk_can_continue_after_malformed_candidate() { + let input = "[info][gc] GC(1) Pause Young (Normal) 1T->0M(2M) 1ms\n[info][gc] GC(2) Pause Young (Normal) 1M->0M(2M) 1ms\n"; + let mut parser = GcLogParser::new(Cursor::new(input)); + assert_eq!( + parser + .next() + .expect("first line") + .expect_err("malformed") + .line, + 1 + ); + let second = parser + .next() + .expect("second line") + .expect("valid second line"); + assert!(matches!(second, Record::Event(event) if event.gc_id == 2 && event.source_line == 2)); +} + +#[test] +fn invalid_utf8_and_long_lines_fail_explicitly() { + let error = GcLogParser::new(Cursor::new(vec![0xff, b'\n'])) + .next() + .expect("line") + .expect_err("invalid UTF-8"); + assert!(matches!(error.kind, ParseErrorKind::InvalidUtf8)); + let error = GcLogParser::new(Cursor::new(vec![b'a'; 65_537])) + .next() + .expect("line") + .expect_err("long line"); + assert!(matches!(error.kind, ParseErrorKind::LineTooLong)); +} + +#[test] +fn streams_ten_thousand_events() { + let line = + "[0.1s][info][gc] GC(1) Pause Young (Normal) (G1 Evacuation Pause) 2M->1M(4M) 0.5ms\n"; + let input = line.repeat(10_000); + let mut count = 0; + for record in GcLogParser::new(Cursor::new(input)) { + assert!(matches!(record.expect("valid event"), Record::Event(_))); + count += 1; + } + assert_eq!(count, 10_000); +} diff --git a/docs/ARCHITECTURE.md b/docs/ARCHITECTURE.md index 84fcd96..89a7545 100644 --- a/docs/ARCHITECTURE.md +++ b/docs/ARCHITECTURE.md @@ -1,25 +1,19 @@ # Architecture -The workspace separates analysis from command-line presentation. +`jvmdelta-core` owns format parsing and analysis types. `jvmdelta-cli` owns argument parsing, file opening, presentation, and process exit status. The core parser takes any `BufRead`; it does not depend on Clap, paths, or a JVM. -`jvmdelta-core` owns input interpretation, measurements, comparison rules, regression decisions, and report data. `jvmdelta-cli` will parse user arguments, call core APIs, select an output format, and choose an exit status. A caller using the library will not need Clap or a JVM. - -Intended data flow: +The implemented GC path is: ```text -GC log / JFR recording - ↓ -format-specific parser and validated events - ↓ -measurements with explicit units and provenance +UTF-8 G1 Unified GC log + ↓ bounded line reader (64 KiB per line) +validated pause event / explicit skip reason / structured error ↓ -baseline/candidate comparison - ↓ -regression decisions and structured report - ↓ -terminal / JSON / HTML renderer +CLI category counts or SDK caller processing ``` -Only module boundaries and a few domain types exist on Day 1. A source line type validates one-based line numbering. Units, comparison sides, regression direction, and report formats are enums for upcoming APIs. There is no parser, analysis, or renderer yet. +`GcLogParser` yields records one at a time, so SDK users can aggregate or store only what they need. An event retains its source line and original line, GC ID, pause category, description, optional heap values in bytes, duration in nanoseconds, and optional uptime in nanoseconds. The CLI stops at the first error. SDK users may continue after malformed candidate lines, but terminal errors end iteration. + +The comparison, metrics, regression, and report modules remain small domain definitions for later work. They do not calculate results. The intended later flow is measurements → baseline/candidate comparison → regression decisions → report model → output renderer. Metric definitions must state units and aggregation rules; comparison must avoid implying statistical significance from one sample. -Future parsers should preserve source location in errors and distinguish unsupported input from malformed input. Metric definitions should state units, aggregation, and whether higher or lower values are worse. Comparison should avoid inferring statistical significance from a single sample. Structured report data should remain independent of output rendering. +See [GC log support](GC_LOG_SUPPORT.md) for the exact accepted syntax and limitations. diff --git a/docs/DEVELOPMENT.md b/docs/DEVELOPMENT.md index 911bc26..1dd5ca3 100644 --- a/docs/DEVELOPMENT.md +++ b/docs/DEVELOPMENT.md @@ -1,8 +1,8 @@ # Development -Use stable Rust 1.85 or newer. The workspace uses Rust 2024 edition and Cargo resolver 3. +Use stable Rust 1.85 or newer. The workspace uses Rust 2024 edition and Cargo resolver 3. Rust tests use checked-in fixtures and do not require Java. -Run the same commands as CI before submitting a change: +Run the CI checks before submitting a change: ```sh cargo fmt --all -- --check @@ -11,4 +11,10 @@ cargo test --workspace cargo build --workspace --release ``` -Keep core logic independent of CLI formatting. Add unit tests for domain behavior and CLI integration tests for observable exit codes and output. Store small, redistributable sample recordings in `tests/fixtures` once parsers exist; document where each fixture came from. Do not commit generated reports, recordings containing sensitive application data, credentials, or `target` artifacts. +Run the CLI against the real captured fixture: + +```sh +cargo run -p jvmdelta-cli -- gc inspect tests/fixtures/jdk25-g1-real.log +``` + +Keep core logic independent of CLI formatting. Add unit tests for parser behavior and CLI integration tests for exit codes and output. Record each fixture's origin, JDK version, collector, and reproduction procedure in `tests/fixtures/README.md`. Do not commit sensitive recordings, credentials, or build artifacts. See [format support](GC_LOG_SUPPORT.md) before extending the parser. diff --git a/docs/GC_LOG_SUPPORT.md b/docs/GC_LOG_SUPPORT.md new file mode 100644 index 0000000..a97c302 --- /dev/null +++ b/docs/GC_LOG_SUPPORT.md @@ -0,0 +1,40 @@ +# G1 Unified GC log support + +JVMDelta parses a deliberately narrow subset of HotSpot Unified Logging as emitted by G1 on JDK 17 and 21. The JDK 17 and 21 fixtures are **synthetic examples** modeled on documented syntax; they have not been validated against those local JVM versions. A separate small JDK 25 fixture was captured locally and checks the same syntax. The parser does not identify a JVM version or independently verify the collector from a log; callers should supply G1 logs. + +Authoritative references: + +- [JDK 17 `java` command, `-Xlog` syntax and decorations](https://docs.oracle.com/en/java/javase/17/docs/specs/man/java.html) +- [JDK 21 `java` command, `-Xlog` syntax and decorations](https://docs.oracle.com/en/java/javase/21/docs/specs/man/java.html) +- [JDK 21 G1 collector phases](https://docs.oracle.com/en/java/javase/21/gctuning/garbage-first-g1-garbage-collector1.html) +- [JDK 17 GC troubleshooting log examples](https://docs.oracle.com/en/java/javase/17/troubleshoot/troubleshooting-memory-leaks.html) + +## Accepted records + +An `info` record tagged exactly `gc` with `GC()` followed by `Pause Young`, `Pause Full`, `Pause Remark`, or `Pause Cleanup` is a candidate. Young and Full summaries require `before->after(capacity)` and a duration. Remark and Cleanup require a duration and may omit heap sizes. Description text between the category and heap summary is retained. A summary may be undecorated or have `uptime` (`[0.123s]`), a wall-clock `time` decoration, `[info]`, and `[gc]`. The parser accepts those decorations in any order. Wall-clock time is not interpreted. + +Example: + +```text +[0.123s][info][gc] GC(0) Pause Young (Normal) (G1 Evacuation Pause) 20M->8M(128M) 3.452ms +``` + +The event has ID 0, uptime 123,000,000 ns, heap 20/8/128 MiB expressed as bytes, and pause duration 3,452,000 ns. Units `B`, `K`, `M`, and `G` use binary powers of 1024. Heap values must be unsigned integers. Millisecond durations accept up to six fractional digits; uptime seconds accept up to nine. Values must fit in `u64` after conversion. + +`gc,start`, `gc,heap`, `gc,phases`, concurrent records, and non-GC lines are skipped, preventing phase lines from counting as pauses. Unknown `Pause` categories are counted separately as unsupported. `debug` and `trace` records are not interpreted as summary events. Legacy `-XX:+PrintGC` output, other collectors, alternate duration units, additional decorators, and arbitrary GC messages are outside this subset. A log line is limited to 64 KiB including its line ending. + +## Errors and strictness + +`GcLogParser` yields one classified result per line: event, skip reason, or `ParseError` with a one-based line number. Malformed candidate summaries fail explicitly, including invalid IDs, sizes, units, durations, or truncated summaries. Invalid UTF-8, I/O errors, and overlong lines fail explicitly and terminate iteration. Malformed candidate lines are recoverable for SDK callers that choose to continue iterating; this is the **permissive** policy. The `gc inspect` CLI uses the **strict** policy: it reports the first parser error on stderr and exits nonzero, with no partial count report. Unsupported categories are reported as skipped, not analyzed. + +## CLI + +```sh +cargo run -p jvmdelta-cli -- gc inspect tests/fixtures/jdk25-g1-real.log +``` + +The command prints supported event totals, counts for each category, unrelated entries skipped, and unsupported pause types skipped. It does not compute regression scores. + +## Fixtures + +See [`tests/fixtures/README.md`](../tests/fixtures/README.md). Rust tests use checked-in text only; Java is not required for test execution. diff --git a/docs/ROADMAP.md b/docs/ROADMAP.md index e61484e..6a4fe80 100644 --- a/docs/ROADMAP.md +++ b/docs/ROADMAP.md @@ -1,27 +1,29 @@ -# Day 2–7 roadmap +# Development roadmap -These are implementation targets, not shipped features. Adjust scope when format research or representative fixtures reveal constraints. +## Completed — Day 1 -## Day 2 — GC log contract +Cargo workspace, CLI foundation, documentation, Apache-2.0 license, and CI. -Choose supported Java Unified Logging syntax and versions. Add small, redistributable fixtures covering timestamps, tags, units, malformed lines, and unknown events. Define event types and useful parser errors. +## Completed — Day 2 -## Day 3 — GC parsing and measurements +A bounded streaming parser for selected G1 Unified GC pause summaries, typed events with exact units and source provenance, explicit errors and skip reasons, real and synthetic fixtures, and `gc inspect`. See [format support](GC_LOG_SUPPORT.md). -Implement a streaming parser for the documented subset. Calculate pause counts and duration summaries with explicit units. Test event extraction against fixtures and malformed input. +## Day 3 — measurements and broader fixture validation -## Day 4 — Comparison semantics +Validate the supported syntax against local JDK 17 and 21 output when available. Add carefully defined pause duration summaries and GC counts to the core, with tests for aggregation and missing data. Consider explicit support for additional decorators and duration units only after fixture evidence. -Define baseline and candidate data sets, missing-metric behavior, and percentage-change rules. Implement deterministic comparisons with tests for zero baselines and unequal sample sizes. +## Day 4 — comparison semantics -## Day 5 — Regression policy and CLI +Define baseline/candidate data sets, zero-baseline behavior, and missing-metric behavior. Implement deterministic comparisons without implying significance from a single run. -Add explicit thresholds and exit codes. Introduce a compare command only after it can reject unsupported or incomplete input clearly. Test CLI error paths and real fixture comparisons. +## Day 5 — regression policy and CLI -## Day 6 — Reports and CI usage +Add explicit thresholds and exit codes after comparison semantics are tested. -Create a structured report model and terminal/JSON output. Document reproducible CI invocation and add a minimal GitHub Action workflow example. Keep HTML as a later milestone if report data is still changing. +## Day 6 — reports and CI usage + +Add structured report data, terminal and JSON output, and a reproducible CI example. Defer HTML if the report model is still changing. ## Day 7 — JFR research and hardening -Document JFR format and licensing considerations, decide on a JVM-free parsing approach, and prototype a narrow reader if feasible. Review performance on bounded fixtures and improve error messages. Schedule full JFR, HTML, and distribution work based on results. +Document a JVM-free JFR approach and format/licensing constraints. Improve diagnostics and review performance on bounded fixtures. diff --git a/tests/fixtures/README.md b/tests/fixtures/README.md index b4ae4ad..159d62f 100644 --- a/tests/fixtures/README.md +++ b/tests/fixtures/README.md @@ -1,3 +1,28 @@ -# Fixtures +# GC log fixtures -Small, redistributable JVM recording samples will be added alongside parser tests. Record each fixture's source, license, JVM version, and expected interpretation here. +- `jdk17-g1-synthetic.log`: synthetic JDK 17-style G1 examples: young, full, remark, cleanup, and a `gc,start` line. Created for parser tests; not captured from JDK 17. +- `jdk21-g1-synthetic.log`: synthetic JDK 21-style G1 examples with wall-clock and uptime decorations, K/G units, and a detail record. Created for parser tests; not captured from JDK 21. +- `malformed-g1-synthetic.log`: synthetic malformed size-unit case. +- `jdk25-g1-real.log`: selected unchanged lines from a local OpenJDK 25.0.3 G1 run on Fedora. It contains one young summary, one full summary, a start record, and three heap detail records. Pause timings and heap quantities are specific to that run; do not compare them as performance evidence. + +To reproduce a similar JDK 25 log, save this as `/tmp/JvmDeltaGcFixture.java`: + +```java +public class JvmDeltaGcFixture { + public static void main(String[] args) { + for (int i = 0; i < 100; i++) { + byte[] bytes = new byte[1024 * 1024]; + bytes[0] = 1; + } + System.gc(); + } +} +``` + +Then run: + +```sh +java -Xms32m -Xmx32m -XX:+UseG1GC '-Xlog:gc*:file=/tmp/jvmdelta-gc.log:uptime,level,tags' /tmp/JvmDeltaGcFixture.java +``` + +The exact event IDs, heap values, and timing vary between runs. The fixture has no application data or personal paths. diff --git a/tests/fixtures/jdk17-g1-synthetic.log b/tests/fixtures/jdk17-g1-synthetic.log new file mode 100644 index 0000000..97ef142 --- /dev/null +++ b/tests/fixtures/jdk17-g1-synthetic.log @@ -0,0 +1,5 @@ +[0.123s][info][gc] GC(0) Pause Young (Normal) (G1 Evacuation Pause) 20M->8M(128M) 3.452ms +[0.124s][info][gc,start] GC(1) Pause Full (System.gc()) +[0.130s][info][gc] GC(1) Pause Full (System.gc()) 8M->4M(128M) 6.250ms +[0.135s][info][gc] GC(2) Pause Remark 1.125ms +[0.140s][info][gc] GC(2) Pause Cleanup 2M->1M(128M) 0.050ms diff --git a/tests/fixtures/jdk21-g1-synthetic.log b/tests/fixtures/jdk21-g1-synthetic.log new file mode 100644 index 0000000..887d477 --- /dev/null +++ b/tests/fixtures/jdk21-g1-synthetic.log @@ -0,0 +1,3 @@ +[2024-01-01T00:00:00.123+0000][0.123s][info][gc] GC(12) Pause Young (Concurrent Start) (G1 Humongous Allocation) 1024K->512K(1G) 0.125ms +[0.130s][info][gc,heap] GC(12) Eden regions: 4->0(2) +[0.140s][info][gc] GC(13) Pause Full (G1 Compaction Pause) 1G->512M(2G) 12.000ms diff --git a/tests/fixtures/jdk25-g1-real.log b/tests/fixtures/jdk25-g1-real.log new file mode 100644 index 0000000..0c5c195 --- /dev/null +++ b/tests/fixtures/jdk25-g1-real.log @@ -0,0 +1,6 @@ +[0.645s][info][gc,start ] GC(0) Pause Young (Normal) (G1 Evacuation Pause) +[0.656s][info][gc,heap ] GC(0) Eden regions: 17->0(11) +[0.656s][info][gc,heap ] GC(0) Survivor regions: 0->3(3) +[0.656s][info][gc,heap ] GC(0) Old regions: 2->3 +[0.656s][info][gc ] GC(0) Pause Young (Normal) (G1 Evacuation Pause) 18M->4M(32M) 10.235ms +[0.840s][info][gc ] GC(49) Pause Full (System.gc()) 7M->2M(32M) 12.735ms diff --git a/tests/fixtures/malformed-g1-synthetic.log b/tests/fixtures/malformed-g1-synthetic.log new file mode 100644 index 0000000..9962249 --- /dev/null +++ b/tests/fixtures/malformed-g1-synthetic.log @@ -0,0 +1,2 @@ +[0.123s][info][gc] GC(0) Pause Young (Normal) (G1 Evacuation Pause) 20M->8M(128M) 3.452ms +[0.124s][info][gc] GC(1) Pause Young (Normal) (G1 Evacuation Pause) 20T->8M(128M) 3.452ms