From d7247dcc6fce0067f3712b54ba58b93c9f4f2d52 Mon Sep 17 00:00:00 2001 From: Tobias Koppers Date: Thu, 27 Jul 2023 21:17:19 +0000 Subject: [PATCH 1/5] fix tracing span names --- crates/turbo-tasks/src/task/function.rs | 8 +++--- crates/turbopack-convert-trace/src/main.rs | 32 ++++++++++++---------- 2 files changed, 22 insertions(+), 18 deletions(-) diff --git a/crates/turbo-tasks/src/task/function.rs b/crates/turbo-tasks/src/task/function.rs index 2f8ad3820b888..b25fa6f59c06b 100644 --- a/crates/turbo-tasks/src/task/function.rs +++ b/crates/turbo-tasks/src/task/function.rs @@ -114,7 +114,7 @@ macro_rules! task_fn_impl { Box::pin(macro_helpers::tracing::Instrument::instrument(async move { Output::try_into_raw_vc((task_fn)($($arg),*)) - }, macro_helpers::tracing::trace_span!("{}", name))) + }, macro_helpers::tracing::trace_span!("turbo_tasks::function", name))) })) } } @@ -153,7 +153,7 @@ macro_rules! task_fn_impl { let result = Output::try_into_raw_vc((task_fn)($($arg),*).await); macro_helpers::notify_scheduled_tasks(); result - }, macro_helpers::tracing::trace_span!("{}", name))) + }, macro_helpers::tracing::trace_span!("turbo_tasks::function", name))) })) } } @@ -197,7 +197,7 @@ macro_rules! task_fn_impl { let result = Output::try_into_raw_vc((task_fn)(recv, $($arg),*)); macro_helpers::notify_scheduled_tasks(); result - }, macro_helpers::tracing::trace_span!("{}", name))) + }, macro_helpers::tracing::trace_span!("turbo_tasks::function", name))) })) } } @@ -255,7 +255,7 @@ macro_rules! task_fn_impl { let result = >::Output::try_into_raw_vc((task_fn)(recv, $($arg),*).await); macro_helpers::notify_scheduled_tasks(); result - }, macro_helpers::tracing::trace_span!("{}", name))) + }, macro_helpers::tracing::trace_span!("turbo_tasks::function", name))) })) } } diff --git a/crates/turbopack-convert-trace/src/main.rs b/crates/turbopack-convert-trace/src/main.rs index 50a08cf513ea8..3e69025d90115 100644 --- a/crates/turbopack-convert-trace/src/main.rs +++ b/crates/turbopack-convert-trace/src/main.rs @@ -124,6 +124,16 @@ fn main() { let mut all_self_times = Vec::new(); let mut name_counts: HashMap, usize> = HashMap::new(); + fn get_name<'a>( + name: &'a str, + values: &IndexMap, TraceValue<'a>>, + ) -> Cow<'a, str> { + values + .get("name") + .and_then(|v| v.as_str().map(|s| format!("{s} ({name})").into())) + .unwrap_or(name.into()) + } + for data in trace_rows { match data { TraceRow::Start { @@ -134,18 +144,20 @@ fn main() { target, values, } => { + let values = values.into_iter().collect(); + let name = get_name(name, &values); let internal_id = ensure_span(&mut active_ids, &mut spans, id); - spans[internal_id].name = name.into(); + spans[internal_id].name = name.clone(); spans[internal_id].target = target.into(); spans[internal_id].start = ts; spans[internal_id].end = ts; - spans[internal_id].values = values.into_iter().collect(); + spans[internal_id].values = values; let internal_parent = parent.map_or(0, |id| ensure_span(&mut active_ids, &mut spans, id)); spans[internal_id].parent = internal_parent; let parent = &mut spans[internal_parent]; parent.items.push(SpanItem::Child(internal_id)); - *name_counts.entry(Cow::Borrowed(name)).or_default() += 1; + *name_counts.entry(name).or_default() += 1; } TraceRow::End { ts, id } => { // id might be reused @@ -425,11 +437,7 @@ fn main() { merged_tts = span.start; } } - let name_json = if let Some(name_value) = span.values.get("name") { - serde_json::to_string(&format!("{} {name_value}", span.name)).unwrap() - } else { - serde_json::to_string(&span.name).unwrap() - }; + let name_json = serde_json::to_string(&span.name).unwrap(); let target_json = serde_json::to_string(&span.target).unwrap(); let args_json = serde_json::to_string(&span.values).unwrap(); if single { @@ -451,14 +459,10 @@ fn main() { let mut items = take(&mut span.items); if graph { let group_func = |item: &SpanItem| match item { - SpanItem::SelfTime { .. } => (true, "", None), + SpanItem::SelfTime { .. } => (true, ""), SpanItem::Child(id) => { let span = &spans[*id]; - ( - false, - &*span.name, - span.values.get("name").map(|v| v.to_string()), - ) + (false, &*span.name) } }; items.sort_by_cached_key(group_func); From 3dfee494754eeb280d78ab6e4d7942b50b24f0fc Mon Sep 17 00:00:00 2001 From: Tobias Koppers Date: Fri, 28 Jul 2023 06:55:38 +0000 Subject: [PATCH 2/5] add counts to graph trace --- crates/turbopack-convert-trace/src/main.rs | 40 ++++++++++++++-------- 1 file changed, 26 insertions(+), 14 deletions(-) diff --git a/crates/turbopack-convert-trace/src/main.rs b/crates/turbopack-convert-trace/src/main.rs index 3e69025d90115..eb95781286409 100644 --- a/crates/turbopack-convert-trace/src/main.rs +++ b/crates/turbopack-convert-trace/src/main.rs @@ -30,7 +30,6 @@ use std::{ use indexmap::IndexMap; use intervaltree::{Element, IntervalTree}; -use itertools::Itertools; use turbopack_cli_utils::tracing::{TraceRow, TraceValue}; macro_rules! pjson { @@ -458,21 +457,28 @@ fn main() { }); let mut items = take(&mut span.items); if graph { - let group_func = |item: &SpanItem| match item { - SpanItem::SelfTime { .. } => (true, ""), - SpanItem::Child(id) => { - let span = &spans[*id]; - (false, &*span.name) + let mut groups = IndexMap::new(); + let mut self_items = Vec::new(); + for item in items { + match item { + SpanItem::SelfTime { .. } => { + self_items.push(item); + } + SpanItem::Child(id) => { + let span = &spans[id]; + let group = groups.entry(&*span.name).or_insert_with(Vec::new); + group.push(item); + } } - }; - items.sort_by_cached_key(group_func); - // merge childen with the same name + } + if !self_items.is_empty() { + groups + .entry("SELF_TIME") + .or_default() + .extend(self_items.drain(..)); + } + let groups = groups.into_values().collect::>(); let mut new_items = Vec::new(); - let grouped_by = items.into_iter().group_by(group_func); - let groups = grouped_by - .into_iter() - .map(|(_, group)| group.collect::>()) - .collect::>(); for group in groups { let mut group = group.into_iter(); let new_item = group.next().unwrap(); @@ -483,6 +489,7 @@ fn main() { } SpanItem::Child(new_item_id) => { new_items.push(new_item); + let mut count = 1; for item in group { let SpanItem::Child(id) = item else { unreachable!(); @@ -490,6 +497,11 @@ fn main() { assert!(spans[id].name == spans[new_item_id].name); let old_items = take(&mut spans[id].items); spans[new_item_id].items.extend(old_items); + count += 1; + } + if count != 1 { + let span = &mut spans[new_item_id]; + span.name = format!("{count} x {}", span.name).into(); } } } From c96e9e4c31f3bccb7ef7bcfa88219b98d43d1df1 Mon Sep 17 00:00:00 2001 From: Tobias Koppers Date: Fri, 28 Jul 2023 07:49:37 +0000 Subject: [PATCH 3/5] collapse names and recursion --- crates/turbopack-convert-trace/src/main.rs | 140 ++++++++++++++------- 1 file changed, 95 insertions(+), 45 deletions(-) diff --git a/crates/turbopack-convert-trace/src/main.rs b/crates/turbopack-convert-trace/src/main.rs index eb95781286409..3bed676609c14 100644 --- a/crates/turbopack-convert-trace/src/main.rs +++ b/crates/turbopack-convert-trace/src/main.rs @@ -47,6 +47,7 @@ fn main() { let threads = args.remove("--threads"); let idle = args.remove("--idle"); let graph = args.remove("--graph"); + let collapse_names = args.remove("--collapse-names"); if !single && !merged && !threads { merged = true; } @@ -87,6 +88,7 @@ fn main() { let mut spans = Vec::new(); spans.push(Span { parent: 0, + count: 1, name: "".into(), target: "".into(), start: 0, @@ -106,6 +108,7 @@ fn main() { entry.insert(internal_id); let span = Span { parent: 0, + count: 1, name: "".into(), target: "".into(), start: 0, @@ -126,7 +129,11 @@ fn main() { fn get_name<'a>( name: &'a str, values: &IndexMap, TraceValue<'a>>, + collapse_names: bool, ) -> Cow<'a, str> { + if collapse_names && name != "turbo_tasks::function" { + return name.into(); + } values .get("name") .and_then(|v| v.as_str().map(|s| format!("{s} ({name})").into())) @@ -144,7 +151,7 @@ fn main() { values, } => { let values = values.into_iter().collect(); - let name = get_name(name, &values); + let name = get_name(name, &values, collapse_names); let internal_id = ensure_span(&mut active_ids, &mut spans, id); spans[internal_id].name = name.clone(); spans[internal_id].target = target.into(); @@ -207,6 +214,7 @@ fn main() { let start = ts - duration; spans.push(Span { parent: internal_parent, + count: 1, name, target: "".into(), start, @@ -422,61 +430,64 @@ fn main() { match task { Task::Enter { id, root } => { let mut span = take(&mut spans[id]); - if root { - if ts < span.start { - ts = span.start; - } - if tts < span.start { - tts = span.start; - } - if merged_ts < span.start { - merged_ts = span.start; - } - if merged_tts < span.start { - merged_tts = span.start; - } - } - let name_json = serde_json::to_string(&span.name).unwrap(); - let target_json = serde_json::to_string(&span.target).unwrap(); - let args_json = serde_json::to_string(&span.values).unwrap(); - if single { - pjson!( - r#"{{"ph":"B","pid":1,"ts":{ts},"tts":{tts},"name":{name_json},"cat":{target_json},"tid":0,"args":{args_json}}}"#, - ); - } - if merged { - pjson!( - r#"{{"ph":"B","pid":2,"ts":{merged_ts},"tts":{merged_tts},"name":{name_json},"cat":{target_json},"tid":0,"args":{args_json}}}"#, - ); - } - stack.push(Task::Exit { - name_json, - target_json, - start: ts, - start_scaled: tts, - }); + let mut count = span.count; let mut items = take(&mut span.items); - if graph { + if graph && !items.is_empty() { + let parent_name = &*span.name; let mut groups = IndexMap::new(); let mut self_items = Vec::new(); - for item in items { - match item { - SpanItem::SelfTime { .. } => { - self_items.push(item); - } - SpanItem::Child(id) => { - let span = &spans[id]; - let group = groups.entry(&*span.name).or_insert_with(Vec::new); - group.push(item); + fn add_items_to_groups( + groups: &mut IndexMap<&str, Vec>, + self_items: &mut Vec, + spans: &mut Vec, + parent_count: &mut u32, + parent_name: &str, + items: Vec, + ) { + for item in items { + match item { + SpanItem::SelfTime { .. } => { + self_items.push(item); + } + SpanItem::Child(id) => { + // SAFETY: We never mutate the `name` of the spans or the + // Vec itself. We only mutate the `items` Vec. + let key = unsafe { &*(&*spans[id].name as *const str) }; + if key == parent_name { + // Recursion + *parent_count += 1; + let items = take(&mut spans[id].items); + add_items_to_groups( + groups, + self_items, + spans, + parent_count, + parent_name, + items, + ); + } else { + let group = groups.entry(key).or_insert_with(Vec::new); + group.push(item); + } + } } } } + add_items_to_groups( + &mut groups, + &mut self_items, + &mut spans, + &mut count, + &parent_name, + items, + ); if !self_items.is_empty() { groups .entry("SELF_TIME") .or_default() .extend(self_items.drain(..)); } + // SAFETY: Lifetime of the keys in `groups` must end here. let groups = groups.into_values().collect::>(); let mut new_items = Vec::new(); for group in groups { @@ -501,13 +512,51 @@ fn main() { } if count != 1 { let span = &mut spans[new_item_id]; - span.name = format!("{count} x {}", span.name).into(); + span.count = count; } } } } items = new_items; } + if root { + if ts < span.start { + ts = span.start; + } + if tts < span.start { + tts = span.start; + } + if merged_ts < span.start { + merged_ts = span.start; + } + if merged_tts < span.start { + merged_tts = span.start; + } + } + let name_json = if count == 1 { + serde_json::to_string(&span.name).unwrap() + } else { + serde_json::to_string(&format!("{count} x {}", span.name)).unwrap() + }; + let target_json = serde_json::to_string(&span.target).unwrap(); + let args_json = serde_json::to_string(&span.values).unwrap(); + if single { + pjson!( + r#"{{"ph":"B","pid":1,"ts":{ts},"tts":{tts},"name":{name_json},"cat":{target_json},"tid":0,"args":{args_json}}}"#, + ); + } + if merged { + pjson!( + r#"{{"ph":"B","pid":2,"ts":{merged_ts},"tts":{merged_tts},"name":{name_json},"cat":{target_json},"tid":0,"args":{args_json}}}"#, + ); + } + stack.push(Task::Exit { + name_json, + target_json, + start: ts, + start_scaled: tts, + }); + for item in items.iter().rev() { match item { SpanItem::SelfTime { @@ -640,6 +689,7 @@ struct SelfTimeStarted { #[derive(Debug, Default)] struct Span<'a> { parent: usize, + count: u32, name: Cow<'a, str>, target: Cow<'a, str>, start: u64, From ee9c28bd7209a013c9b8fb42f924ce9efa424edf Mon Sep 17 00:00:00 2001 From: Tobias Koppers Date: Fri, 28 Jul 2023 10:06:08 +0000 Subject: [PATCH 4/5] clippy --- crates/turbopack-convert-trace/src/main.rs | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/crates/turbopack-convert-trace/src/main.rs b/crates/turbopack-convert-trace/src/main.rs index 3bed676609c14..a0ff1650ff71f 100644 --- a/crates/turbopack-convert-trace/src/main.rs +++ b/crates/turbopack-convert-trace/src/main.rs @@ -478,14 +478,14 @@ fn main() { &mut self_items, &mut spans, &mut count, - &parent_name, + parent_name, items, ); if !self_items.is_empty() { groups .entry("SELF_TIME") .or_default() - .extend(self_items.drain(..)); + .append(&mut self_items); } // SAFETY: Lifetime of the keys in `groups` must end here. let groups = groups.into_values().collect::>(); From 121685e0a31ca1ccb2f16405ca8aaeabc21caf6b Mon Sep 17 00:00:00 2001 From: Tobias Koppers Date: Fri, 28 Jul 2023 11:55:25 +0000 Subject: [PATCH 5/5] measure time, avoid unsafe --- crates/turbopack-convert-trace/src/main.rs | 41 +++++++++++++++------- 1 file changed, 28 insertions(+), 13 deletions(-) diff --git a/crates/turbopack-convert-trace/src/main.rs b/crates/turbopack-convert-trace/src/main.rs index a0ff1650ff71f..213fdc21801dc 100644 --- a/crates/turbopack-convert-trace/src/main.rs +++ b/crates/turbopack-convert-trace/src/main.rs @@ -26,6 +26,7 @@ use std::{ eprintln, mem::take, ops::Range, + time::Instant, }; use indexmap::IndexMap; @@ -57,12 +58,18 @@ fn main() { .map_or(".turbopack/trace.log", String::as_str); eprint!("Reading content from {}...", arg); + let start = Instant::now(); // Read file to string let file = std::fs::read(arg).unwrap(); - eprintln!(" done ({} MiB)", file.len() / 1024 / 1024); + eprintln!( + " done ({} MiB, {:.3}s)", + file.len() / 1024 / 1024, + start.elapsed().as_secs_f32() + ); eprint!("Parsing trace from content..."); + let start = Instant::now(); let mut trace_rows = Vec::new(); let mut current = &file[..]; @@ -81,9 +88,14 @@ fn main() { } } } - eprintln!(" done ({} items)", trace_rows.len()); + eprintln!( + " done ({} items, {:.3}s)", + trace_rows.len(), + start.elapsed().as_secs_f32() + ); eprint!("Analysing trace into span tree..."); + let start = Instant::now(); let mut spans = Vec::new(); spans.push(Span { @@ -235,7 +247,11 @@ fn main() { } } - eprintln!(" done ({} spans)", spans.len()); + eprintln!( + " done ({} spans, {:.3}s)", + spans.len(), + start.elapsed().as_secs_f64() + ); let mut name_counts: Vec<(Cow<'_, str>, usize)> = name_counts.into_iter().collect(); name_counts.sort_by_key(|(_, count)| Reverse(*count)); @@ -254,6 +270,7 @@ fn main() { if threads { eprint!("Distributing time into virtual threads..."); + let start = Instant::now(); let mut virtual_threads = Vec::new(); let find_thread = |virtual_threads: &mut Vec, @@ -368,11 +385,12 @@ fn main() { ); } } - eprintln!(" done"); + eprintln!(" done ({:.3}s)", start.elapsed().as_secs_f32()); } if single || merged { eprint!("Emitting span tree..."); + let start = Instant::now(); const CONCURRENCY_FIXED_POINT_FACTOR: u64 = 100; const CONCURRENCY_FIXED_POINT_FACTOR_F: f32 = 100.0; @@ -436,10 +454,10 @@ fn main() { let parent_name = &*span.name; let mut groups = IndexMap::new(); let mut self_items = Vec::new(); - fn add_items_to_groups( - groups: &mut IndexMap<&str, Vec>, + fn add_items_to_groups<'a>( + groups: &mut IndexMap, Vec>, self_items: &mut Vec, - spans: &mut Vec, + spans: &mut Vec>, parent_count: &mut u32, parent_name: &str, items: Vec, @@ -450,9 +468,7 @@ fn main() { self_items.push(item); } SpanItem::Child(id) => { - // SAFETY: We never mutate the `name` of the spans or the - // Vec itself. We only mutate the `items` Vec. - let key = unsafe { &*(&*spans[id].name as *const str) }; + let key = spans[id].name.clone(); if key == parent_name { // Recursion *parent_count += 1; @@ -483,11 +499,10 @@ fn main() { ); if !self_items.is_empty() { groups - .entry("SELF_TIME") + .entry(Cow::Borrowed("SELF_TIME")) .or_default() .append(&mut self_items); } - // SAFETY: Lifetime of the keys in `groups` must end here. let groups = groups.into_values().collect::>(); let mut new_items = Vec::new(); for group in groups { @@ -675,7 +690,7 @@ fn main() { } } } - eprintln!(" done"); + eprintln!(" done ({:.3}s)", start.elapsed().as_secs_f64()); } println!(); println!("]");