Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

fix tracing span names #5624

Merged
merged 5 commits into from
Aug 2, 2023
Merged

fix tracing span names #5624

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
5 commits
Select commit Hold shift + click to select a range
d7247dc
fix tracing span names
sokra Jul 27, 2023
3dfee49
add counts to graph trace
sokra Jul 28, 2023
c96e9e4
collapse names and recursion
sokra Jul 28, 2023
ee9c28b
clippy
sokra Jul 28, 2023
121685e
measure time, avoid unsafe
sokra Jul 28, 2023
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
8 changes: 4 additions & 4 deletions crates/turbo-tasks/src/task/function.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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)))
}))
}
}
Expand Down Expand Up @@ -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)))
}))
}
}
Expand Down Expand Up @@ -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)))
}))
}
}
Expand Down Expand Up @@ -255,7 +255,7 @@ macro_rules! task_fn_impl {
let result = <F as $async_fn_trait<&Recv, $($arg,)*>>::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)))
}))
}
}
Expand Down
193 changes: 137 additions & 56 deletions crates/turbopack-convert-trace/src/main.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -26,11 +26,11 @@ use std::{
eprintln,
mem::take,
ops::Range,
time::Instant,
};

use indexmap::IndexMap;
use intervaltree::{Element, IntervalTree};
use itertools::Itertools;
use turbopack_cli_utils::tracing::{TraceRow, TraceValue};

macro_rules! pjson {
Expand All @@ -48,6 +48,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;
}
Expand All @@ -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[..];
Expand All @@ -81,13 +88,19 @@ 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 {
parent: 0,
count: 1,
name: "".into(),
target: "".into(),
start: 0,
Expand All @@ -107,6 +120,7 @@ fn main() {
entry.insert(internal_id);
let span = Span {
parent: 0,
count: 1,
name: "".into(),
target: "".into(),
start: 0,
Expand All @@ -124,6 +138,20 @@ fn main() {
let mut all_self_times = Vec::new();
let mut name_counts: HashMap<Cow<'_, str>, usize> = HashMap::new();

fn get_name<'a>(
name: &'a str,
values: &IndexMap<Cow<'a, str>, 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()))
.unwrap_or(name.into())
}

for data in trace_rows {
match data {
TraceRow::Start {
Expand All @@ -134,18 +162,20 @@ fn main() {
target,
values,
} => {
let values = values.into_iter().collect();
let name = get_name(name, &values, collapse_names);
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
Expand Down Expand Up @@ -196,6 +226,7 @@ fn main() {
let start = ts - duration;
spans.push(Span {
parent: internal_parent,
count: 1,
name,
target: "".into(),
start,
Expand All @@ -216,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));
Expand All @@ -235,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<VirtualThread>,
Expand Down Expand Up @@ -349,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;
Expand Down Expand Up @@ -411,6 +448,92 @@ fn main() {
match task {
Task::Enter { id, root } => {
let mut span = take(&mut spans[id]);
let mut count = span.count;
let mut items = take(&mut span.items);
if graph && !items.is_empty() {
let parent_name = &*span.name;
let mut groups = IndexMap::new();
let mut self_items = Vec::new();
fn add_items_to_groups<'a>(
groups: &mut IndexMap<Cow<'a, str>, Vec<SpanItem>>,
self_items: &mut Vec<SpanItem>,
spans: &mut Vec<Span<'a>>,
parent_count: &mut u32,
parent_name: &str,
items: Vec<SpanItem>,
) {
for item in items {
match item {
SpanItem::SelfTime { .. } => {
self_items.push(item);
}
SpanItem::Child(id) => {
let key = spans[id].name.clone();
if key == parent_name {
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Does this also imply id == parent_id? Or does each span have a unique id regardless of the called function?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The same function can be called multiple times (different ids) and it would have the same 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(Cow::Borrowed("SELF_TIME"))
.or_default()
.append(&mut self_items);
}
let groups = groups.into_values().collect::<Vec<_>>();
let mut new_items = Vec::new();
for group in groups {
let mut group = group.into_iter();
let new_item = group.next().unwrap();
match new_item {
SpanItem::SelfTime { .. } => {
new_items.push(new_item);
new_items.extend(group);
}
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!();
};
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.count = count;
}
}
}
}
items = new_items;
}
if root {
if ts < span.start {
ts = span.start;
Expand All @@ -425,10 +548,10 @@ 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 {
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();
Expand All @@ -448,50 +571,7 @@ fn main() {
start: ts,
start_scaled: tts,
});
let mut items = take(&mut span.items);
if graph {
let group_func = |item: &SpanItem| match item {
SpanItem::SelfTime { .. } => (true, "", None),
SpanItem::Child(id) => {
let span = &spans[*id];
(
false,
&*span.name,
span.values.get("name").map(|v| v.to_string()),
)
}
};
items.sort_by_cached_key(group_func);
// merge childen with the same name
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::<Vec<_>>())
.collect::<Vec<_>>();
for group in groups {
let mut group = group.into_iter();
let new_item = group.next().unwrap();
match new_item {
SpanItem::SelfTime { .. } => {
new_items.push(new_item);
new_items.extend(group);
}
SpanItem::Child(new_item_id) => {
new_items.push(new_item);
for item in group {
let SpanItem::Child(id) = item else {
unreachable!();
};
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);
}
}
}
}
items = new_items;
}

for item in items.iter().rev() {
match item {
SpanItem::SelfTime {
Expand Down Expand Up @@ -610,7 +690,7 @@ fn main() {
}
}
}
eprintln!(" done");
eprintln!(" done ({:.3}s)", start.elapsed().as_secs_f64());
}
println!();
println!("]");
Expand All @@ -624,6 +704,7 @@ struct SelfTimeStarted {
#[derive(Debug, Default)]
struct Span<'a> {
parent: usize,
count: u32,
name: Cow<'a, str>,
target: Cow<'a, str>,
start: u64,
Expand Down
Loading