diff --git a/fixtures/other/stack-read-cache/stack-cache-repro.gz b/fixtures/other/stack-read-cache/stack-cache-repro.gz new file mode 100644 index 000000000..b0f5eee8c Binary files /dev/null and b/fixtures/other/stack-read-cache/stack-cache-repro.gz differ diff --git a/fixtures/other/stack-read-cache/stack-cache-repro.perf.data.gz b/fixtures/other/stack-read-cache/stack-cache-repro.perf.data.gz new file mode 100644 index 000000000..25e270316 Binary files /dev/null and b/fixtures/other/stack-read-cache/stack-cache-repro.perf.data.gz differ diff --git a/samply-api/src/asm/mod.rs b/samply-api/src/asm/mod.rs index b5b487212..ec757f39b 100644 --- a/samply-api/src/asm/mod.rs +++ b/samply-api/src/asm/mod.rs @@ -526,7 +526,7 @@ where let s = remaining_bytes .iter() .take(A::ADJUST_BY_AFTER_ERROR) - .map(|b| format!("{b:#02x}")) + .map(|b| format!("{b:#x}")) .collect::>() .join(", "); let s2 = remaining_bytes diff --git a/samply-api/tests/integration_tests/main.rs b/samply-api/tests/integration_tests/main.rs index 96f608145..868bb7989 100644 --- a/samply-api/tests/integration_tests/main.rs +++ b/samply-api/tests/integration_tests/main.rs @@ -116,13 +116,13 @@ impl FileAndPathHelper for Helper { let redirected_path = self.symbol_directory.join(filename); if std::fs::metadata(&redirected_path).is_ok() { // redirected_path exists! - eprintln!("Redirecting {:?} to {:?}", &path, &redirected_path); + eprintln!("Redirecting {:?} to {:?}", path, redirected_path); path = redirected_path; } } } - eprintln!("Reading file {:?}", &path); + eprintln!("Reading file {:?}", path); let file = File::open(&path)?; Ok(unsafe { memmap2::MmapOptions::new().map(&file)? }) }) diff --git a/samply-symbols/tests/integration_tests/main.rs b/samply-symbols/tests/integration_tests/main.rs index f896323b5..1cc40b408 100644 --- a/samply-symbols/tests/integration_tests/main.rs +++ b/samply-symbols/tests/integration_tests/main.rs @@ -185,7 +185,7 @@ impl FileAndPathHelper for Helper { { Box::pin(async { let path = location.0; - eprintln!("Opening file {:?}", &path); + eprintln!("Opening file {:?}", path); let file = File::open(&path)?; let mmap = unsafe { memmap2::MmapOptions::new().map(&file)? }; Ok(mmap_to_file_contents(mmap)) diff --git a/samply/src/lib.rs b/samply/src/lib.rs index 22748403b..0f716c022 100644 --- a/samply/src/lib.rs +++ b/samply/src/lib.rs @@ -159,17 +159,13 @@ pub fn do_record_action(record_args: cli::RecordArgs) { // A process killed by a signal has no exit code; report it as 128 + signal, // following the shell convention. + #[cfg(unix)] let exit_code = exit_status.code().unwrap_or_else(|| { - #[cfg(unix)] - { - use std::os::unix::process::ExitStatusExt; - exit_status.signal().map_or(1, |signal| 128 + signal) - } - #[cfg(not(unix))] - { - 1 - } + use std::os::unix::process::ExitStatusExt; + exit_status.signal().map_or(1, |signal| 128 + signal) }); + #[cfg(not(unix))] + let exit_code = exit_status.code().unwrap_or(1); std::process::exit(exit_code); } @@ -256,7 +252,7 @@ pub fn run_server_serving_profile( let precog_path = profile_path.with_extension("syms.json"); if let Some(precog_info) = shared::symbol_precog::PrecogSymbolInfo::try_load(&precog_path) { - for symbol_map in precog_info.into_iter() { + for symbol_map in precog_info.into_symbol_maps() { let lib_info = symbol_map.library_info(); symbol_manager.add_known_library_symbols(lib_info, Arc::new(symbol_map)); } diff --git a/samply/src/linux/profiler.rs b/samply/src/linux/profiler.rs index bf5cdc662..271e01cdf 100644 --- a/samply/src/linux/profiler.rs +++ b/samply/src/linux/profiler.rs @@ -39,7 +39,7 @@ pub fn run( recording_mode: RecordingMode, recording_props: RecordingProps, profile_creation_props: ProfileCreationProps, -) -> Result<(Profile, ExitStatus), ()> { +) -> Result<(Profile, ExitStatus), std::convert::Infallible> { let process_launch_props = match recording_mode { RecordingMode::All => { // TODO: Implement, by sudo launching a helper process which opens cpu-wide perf events diff --git a/samply/src/linux_shared/converter.rs b/samply/src/linux_shared/converter.rs index cd142ce6c..120020d43 100644 --- a/samply/src/linux_shared/converter.rs +++ b/samply/src/linux_shared/converter.rs @@ -38,7 +38,7 @@ use super::injected_jit_object::{correct_bad_perf_jit_so_file, jit_function_name use super::kernel_symbols::{kernel_module_build_id, KernelSymbols}; use super::mmap_range_or_vec::MmapRangeOrVec; use super::pe_mappings::{PeMappings, SuspectedPeMapping}; -use super::process::ExtraEventInstance; +use super::process::{ExtraEventInstance, StackSnapshot, ThreadStackSnapshots}; use super::processes::Processes; use super::rss_stat::{RssStat, MM_ANONPAGES, MM_FILEPAGES, MM_SHMEMPAGES, MM_SWAPENTS}; use super::svma_file_range::compute_vma_bias; @@ -693,12 +693,12 @@ where e: &SampleRecord, unwinder: &U, cache: &mut U::Cache, - stack_read_cache: &mut std::collections::HashMap, + stack_read_cache: &mut HashMap, stack: &mut Vec, fold_recursive_prefix: bool, call_chain_return_addresses_are_preadjusted: bool, ) { - stack.truncate(0); + stack.clear(); // Parse e.callchain into kernel frames and user FP frames. let mut callchain_buf = Vec::new(); @@ -738,23 +738,33 @@ where if let (Some(regs), Some((user_stack, _))) = (&e.user_regs, e.user_stack) { let ustack_bytes = RawDataU64::from_raw_data::(user_stack); let (pc, sp, regs) = C::convert_regs(regs); + let sample_window = StackSnapshot { + sp, + // The current window is only used as the base of a + // continuation check. Its stable start is learned while + // unwinding and is set on the snapshot stored afterward. + stable_start: sp, + // The whole captured window: perf bounds it (at most ~64 KiB). + words: (0..ustack_bytes.len()) + .filter_map(|index| ustack_bytes.get(index)) + .collect(), + }; + let mut stable_start = None; + // Without a tid we can't tell whose stack earlier words came from. + if let Some(cache) = e.tid.and_then(|tid| stack_read_cache.get_mut(&tid)) { + cache.retire_returned(sp); + } + let thread_cache = e.tid.and_then(|tid| stack_read_cache.get(&tid)); + // The snapshots followed past the window, extended lazily by reads. + let mut chain = Vec::new(); let mut read_stack = |addr: u64| { - // Prefer this sample's freshly captured stack window. ustack_bytes - // has the stack bytes starting from the current stack pointer. - if let Some(value) = addr - .checked_sub(sp) - .and_then(|offset| usize::try_from(offset / 8).ok()) - .and_then(|index| ustack_bytes.get(index)) - { - // Remember it: the upper stack is stable across samples, so a - // later sample whose window doesn't reach this far can still - // satisfy the read. - stack_read_cache.insert(addr, value); + if let Some(value) = sample_window.get(addr) { + stable_start = Some(stable_start.map_or(addr, |start: u64| start.min(addr))); return Ok(value); } - // The read is below sp or past the captured window. Fall back to - // a value seen in an earlier sample, if any. - stack_read_cache.get(&addr).copied().ok_or(()) + thread_cache + .and_then(|cache| cache.read_past(&sample_window, &mut chain, addr)) + .ok_or(()) }; // Unwind. @@ -778,6 +788,15 @@ where }; stack.push(stack_frame); } + if let (Some(tid), Some(stable_start)) = (e.tid, stable_start) { + stack_read_cache + .entry(tid) + .or_default() + .push(StackSnapshot { + stable_start, + ..sample_window + }); + } } // Frame-pointer unwinding (framehop's fallback for code without @@ -1170,6 +1189,8 @@ where process .threads .remove_non_main_thread(e.tid, end_time, &mut self.profile); + // The tid may be reused by an unrelated thread. + process.stack_read_cache.remove(&e.tid); } } @@ -1230,6 +1251,7 @@ where process .threads .remove_non_main_thread(e.tid, timestamp, &mut self.profile); + process.stack_read_cache.remove(&e.tid); process.recycle_or_get_new_thread( e.tid, Some(name.to_string()), @@ -1509,10 +1531,9 @@ where } } - let name = match path.rfind('/') { - Some(pos) => path[pos + 1..].to_owned(), - None => path.clone(), - }; + let name = Path::new(&path) + .file_name() + .map_or_else(|| path.clone(), |name| name.to_string_lossy().into_owned()); let process = self.processes.get_by_pid(process_pid, &mut self.profile); diff --git a/samply/src/linux_shared/process.rs b/samply/src/linux_shared/process.rs index 6295ab829..47fc0106e 100644 --- a/samply/src/linux_shared/process.rs +++ b/samply/src/linux_shared/process.rs @@ -1,4 +1,4 @@ -use std::collections::HashMap; +use std::collections::{HashMap, VecDeque}; use std::path::{Path, PathBuf}; use framehop::Unwinder; @@ -34,12 +34,13 @@ pub struct Process { pub jit_app_cache_mapping_ops: LibMappingOpQueue, pub jit_function_recycler: Option, marker_file_paths: Vec<(ThreadHandle, PathBuf, Vec)>, - /// Per-process cache of stack memory previously read during unwinding, - /// keyed by absolute stack address. The upper part of the stack (the frames - /// above the churning leaf) is stable across samples, so when an unwind - /// walks past the current sample's captured stack window we can satisfy the - /// read from a value seen in an earlier sample instead of truncating. - pub stack_read_cache: HashMap, + /// Per-thread rings of recent stack windows captured with samples, keyed + /// by tid. When an unwind walks past the current sample's captured stack + /// window, it continues through an earlier window of the same thread + /// whose overlap with the current one is word-for-word identical (see + /// [`StackSnapshot::continues`]). Other threads' stacks are unrelated, so + /// their windows must never be used. + pub stack_read_cache: HashMap, pub prev_mm_filepages_size: i64, pub prev_mm_anonpages_size: i64, pub prev_mm_swapents_size: i64, @@ -59,6 +60,110 @@ pub struct ExtraEventInstance { pub prev_value: u64, } +/// The user stack words `[sp, end())` captured with one sample. +pub struct StackSnapshot { + pub sp: u64, + pub stable_start: u64, + pub words: Vec, +} + +impl StackSnapshot { + pub fn end(&self) -> u64 { + self.sp + self.words.len() as u64 * 8 + } + + /// The word at `addr`, if it lies inside this snapshot. + pub fn get(&self, addr: u64) -> Option { + let index = usize::try_from(addr.checked_sub(self.sp)? / 8).ok()?; + self.words.get(index).copied() + } + + /// Whether `self`, captured by an earlier sample, continues `window` past + /// its end. Only words at or above this snapshot's stable start are + /// compared: words below it belong to the leaf frame and can change + /// between samples. + pub fn continues(&self, window: &StackSnapshot) -> bool { + if self.sp <= window.sp + || self.sp >= window.end() + || self.end() <= window.end() + || self.stable_start <= self.sp + || self.stable_start >= window.end() + { + return false; + } + let stable_offset = self.stable_start - self.sp; + let window_offset = self.stable_start - window.sp; + if stable_offset % 8 != 0 || window_offset % 8 != 0 { + return false; + } + let overlap_words = ((window.end() - self.stable_start) / 8) as usize; + let self_start = (stable_offset / 8) as usize; + let window_start = (window_offset / 8) as usize; + self.words + .get(self_start..self_start + overlap_words) + .zip(window.words.get(window_start..window_start + overlap_words)) + .is_some_and(|(self_words, window_words)| self_words == window_words) + } +} + +/// The stack windows of one thread that may still be current, newest first. +/// Retirement and covering keep only snapshots that extend further up the +/// stack than every newer one, so the count stays bounded by the stack depth. +#[derive(Default)] +pub struct ThreadStackSnapshots { + ring: VecDeque, +} + +impl ThreadStackSnapshots { + /// Adds the newest snapshot. Older snapshots whose stable part it fully + /// covers are dropped: it holds fresher words for all of their addresses. + pub fn push(&mut self, snapshot: StackSnapshot) { + self.ring.retain(|older| { + older.stable_start < snapshot.stable_start || older.end() > snapshot.end() + }); + self.ring.push_front(snapshot); + } + + /// Drops the snapshots whose stable frames have returned by the time of a + /// sample at `sp`: the thread's stack pointer is now above their lowest + /// trusted slot, so the words there have been overwritten or will be. + pub fn retire_returned(&mut self, sp: u64) { + self.ring.retain(|snapshot| snapshot.stable_start >= sp); + } + + /// The word at `addr` past the end of `window`, read from the snapshots + /// that continue it. `chain` holds the indices of the snapshots followed + /// so far and is extended only when a read needs another hop. + pub fn read_past( + &self, + window: &StackSnapshot, + chain: &mut Vec, + addr: u64, + ) -> Option { + loop { + let tip = chain.last().map_or(window, |&index| &self.ring[index]); + if let Some(value) = tip.get(addr) { + return Some(value); + } + // Continuations only start above the tip's sp. + if addr < tip.sp { + return None; + } + let next = self.find_continuation(tip, chain)?; + chain.push(next); + } + } + + /// The index of the newest snapshot that continues `window` (see + /// [`StackSnapshot::continues`]), skipping the indices in `used`. + fn find_continuation(&self, window: &StackSnapshot, used: &[usize]) -> Option { + self.ring + .iter() + .enumerate() + .position(|(index, snapshot)| !used.contains(&index) && snapshot.continues(window)) + } +} + pub struct ProcessForkData { unwinder: U, lib_mapping_ops: LibMappingOpQueue, @@ -381,3 +486,69 @@ where }) } } + +#[cfg(test)] +mod tests { + use super::{StackSnapshot, ThreadStackSnapshots}; + + const WINDOW_SP: u64 = 0x7fff_0000_0000; + const WINDOW_WORDS: usize = 4096; + + fn window() -> StackSnapshot { + StackSnapshot { + sp: WINDOW_SP, + stable_start: WINDOW_SP, + words: vec![0; WINDOW_WORDS], + } + } + + /// An earlier snapshot that matches `window()` on its last + /// `overlap_words` words and extends one word past it. + fn earlier(overlap_words: usize) -> StackSnapshot { + let stable_start = window().end() - overlap_words as u64 * 8; + let sp = stable_start - 8; + StackSnapshot { + sp, + stable_start, + words: vec![0; overlap_words + 2], + } + } + + #[test] + fn only_words_from_stable_start_must_match() { + let window = window(); + + let mut leaf_differs = earlier(1); + leaf_differs.words[0] = 0xdead; + assert!(leaf_differs.continues(&window)); + + let mut overlap_differs = earlier(1); + overlap_differs.words[1] = 0xdead; + assert!(!overlap_differs.continues(&window)); + } + + #[test] + fn snapshots_are_retired_once_their_stable_frames_returned() { + let mut snapshots = ThreadStackSnapshots::default(); + snapshots.push(earlier(16)); + let stable_start = snapshots.ring[0].stable_start; + + snapshots.retire_returned(stable_start); + assert_eq!(snapshots.ring.len(), 1); + + snapshots.retire_returned(stable_start + 8); + assert!(snapshots.ring.is_empty()); + } + + #[test] + fn covered_snapshots_are_dropped() { + let mut snapshots = ThreadStackSnapshots::default(); + snapshots.push(earlier(16)); + // Same range, captured later: the older copy is redundant. + snapshots.push(earlier(16)); + assert_eq!(snapshots.ring.len(), 1); + // Reaches less far up the stack: both are kept. + snapshots.push(earlier(8)); + assert_eq!(snapshots.ring.len(), 2); + } +} diff --git a/samply/src/mac/thread_profiler.rs b/samply/src/mac/thread_profiler.rs index 5e32f7aee..4cb1755a9 100644 --- a/samply/src/mac/thread_profiler.rs +++ b/samply/src/mac/thread_profiler.rs @@ -14,7 +14,6 @@ use super::thread_info::{ thread_info_t, time_value, THREAD_BASIC_INFO, THREAD_BASIC_INFO_COUNT, THREAD_EXTENDED_INFO, THREAD_EXTENDED_INFO_COUNT, THREAD_IDENTIFIER_INFO, THREAD_IDENTIFIER_INFO_COUNT, }; -use crate::mac::time; use crate::shared::recycling::ThreadRecycler; use crate::shared::types::{StackFrame, StackMode}; use crate::shared::unresolved_samples::{UnresolvedSamples, UnresolvedStacks}; diff --git a/samply/src/shared/jit_category_manager.rs b/samply/src/shared/jit_category_manager.rs index 560e4e149..ab14d9485 100644 --- a/samply/src/shared/jit_category_manager.rs +++ b/samply/src/shared/jit_category_manager.rs @@ -27,6 +27,12 @@ pub struct JitCategoryManager { generic_jit_category: LazilyCreatedCategory, } +impl Default for JitCategoryManager { + fn default() -> Self { + Self::new() + } +} + impl JitCategoryManager { /// (prefix, name, color, is_js) const CATEGORIES: &'static [(&'static str, Category<'static>, bool)] = &[ diff --git a/samply/src/shared/lib_mappings.rs b/samply/src/shared/lib_mappings.rs index be98c970f..0c4dfdac7 100644 --- a/samply/src/shared/lib_mappings.rs +++ b/samply/src/shared/lib_mappings.rs @@ -87,7 +87,10 @@ pub struct LibMappingsHierarchy { impl LibMappingsHierarchy { pub fn new(regular_lib_mappings_ops: LibMappingOpQueue) -> Self { Self { - regular_libs: (LibMappings::default(), regular_lib_mappings_ops.into_iter()), + regular_libs: ( + LibMappings::default(), + regular_lib_mappings_ops.into_queue_iter(), + ), jitdumps: Vec::new(), perf_map: None, } @@ -95,7 +98,7 @@ impl LibMappingsHierarchy { pub fn add_jitdump_lib_mappings_ops(&mut self, lib_mappings_ops: LibMappingOpQueue) { self.jitdumps - .push((LibMappings::default(), lib_mappings_ops.into_iter())); + .push((LibMappings::default(), lib_mappings_ops.into_queue_iter())); } pub fn add_perf_map_mappings(&mut self, mappings: LibMappings) { @@ -143,7 +146,7 @@ impl LibMappingOpQueue { self.0.is_empty() } - pub fn into_iter(self) -> LibMappingOpQueueIter { + pub fn into_queue_iter(self) -> LibMappingOpQueueIter { LibMappingOpQueueIter(self.0.into_iter().peekable()) } } diff --git a/samply/src/shared/recycling.rs b/samply/src/shared/recycling.rs index fc88c1b0d..32e7672df 100644 --- a/samply/src/shared/recycling.rs +++ b/samply/src/shared/recycling.rs @@ -38,6 +38,12 @@ pub type ThreadRecycler = RecyclerByName<(ThreadHandle, StringHandle)>; pub struct RecyclerByName(FastHashMap>>); +impl Default for RecyclerByName { + fn default() -> Self { + Self::new() + } +} + impl RecyclerByName { pub fn new() -> Self { Self(FastHashMap::default()) diff --git a/samply/src/shared/symbol_precog.rs b/samply/src/shared/symbol_precog.rs index 0e98e0a09..81103b68f 100644 --- a/samply/src/shared/symbol_precog.rs +++ b/samply/src/shared/symbol_precog.rs @@ -237,7 +237,7 @@ impl PrecogSymbolInfo { serde_json::from_reader(reader).expect("failed to parse sidecar syms.json") } - pub fn into_iter(self) -> impl Iterator { + pub fn into_symbol_maps(self) -> impl Iterator { let Self { data, string_table } = self; let string_table = Arc::new(string_table); data.into_iter() diff --git a/samply/tests/stack_read_cache_replay.rs b/samply/tests/stack_read_cache_replay.rs new file mode 100644 index 000000000..e1309b42e --- /dev/null +++ b/samply/tests/stack_read_cache_replay.rs @@ -0,0 +1,187 @@ +//! Replays a recorded perf.data through `samply import` and checks that the +//! stack read cache doesn't splice stacks from earlier samples. +//! +//! The fixture in `fixtures/other/stack-read-cache/` was recorded from the +//! `tools/stack-cache-repro` workload (see `make-fixture.sh` there): phase A +//! recurses through `a_recurse` deeper than the 32000-byte user stack copy and +//! works at every depth, then phase B recurses to the same depth through +//! `b_recurse` and only works in `b_leaf`. A `b_leaf` stack that contains +//! `a_recurse` (or the reverse) was completed from stale cached stack words. +//! With an unchecked address -> word cache, every phase B stack in this +//! fixture is spliced onto phase A's frames. +//! +//! The workload is a static x86_64 binary, so the replay doesn't depend on the +//! host's libraries and runs on any host. + +use std::io::{Cursor, Read}; +use std::ops::Range; +use std::path::{Path, PathBuf}; + +use flate2::read::GzDecoder; +use object::{Object, ObjectSymbol}; +use samply::shared::prop_types::{CoreClrProfileProps, ProfileCreationProps}; +use serde_json::Value; + +const LIB_NAME: &str = "stack-cache-repro"; +/// Frames of the deepest `a_recurse` recursion: depths 0..=35. +const FULL_A_DEPTH: usize = 36; + +fn fixture_dir() -> PathBuf { + Path::new(env!("CARGO_MANIFEST_DIR")).join("../fixtures/other/stack-read-cache") +} + +fn gunzip(path: &Path) -> Vec { + let mut bytes = Vec::new(); + GzDecoder::new(std::fs::File::open(path).unwrap()) + .read_to_end(&mut bytes) + .unwrap(); + bytes +} + +fn props() -> ProfileCreationProps { + ProfileCreationProps { + profile_name: None, + fallback_profile_name: "stack-read-cache".into(), + main_thread_only: false, + reuse_threads: false, + fold_recursive_prefix: false, + unlink_aux_files: false, + create_per_cpu_threads: false, + arg_count_to_include_in_process_name: 0, + override_arch: None, + presymbolicate: false, + coreclr: CoreClrProfileProps::default(), + unknown_event_markers: false, + should_emit_jit_markers: false, + should_emit_cswitch_markers: false, + } +} + +/// Address ranges of the workload's functions, as relative addresses (the +/// binary is position-independent, so they equal the symbol addresses). +struct Functions { + a_leaf: Range, + a_recurse: Range, + b_leaf: Range, + b_recurse: Range, +} + +impl Functions { + fn from_binary(data: &[u8]) -> Self { + let file = object::File::parse(data).unwrap(); + let range = |suffix: &str| { + let symbol = file + .symbols() + .find(|symbol| symbol.name().is_ok_and(|name| name.ends_with(suffix))) + .unwrap_or_else(|| panic!("no symbol ending with {suffix}")); + symbol.address()..symbol.address() + symbol.size() + }; + Self { + a_leaf: range("6a_leaf"), + a_recurse: range("9a_recurse"), + b_leaf: range("6b_leaf"), + b_recurse: range("9b_recurse"), + } + } +} + +/// The workload-binary frame addresses of every sample, leaf first. +fn sample_stacks(profile: &Value) -> Vec> { + let libs = profile["libs"].as_array().unwrap(); + let shared = &profile["shared"]; + let column = |table: &str, name: &str| shared[table][name].as_array().unwrap().clone(); + let resource_lib = column("resourceTable", "lib"); + let func_resource = column("funcTable", "resource"); + let frame_func = column("frameTable", "func"); + let frame_address = column("frameTable", "address"); + let stack_prefix = column("stackTable", "prefix"); + let stack_frame = column("stackTable", "frame"); + let index = |value: &Value| value.as_u64().map(|v| v as usize); + + let frame_in_workload = |frame: usize| -> Option { + let resource = index(&func_resource[index(&frame_func[frame])?])?; + let lib = index(&resource_lib[resource])?; + (libs[lib]["name"] == LIB_NAME).then(|| frame_address[frame].as_u64())? + }; + + let mut stacks = Vec::new(); + for thread in profile["threads"].as_array().unwrap() { + for stack in thread["samples"]["stack"].as_array().unwrap() { + let mut addresses = Vec::new(); + let mut cursor = index(stack); + while let Some(stack) = cursor { + if let Some(address) = frame_in_workload(index(&stack_frame[stack]).unwrap()) { + addresses.push(address); + } + cursor = index(&stack_prefix[stack]); + } + stacks.push(addresses); + } + } + stacks +} + +#[test] +fn replayed_stacks_are_not_spliced_from_earlier_samples() { + let dir = fixture_dir(); + let binary = gunzip(&dir.join("stack-cache-repro.gz")); + let functions = Functions::from_binary(&binary); + // The perf.data refers to the binary by its recording path; the converter + // falls back to looking it up by file name in the binary lookup dirs. + let binary_dir = tempfile::tempdir().unwrap(); + std::fs::write(binary_dir.path().join(LIB_NAME), &binary).unwrap(); + + let perf_data = gunzip(&dir.join("stack-cache-repro.perf.data.gz")); + let profile = samply::import::perf::convert( + Cursor::new(perf_data), + None, + vec![binary_dir.path().to_owned()], + vec![], + props(), + ) + .unwrap(); + let profile = serde_json::to_value(&profile).unwrap(); + + let count_in = + |stack: &[u64], range: &Range| stack.iter().filter(|a| range.contains(a)).count(); + let stacks = sample_stacks(&profile); + let a_stacks: Vec<_> = stacks + .iter() + .filter(|stack| stack.first().is_some_and(|a| functions.a_leaf.contains(a))) + .collect(); + let b_stacks: Vec<_> = stacks + .iter() + .filter(|stack| stack.first().is_some_and(|a| functions.b_leaf.contains(a))) + .collect(); + assert!( + !a_stacks.is_empty() && !b_stacks.is_empty(), + "fixture has samples in both leaves" + ); + + let spliced_b = b_stacks + .iter() + .filter(|s| count_in(s, &functions.a_recurse) > 0) + .count(); + let spliced_a = a_stacks + .iter() + .filter(|s| count_in(s, &functions.b_recurse) > 0) + .count(); + assert_eq!( + (spliced_a, spliced_b), + (0, 0), + "spliced stacks out of {} phase A and {} phase B samples", + a_stacks.len(), + b_stacks.len() + ); + + // The full phase A chain is deeper than one stack copy, so it can only be + // unwound completely through cached words of earlier samples. + let complete_a = a_stacks + .iter() + .filter(|s| count_in(s, &functions.a_recurse) == FULL_A_DEPTH) + .count(); + assert!( + complete_a > 0, + "no phase A stack was completed past the stack copy" + ); +} diff --git a/tools/dump_table/src/lib.rs b/tools/dump_table/src/lib.rs index f54f8abce..9258f067b 100644 --- a/tools/dump_table/src/lib.rs +++ b/tools/dump_table/src/lib.rs @@ -219,13 +219,13 @@ impl FileAndPathHelper for Helper { let redirected_path = self.symbol_directory.join(filename); if std::fs::metadata(&redirected_path).is_ok() { // redirected_path exists! - eprintln!("Redirecting {:?} to {:?}", &path, &redirected_path); + eprintln!("Redirecting {:?} to {:?}", path, redirected_path); path = redirected_path; } } } - eprintln!("Reading file {:?}", &path); + eprintln!("Reading file {:?}", path); let file = File::open(&path)?; let mmap = unsafe { memmap2::MmapOptions::new().map(&file)? }; Ok(mmap_to_file_contents(mmap)) diff --git a/tools/query_api/src/lib.rs b/tools/query_api/src/lib.rs index d9b9c3e9c..2eb08dc2c 100644 --- a/tools/query_api/src/lib.rs +++ b/tools/query_api/src/lib.rs @@ -121,13 +121,13 @@ impl FileAndPathHelper for Helper { let redirected_path = self.symbol_directory.join(filename); if std::fs::metadata(&redirected_path).is_ok() { // redirected_path exists! - eprintln!("Redirecting {:?} to {:?}", &path, &redirected_path); + eprintln!("Redirecting {:?} to {:?}", path, redirected_path); path = redirected_path; } } } - eprintln!("Reading file {:?}", &path); + eprintln!("Reading file {:?}", path); let file = File::open(&path)?; Ok(unsafe { memmap2::MmapOptions::new().map(&file)? }) }) diff --git a/tools/stack-cache-repro/Cargo.lock b/tools/stack-cache-repro/Cargo.lock new file mode 100644 index 000000000..a4ac7e1ed --- /dev/null +++ b/tools/stack-cache-repro/Cargo.lock @@ -0,0 +1,7 @@ +# This file is automatically @generated by Cargo. +# It is not intended for manual editing. +version = 4 + +[[package]] +name = "stack-cache-repro" +version = "0.1.0" diff --git a/tools/stack-cache-repro/Cargo.toml b/tools/stack-cache-repro/Cargo.toml new file mode 100644 index 000000000..405cb1bc9 --- /dev/null +++ b/tools/stack-cache-repro/Cargo.toml @@ -0,0 +1,11 @@ +[package] +name = "stack-cache-repro" +version = "0.1.0" +edition = "2021" +publish = false + +# Standalone: profiled by the replay script, not part of the samply workspace. +[workspace] + +[profile.release] +debug = 1 diff --git a/tools/stack-cache-repro/README.md b/tools/stack-cache-repro/README.md new file mode 100644 index 000000000..bbb47537c --- /dev/null +++ b/tools/stack-cache-repro/README.md @@ -0,0 +1,36 @@ +# Stack-cache reproduction + +This workload runs two phases. Phase A recurses through `a_recurse` and spends +work at every depth; phase B uses the same deep layout through `b_recurse` but +spends work only in `b_leaf`. The stack is deeper than samply's 32,000-byte +user-stack capture, making stale cached words observable as impossible +cross-phase ancestry. + +From this directory, run: + +```sh +./replay.sh [path/to/samply ...] +``` + +With no arguments, `samply` is taken from `PATH`. The script builds the +workload, records one `perf.data`, imports it with each requested samply +binary, and prints per-phase statistics. Set `RERECORD=1` to replace an +existing recording; set `OUT_DIR` to choose another output directory. + +The table reports total samples containing each phase's leaf, impossible +**stitched** samples containing the other phase's recursive function, +**truncated** samples that do not reach `main`, and **complete** samples (the +remainder). The script exits non-zero if any stitched sample is found. + +The workload uses x86_64 inline assembly, so it builds on x86_64 only. + +For ordinary users, recording only needs `perf_event_paranoid <= 2` and the +`cycles:u` event used by the script. + +The workload takes an optional phase duration in milliseconds (default 3500). + +`make-fixture.sh` records a short run into `fixtures/other/stack-read-cache/`. +`samply/tests/stack_read_cache_replay.rs` replays that recording through +`samply import` in `cargo test`, so the check needs no perf permissions. It +fails if any stack is spliced from an earlier sample, or if no phase A stack +is completed past the stack copy. diff --git a/tools/stack-cache-repro/make-fixture.sh b/tools/stack-cache-repro/make-fixture.sh new file mode 100755 index 000000000..a8e346c3e --- /dev/null +++ b/tools/stack-cache-repro/make-fixture.sh @@ -0,0 +1,38 @@ +#!/usr/bin/env bash +# Regenerate fixtures/other/stack-read-cache/, used by +# samply/tests/stack_read_cache_replay.rs. +# +# Builds the workload as a static x86_64 binary (so the replay doesn't depend +# on the host's libc), records 400 ms per phase with DWARF call graphs, and +# stores both gzipped. The binary is recorded from a fixed path; the test +# finds it by file name in a lookup dir instead. +# +# Needs a static glibc: set GLIBC_STATIC_LIB to a directory with libc.a +# (on NixOS: $(nix-build '' -A glibc.static --no-out-link)/lib). +set -euo pipefail + +script_dir=$(CDPATH='' cd -- "$(dirname -- "${BASH_SOURCE[0]}")" && pwd) +fixture_dir=${FIXTURE_DIR:-$script_dir/../../fixtures/other/stack-read-cache} +record_dir=/tmp/samply-stack-cache-fixture +target=x86_64-unknown-linux-gnu + +rustflags="-C target-feature=+crt-static" +if [[ -n ${GLIBC_STATIC_LIB:-} ]]; then + rustflags+=" -L native=$GLIBC_STATIC_LIB" +fi +RUSTFLAGS=$rustflags cargo build --release --target "$target" --manifest-path "$script_dir/Cargo.toml" + +# The recording path ends up in perf.data, so it is fixed; refuse to reuse it. +if [[ -e $record_dir ]]; then + echo "$record_dir already exists; move it away first" >&2 + exit 1 +fi +mkdir -p "$record_dir" "$fixture_dir" +cp "$script_dir/target/$target/release/stack-cache-repro" "$record_dir/stack-cache-repro" +strip --strip-debug "$record_dir/stack-cache-repro" +(cd "$record_dir" && perf record -e cycles:u --call-graph dwarf,32000 -F 199 -m 16 \ + -o stack-cache-repro.perf.data -- ./stack-cache-repro 400) + +gzip -9 -c "$record_dir/stack-cache-repro" > "$fixture_dir/stack-cache-repro.gz" +gzip -9 -c "$record_dir/stack-cache-repro.perf.data" > "$fixture_dir/stack-cache-repro.perf.data.gz" +trash-put "$record_dir" diff --git a/tools/stack-cache-repro/replay.sh b/tools/stack-cache-repro/replay.sh new file mode 100755 index 000000000..582c69b71 --- /dev/null +++ b/tools/stack-cache-repro/replay.sh @@ -0,0 +1,39 @@ +#!/usr/bin/env bash +set -euo pipefail + +SCRIPT_DIR=$(CDPATH='' cd -- "$(dirname -- "${BASH_SOURCE[0]}")" && pwd) +CRATE_MANIFEST="$SCRIPT_DIR/Cargo.toml" +WORKLOAD="$SCRIPT_DIR/target/release/stack-cache-repro" +OUT_DIR=${OUT_DIR:-"$SCRIPT_DIR/target/stack-cache-repro"} +PERF_DATA="$OUT_DIR/repro.perf.data" + +mkdir -p "$OUT_DIR" +cargo build --release --manifest-path "$CRATE_MANIFEST" + +if [[ ! -e "$PERF_DATA" || ${RERECORD:-0} == 1 ]]; then + perf record \ + -e cycles:u \ + --call-graph dwarf,32000 \ + -F 499 \ + -m 16 \ + -o "$PERF_DATA" \ + -- "$WORKLOAD" +fi + +if (($# == 0)); then + set -- samply +fi + +outputs=() +for samply in "$@"; do + name=$(basename -- "$samply") + output="$OUT_DIR/$name.json.gz" + "$samply" import \ + --presymbolicate \ + --save-only \ + -o "$output" \ + "$PERF_DATA" + outputs+=("$output") +done + +"$SCRIPT_DIR/stats.py" "${outputs[@]}" diff --git a/tools/stack-cache-repro/src/main.rs b/tools/stack-cache-repro/src/main.rs new file mode 100644 index 000000000..99df0130a --- /dev/null +++ b/tools/stack-cache-repro/src/main.rs @@ -0,0 +1,167 @@ +use std::time::{Duration, Instant}; + +#[repr(C)] +struct Timespec { + tv_sec: i64, + tv_nsec: i64, +} + +extern "C" { + fn clock_gettime(clk_id: i32, tp: *mut Timespec) -> i32; +} + +fn monotonic_ns() -> u64 { + let mut ts = Timespec { + tv_sec: 0, + tv_nsec: 0, + }; + unsafe { + clock_gettime(1, &mut ts); // 1 = CLOCK_MONOTONIC + } + (ts.tv_sec as u64) * 1_000_000_000 + (ts.tv_nsec as u64) +} + +const FRAME_SIZE: usize = 2048; +const MAX_DEPTH: usize = 35; // 35 * 2048 = 71680 bytes (> 32000 bytes) +// Phase A works long enough at every depth that one descent is sampled +// several times on the way down: its snapshots then chain from the leaf up to +// `main` without the thread returning in between, so the stack read cache can +// complete deep phase A stacks even though it retires returned snapshots. +const WORK_PER_LEVEL_A: u64 = 2_000_000; +const WORK_IN_LEAF_A: u64 = 20_000_000; +const WORK_IN_LEAF_B: u64 = 1_000_000; + +#[inline(never)] +fn a_leaf() { + let mut x: u64 = 0x1111_2222; + for i in 0..WORK_IN_LEAF_A { + unsafe { + std::arch::asm!( + "add {0}, {1}", + "xor {0}, 0x55", + inout(reg) x, + in(reg) i, + options(nostack, nomem), + ); + } + } + std::hint::black_box(x); +} + +#[inline(never)] +fn a_recurse(depth: usize, max_depth: usize) { + let mut buf = [0xAAu8; FRAME_SIZE]; + buf[0] = depth as u8; + buf[FRAME_SIZE - 1] = (depth & 0xff) as u8; + unsafe { + std::arch::asm!("/* a_buf {0} */", in(reg) buf.as_ptr(), options(nostack)); + } + + // Spend time at every level in Phase A to populate stack_read_cache for all depths + let mut x: u64 = 0x1234; + for i in 0..WORK_PER_LEVEL_A { + unsafe { + std::arch::asm!( + "add {0}, {1}", + inout(reg) x, + in(reg) i, + options(nostack, nomem), + ); + } + } + + if depth < max_depth { + a_recurse(depth + 1, max_depth); + } else { + a_leaf(); + } +} + +#[inline(never)] +fn a_root(max_depth: usize) { + unsafe { + std::arch::asm!("/* a_root */", options(nostack)); + } + a_recurse(0, max_depth); +} + +#[inline(never)] +fn b_leaf() { + let mut x: u64 = 0x3333_4444; + for i in 0..WORK_IN_LEAF_B { + unsafe { + std::arch::asm!( + "add {0}, {1}", + "xor {0}, 0xaa", + inout(reg) x, + in(reg) i, + options(nostack, nomem), + ); + } + } + std::hint::black_box(x); +} + +#[inline(never)] +fn b_recurse(depth: usize, max_depth: usize) { + let mut buf = [0xBBu8; FRAME_SIZE]; + buf[0] = depth as u8; + buf[FRAME_SIZE - 1] = (depth & 0xff) as u8; + unsafe { + std::arch::asm!("/* b_buf {0} */", in(reg) buf.as_ptr(), options(nostack)); + } + + // Phase B does negligible work during recursion traversal, + // so no samples land at shallow depths to overwrite the cache! + if depth < max_depth { + b_recurse(depth + 1, max_depth); + } else { + b_leaf(); + } +} + +#[inline(never)] +fn b_root(max_depth: usize) { + unsafe { + std::arch::asm!("/* b_root */", options(nostack)); + } + b_recurse(0, max_depth); +} + +#[inline(never)] +fn run_phase_a(duration: Duration) { + let start = Instant::now(); + while start.elapsed() < duration { + a_root(MAX_DEPTH); + } +} + +#[inline(never)] +fn run_phase_b(duration: Duration) { + let start = Instant::now(); + while start.elapsed() < duration { + b_root(MAX_DEPTH); + } +} + +fn main() { + // Optional first argument: milliseconds per phase (default 3500). + let phase_ms = std::env::args() + .nth(1) + .map_or(3500, |ms| ms.parse().expect("phase duration in ms")); + let phase_duration = Duration::from_millis(phase_ms); + + let t0 = monotonic_ns(); + println!("PHASE_A_START: {t0}"); + run_phase_a(phase_duration); + let t1 = monotonic_ns(); + println!("PHASE_A_END: {t1}"); + + let t2 = monotonic_ns(); + println!("PHASE_B_START: {t2}"); + run_phase_b(phase_duration); + let t3 = monotonic_ns(); + println!("PHASE_B_END: {t3}"); + + println!("DONE"); +} diff --git a/tools/stack-cache-repro/stats.py b/tools/stack-cache-repro/stats.py new file mode 100755 index 000000000..c93455ca4 --- /dev/null +++ b/tools/stack-cache-repro/stats.py @@ -0,0 +1,74 @@ +#!/usr/bin/env python3 +"""Count stitched and truncated stacks in profiles of stack-cache-repro. + +Usage: stats.py ... + +Phase A spins in `a_leaf` under `a_recurse`, phase B spins in `b_leaf` under +`b_recurse`. A `b_leaf` stack containing `a_recurse` (or the reverse) is +impossible, so it is counted as stitched. A stack not reaching `main` is +truncated. Exits with status 1 if any profile contains a stitched stack. +""" +import gzip +import json +import os +import sys + +LEAVES = { + "a": ("stack_cache_repro::a_leaf", "stack_cache_repro::b_recurse"), + "b": ("stack_cache_repro::b_leaf", "stack_cache_repro::a_recurse"), +} +MAIN = "stack_cache_repro::main" + + +def stacks(path): + """Yield the set of function names on each sampled stack.""" + with gzip.open(path, "rt") as f: + profile = json.load(f) + shared = profile["shared"] + names = shared["stringArray"] + func_name = shared["funcTable"]["name"] + frame_func = shared["frameTable"]["func"] + prefix = shared["stackTable"]["prefix"] + stack_frame = shared["stackTable"]["frame"] + for thread in profile["threads"]: + for stack in thread["samples"]["stack"]: + chain = set() + while stack is not None: + chain.add(names[func_name[frame_func[stack_frame[stack]]]]) + stack = prefix[stack] + yield chain + + +def count(path): + """Return {phase: [total, stitched, truncated]} for one profile.""" + counts = {phase: [0, 0, 0] for phase in LEAVES} + for chain in stacks(path): + for phase, (leaf, foreign) in LEAVES.items(): + if leaf not in chain: + continue + counts[phase][0] += 1 + if foreign in chain: + counts[phase][1] += 1 + elif MAIN not in chain: + counts[phase][2] += 1 + return counts + + +def main(paths): + if not paths: + sys.exit(__doc__) + print(f"{'profile':40} {'phase':5} {'total':>6} {'stitched':>8} {'truncated':>9} {'complete':>8}") + any_stitched = False + for path in paths: + for phase, (total, stitched, truncated) in count(path).items(): + complete = total - stitched - truncated + any_stitched |= stitched > 0 + print(f"{os.path.basename(path):40} {phase:5} {total:6} {stitched:8} {truncated:9} {complete:8}") + if any_stitched: + print("FAIL: found stitched stacks", file=sys.stderr) + return 1 + return 0 + + +if __name__ == "__main__": + sys.exit(main(sys.argv[1:]))