diff --git a/src/data.rs b/src/data.rs index 8062af23..7adddd2c 100644 --- a/src/data.rs +++ b/src/data.rs @@ -77,6 +77,7 @@ pub struct CollectorParams { pub runlog: PathBuf, pub pmu_config: Option, pub perf_frequency: u32, + pub save_profile_events: bool, pub hotline_frequency: u32, pub interval: u64, pub num_to_report: u32, @@ -97,6 +98,7 @@ impl CollectorParams { runlog: PathBuf::new(), pmu_config: None, perf_frequency: 99, + save_profile_events: false, hotline_frequency: 1000, interval: 1, num_to_report: 5000, @@ -153,6 +155,8 @@ impl DataType { self.collector_params.profile = param.profile.clone(); self.collector_params.tmp_dir = param.tmp_dir.clone(); self.collector_params.runlog = param.runlog.clone(); + self.collector_params.perf_frequency = param.perf_frequency; + self.collector_params.save_profile_events = param.save_profile_events; self.collector_params.pmu_config = param.pmu_config.clone(); self.collector_params.interval = param.interval; self.collector_params.hotline_frequency = param.hotline_frequency; diff --git a/src/data/java_profile.rs b/src/data/java_profile.rs index f6bbc488..836ee352 100644 --- a/src/data/java_profile.rs +++ b/src/data/java_profile.rs @@ -343,7 +343,16 @@ impl CollectData for JavaProfileRaw { "{}-java-profile-{}-profiler-data.json", params.run_name, key )); - match jfr::jfr_to_profiler(&jfr_path) { + + let event_out_path_buf = + params.data_dir.join(format!("parsed_jfr_events_{key}.out")); + let events_out_path = if params.save_profile_events { + Some(event_out_path_buf.as_path()) + } else { + None + }; + + match jfr::build_java_profiler_data(&jfr_path, events_out_path) { Ok(mut profiler) => { profiler.metadata = jfr::parse_jfr_metadata(&metadata_json); if let Ok(json) = serde_json::to_string(&profiler) { diff --git a/src/data/perf_profile.rs b/src/data/perf_profile.rs index b7a45459..756654ff 100644 --- a/src/data/perf_profile.rs +++ b/src/data/perf_profile.rs @@ -136,10 +136,18 @@ impl CollectData for PerfProfileRaw { Ok(_) => debug!("'perf record' executed successfully."), } + let event_out_path_buf = params.data_dir.join("parsed_perf_data.out"); + let events_out_path = if params.save_profile_events { + Some(event_out_path_buf.as_path()) + } else { + None + }; + // Parse raw Perf profile and build ProfilingData let perf_profiler_data = build_perf_profiler_data( ¶ms.data_file_path, *PROFILE_START_TIME_MS.lock().unwrap(), + events_out_path, ); let perf_profiler_data_path = params .data_dir diff --git a/src/lib.rs b/src/lib.rs index 20255b86..53695832 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -543,6 +543,7 @@ pub struct InitParams { pub tmp_dir: PathBuf, pub runlog: PathBuf, pub perf_frequency: u32, + pub save_profile_events: bool, pub hotline_frequency: u32, pub num_to_report: u32, /// Wall-clock start of `collect_data_serial`. `None` for archives @@ -592,6 +593,7 @@ impl InitParams { tmp_dir: PathBuf::from(APERF_TMP), runlog: PathBuf::new(), perf_frequency: 99, + save_profile_events: false, hotline_frequency: 1000, num_to_report: 5000, collection_start: None, diff --git a/src/profiling/jfr/convert.rs b/src/profiling/jfr/convert.rs index 7c0f5f38..f2105224 100644 --- a/src/profiling/jfr/convert.rs +++ b/src/profiling/jfr/convert.rs @@ -2,33 +2,66 @@ use crate::data::common::data_formats::{KeyValueData, Profiler}; use crate::profiling::jfr::{ExecSampleType, JfrEvent, JfrReader}; use crate::profiling::{FrameType, ThreadState}; use anyhow::Result; +use chrono::{TimeZone, Utc}; +use log::{debug, warn}; use serde_json::Value; use std::collections::HashMap; -use std::fmt::Write; +use std::fs::File; +use std::io::Write; use std::path::Path; +use std::time::Instant; -/// This converts a JFR to string output, and should be equivalent to jfr print function. -/// Only used for validating data parsing. -pub fn format_jfr(path: &Path) -> Result { - let mut out = String::new(); - let mut reader = JfrReader::open(path.to_str().unwrap())?; +/// This function uses JfrReader to parse async-profiler generated JFR files into +/// APerf data Profiler. +pub fn build_java_profiler_data( + jfr_path: &Path, + events_output_path: Option<&Path>, +) -> Result { + debug!("Start parsing raw JFR records..."); + let jfr_parse_start_time = Instant::now(); + + let mut reader = JfrReader::open(jfr_path.to_str().unwrap())?; + + let mut events_output_file = if let Some(events_output_path) = events_output_path { + if let Ok(events_output_file) = File::create(events_output_path) { + Some(events_output_file) + } else { + warn!( + "Failed to create file {} to save the JFR events", + events_output_path.display() + ); + None + } + } else { + None + }; - writeln!(out, "start_nanos: {}", reader.start_nanos)?; - writeln!(out, "end_nanos: {}", reader.end_nanos)?; - writeln!( - out, - "chunk ticks_per_sec: {}", - reader.chunk_info.ticks_per_sec - )?; - writeln!(out, "threads: {}", reader.threads.len())?; - writeln!(out, "methods: {}", reader.methods.len())?; - writeln!(out, "stack_traces: {}", reader.stack_traces.len())?; - writeln!(out, "classes: {}", reader.classes.len())?; - writeln!(out, "strings: {}", reader.strings.len())?; - writeln!(out, "enums: {:?}", reader.enums)?; - writeln!(out, "settings: {:?}", reader.settings)?; - writeln!(out, "---")?; + let frame_type_suffix: HashMap = reader + .enums + .get("jdk.types.FrameType") + .map(|m| { + m.iter() + .map(|(&k, v)| (k as u8, FrameType::from_jfr_name(v).literal_suffix())) + .collect() + }) + .unwrap_or_default(); + let thread_state_map = reader + .enums + .get("jdk.types.ThreadState") + .cloned() + .unwrap_or_default(); + // Cache: (method_id, frame_type) -> formatted frame string + let mut formatted_frame_name_cache: HashMap<(i64, u8), String> = HashMap::new(); + // Cache: class_id -> humanized class name string + let mut humanized_class_name_cache: HashMap = HashMap::new(); + + let mut profiler = Profiler::new(reader.start_nanos / 1_000_000); + if let Some(file) = events_output_file.as_mut() { + let _ = write_jfr_out_header(file, &reader); + } + + let mut num_samples: usize = 0; loop { match reader.read_event() { Ok(JfrEvent::EndOfChunk) => { @@ -37,164 +70,294 @@ pub fn format_jfr(path: &Path) -> Result { } } Ok(event) => { - let time_nanos = reader.chunk_info.event_time_to_nanos(event.time()); - let secs = time_nanos / 1_000_000_000; - let nanos_rem = (time_nanos % 1_000_000_000).unsigned_abs(); - let h = (secs / 3600) % 24; - let m = (secs / 60) % 60; - let s = secs % 60; - let ms = nanos_rem / 1_000_000; - let time_str = format!("{:02}:{:02}:{:02}.{:03}", h, m, s, ms); - - let tid = event.tid(); - let thread_name = reader.resolve_thread(tid as i64).unwrap_or_default(); - let java_tid = reader.java_thread_ids.get(&(tid as i64)).copied(); - - match &event { + let sample_time_ms = reader.chunk_info.event_time_to_millis(event.time()); + + if let Some(file) = events_output_file.as_mut() { + let _ = + write_jfr_out_event(file, &event, &mut humanized_class_name_cache, &reader); + } + + let (profile_type, thread_state, samples) = match &event { JfrEvent::ExecutionSample(e) => { - let state = reader - .enums - .get("jdk.types.ThreadState") - .and_then(|m| m.get(&e.thread_state)) - .cloned() - .unwrap_or_else(|| format!("STATE_{}", e.thread_state)); - let type_name = match e.sample_type { - ExecSampleType::Execution => "jdk.ExecutionSample", - ExecSampleType::NativeMethod => "jdk.NativeMethodSample", - ExecSampleType::WallClock => "profiler.WallClockSample", - ExecSampleType::CpuTime => "jdk.CPUTimeSample", - }; - writeln!(out, "{} {{", type_name)?; - writeln!(out, " startTime = {}", time_str)?; - write_thread_field(&mut out, "sampledThread", &thread_name, tid, java_tid)?; - writeln!(out, " state = \"{}\"", state)?; - if e.sample_type == ExecSampleType::WallClock { - writeln!(out, " samples = {}", e.samples)?; - } - } - JfrEvent::AllocationSample(e) => { - let cls = jvm_type_to_human(&reader.resolve_class(e.class_id as i64)); - let type_name = if e.tlab_size > 0 { - "jdk.ObjectAllocationInNewTLAB" - } else { - "jdk.ObjectAllocationOutsideTLAB" - }; - writeln!(out, "{} {{", type_name)?; - writeln!(out, " startTime = {}", time_str)?; - writeln!(out, " objectClass = {} (classLoader = null)", cls)?; - writeln!( - out, - " allocationSize = {}", - format_bytes(e.allocation_size) - )?; - if e.tlab_size > 0 { - writeln!(out, " tlabSize = {}", format_bytes(e.tlab_size))?; - } - write_thread_field(&mut out, "eventThread", &thread_name, tid, java_tid)?; - } - JfrEvent::ContendedLock(e) => { - let cls = jvm_type_to_human(&reader.resolve_class(e.class_id as i64)); - writeln!(out, "jdk.JavaMonitorEnter {{")?; - writeln!(out, " startTime = {}", time_str)?; - writeln!(out, " duration = {} ns", e.duration)?; - writeln!(out, " monitorClass = {}", cls)?; - write_thread_field(&mut out, "eventThread", &thread_name, tid, java_tid)?; - } - JfrEvent::LiveObject(e) => { - let cls = jvm_type_to_human(&reader.resolve_class(e.class_id as i64)); - writeln!(out, "profiler.LiveObject {{")?; - writeln!(out, " startTime = {}", time_str)?; - writeln!(out, " objectClass = {}", cls)?; - writeln!( - out, - " allocationSize = {}", - format_bytes(e.allocation_size) - )?; - writeln!(out, " allocationTime = {}", e.allocation_time)?; - } - JfrEvent::MallocEvent(e) => { - let type_name = if e.size > 0 { - "profiler.Malloc" - } else { - "profiler.Free" + let ptype = match e.sample_type { + ExecSampleType::Execution + | ExecSampleType::NativeMethod + | ExecSampleType::CpuTime => "cpu", + ExecSampleType::WallClock => "wall", }; - writeln!(out, "{} {{", type_name)?; - writeln!(out, " startTime = {}", time_str)?; - writeln!(out, " address = 0x{:x}", e.address)?; - if e.size > 0 { - writeln!(out, " size = {}", format_bytes(e.size))?; - } - } - JfrEvent::MethodTrace(e) => { - writeln!(out, "jdk.MethodTrace {{")?; - writeln!(out, " startTime = {}", time_str)?; - writeln!(out, " duration = {} ns", e.duration)?; - writeln!(out, " method = {}", e.method)?; - } - JfrEvent::NativeLock(e) => { - writeln!(out, "profiler.NativeLock {{")?; - writeln!(out, " startTime = {}", time_str)?; - writeln!(out, " duration = {} ns", e.duration)?; - writeln!(out, " address = 0x{:x}", e.address)?; - } - JfrEvent::Custom(_) => { - writeln!(out, "CustomEvent {{")?; - writeln!(out, " startTime = {}", time_str)?; + let state_name = thread_state_map + .get(&e.thread_state) + .map(|s| s.as_str()) + .unwrap_or(""); + (ptype, ThreadState::from_str(state_name), e.samples as u64) } - JfrEvent::EndOfChunk => unreachable!(), - } + JfrEvent::AllocationSample(_) => ("alloc", ThreadState::None, 1u64), + _ => continue, + }; + + num_samples += 1; if let Some(trace) = reader.stack_traces.get(&(event.stack_trace_id() as i64)) { - writeln!(out, " stackTrace = [")?; - for (i, &method_id) in trace.methods.iter().enumerate() { - let loc = trace.locations[i]; - let line = loc >> 16; - if let Some((cls, method, sig)) = reader.resolve_method(method_id) { - let sig_str = if sig.is_empty() || sig.starts_with("[unknown") { - String::new() - } else { - format_signature(&sig) - }; - writeln!( - out, - " {}.{}({}) line: {}", - cls.replace('/', "."), - method, - sig_str, - line - )?; - } else { - writeln!(out, " [unknown:{}]() line: {}", method_id, line)?; - } + let mut frames: Vec = trace + .methods + .iter() + .zip(trace.types.iter()) + .rev() + .map(|(&method_id, &frame_type)| { + formatted_frame_name_cache + .entry((method_id, frame_type)) + .or_insert_with(|| { + let suffix = + frame_type_suffix.get(&frame_type).copied().unwrap_or(""); + if let Some((cls, method, _)) = reader.resolve_method(method_id) + { + if frame_type == 3 || frame_type == 4 || cls.is_empty() { + format!("{}{}", method, suffix) + } else if method.is_empty() { + format!("{}{}", cls.replace('/', "."), suffix) + } else { + format!( + "{}.{}{}", + cls.replace('/', "."), + method, + suffix + ) + } + } else { + format!("[unknown:{}]{}", method_id, suffix) + } + }) + .clone() + }) + .collect(); + + if let JfrEvent::AllocationSample(e) = &event { + let cls = humanized_class_name_cache + .entry(e.class_id as i64) + .or_insert_with(|| { + jvm_type_to_human(&reader.resolve_class(e.class_id as i64)) + }); + let frame = format!("{}{}", cls, FrameType::Inlined.literal_suffix()); + frames.push(frame); } - writeln!(out, " ]")?; - } - writeln!(out, "}}")?; - writeln!(out)?; + if !frames.is_empty() { + profiler.insert_stack( + profile_type, + sample_time_ms, + thread_state, + &frames, + samples, + ); + } + } } Err(e) => return Err(e.into()), } } - Ok(out) + + debug!( + "Finished parsing {num_samples} JFR samples in {:?}", + jfr_parse_start_time.elapsed() + ); + + Ok(profiler) +} + +fn write_jfr_out_header(out_file: &mut File, reader: &JfrReader) -> Result<()> { + writeln!(out_file, "start_nanos: {}", reader.start_nanos)?; + writeln!(out_file, "end_nanos: {}", reader.end_nanos)?; + writeln!( + out_file, + "chunk ticks_per_sec: {}", + reader.chunk_info.ticks_per_sec + )?; + writeln!(out_file, "threads: {}", reader.threads.len())?; + writeln!(out_file, "methods: {}", reader.methods.len())?; + writeln!(out_file, "stack_traces: {}", reader.stack_traces.len())?; + writeln!(out_file, "classes: {}", reader.classes.len())?; + writeln!(out_file, "strings: {}", reader.strings.len())?; + writeln!(out_file, "enums: {:?}", reader.enums)?; + writeln!(out_file, "settings: {:?}", reader.settings)?; + writeln!(out_file, "---")?; + + Ok(()) +} + +fn write_jfr_out_event( + out_file: &mut File, + event: &JfrEvent, + humanized_class_name_cache: &mut HashMap, + reader: &JfrReader, +) -> Result<()> { + let time_nanos = reader.chunk_info.event_time_to_nanos(event.time()); + let date_time = Utc.timestamp_nanos(time_nanos); + let time_str = date_time.format("%H:%M:%S%.3f (%Y-%m-%d)").to_string(); + + let tid = event.tid(); + let thread_name = reader.resolve_thread(tid as i64).unwrap_or_default(); + let java_tid = reader.java_thread_ids.get(&(tid as i64)).copied(); + + match &event { + JfrEvent::ExecutionSample(e) => { + let state = reader + .enums + .get("jdk.types.ThreadState") + .and_then(|m| m.get(&e.thread_state)) + .cloned() + .unwrap_or_else(|| format!("STATE_{}", e.thread_state)); + let type_name = match e.sample_type { + ExecSampleType::Execution => "jdk.ExecutionSample", + ExecSampleType::NativeMethod => "jdk.NativeMethodSample", + ExecSampleType::WallClock => "profiler.WallClockSample", + ExecSampleType::CpuTime => "jdk.CPUTimeSample", + }; + writeln!(out_file, "{} {{", type_name)?; + writeln!(out_file, " startTime = {}", time_str)?; + write_thread_field(out_file, "sampledThread", &thread_name, tid, java_tid)?; + writeln!(out_file, " state = \"{}\"", state)?; + if e.sample_type == ExecSampleType::WallClock { + writeln!(out_file, " samples = {}", e.samples)?; + } + } + JfrEvent::AllocationSample(e) => { + let cls = humanized_class_name_cache + .entry(e.class_id as i64) + .or_insert_with(|| jvm_type_to_human(&reader.resolve_class(e.class_id as i64))); + let type_name = if e.tlab_size > 0 { + "jdk.ObjectAllocationInNewTLAB" + } else { + "jdk.ObjectAllocationOutsideTLAB" + }; + writeln!(out_file, "{} {{", type_name)?; + writeln!(out_file, " startTime = {}", time_str)?; + writeln!(out_file, " objectClass = {} (classLoader = null)", cls)?; + writeln!( + out_file, + " allocationSize = {}", + format_bytes(e.allocation_size) + )?; + if e.tlab_size > 0 { + writeln!(out_file, " tlabSize = {}", format_bytes(e.tlab_size))?; + } + write_thread_field(out_file, "eventThread", &thread_name, tid, java_tid)?; + } + JfrEvent::ContendedLock(e) => { + let cls = humanized_class_name_cache + .entry(e.class_id as i64) + .or_insert_with(|| jvm_type_to_human(&reader.resolve_class(e.class_id as i64))); + writeln!(out_file, "jdk.JavaMonitorEnter {{")?; + writeln!(out_file, " startTime = {}", time_str)?; + writeln!(out_file, " duration = {} ns", e.duration)?; + writeln!(out_file, " monitorClass = {}", cls)?; + write_thread_field(out_file, "eventThread", &thread_name, tid, java_tid)?; + } + JfrEvent::LiveObject(e) => { + let cls = humanized_class_name_cache + .entry(e.class_id as i64) + .or_insert_with(|| jvm_type_to_human(&reader.resolve_class(e.class_id as i64))); + writeln!(out_file, "profiler.LiveObject {{")?; + writeln!(out_file, " startTime = {}", time_str)?; + writeln!(out_file, " objectClass = {}", cls)?; + writeln!( + out_file, + " allocationSize = {}", + format_bytes(e.allocation_size) + )?; + writeln!(out_file, " allocationTime = {}", e.allocation_time)?; + } + JfrEvent::MallocEvent(e) => { + let type_name = if e.size > 0 { + "profiler.Malloc" + } else { + "profiler.Free" + }; + writeln!(out_file, "{} {{", type_name)?; + writeln!(out_file, " startTime = {}", time_str)?; + writeln!(out_file, " address = 0x{:x}", e.address)?; + if e.size > 0 { + writeln!(out_file, " size = {}", format_bytes(e.size))?; + } + } + JfrEvent::MethodTrace(e) => { + writeln!(out_file, "jdk.MethodTrace {{")?; + writeln!(out_file, " startTime = {}", time_str)?; + writeln!(out_file, " duration = {} ns", e.duration)?; + writeln!(out_file, " method = {}", e.method)?; + } + JfrEvent::NativeLock(e) => { + writeln!(out_file, "profiler.NativeLock {{")?; + writeln!(out_file, " startTime = {}", time_str)?; + writeln!(out_file, " duration = {} ns", e.duration)?; + writeln!(out_file, " address = 0x{:x}", e.address)?; + } + JfrEvent::Custom(_) => { + writeln!(out_file, "CustomEvent {{")?; + writeln!(out_file, " startTime = {}", time_str)?; + } + JfrEvent::EndOfChunk => unreachable!(), + } + + if let Some(trace) = reader.stack_traces.get(&(event.stack_trace_id() as i64)) { + writeln!(out_file, " stackTrace = [")?; + for (i, &method_id) in trace.methods.iter().enumerate() { + let loc = trace.locations[i]; + let line = loc >> 16; + if let Some((cls, method, sig)) = reader.resolve_method(method_id) { + let sig_str = if sig.is_empty() || sig.starts_with("[unknown") { + String::new() + } else { + format_signature(&sig) + }; + writeln!( + out_file, + " {}.{}({}) line: {}", + cls.replace('/', "."), + method, + sig_str, + line + )?; + } else { + writeln!(out_file, " [unknown:{}]() line: {}", method_id, line)?; + } + } + writeln!(out_file, " ]")?; + } + + writeln!(out_file, "}}")?; + writeln!(out_file)?; + + Ok(()) } fn write_thread_field( - out: &mut String, + out_file: &mut File, field: &str, name: &str, tid: i32, java_tid: Option, -) -> std::fmt::Result { +) -> Result<()> { if name.is_empty() { - return writeln!(out, " {} = N/A", field); + writeln!(out_file, " {} = N/A", field)?; + return Ok(()); } if let Some(jtid) = java_tid { if jtid > 0 { - return writeln!(out, " {} = \"{}\" (javaThreadId = {})", field, name, jtid); + writeln!( + out_file, + " {} = \"{}\" (javaThreadId = {})", + field, name, jtid + )?; + return Ok(()); } } - writeln!(out, " {} = \"{}\" (osThreadId = {})", field, name, tid) + writeln!( + out_file, + " {} = \"{}\" (osThreadId = {})", + field, name, tid + )?; + + Ok(()) } fn jvm_type_to_human(name: &str) -> String { @@ -279,156 +442,6 @@ fn parse_type(chars: &mut std::iter::Peekable) -> String { } } -/// This function uses JfrReader to parse async-profiler generated JFR files into -/// APerf Profiler. -pub fn jfr_to_profiler(path: &Path) -> Result { - let mut reader = JfrReader::open(path.to_str().unwrap())?; - let start_time_ms = reader.start_nanos / 1_000_000; - - let frame_type_suffix: HashMap = reader - .enums - .get("jdk.types.FrameType") - .map(|m| { - m.iter() - .map(|(&k, v)| (k as u8, FrameType::from_jfr_name(v).literal_suffix())) - .collect() - }) - .unwrap_or_default(); - - let thread_state_map = reader - .enums - .get("jdk.types.ThreadState") - .cloned() - .unwrap_or_default(); - - let mut profiler = Profiler::new(start_time_ms); - // Computed lazily after settings are populated from ActiveSetting events - let mut wall_interval_ms: Option = None; - - // Cache: (method_id, frame_type) -> formatted frame string - let mut frame_cache: HashMap<(i64, u8), String> = HashMap::new(); - // Cache: class_id -> formatted alloc class string - let mut alloc_class_cache: HashMap = HashMap::new(); - - loop { - match reader.read_event() { - Ok(JfrEvent::EndOfChunk) => { - if !reader.has_more_chunks().unwrap_or(false) { - break; - } - } - Ok(event) => { - let sample_time_ms = reader.chunk_info.event_time_to_millis(event.time()); - - let (profile_type, thread_state, samples) = match &event { - JfrEvent::ExecutionSample(e) => { - let ptype = match e.sample_type { - ExecSampleType::Execution - | ExecSampleType::NativeMethod - | ExecSampleType::CpuTime => "cpu", - ExecSampleType::WallClock => "wall", - }; - let state_name = thread_state_map - .get(&e.thread_state) - .map(|s| s.as_str()) - .unwrap_or(""); - (ptype, ThreadState::from_str(state_name), e.samples as u64) - } - JfrEvent::AllocationSample(_) => ("alloc", ThreadState::None, 1u64), - _ => continue, - }; - - if let Some(trace) = reader.stack_traces.get(&(event.stack_trace_id() as i64)) { - let mut frames: Vec = trace - .methods - .iter() - .zip(trace.types.iter()) - .rev() - .map(|(&mid, &ftype)| { - frame_cache - .entry((mid, ftype)) - .or_insert_with(|| { - let suffix = - frame_type_suffix.get(&ftype).copied().unwrap_or(""); - if let Some((cls, method, _)) = reader.resolve_method(mid) { - if ftype == 3 || ftype == 4 || cls.is_empty() { - format!("{}{}", method, suffix) - } else if method.is_empty() { - format!("{}{}", cls.replace('/', "."), suffix) - } else { - format!( - "{}.{}{}", - cls.replace('/', "."), - method, - suffix - ) - } - } else { - format!("[unknown:{}]{}", mid, suffix) - } - }) - .clone() - }) - .collect(); - - if let JfrEvent::AllocationSample(e) = &event { - let frame = alloc_class_cache - .entry(e.class_id as i64) - .or_insert_with(|| { - let cls = - jvm_type_to_human(&reader.resolve_class(e.class_id as i64)); - format!("{}{}", cls, FrameType::Inlined.literal_suffix()) - }) - .clone(); - frames.push(frame); - } - - if !frames.is_empty() { - // Wall clock events with samples > 1 represent consecutive sampling - // intervals. Spread them across time blocks to match async-profiler - // heatmap behavior. - // Source https://github.com/async-profiler/async-profiler/blob/20e0b5cfc344bf5e32e5554750c2b08462c353b8/src/converter/one/convert/JfrToHeatmap.java#L34 - if profile_type == "wall" && samples > 1 { - let interval = *wall_interval_ms.get_or_insert_with(|| { - reader - .settings - .get("wall") - .or_else(|| reader.settings.get("interval")) - .and_then(|s| s.parse::().ok()) - .filter(|&v| v > 0) - .unwrap_or(50_000_000) - / 1_000_000 - }); - let mut time_ms = sample_time_ms; - for _ in 0..samples { - profiler.insert_stack( - profile_type, - time_ms, - thread_state, - &frames, - 1, - ); - time_ms += interval; - } - } else { - profiler.insert_stack( - profile_type, - sample_time_ms, - thread_state, - &frames, - samples, - ); - } - } - } - } - Err(e) => return Err(e.into()), - } - } - - Ok(profiler) -} - // Reference: https://github.com/async-profiler/async-profiler/blob/master/src/jfrMetadata.h#L46-L70 fn jfr_event_type_name(id: &str) -> Option<&'static str> { match id { diff --git a/src/profiling/jfr/mod.rs b/src/profiling/jfr/mod.rs index 7bcf8d0b..cc1dfd72 100644 --- a/src/profiling/jfr/mod.rs +++ b/src/profiling/jfr/mod.rs @@ -8,7 +8,7 @@ mod convert; mod reader; mod types; -pub use convert::{format_jfr, jfr_to_profiler, parse_jfr_metadata}; +pub use convert::{build_java_profiler_data, parse_jfr_metadata}; pub use reader::JfrReader; pub use types::*; diff --git a/src/profiling/jfr/reader.rs b/src/profiling/jfr/reader.rs index 2003bac7..d51dd612 100644 --- a/src/profiling/jfr/reader.rs +++ b/src/profiling/jfr/reader.rs @@ -20,20 +20,6 @@ enum State { /// JFR binary format reader. Iterates chunk-by-chunk, event-by-event. /// Based on async-profiler implementation: https://github.com/async-profiler/async-profiler/tree/master /// src/converter/one/jfr -/// -/// Usage: -/// -/// ```ignore -/// let mut reader = JfrReader::open("recording.jfr")?; -/// while reader.has_more_chunks()? { -/// loop { -/// match reader.read_event()? { -/// JfrEvent::EndOfChunk => break, -/// event => { /* process event */ } -/// } -/// } -/// } -/// ``` #[derive(Default)] pub struct JfrReader { data: Vec, diff --git a/src/profiling/perf/parser.rs b/src/profiling/perf/parser.rs index 6812380e..274c3870 100644 --- a/src/profiling/perf/parser.rs +++ b/src/profiling/perf/parser.rs @@ -8,17 +8,18 @@ use crate::profiling::ThreadState; use anyhow::Result; use linux_perf_data::{PerfFileReader, PerfFileRecord}; use linux_perf_event_reader::{EventRecord, RawData, SampleRecord}; -use log::{debug, error}; +use log::{debug, error, warn}; use std::env; use std::fs::File; use std::io::{BufReader, Write}; -use std::path::PathBuf; +use std::path::{Path, PathBuf}; use std::time::Instant; /// Parse the raw Perf profile and build the Profiler Data. pub fn build_perf_profiler_data( perf_data_path: &PathBuf, profile_start_timestamp_ms: i64, + events_output_path: Option<&Path>, ) -> Profiler { debug!("Start parsing raw Perf profile..."); @@ -33,7 +34,8 @@ pub fn build_perf_profiler_data( } }; debug!( - "Raw Perf Data was parsed in {:?}", + "Finished parsing {} Perf samples in {:?}", + perf_samples.len(), perf_parse_start_time.elapsed() ); @@ -54,17 +56,23 @@ pub fn build_perf_profiler_data( } }; - // TODO: writing the stack output is for development only. Remove after verification step completes - let mut stack_output_file = perf_data_path - .parent() - .map(|parent_dir| { - File::create(PathBuf::from(parent_dir).join("parsed_perf_data.out")).unwrap() - }) - .unwrap(); + let mut stack_output_file = if let Some(events_output_path) = events_output_path { + if let Ok(file) = File::create(events_output_path) { + Some(file) + } else { + warn!( + "Failed to create file {} to save the Perf events", + events_output_path.display() + ); + None + } + } else { + None + }; let build_perf_profiler_data_start_time = Instant::now(); let profile_type = "cpu"; - for perf_sample in perf_samples { + for perf_sample in &perf_samples { let mut frames: Vec = perf_sample .call_chain .iter() @@ -80,14 +88,15 @@ pub fn build_perf_profiler_data( let sample_timestamp_ms = system_boot_timestamp_ms + (perf_sample.timestamp / 1_000_000) as i64; - // TODO: for development only. Remove after verification step completes. - writeln!( - stack_output_file, - "{}|{}|{}", - sample_timestamp_ms, - perf_sample.pid, - frames.join(";") - ); + if let Some(file) = stack_output_file.as_mut() { + let _ = writeln!( + file, + "{}|{}|{}", + sample_timestamp_ms, + perf_sample.pid, + frames.join(";") + ); + } profiler.insert_stack( profile_type, @@ -98,7 +107,8 @@ pub fn build_perf_profiler_data( ); } debug!( - "Perf Profiler Data was built in {:?}", + "Finished building Perf ProfilerData for {} samples in {:?}", + perf_samples.len(), build_perf_profiler_data_start_time.elapsed() ); diff --git a/src/record.rs b/src/record.rs index 2189f66c..ea62205d 100644 --- a/src/record.rs +++ b/src/record.rs @@ -60,12 +60,12 @@ pub struct Record { pub collect_only: Option>, /// Gather profiling data using 'perf' binary. - #[clap(help_heading = "Perf Profiling", long, value_parser)] + #[clap(help_heading = "Profiling", long, value_parser)] pub profile: bool, /// Frequency for perf profiling (Hz). #[clap( - help_heading = "Perf Profiling", + help_heading = "Profiling", short = 'F', long, value_parser, @@ -75,7 +75,7 @@ pub struct Record { /// Profile JVMs using async-profiler. Specify args using comma separated values. Profiles all JVMs if no args are provided. #[clap( - help_heading = "Java Profiling", + help_heading = "Profiling", long, value_parser, default_missing_value = Some("jps"), value_names = &["PID/Name>,,...,, + /// Save all profile events in the output file. + #[clap(help_heading = "Profiling", long, value_parser)] + pub save_profile_events: bool, + /// Custom PMU config file to use. #[clap(help_heading = "PMU Options", long, value_parser)] pub pmu_config: Option, @@ -155,6 +159,7 @@ pub fn record(record: &Record, tmp_dir: &Path, runlog: &Path) -> Result<()> { if record.profile { params.perf_frequency = record.perf_frequency; } + params.save_profile_events = record.save_profile_events; let mut performance_data = PerformanceData::new(params); diff --git a/tests/jfr_compare.rs b/tests/jfr_compare.rs deleted file mode 100644 index ba0c750e..00000000 --- a/tests/jfr_compare.rs +++ /dev/null @@ -1,123 +0,0 @@ -use aperf::profiling::jfr::format_jfr; -use std::collections::HashMap; -use std::fs; -use std::path::Path; -use std::process::Command; - -const JFR_EVENTS: &str = "jdk.ExecutionSample,jdk.NativeMethodSample,profiler.WallClockSample,jdk.MethodTrace,jdk.ObjectAllocationInNewTLAB,jdk.ObjectAllocationOutsideTLAB,jdk.ObjectAllocationSample,profiler.LiveObject,jdk.JavaMonitorEnter,jdk.ThreadPark,profiler.Malloc,profiler.Free,jdk.CPUTimeSample,profiler.NativeLock"; - -fn parse_events(output: &str) -> HashMap { - let text = if let Some(pos) = output.find("\n---\n") { - &output[pos + 5..] - } else { - output - }; - - let mut events: HashMap = HashMap::new(); - let mut current = Vec::new(); - - for line in text.lines() { - if line.trim().is_empty() && !current.is_empty() { - let event = current.join("\n").trim().to_string(); - if !event.is_empty() { - *events.entry(event).or_default() += 1; - } - current.clear(); - } else { - current.push(line); - } - } - if !current.is_empty() { - let event = current.join("\n").trim().to_string(); - if !event.is_empty() { - *events.entry(event).or_default() += 1; - } - } - events -} - -fn run_jfr_print(jfr_path: &Path) -> String { - let output = Command::new("jfr") - .args(["print", "--stack-depth", "999", "--events", JFR_EVENTS]) - .arg(jfr_path) - .output() - .expect("failed to run jfr"); - assert!( - output.status.success(), - "jfr print failed: {}", - String::from_utf8_lossy(&output.stderr) - ); - String::from_utf8(output.stdout).expect("jfr output not utf8") -} - -#[cfg(target_os = "linux")] -#[test] -fn compare_jfr_outputs() { - let fixtures = Path::new(env!("CARGO_MANIFEST_DIR")).join("tests/jfr_fixtures"); - let mut tested = 0; - - for entry in std::fs::read_dir(&fixtures).expect("cannot read jfr_fixtures dir") { - let path = entry.unwrap().path(); - if path.extension().and_then(|e| e.to_str()) != Some("jfr") { - continue; - } - - let name = path.file_name().unwrap().to_string_lossy(); - println!("Testing: {}", name); - - let gt_raw = run_jfr_print(&path); - let ours_raw = format_jfr(&path).expect("format_jfr failed"); - - let ground_truth = parse_events(>_raw); - let ours = parse_events(&ours_raw); - - let gt_total: usize = ground_truth.values().sum(); - let our_total: usize = ours.values().sum(); - - let mut only_gt = Vec::new(); - let mut only_ours = Vec::new(); - - for (event, &count) in &ground_truth { - let ours_count = ours.get(event).copied().unwrap_or(0); - if count > ours_count { - only_gt.push((count - ours_count, &event[..event.len().min(120)])); - } - } - for (event, &count) in &ours { - let gt_count = ground_truth.get(event).copied().unwrap_or(0); - if count > gt_count { - only_ours.push((count - gt_count, &event[..event.len().min(120)])); - } - } - - if !only_gt.is_empty() || !only_ours.is_empty() { - let dump_dir = Path::new("/tmp/aperf_java_testing"); - fs::create_dir_all(dump_dir).ok(); - let stem = path.file_stem().unwrap().to_string_lossy(); - fs::write(dump_dir.join(format!("{}_ground_truth.out", stem)), >_raw).ok(); - fs::write(dump_dir.join(format!("{}_ours.out", stem)), &ours_raw).ok(); - - let mut msg = - format!("MISMATCH in {name} (ground_truth: {gt_total}, ours: {our_total})\n"); - msg.push_str(&format!(" Outputs saved to {}\n", dump_dir.display())); - for (count, preview) in &only_gt { - msg.push_str(&format!( - " only in ground_truth [{count}x]: {}...\n", - preview.replace('\n', " | ") - )); - } - for (count, preview) in &only_ours { - msg.push_str(&format!( - " only in ours [{count}x]: {}...\n", - preview.replace('\n', " | ") - )); - } - panic!("{}", msg); - } - - println!(" PASS ({} events)", gt_total); - tested += 1; - } - - assert!(tested > 0, "No .jfr files found in {}", fixtures.display()); -} diff --git a/tests/jfr_fixtures/test_0.jfr b/tests/jfr_fixtures/test_0.jfr deleted file mode 100644 index c4df7452..00000000 Binary files a/tests/jfr_fixtures/test_0.jfr and /dev/null differ diff --git a/tests/test_aperf.rs b/tests/test_aperf.rs index 28950ce6..3f52729d 100644 --- a/tests/test_aperf.rs +++ b/tests/test_aperf.rs @@ -753,6 +753,7 @@ fn record_with_name( collect_only, profile: false, perf_frequency: 99, + save_profile_events: false, profile_java: None, pmu_config: None, hotline_frequency: 1000, @@ -768,6 +769,7 @@ fn record_with_name( collect_only, profile: false, perf_frequency: 99, + save_profile_events: false, profile_java: None, pmu_config: None, };