From e41c412ecee32a2eedbbbc9675b7e46fdf42e73a Mon Sep 17 00:00:00 2001 From: Tobias Koppers Date: Sat, 30 Mar 2024 11:05:55 +0100 Subject: [PATCH] add heaptrack trace format (#7849) ### Description allow to load heaptrack files with the turbo-trace-viewer ### Testing Instructions Closes PACK-2848 --- crates/turbopack-trace-server/Cargo.toml | 2 + .../turbopack-trace-server/src/bottom_up.rs | 8 +- .../src/reader/heaptrack.rs | 511 ++++++++++++++++++ .../turbopack-trace-server/src/reader/mod.rs | 199 +++++-- .../src/self_time_tree.rs | 4 + crates/turbopack-trace-server/src/span.rs | 69 ++- .../src/span_bottom_up_ref.rs | 15 +- .../src/span_graph_ref.rs | 14 +- crates/turbopack-trace-server/src/span_ref.rs | 85 +-- crates/turbopack-trace-server/src/store.rs | 90 ++- crates/turbopack-trace-server/src/viewer.rs | 37 +- 11 files changed, 880 insertions(+), 154 deletions(-) create mode 100644 crates/turbopack-trace-server/src/reader/heaptrack.rs diff --git a/crates/turbopack-trace-server/Cargo.toml b/crates/turbopack-trace-server/Cargo.toml index e3ea2ed20f47f..c1e2485de599d 100644 --- a/crates/turbopack-trace-server/Cargo.toml +++ b/crates/turbopack-trace-server/Cargo.toml @@ -21,7 +21,9 @@ intervaltree = "0.2.7" itertools = { workspace = true } owo-colors = { workspace = true } postcard = { workspace = true } +rustc-demangle = "0.1" serde = { workspace = true } serde_json = { workspace = true } turbopack-trace-utils = { workspace = true } websocket = { version = "0.27.0", features = ["sync"] } +zstd = { version = "0.13.0" } diff --git a/crates/turbopack-trace-server/src/bottom_up.rs b/crates/turbopack-trace-server/src/bottom_up.rs index 2a20e94414cda..b43f70bf44e08 100644 --- a/crates/turbopack-trace-server/src/bottom_up.rs +++ b/crates/turbopack-trace-server/src/bottom_up.rs @@ -1,4 +1,4 @@ -use std::{collections::HashMap, sync::Arc}; +use std::{collections::HashMap, env, sync::Arc}; use either::Either; @@ -38,6 +38,10 @@ impl SpanBottomUpBuilder { pub fn build_bottom_up_graph<'a>( spans: impl IntoIterator>, ) -> Vec> { + let max_depth = env::var("BOTTOM_UP_DEPTH") + .ok() + .and_then(|s| s.parse().ok()) + .unwrap_or(usize::MAX); let mut roots = HashMap::new(); let mut current_iterators = vec![Either::Left( spans.into_iter().flat_map(|span| span.children()), @@ -54,7 +58,7 @@ pub fn build_bottom_up_graph<'a>( .or_insert_with(|| (name.to_string(), SpanBottomUpBuilder::new(child.index()))); bottom_up.self_spans.push(child.index()); let mut prev = None; - for &(name, example_span) in current_path.iter().rev() { + for &(name, example_span) in current_path.iter().rev().take(max_depth) { if prev == Some(name) { continue; } diff --git a/crates/turbopack-trace-server/src/reader/heaptrack.rs b/crates/turbopack-trace-server/src/reader/heaptrack.rs new file mode 100644 index 0000000000000..4cc79feb583e8 --- /dev/null +++ b/crates/turbopack-trace-server/src/reader/heaptrack.rs @@ -0,0 +1,511 @@ +use std::{ + collections::{HashMap, HashSet}, + env, + str::from_utf8, + sync::Arc, +}; + +use anyhow::{bail, Context, Result}; +use indexmap::{indexmap, map::Entry, IndexMap}; +use rustc_demangle::demangle; + +use super::TraceFormat; +use crate::{span::SpanIndex, store_container::StoreContainer}; + +#[derive(Debug, Clone, Copy)] +struct TraceNode { + ip_index: usize, + parent_index: usize, +} + +impl TraceNode { + pub fn read(s: &mut &[u8]) -> Result { + Ok(Self { + ip_index: read_hex_index(s)?, + parent_index: read_hex_index(s)?, + }) + } +} + +#[derive(Debug, Hash, PartialEq, Eq)] +struct InstructionPointer { + module_index: usize, + frames: Vec, + custom_name: Option, +} + +impl InstructionPointer { + pub fn read(s: &mut &[u8]) -> Result { + let _ip = read_hex(s)?; + Ok(Self { + module_index: read_hex_index(s)?, + frames: read_all(s, Frame::read)?, + custom_name: None, + }) + } +} + +#[derive(Debug, Hash, PartialEq, Eq)] +struct Frame { + function_index: usize, + file_index: usize, + line: u64, +} + +impl Frame { + pub fn read(s: &mut &[u8]) -> Result { + Ok(Self { + function_index: read_hex_index(s)?, + file_index: read_hex_index(s)?, + line: read_hex(s)?, + }) + } +} + +#[derive(Debug)] +struct AllocationInfo { + size: u64, + trace_index: usize, +} + +impl AllocationInfo { + pub fn read(s: &mut &[u8]) -> Result { + Ok(Self { + size: read_hex(s)?, + trace_index: read_hex_index(s)?, + }) + } +} + +struct InstructionPointerExtraInfo { + first_trace_of_ip: Option, +} + +#[derive(Clone, Copy)] +struct TraceData { + span_index: SpanIndex, + ip_index: usize, + parent_trace_index: usize, +} + +pub struct HeaptrackFormat { + store: Arc, + version: u32, + last_timestamp: u64, + strings: Vec, + traces: Vec, + ip_parent_map: HashMap<(usize, SpanIndex), usize>, + trace_instruction_pointers: Vec, + instruction_pointers: IndexMap, + allocations: Vec, + spans: usize, + collapse_crates: HashSet, + expand_crates: HashSet, + expand_recursion: bool, +} + +const RECURSION_IP: usize = 1; + +impl HeaptrackFormat { + pub fn new(store: Arc) -> Self { + Self { + store, + version: 0, + last_timestamp: 0, + strings: vec!["".to_string()], + traces: vec![TraceData { + span_index: SpanIndex::new(usize::MAX).unwrap(), + ip_index: 0, + parent_trace_index: 0, + }], + ip_parent_map: HashMap::new(), + instruction_pointers: indexmap! { + InstructionPointer { + module_index: 0, + frames: Vec::new(), + custom_name: Some("root".to_string()) + } => InstructionPointerExtraInfo { + first_trace_of_ip: None, + }, + InstructionPointer { + module_index: 0, + frames: Vec::new(), + custom_name: Some("recursion".to_string()) + } => InstructionPointerExtraInfo { + first_trace_of_ip: None, + } + }, + trace_instruction_pointers: vec![0], + allocations: vec![AllocationInfo { + size: 0, + trace_index: 0, + }], + spans: 0, + collapse_crates: env::var("COLLAPSE_CRATES") + .unwrap_or_default() + .split(',') + .map(|s| s.to_string()) + .collect(), + expand_crates: env::var("EXPAND_CRATES") + .unwrap_or_default() + .split(',') + .filter(|s| !s.is_empty()) + .map(|s| s.to_string()) + .collect(), + expand_recursion: env::var("EXPAND_RECURSION").is_ok(), + } + } +} + +impl TraceFormat for HeaptrackFormat { + fn stats(&self) -> String { + format!( + "{} spans, {} strings, {} ips, {} traces, {} allocations", + self.spans, + self.strings.len() - 1, + self.trace_instruction_pointers.len() - 1, + self.traces.len() - 1, + self.allocations.len() - 1 + ) + } + + fn read(&mut self, mut buffer: &[u8]) -> anyhow::Result { + let mut bytes_read = 0; + let mut outdated_spans = HashSet::new(); + let mut store = self.store.write(); + 'outer: loop { + let Some(line_end) = buffer.iter().position(|b| *b == b'\n') else { + break; + }; + let full_line = &buffer[..line_end]; + buffer = &buffer[line_end + 1..]; + bytes_read += full_line.len() + 1; + + if full_line.is_empty() { + continue; + } + let ty = full_line[0]; + let mut line = &full_line[2..]; + + // For format see https://github.com/KDE/heaptrack/blob/b000a73e0bf0a275ec41eef0fe34701a0942cdd8/src/analyze/accumulatedtracedata.cpp#L151 + match ty { + b'v' => { + let _ = read_hex(&mut line)?; + self.version = read_hex(&mut line)? as u32; + if self.version != 2 && self.version != 3 { + bail!("Unsupported version: {} (expected 2 or 3)", self.version); + } + } + b's' => { + let string = if self.version == 2 { + String::from_utf8(line.to_vec())? + } else { + read_sized_string(&mut line)? + }; + self.strings.push(demangle(&string).to_string()); + } + b't' => { + let TraceNode { + ip_index, + parent_index, + } = TraceNode::read(&mut line)?; + let ip_index = *self + .trace_instruction_pointers + .get(ip_index) + .context("ip not found")?; + let (ip, ip_info) = self + .instruction_pointers + .get_index(ip_index) + .context("ip not found")?; + // Try to fix cut-off traces + if parent_index == 0 { + if let Some(trace_index) = ip_info.first_trace_of_ip { + let trace = self.traces.get(trace_index).context("trace not found")?; + self.traces.push(*trace); + continue; + } + } + // Lookup parent + let parent = if parent_index > 0 { + let parent = *self.traces.get(parent_index).context("parent not found")?; + // Check if we have an duplicate (can only happen due to cut-off traces) + if let Some(trace_index) = + self.ip_parent_map.get(&(ip_index, parent.span_index)) + { + let trace = self.traces.get(*trace_index).context("trace not found")?; + self.traces.push(*trace); + continue; + } + // Check if we repeat parent frame + if parent.ip_index == ip_index { + self.traces.push(parent); + continue; + } + if !self.expand_recursion { + // Check for recursion + let mut current = parent.parent_trace_index; + while current > 0 { + let current_parent = + self.traces.get(current).context("parent not found")?; + current = current_parent.parent_trace_index; + if current_parent.ip_index == ip_index { + if parent.ip_index == RECURSION_IP { + // Parent is recursion node, do nothing + self.traces.push(parent); + } else if let Some(trace_index) = + self.ip_parent_map.get(&(RECURSION_IP, parent.span_index)) + { + // There is already one recursion node, reuse it + let trace = self + .traces + .get(*trace_index) + .context("trace not found")?; + self.traces.push(*trace); + } else { + // create a new recursion node + let span_index = store.add_span( + Some(parent.span_index), + self.last_timestamp, + "".to_string(), + "recursion".to_string(), + Vec::new(), + &mut outdated_spans, + ); + store.complete_span(span_index); + let index = self.traces.len(); + self.traces.push(TraceData { + ip_index: RECURSION_IP, + parent_trace_index: parent_index, + span_index, + }); + self.ip_parent_map + .insert((RECURSION_IP, parent.span_index), index); + } + continue 'outer; + } + } + } + Some(parent.span_index) + } else { + None + }; + let InstructionPointer { + module_index, + frames, + custom_name, + } = ip; + let module = self + .strings + .get(*module_index) + .context("module not found")?; + let name = if let Some(name) = custom_name.as_ref() { + name.to_string() + } else if let Some(first_frame) = frames.first() { + let file = self + .strings + .get(first_frame.file_index) + .context("file not found")?; + let function = self + .strings + .get(first_frame.function_index) + .context("function not found")?; + format!("{} @ {file}:{}", function, first_frame.line) + } else { + "unknown".to_string() + }; + let mut args = Vec::new(); + for Frame { + function_index, + file_index, + line, + } in frames.iter() + { + let file = self.strings.get(*file_index).context("file not found")?; + let function = self + .strings + .get(*function_index) + .context("function not found")?; + args.push(( + "location".to_string(), + format!("{} @ {file}:{line}", function), + )); + } + + let span_index = store.add_span( + parent, + self.last_timestamp, + module.to_string(), + name, + args, + &mut outdated_spans, + ); + store.complete_span(span_index); + self.spans += 1; + let index = self.traces.len(); + self.traces.push(TraceData { + span_index, + ip_index, + parent_trace_index: parent_index, + }); + self.instruction_pointers + .get_index_mut(ip_index) + .unwrap() + .1 + .first_trace_of_ip + .get_or_insert(index); + if let Some(parent) = parent { + self.ip_parent_map.insert((ip_index, parent), index); + } + } + b'i' => { + let mut ip = InstructionPointer::read(&mut line)?; + if let Some(frame) = ip.frames.first() { + if let Some(function) = self.strings.get(frame.function_index) { + let crate_name = function + .strip_prefix('<') + .unwrap_or(function) + .split("::") + .next() + .unwrap() + .split('[') + .next() + .unwrap(); + if self.collapse_crates.contains(crate_name) + || !self.expand_crates.is_empty() + && !self.expand_crates.contains(crate_name) + { + ip.frames.clear(); + ip.custom_name = Some(crate_name.to_string()); + } + } + } + match self.instruction_pointers.entry(ip) { + Entry::Occupied(e) => { + self.trace_instruction_pointers.push(e.index()); + } + Entry::Vacant(e) => { + self.trace_instruction_pointers.push(e.index()); + e.insert(InstructionPointerExtraInfo { + first_trace_of_ip: None, + }); + } + } + } + b'#' => { + // comment + } + b'X' => { + let line = from_utf8(line)?; + println!("Debuggee: {line}"); + } + b'c' => { + // timestamp + let timestamp = read_hex(&mut line)?; + self.last_timestamp = timestamp; + } + b'a' => { + // allocation info + let info = AllocationInfo::read(&mut line)?; + self.allocations.push(info); + } + b'+' => { + // allocation + let index = read_hex_index(&mut line)?; + let AllocationInfo { size, trace_index } = self + .allocations + .get(index) + .context("allocation not found")?; + if *trace_index > 0 { + let TraceData { span_index, .. } = + self.traces.get(*trace_index).context("trace not found")?; + store.add_allocation(*span_index, *size, 1, &mut outdated_spans); + } + } + b'-' => { + // deallocation + let index = read_hex_index(&mut line)?; + let AllocationInfo { size, trace_index } = self + .allocations + .get(index) + .context("allocation not found")?; + if *trace_index > 0 { + let TraceData { span_index, .. } = + self.traces.get(*trace_index).context("trace not found")?; + store.add_deallocation(*span_index, *size, 1, &mut outdated_spans); + } + } + b'R' => { + // RSS timestamp + } + b'A' => { + // attached + // ignore + } + b'S' => { + // embedded suppression + // ignore + } + b'I' => { + // System info + // ignore + } + _ => { + let line = from_utf8(line)?; + println!("{} {line}", ty as char) + } + } + } + store.invalidate_outdated_spans(&outdated_spans); + Ok(bytes_read) + } +} + +fn read_hex_index(s: &mut &[u8]) -> anyhow::Result { + Ok(read_hex(s)? as usize) +} + +fn read_hex(s: &mut &[u8]) -> anyhow::Result { + let mut n: u64 = 0; + loop { + if let Some(c) = s.first() { + match c { + b'0'..=b'9' => { + n *= 16; + n += (*c - b'0') as u64; + } + b'a'..=b'f' => { + n *= 16; + n += (*c - b'a' + 10) as u64; + } + b' ' => { + *s = &s[1..]; + return Ok(n); + } + _ => { + bail!("Expected hex char"); + } + } + *s = &s[1..]; + } else { + return Ok(n); + } + } +} + +fn read_sized_string(s: &mut &[u8]) -> anyhow::Result { + let size = read_hex(s)? as usize; + let str = &s[..size]; + *s = &s[size..]; + Ok(String::from_utf8(str.to_vec())?) +} + +fn read_all( + s: &mut &[u8], + f: impl Fn(&mut &[u8]) -> anyhow::Result, +) -> anyhow::Result> { + let mut res = Vec::new(); + while !s.is_empty() { + res.push(f(s)?); + } + Ok(res) +} diff --git a/crates/turbopack-trace-server/src/reader/mod.rs b/crates/turbopack-trace-server/src/reader/mod.rs index d76c7aad162a4..765976b3e4410 100644 --- a/crates/turbopack-trace-server/src/reader/mod.rs +++ b/crates/turbopack-trace-server/src/reader/mod.rs @@ -1,9 +1,11 @@ +mod heaptrack; mod nextjs; mod turbopack; use std::{ + env, fs::File, - io::{Read, Seek, SeekFrom}, + io::{self, BufReader, Read, Seek, SeekFrom}, path::PathBuf, sync::Arc, thread::{self, JoinHandle}, @@ -13,12 +15,49 @@ use std::{ use anyhow::Result; use crate::{ - reader::{nextjs::NextJsFormat, turbopack::TurbopackFormat}, + reader::{heaptrack::HeaptrackFormat, nextjs::NextJsFormat, turbopack::TurbopackFormat}, store_container::StoreContainer, }; trait TraceFormat { fn read(&mut self, buffer: &[u8]) -> Result; + fn stats(&self) -> String { + String::new() + } +} + +#[derive(Default)] +enum TraceFile { + Raw(File), + Zstd(zstd::Decoder<'static, BufReader>), + #[default] + Unloaded, +} + +impl TraceFile { + fn read(&mut self, buffer: &mut [u8]) -> io::Result { + match self { + Self::Raw(file) => file.read(buffer), + Self::Zstd(decoder) => decoder.read(buffer), + Self::Unloaded => unreachable!(), + } + } + + fn stream_position(&mut self) -> io::Result { + match self { + Self::Raw(file) => file.stream_position(), + Self::Zstd(decoder) => decoder.get_mut().stream_position(), + Self::Unloaded => unreachable!(), + } + } + + fn seek(&mut self, pos: SeekFrom) -> io::Result { + match self { + Self::Raw(file) => file.seek(pos), + Self::Zstd(decoder) => decoder.get_mut().seek(pos), + Self::Unloaded => unreachable!(), + } + } } pub struct TraceReader { @@ -39,11 +78,26 @@ impl TraceReader { } } + fn trace_file_from_file(&self, file: File) -> io::Result { + Ok(if self.path.to_string_lossy().ends_with(".zst") { + TraceFile::Zstd(zstd::Decoder::new(file)?) + } else { + TraceFile::Raw(file) + }) + } + fn try_read(&mut self) -> bool { let Ok(mut file) = File::open(&self.path) else { return false; }; println!("Trace file opened"); + let stop_at = env::var("STOP_AT") + .unwrap_or_default() + .parse() + .map_or(u64::MAX, |v: u64| v * 1024 * 1024); + if stop_at != u64::MAX { + println!("Will stop reading file at {} MB", stop_at / 1024 / 1024) + } { let mut store = self.store.write(); @@ -52,10 +106,11 @@ impl TraceReader { let mut format: Option> = None; + let mut current_read = 0; let mut initial_read = { if let Ok(pos) = file.seek(SeekFrom::End(0)) { if pos > 100 * 1024 * 1024 { - Some((0, pos)) + Some(pos) } else { None } @@ -66,6 +121,13 @@ impl TraceReader { if file.seek(SeekFrom::Start(0)).is_err() { return false; } + let mut file = match self.trace_file_from_file(file) { + Ok(f) => f, + Err(err) => { + println!("Error creating zstd decoder: {err}"); + return false; + } + }; let mut buffer = Vec::new(); let mut index = 0; @@ -75,33 +137,8 @@ impl TraceReader { match file.read(&mut chunk) { Ok(bytes_read) => { if bytes_read == 0 { - let Ok(pos) = file.stream_position() else { - return true; - }; - drop(file); - if let Some((_, total)) = initial_read.take() { - println!("Initial read completed ({} MB)", total / (1024 * 1024),); - } - // No more data to read, sleep for a while to wait for more data - thread::sleep(Duration::from_millis(100)); - let Ok(file_again) = File::open(&self.path) else { - return true; - }; - file = file_again; - let Ok(end) = file.seek(SeekFrom::End(0)) else { - return true; - }; - if end < pos { - return true; - } else if end != pos { - // Seek to the same position. This will fail when the file was - // truncated. - let Ok(new_pos) = file.seek(SeekFrom::Start(pos)) else { - return true; - }; - if new_pos != pos { - return true; - } + if let Some(value) = self.wait_for_more_data(&mut file, &mut initial_read) { + return value; } } else { // If we have partially consumed some data, and we are at buffer capacity, @@ -117,6 +154,8 @@ impl TraceReader { format = Some(Box::new(TurbopackFormat::new(self.store.clone()))); } else if buffer.starts_with(b"[{\"name\"") { format = Some(Box::new(NextJsFormat::new(self.store.clone()))); + } else if buffer.starts_with(b"v ") { + format = Some(Box::new(HeaptrackFormat::new(self.store.clone()))) } else { // Fallback to the format without magic bytes // TODO Remove this after a while and show an error instead @@ -136,28 +175,100 @@ impl TraceReader { if self.store.want_to_read() { thread::yield_now(); } - if let Some((current, total)) = &mut initial_read { - let old_mbs = *current / (97 * 1024 * 1024); - *current += bytes_read as u64; - *total = *total.max(current); - let new_mbs = *current / (97 * 1024 * 1024); + let prev_read = current_read; + current_read += bytes_read as u64; + if let Some(total) = &mut initial_read { + let old_mbs = prev_read / (97 * 1024 * 1024); + let new_mbs = current_read / (97 * 1024 * 1024); if old_mbs != new_mbs { - println!( - "{}% read ({}/{} MB)", - *current * 100 / *total, - *current / (1024 * 1024), - *total / (1024 * 1024), - ); + let pos = file.stream_position().unwrap_or(current_read); + *total = (*total).max(pos); + let percentage = pos * 100 / *total; + let read = pos / (1024 * 1024); + let uncompressed = current_read / (1024 * 1024); + let total = *total / (1024 * 1024); + let stats = format.stats(); + print!("{}% read ({}/{} MB)", percentage, read, total); + if uncompressed != read { + print!(" ({} MB uncompressed)", uncompressed); + } + if stats.is_empty() { + println!(); + } else { + println!(" - {}", stats); + } } } + if current_read >= stop_at { + println!( + "Stopped reading file as requested by STOP_AT env var. \ + Waiting for new file..." + ); + self.wait_for_new_file(&mut file); + return true; + } } } } - Err(_) => { - // Error reading file, maybe it was removed - return true; + Err(err) => { + if err.kind() == io::ErrorKind::UnexpectedEof { + if let Some(value) = self.wait_for_more_data(&mut file, &mut initial_read) { + return value; + } + } else { + // Error reading file, maybe it was removed + println!("Error reading trace file: {err:?}"); + return true; + } } } } } + + fn wait_for_more_data( + &mut self, + file: &mut TraceFile, + initial_read: &mut Option, + ) -> Option { + let Ok(pos) = file.stream_position() else { + return Some(true); + }; + if let Some(total) = initial_read.take() { + println!("Initial read completed ({} MB)", total / (1024 * 1024),); + } + thread::sleep(Duration::from_millis(100)); + let Ok(end) = file.seek(SeekFrom::End(0)) else { + return Some(true); + }; + // No more data to read, sleep for a while to wait for more data + if end < pos { + // new file + return Some(true); + } else if end != pos { + // Seek to the same position. This will fail when the file was + // truncated. + let Ok(new_pos) = file.seek(SeekFrom::Start(pos)) else { + return Some(true); + }; + if new_pos != pos { + return Some(true); + } + } + None + } + + fn wait_for_new_file(&self, file: &mut TraceFile) { + let Ok(pos) = file.stream_position() else { + return; + }; + loop { + thread::sleep(Duration::from_millis(1000)); + let Ok(end) = file.seek(SeekFrom::End(0)) else { + return; + }; + if end < pos { + return; + } + } + } } diff --git a/crates/turbopack-trace-server/src/self_time_tree.rs b/crates/turbopack-trace-server/src/self_time_tree.rs index e09c2d20839a4..f795d5b52cdd3 100644 --- a/crates/turbopack-trace-server/src/self_time_tree.rs +++ b/crates/turbopack-trace-server/src/self_time_tree.rs @@ -40,6 +40,10 @@ impl SelfTimeTree { Self::default() } + pub fn len(&self) -> usize { + self.count + } + pub fn insert(&mut self, start: u64, end: u64, item: T) { self.count += 1; if let Some(children) = &mut self.children { diff --git a/crates/turbopack-trace-server/src/span.rs b/crates/turbopack-trace-server/src/span.rs index e441f9a3038b0..93f5be1a73a4f 100644 --- a/crates/turbopack-trace-server/src/span.rs +++ b/crates/turbopack-trace-server/src/span.rs @@ -8,11 +8,9 @@ pub type SpanIndex = NonZeroUsize; pub struct Span { // These values won't change after creation: - pub index: SpanIndex, pub parent: Option, pub depth: u32, pub start: u64, - pub ignore_self_time: bool, pub category: String, pub name: String, pub args: Vec<(String, String)>, @@ -22,35 +20,86 @@ pub struct Span { pub is_complete: bool, // These values are computed automatically: - pub self_end: u64, - pub self_time: u64, pub self_allocations: u64, pub self_allocation_count: u64, pub self_deallocations: u64, pub self_deallocation_count: u64, // These values are computed when accessed (and maybe deleted during writing): - pub end: OnceLock, - pub nice_name: OnceLock<(String, String)>, - pub group_name: OnceLock, pub max_depth: OnceLock, - pub total_time: OnceLock, pub total_allocations: OnceLock, pub total_deallocations: OnceLock, pub total_persistent_allocations: OnceLock, - pub total_allocation_count: OnceLock, pub total_span_count: OnceLock, + pub total_allocation_count: OnceLock, + + // More nested fields, but memory lazily allocated + pub time_data: OnceLock>, + pub extra: OnceLock>, + pub names: OnceLock>, +} + +#[derive(Default)] +pub struct SpanTimeData { + // These values won't change after creation: + pub ignore_self_time: bool, + + // This might change during writing: + pub self_end: u64, + + // These values are computed automatically: + pub self_time: u64, + + // These values are computed when accessed (and maybe deleted during writing): + pub end: OnceLock, + pub total_time: OnceLock, pub corrected_self_time: OnceLock, pub corrected_total_time: OnceLock, +} + +#[derive(Default)] +pub struct SpanExtra { pub graph: OnceLock>, pub bottom_up: OnceLock>>, pub search_index: OnceLock>>, } +#[derive(Default)] +pub struct SpanNames { + // These values are computed when accessed (and maybe deleted during writing): + pub nice_name: OnceLock<(String, String)>, + pub group_name: OnceLock, +} + +impl Span { + pub fn time_data(&self) -> &SpanTimeData { + self.time_data.get_or_init(|| { + Box::new(SpanTimeData { + self_end: self.start, + ignore_self_time: &self.name == "thread", + ..Default::default() + }) + }) + } + + pub fn time_data_mut(&mut self) -> &mut SpanTimeData { + self.time_data(); + self.time_data.get_mut().unwrap() + } + + pub fn extra(&self) -> &SpanExtra { + self.extra.get_or_init(Default::default) + } + + pub fn names(&self) -> &SpanNames { + self.names.get_or_init(Default::default) + } +} + #[derive(Copy, Clone, PartialEq, Eq)] pub enum SpanEvent { SelfTime { start: u64, end: u64 }, - Child { id: SpanIndex }, + Child { index: SpanIndex }, } #[derive(Clone)] diff --git a/crates/turbopack-trace-server/src/span_bottom_up_ref.rs b/crates/turbopack-trace-server/src/span_bottom_up_ref.rs index 47f2f2f172358..431a9858f0df3 100644 --- a/crates/turbopack-trace-server/src/span_bottom_up_ref.rs +++ b/crates/turbopack-trace-server/src/span_bottom_up_ref.rs @@ -24,16 +24,20 @@ impl<'a> SpanBottomUpRef<'a> { } fn first_span(&self) -> SpanRef<'a> { + let index = self.bottom_up.self_spans[0].get(); SpanRef { - span: &self.store.spans[self.bottom_up.self_spans[0].get()], + span: &self.store.spans[index], store: self.store, + index, } } fn example_span(&self) -> SpanRef<'a> { + let index = self.bottom_up.example_span.get(); SpanRef { - span: &self.store.spans[self.bottom_up.example_span.get()], + span: &self.store.spans[index], store: self.store, + index, } } @@ -42,6 +46,7 @@ impl<'a> SpanBottomUpRef<'a> { self.bottom_up.self_spans.iter().map(move |span| SpanRef { span: &store.spans[span.get()], store, + index: span.get(), }) } @@ -78,20 +83,20 @@ impl<'a> SpanBottomUpRef<'a> { .get_or_init(|| { if self.count() == 1 { let _ = self.first_span().graph(); - self.first_span().span.graph.get().unwrap().clone() + self.first_span().extra().graph.get().unwrap().clone() } else { let mut map: IndexMap<&str, (Vec, Vec)> = IndexMap::new(); let mut queue = VecDeque::with_capacity(8); for child in self.spans() { let name = child.group_name(); let (list, recursive_list) = map.entry(name).or_default(); - list.push(child.span.index); + list.push(child.index()); queue.push_back(child); while let Some(child) = queue.pop_front() { for nested_child in child.children() { let nested_name = nested_child.group_name(); if name == nested_name { - recursive_list.push(nested_child.span.index); + recursive_list.push(nested_child.index()); queue.push_back(nested_child); } } diff --git a/crates/turbopack-trace-server/src/span_graph_ref.rs b/crates/turbopack-trace-server/src/span_graph_ref.rs index 8c2640cb52223..0b9be90c71493 100644 --- a/crates/turbopack-trace-server/src/span_graph_ref.rs +++ b/crates/turbopack-trace-server/src/span_graph_ref.rs @@ -22,14 +22,16 @@ pub struct SpanGraphRef<'a> { impl<'a> SpanGraphRef<'a> { pub fn first_span(&self) -> SpanRef<'a> { + let index = self.graph.root_spans[0].get(); SpanRef { - span: &self.store.spans[self.graph.root_spans[0].get()], + span: &self.store.spans[index], store: self.store, + index, } } pub fn id(&self) -> SpanId { - unsafe { SpanId::new_unchecked((self.first_span().span.index.get() << 1) | 1) } + unsafe { SpanId::new_unchecked((self.first_span().index << 1) | 1) } } pub fn nice_name(&self) -> (&str, &str) { @@ -48,6 +50,7 @@ impl<'a> SpanGraphRef<'a> { self.graph.root_spans.iter().map(move |span| SpanRef { span: &self.store.spans[span.get()], store: self.store, + index: span.get(), }) } @@ -59,6 +62,7 @@ impl<'a> SpanGraphRef<'a> { .map(move |span| SpanRef { span: &self.store.spans[span.get()], store: self.store, + index: span.get(), }) } @@ -68,7 +72,7 @@ impl<'a> SpanGraphRef<'a> { .get_or_init(|| { if self.count() == 1 { let _ = self.first_span().graph(); - self.first_span().span.graph.get().unwrap().clone() + self.first_span().extra().graph.get().unwrap().clone() } else { let self_group = self.first_span().group_name(); let mut map: IndexMap<&str, (Vec, Vec)> = IndexMap::new(); @@ -78,13 +82,13 @@ impl<'a> SpanGraphRef<'a> { let name = span.group_name(); if name != self_group { let (list, recusive_list) = map.entry(name).or_default(); - list.push(span.span.index); + list.push(span.index()); queue.push_back(span); while let Some(child) = queue.pop_front() { for nested_child in child.children() { let nested_name = nested_child.group_name(); if name == nested_name { - recusive_list.push(nested_child.span.index); + recusive_list.push(nested_child.index()); queue.push_back(nested_child); } } diff --git a/crates/turbopack-trace-server/src/span_ref.rs b/crates/turbopack-trace-server/src/span_ref.rs index dd6a28a8dee5e..2d155519834b4 100644 --- a/crates/turbopack-trace-server/src/span_ref.rs +++ b/crates/turbopack-trace-server/src/span_ref.rs @@ -9,7 +9,7 @@ use indexmap::IndexMap; use crate::{ bottom_up::build_bottom_up_graph, - span::{Span, SpanEvent, SpanGraphEvent, SpanIndex}, + span::{Span, SpanEvent, SpanExtra, SpanGraphEvent, SpanIndex, SpanNames, SpanTimeData}, span_bottom_up_ref::SpanBottomUpRef, span_graph_ref::{event_map_to_list, SpanGraphEventRef, SpanGraphRef}, store::{SpanId, Store}, @@ -19,21 +19,23 @@ use crate::{ pub struct SpanRef<'a> { pub(crate) span: &'a Span, pub(crate) store: &'a Store, + pub(crate) index: usize, } impl<'a> SpanRef<'a> { pub fn id(&self) -> SpanId { - unsafe { SpanId::new_unchecked(self.span.index.get() << 1) } + unsafe { SpanId::new_unchecked(self.index << 1) } } pub fn index(&self) -> SpanIndex { - self.span.index + SpanIndex::new(self.index).unwrap() } pub fn parent(&self) -> Option> { - self.span.parent.map(|id| SpanRef { - span: &self.store.spans[id.get()], + self.span.parent.map(|index| SpanRef { + span: &self.store.spans[index.get()], store: self.store, + index: index.get(), }) } @@ -41,10 +43,23 @@ impl<'a> SpanRef<'a> { self.span.start } + pub fn time_data(&self) -> &'a SpanTimeData { + self.span.time_data() + } + + pub fn extra(&self) -> &'a SpanExtra { + self.span.extra() + } + + pub fn names(&self) -> &'a SpanNames { + self.span.names() + } + pub fn end(&self) -> u64 { - *self.span.end.get_or_init(|| { + let time_data = self.time_data(); + *time_data.end.get_or_init(|| { max( - self.span.self_end, + time_data.self_end, self.children() .map(|child| child.end()) .max() @@ -58,7 +73,7 @@ impl<'a> SpanRef<'a> { } pub fn nice_name(&self) -> (&'a str, &'a str) { - let (category, title) = self.span.nice_name.get_or_init(|| { + let (category, title) = self.names().nice_name.get_or_init(|| { if let Some(name) = self .span .args @@ -88,7 +103,7 @@ impl<'a> SpanRef<'a> { } pub fn group_name(&self) -> &'a str { - self.span.group_name.get_or_init(|| { + self.names().group_name.get_or_init(|| { if matches!(self.span.name.as_str(), "turbo_tasks::function") { self.span .args @@ -117,7 +132,7 @@ impl<'a> SpanRef<'a> { } pub fn self_time(&self) -> u64 { - self.span.self_time + self.time_data().self_time } pub fn self_allocations(&self) -> u64 { @@ -154,10 +169,11 @@ impl<'a> SpanRef<'a> { pub fn events(&self) -> impl Iterator> { self.span.events.iter().map(|event| match event { &SpanEvent::SelfTime { start, end } => SpanEventRef::SelfTime { start, end }, - SpanEvent::Child { id } => SpanEventRef::Child { + SpanEvent::Child { index } => SpanEventRef::Child { span: SpanRef { - span: &self.store.spans[id.get()], + span: &self.store.spans[index.get()], store: self.store, + index: index.get(), }, }, }) @@ -166,15 +182,16 @@ impl<'a> SpanRef<'a> { pub fn children(&self) -> impl Iterator> + DoubleEndedIterator + 'a { self.span.events.iter().filter_map(|event| match event { SpanEvent::SelfTime { .. } => None, - SpanEvent::Child { id } => Some(SpanRef { - span: &self.store.spans[id.get()], + SpanEvent::Child { index } => Some(SpanRef { + span: &self.store.spans[index.get()], store: self.store, + index: index.get(), }), }) } pub fn total_time(&self) -> u64 { - *self.span.total_time.get_or_init(|| { + *self.time_data().total_time.get_or_init(|| { self.children() .map(|child| child.total_time()) .reduce(|a, b| a + b) @@ -235,7 +252,7 @@ impl<'a> SpanRef<'a> { pub fn corrected_self_time(&self) -> u64 { let store = self.store; - *self.span.corrected_self_time.get_or_init(|| { + *self.time_data().corrected_self_time.get_or_init(|| { let mut self_time = 0; for event in self.span.events.iter() { if let SpanEvent::SelfTime { start, end } = event { @@ -252,7 +269,7 @@ impl<'a> SpanRef<'a> { } pub fn corrected_total_time(&self) -> u64 { - *self.span.corrected_total_time.get_or_init(|| { + *self.time_data().corrected_total_time.get_or_init(|| { self.children() .map(|child| child.corrected_total_time()) .reduce(|a, b| a + b) @@ -271,7 +288,7 @@ impl<'a> SpanRef<'a> { } pub fn graph(&self) -> impl Iterator> + '_ { - self.span + self.extra() .graph .get_or_init(|| { let mut map: IndexMap<&str, (Vec, Vec)> = IndexMap::new(); @@ -279,13 +296,13 @@ impl<'a> SpanRef<'a> { for child in self.children() { let name = child.group_name(); let (list, recursive_list) = map.entry(name).or_default(); - list.push(child.span.index); + list.push(child.index()); queue.push_back(child); while let Some(child) = queue.pop_front() { for nested_child in child.children() { let nested_name = nested_child.group_name(); if name == nested_name { - recursive_list.push(nested_child.span.index); + recursive_list.push(nested_child.index()); queue.push_back(nested_child); } } @@ -308,14 +325,9 @@ impl<'a> SpanRef<'a> { } pub fn bottom_up(self) -> impl Iterator> { - self.span + self.extra() .bottom_up - .get_or_init(|| { - build_bottom_up_graph([SpanRef { - span: self.span, - store: self.store, - }]) - }) + .get_or_init(|| build_bottom_up_graph([self])) .iter() .map(|bottom_up| SpanBottomUpRef { bottom_up: bottom_up.clone(), @@ -335,11 +347,12 @@ impl<'a> SpanRef<'a> { result.into_iter().map(move |index| SpanRef { span: &store.spans[index.get()], store, + index: index.get(), }) } fn search_index(&self) -> &HashMap> { - self.span.search_index.get_or_init(|| { + self.extra().search_index.get_or_init(|| { let mut index: HashMap> = HashMap::new(); let mut queue = VecDeque::with_capacity(8); queue.push_back(*self); @@ -349,30 +362,30 @@ impl<'a> SpanRef<'a> { index .raw_entry_mut() .from_key(cat) - .and_modify(|_, v| v.push(span.span.index)) - .or_insert_with(|| (cat.to_string(), vec![span.span.index])); + .and_modify(|_, v| v.push(span.index())) + .or_insert_with(|| (cat.to_string(), vec![span.index()])); } if !name.is_empty() { index .raw_entry_mut() .from_key(name) - .and_modify(|_, v| v.push(span.span.index)) - .or_insert_with(|| (name.to_string(), vec![span.span.index])); + .and_modify(|_, v| v.push(span.index())) + .or_insert_with(|| (name.to_string(), vec![span.index()])); } for (_, value) in span.span.args.iter() { index .raw_entry_mut() .from_key(value) - .and_modify(|_, v| v.push(span.span.index)) - .or_insert_with(|| (value.to_string(), vec![span.span.index])); + .and_modify(|_, v| v.push(span.index())) + .or_insert_with(|| (value.to_string(), vec![span.index()])); } if !span.is_complete() { let name = "incomplete"; index .raw_entry_mut() .from_key(name) - .and_modify(|_, v| v.push(span.span.index)) - .or_insert_with(|| (name.to_string(), vec![span.span.index])); + .and_modify(|_, v| v.push(span.index())) + .or_insert_with(|| (name.to_string(), vec![span.index()])); } for child in span.children() { queue.push_back(child); diff --git a/crates/turbopack-trace-server/src/store.rs b/crates/turbopack-trace-server/src/store.rs index 4911e732736e8..d7cb16d97317f 100644 --- a/crates/turbopack-trace-server/src/store.rs +++ b/crates/turbopack-trace-server/src/store.rs @@ -23,37 +23,27 @@ pub struct Store { fn new_root_span() -> Span { Span { - index: SpanIndex::MAX, parent: None, depth: 0, start: u64::MAX, - ignore_self_time: false, - self_end: 0, category: "".into(), name: "(root)".into(), args: vec![], events: vec![], is_complete: true, - end: OnceLock::new(), - nice_name: OnceLock::new(), - group_name: OnceLock::new(), max_depth: OnceLock::new(), - graph: OnceLock::new(), - bottom_up: OnceLock::new(), - self_time: 0, self_allocations: 0, self_allocation_count: 0, self_deallocations: 0, self_deallocation_count: 0, - total_time: OnceLock::new(), total_allocations: OnceLock::new(), total_deallocations: OnceLock::new(), total_persistent_allocations: OnceLock::new(), total_allocation_count: OnceLock::new(), total_span_count: OnceLock::new(), - corrected_self_time: OnceLock::new(), - corrected_total_time: OnceLock::new(), - search_index: OnceLock::new(), + time_data: OnceLock::new(), + extra: OnceLock::new(), + names: OnceLock::new(), } } @@ -71,6 +61,10 @@ impl Store { self.self_time_tree = SelfTimeTree::new(); } + pub fn has_time_info(&self) -> bool { + self.self_time_tree.len() > 0 + } + pub fn add_span( &mut self, parent: Option, @@ -82,37 +76,27 @@ impl Store { ) -> SpanIndex { let id = SpanIndex::new(self.spans.len()).unwrap(); self.spans.push(Span { - index: id, parent, depth: 0, start, - ignore_self_time: &name == "thread", - self_end: start, category, name, args, events: vec![], is_complete: false, - end: OnceLock::new(), - nice_name: OnceLock::new(), - group_name: OnceLock::new(), max_depth: OnceLock::new(), - graph: OnceLock::new(), - bottom_up: OnceLock::new(), - self_time: 0, self_allocations: 0, self_allocation_count: 0, self_deallocations: 0, self_deallocation_count: 0, - total_time: OnceLock::new(), total_allocations: OnceLock::new(), total_deallocations: OnceLock::new(), total_persistent_allocations: OnceLock::new(), total_allocation_count: OnceLock::new(), total_span_count: OnceLock::new(), - corrected_self_time: OnceLock::new(), - corrected_total_time: OnceLock::new(), - search_index: OnceLock::new(), + time_data: OnceLock::new(), + extra: OnceLock::new(), + names: OnceLock::new(), }); let parent = if let Some(parent) = parent { outdated_spans.insert(parent); @@ -123,7 +107,7 @@ impl Store { parent.start = min(parent.start, start); let depth = parent.depth + 1; if depth < CUT_OFF_DEPTH { - parent.events.push(SpanEvent::Child { id }); + parent.events.push(SpanEvent::Child { index: id }); } let span = &mut self.spans[id.get()]; span.depth = depth; @@ -163,13 +147,14 @@ impl Store { outdated_spans: &mut HashSet, ) { let span = &mut self.spans[span_index.get()]; - if span.ignore_self_time { + let time_data = span.time_data_mut(); + if time_data.ignore_self_time { return; } outdated_spans.insert(span_index); - span.self_time += end - start; + time_data.self_time += end - start; + time_data.self_end = max(time_data.self_end, end); span.events.push(SpanEvent::SelfTime { start, end }); - span.self_end = max(span.self_end, end); self.insert_self_time(start, end, span_index, outdated_spans); } @@ -183,10 +168,11 @@ impl Store { let span = SpanRef { span: &self.spans[span_index.get()], store: self, + index: span_index.get(), }; let mut children = span .children() - .map(|c| (c.span.start, c.span.self_end, c.span.index)) + .map(|c| (c.span.start, c.span.time_data().self_end, c.index())) .collect::>(); children.sort(); let self_end = start_time + total_time; @@ -211,7 +197,7 @@ impl Store { self.insert_self_time(current, start, span_index, outdated_spans); self_time += start - current; } - events.push(SpanEvent::Child { id: index }); + events.push(SpanEvent::Child { index }); current = max(current, end); } current -= start_time; @@ -230,10 +216,11 @@ impl Store { } let span = &mut self.spans[span_index.get()]; outdated_spans.insert(span_index); - span.self_time = self_time; + let time_data = span.time_data_mut(); + time_data.self_time = self_time; + time_data.self_end = self_end; span.events = events; span.start = start_time; - span.self_end = self_end; } pub fn set_parent( @@ -255,14 +242,14 @@ impl Store { if let Some(index) = old_parent .events .iter() - .position(|event| *event == SpanEvent::Child { id: span_index }) + .position(|event| *event == SpanEvent::Child { index: span_index }) { old_parent.events.remove(index); } outdated_spans.insert(parent); let parent = &mut self.spans[parent.get()]; - parent.events.push(SpanEvent::Child { id: span_index }); + parent.events.push(SpanEvent::Child { index: span_index }); } pub fn add_allocation( @@ -298,17 +285,17 @@ impl Store { pub fn invalidate_outdated_spans(&mut self, outdated_spans: &HashSet) { fn invalidate_span(span: &mut Span) { - span.end.take(); - span.total_time.take(); + if let Some(time_data) = span.time_data.get_mut() { + time_data.end.take(); + time_data.total_time.take(); + time_data.corrected_self_time.take(); + time_data.corrected_total_time.take(); + } span.total_allocations.take(); span.total_deallocations.take(); span.total_persistent_allocations.take(); span.total_allocation_count.take(); - span.corrected_self_time.take(); - span.corrected_total_time.take(); - span.graph.take(); - span.bottom_up.take(); - span.search_index.take(); + span.extra.take(); } for id in outdated_spans.iter() { @@ -330,9 +317,10 @@ impl Store { pub fn root_spans(&self) -> impl Iterator> { self.spans[0].events.iter().filter_map(|event| match event { - &SpanEvent::Child { id } => Some(SpanRef { + &SpanEvent::Child { index: id } => Some(SpanRef { span: &self.spans[id.get()], store: self, + index: id.get(), }), _ => None, }) @@ -342,6 +330,7 @@ impl Store { SpanRef { span: &self.spans[0], store: self, + index: 0, } } @@ -349,8 +338,15 @@ impl Store { let id = id.get(); let is_graph = id & 1 == 1; let index = id >> 1; - self.spans - .get(index) - .map(|span| (SpanRef { span, store: self }, is_graph)) + self.spans.get(index).map(|span| { + ( + SpanRef { + span, + store: self, + index, + }, + is_graph, + ) + }) } } diff --git a/crates/turbopack-trace-server/src/viewer.rs b/crates/turbopack-trace-server/src/viewer.rs index fc6abca4fe424..b45524b793950 100644 --- a/crates/turbopack-trace-server/src/viewer.rs +++ b/crates/turbopack-trace-server/src/viewer.rs @@ -325,6 +325,27 @@ impl Viewer { _ => ValueMode::Duration, }; + if !store.has_time_info() && matches!(value_mode, ValueMode::Duration) { + return Update { + lines: vec![ViewLineUpdate { + spans: vec![ViewSpan { + id: 0, + start: 0, + width: 1, + category: "info".to_string(), + text: "No time info in trace".to_string(), + count: 1, + kind: 0, + start_in_parent: 0, + end_in_parent: 0, + secondary: 0, + }], + y: 0, + }], + max: 1, + }; + } + let mut queue = Vec::new(); let root_spans = if with_root { @@ -754,11 +775,17 @@ impl Viewer { if let Some(parent) = span.parent() { let parent_start = parent.start(); let parent_duration = parent.end() - parent_start; - start_in_parent = ((span.start() - parent_start) * 10000 - / parent_duration) - as u32; - end_in_parent = - ((span.end() - parent_start) * 10000 / parent_duration) as u32; + if parent_duration > 0 { + start_in_parent = ((span.start() - parent_start) * 10000 + / parent_duration) + as u32; + end_in_parent = ((span.end() - parent_start) * 10000 + / parent_duration) + as u32; + } else { + start_in_parent = 0; + end_in_parent = 10000; + } } ViewSpan { id: span.id().get() as u64,