Initial tracing implementation (vercel/turborepo#4966)

### Description

* adds a raw_trace subscriber that will emit the raw trace events into
`.turbopack/trace.log` (resp. `.next/trace.log` for next.js)
* adds a CLI script which converts the raw trace into a chrome trace
json file -> https://ui.perfetto.dev/
* adds a `TURBOPACK_TRACING` (resp. `NEXT_TURBOPACK_TRACING`) env var to
enable tracing
* adds some presets e. g. `turbopack` or `next` to enable tracing for
certain things.
* add tracing for invalidations

There are three different visualization modes:

#### `--single`

Shows all cpu time as it would look like when a single cpu would execute
the workload.

(10 concurrent tasks that take 1s are shown as 10 tasks that take 1s
with total time of 10s)

Pro:
* Concurrency is visualized by bar filling (dark filled bars -> too few
concurrency)
* It injects pseudo bars with "cpus idle" for low concurrency (with
`--idle`)

Con:
* Total time won't be represented correctly, since a single CPU would
take longer

Use Case: Gives a good overview of slow tasks in a build.

#### `--merged`

Shows all cpu time scaled by the concurrency.

(10 concurrent tasks that take 1s are shown as 10 tasks that take 0.1s
with total time of 1s)

Pro:
* Total time is represented correctly
* Low concurrent tasks are bigger
* Concurrency is visualized by bar filling (dark filled bars -> too few
concurrency)
* It injects pseudo bars with "cpus idle" for low concurrency (with
`--idle`)

Con:
* Individual tasks time won't be represented correctly.

Use Case: Gives a good overview why a build is slow overall.

#### `--threads`

Shows cpu time distributed on infinite virtual cpus/threads.

(10 concurrent tasks that take 1s are shown as 10 concurrent tasks that
take 1s with total time of 1s)

Pro:
* Concurrency is shown via multiple CPU
* Most realistic visualization

Con:
* Hard to read

crates/turbo-tasks-fs/Cargo.toml

@@ -38,6 +38,7 @@ serde = { workspace = true, features = ["rc"] }
 serde_json = { workspace = true }
 serde_path_to_error = "0.1.9"
 tokio = { workspace = true }
+tracing = { workspace = true }
 turbo-tasks = { workspace = true }
 turbo-tasks-hash = { workspace = true }
 

crates/turbo-tasks-fs/src/lib.rs

@@ -51,6 +51,7 @@ use tokio::{
  fs,
  io::{AsyncBufReadExt, AsyncReadExt, BufReader},
 };
+use tracing::{instrument, Level};
 use turbo_tasks::{
  mark_stateful,
  primitives::{BoolVc, StringReadRef, StringVc},
@@ -356,6 +357,7 @@ impl DiskFileSystem {
  }
  event = rx.try_recv();
  }
+ #[instrument(parent = None, level = Level::INFO, name = "DiskFileSystem file change", skip_all, fields(name = display(path.display())))]
  fn invalidate(
  report_invalidation_reason: &Option<(String, PathBuf)>,
  path: &Path,

crates/turbo-tasks-macros/src/func.rs

@@ -165,8 +165,10 @@ pub fn gen_native_function_code(
  },
  (true, false) => quote! { #original_call_code.map(|v| v.into()) },
  (false, true) => quote! {
- #original_call_code;
- Ok(turbo_tasks::NothingVc::new().into())
+ {
+ #original_call_code;
+ Ok(turbo_tasks::NothingVc::new().into())
+ }
  },
  (false, false) => quote! { Ok(#original_call_code.into()) },
  };
@@ -184,10 +186,12 @@ pub fn gen_native_function_code(
  #(#input_convert)*
  Ok(Box::new(move || {
  #(#input_clone)*
- Box::pin(async move {
+ Box::pin(turbo_tasks::macro_helpers::tracing::Instrument::instrument(async move {
  #(#input_final)*
- #original_call_code
- })
+ let turbo_tasks_result = #original_call_code;
+ turbo_tasks::macro_helpers::notify_scheduled_tasks();
+ turbo_tasks_result
+ }, turbo_tasks::macro_helpers::tracing::trace_span!(#name_code)))
  }))
  }))
  });

crates/turbo-tasks-macros/src/value_impl_macro.rs

@@ -102,7 +102,7 @@ pub fn value_impl(_args: TokenStream, input: TokenStream) -> TokenStream {
 
  let (native_function_code, input_raw_vc_arguments) = gen_native_function_code(
  // use const string
- quote! { format!(concat!("{}::", stringify!(#ident)), std::any::type_name::<#vc_ident>()) },
+ quote! { concat!(stringify!(#vc_ident), "::", stringify!(#ident)) },
  quote! { #vc_ident::#inline_ident },
  &function_ident,
  &function_id_ident,

crates/turbo-tasks-macros/src/value_trait_macro.rs

@@ -109,7 +109,7 @@ pub fn value_trait(args: TokenStream, input: TokenStream) -> TokenStream {
  inline_sig.ident = inline_ident.clone();
 
  let (native_function_code, input_raw_vc_arguments) = gen_native_function_code(
- quote! { format!(concat!("{}::", stringify!(#method_ident)), std::any::type_name::<#ref_ident>()) },
+ quote! { concat!(stringify!(#ref_ident), "::", stringify!(#method_ident)) },
  quote! { #ref_ident::#inline_ident },
  &function_ident,
  &function_id_ident,

crates/turbo-tasks-memory/Cargo.toml

@@ -21,6 +21,7 @@ parking_lot = { workspace = true }
 priority-queue = "1.3.0"
 rustc-hash = { workspace = true }
 tokio = { workspace = true }
+tracing = { workspace = true }
 turbo-tasks = { workspace = true }
 turbo-tasks-hash = { workspace = true }
 turbo-tasks-malloc = { workspace = true, default-features = false }

crates/turbo-tasks-memory/src/memory_backend.rs

@@ -19,6 +19,7 @@ use dashmap::{mapref::entry::Entry, DashMap};
 use nohash_hasher::BuildNoHashHasher;
 use rustc_hash::FxHasher;
 use tokio::task::futures::TaskLocalFuture;
+use tracing::{trace_span, Instrument};
 use turbo_tasks::{
  backend::{
  Backend, BackendJobId, CellContent, PersistentTaskType, TaskExecutionSpec,
@@ -767,6 +768,7 @@ impl Job {
  ) {
  match self {
  Job::RemoveFromScopes(tasks, scopes) => {
+ let _guard = trace_span!("Job::RemoveFromScopes").entered();
  for task in tasks {
  backend.with_task(task, |task| {
  task.remove_from_scopes(scopes.iter().copied(), backend, turbo_tasks)
@@ -775,6 +777,7 @@ impl Job {
  backend.scope_add_remove_priority.finish_high();
  }
  Job::RemoveFromScope(tasks, scope) => {
+ let _guard = trace_span!("Job::RemoveFromScope").entered();
  for task in tasks {
  backend.with_task(task, |task| {
  task.remove_from_scope(scope, backend, turbo_tasks)
@@ -783,6 +786,7 @@ impl Job {
  backend.scope_add_remove_priority.finish_high();
  }
  Job::ScheduleWhenDirtyFromScope(tasks) => {
+ let _guard = trace_span!("Job::ScheduleWhenDirtyFromScope").entered();
  for task in tasks.into_iter() {
  backend.with_task(task, |task| {
  task.schedule_when_dirty_from_scope(backend, turbo_tasks);
@@ -799,16 +803,20 @@ impl Job {
  .run_low(async {
  run_add_to_scope_queue(queue, scope, merging_scopes, backend, turbo_tasks);
  })
+ .instrument(trace_span!("Job::AddToScopeQueue"))
  .await;
  }
  Job::RemoveFromScopeQueue(queue, id) => {
+ let _guard = trace_span!("Job::AddToScopeQueue").entered();
  run_remove_from_scope_queue(queue, id, backend, turbo_tasks);
  backend.scope_add_remove_priority.finish_high();
  }
  Job::UnloadRootScope(id) => {
+ let span = trace_span!("Job::UnloadRootScope");
  if let Some(future) = turbo_tasks.wait_foreground_done_excluding_own() {
- future.await;
+ future.instrument(span.clone()).await;
  }
+ let _guard = span.entered();
  backend.with_scope(id, |scope| {
  scope.assert_unused();
  });
@@ -817,6 +825,7 @@ impl Job {
  }
  }
  Job::GarbageCollection => {
+ let _guard = trace_span!("Job::GarbageCollection").entered();
  backend.run_gc(true, turbo_tasks);
  }
  }

crates/turbo-tasks/Cargo.toml

@@ -36,6 +36,7 @@ serde_regex = "1.1.0"
 stable_deref_trait = "1.2.0"
 thiserror = { workspace = true }
 tokio = { workspace = true, features = ["full"] }
+tracing = { workspace = true }
 turbo-tasks-hash = { workspace = true }
 turbo-tasks-macros = { workspace = true }
 

crates/turbo-tasks/src/duration_span.rs

@@ -0,0 +1,44 @@
+use std::time::Instant;
+
+/// Guard that emits a tracing event when dropped with the duration of the
+/// lifetime of the guard.
+pub struct DurationSpanGuard<F: FnOnce(u64)> {
+ start: Instant,
+ f: Option<F>,
+}
+
+impl<F: FnOnce(u64)> DurationSpanGuard<F> {
+ pub fn new(f: F) -> Self {
+ Self {
+ start: Instant::now(),
+ f: Some(f),
+ }
+ }
+}
+
+impl<F: FnOnce(u64)> Drop for DurationSpanGuard<F> {
+ fn drop(&mut self) {
+ if let Some(f) = self.f.take() {
+ f(self.start.elapsed().as_micros() as u64);
+ }
+ }
+}
+
+/// Creates a event-based span that traces a certain duration (lifetime of the
+/// guard). It's not a real span, which means it can be used across threads. It
+/// will trace a duration and not the time the cpu is doing actual work. This
+/// way it can be used to trace non-cpu-time or time that is spend in other
+/// processes.
+#[macro_export]
+macro_rules! duration_span {
+ ($name:literal) => {
+ turbo_tasks::duration_span::DurationSpanGuard::new(|duration| {
+ turbo_tasks::macro_helpers::tracing::info!(name = $name, duration = duration);
+ })
+ };
+ ($name:literal, $($arg:tt)+) => {
+ turbo_tasks::duration_span::DurationSpanGuard::new(|duration| {
+ turbo_tasks::macro_helpers::tracing::info!(name = $name, $($arg)+, duration = duration);
+ })
+ };
+}

crates/turbo-tasks/src/graph/graph_traversal.rs

@@ -45,8 +45,9 @@ where
  for edge in root_edges {
  match visit.visit(edge) {
  VisitControlFlow::Continue(node) => {
+ let span = visit.span(&node);
  if let Some((parent_handle, node_ref)) = self.insert(None, GraphNode(node)) {
- futures.push(With::new(visit.edges(node_ref), parent_handle));
+ futures.push(With::new(visit.edges(node_ref), span, parent_handle));
  }
  }
  VisitControlFlow::Skip(node) => {
@@ -146,16 +147,19 @@ where
  GraphTraversalState::Running(mut running) => 'outer: loop {
  let futures_pin = unsafe { Pin::new_unchecked(&mut running.futures) };
  match futures_pin.poll_next(cx) {
- std::task::Poll::Ready(Some((parent_handle, Ok(edges)))) => {
+ std::task::Poll::Ready(Some((parent_handle, span, Ok(edges)))) => {
+ let _guard = span.enter();
  for edge in edges {
  match running.visit.visit(edge) {
  VisitControlFlow::Continue(node) => {
+ let span = running.visit.span(&node);
  if let Some((node_handle, node_ref)) = running
  .store
  .insert(Some(parent_handle.clone()), GraphNode(node))
  {
  running.futures.push(With::new(
  running.visit.edges(node_ref),
+ span,
  node_handle,
  ));
  }
@@ -176,7 +180,7 @@ where
  }
  }
  }
- std::task::Poll::Ready(Some((_, Err(err)))) => {
+ std::task::Poll::Ready(Some((_, _, Err(err)))) => {
  break (
  GraphTraversalState::Completed,
  std::task::Poll::Ready(GraphTraversalResult::Completed(Err(err))),

crates/turbo-tasks/src/graph/visit.rs

@@ -1,6 +1,7 @@
 use std::future::Future;
 
 use anyhow::Result;
+use tracing::Span;
 
 use super::VisitControlFlow;
 
@@ -21,6 +22,13 @@ pub trait Visit<Node, Abort = !, Impl = ()> {
  /// Returns a future that resolves to the outgoing edges of the given
  /// `node`.
  fn edges(&mut self, node: &Node) -> Self::EdgesFuture;
+
+ /// Returns a [Span] for the given `node`, under which all edges are
+ /// processed.
+ fn span(&mut self, node: &Node) -> Span {
+ let _ = node;
+ Span::current()
+ }
 }
 
 // The different `Impl*` here are necessary in order to avoid the `Conflicting

crates/turbo-tasks/src/graph/with_future.rs

@@ -1,6 +1,7 @@
-use std::future::Future;
+use std::{future::Future, mem::replace};
 
 use pin_project_lite::pin_project;
+use tracing::Span;
 
 pin_project! {
  pub struct With<T, H>
@@ -9,6 +10,7 @@ pin_project! {
  {
  #[pin]
  future: T,
+ span: Span,
  handle: Option<H>,
  }
 }
@@ -17,9 +19,10 @@ impl<T, H> With<T, H>
 where
  T: Future,
 {
- pub fn new(future: T, handle: H) -> Self {
+ pub fn new(future: T, span: Span, handle: H) -> Self {
  Self {
  future,
+ span,
  handle: Some(handle),
  }
  }
@@ -29,18 +32,23 @@ impl<T, H> Future for With<T, H>
 where
  T: Future,
 {
- type Output = (H, T::Output);
+ type Output = (H, Span, T::Output);
 
  fn poll(
  self: std::pin::Pin<&mut Self>,
  cx: &mut std::task::Context<'_>,
  ) -> std::task::Poll<Self::Output> {
  let this = self.project();
+ let guard = this.span.enter();
  match this.future.poll(cx) {
- std::task::Poll::Ready(result) => std::task::Poll::Ready((
- this.handle.take().expect("polled after completion"),
- result,
- )),
+ std::task::Poll::Ready(result) => {
+ drop(guard);
+ std::task::Poll::Ready((
+ this.handle.take().expect("polled after completion"),
+ replace(this.span, Span::none()),
+ result,
+ ))
+ }
  std::task::Poll::Pending => std::task::Poll::Pending,
  }
  }

crates/turbo-tasks/src/lib.rs

@@ -38,6 +38,7 @@ mod collectibles;
 mod completion;
 pub mod debug;
 mod display;
+pub mod duration_span;
 pub mod event;
 pub mod graph;
 mod id;
@@ -103,8 +104,9 @@ pub use value_type::{
 #[doc(hidden)]
 pub mod macro_helpers {
  pub use once_cell::sync::{Lazy, OnceCell};
+ pub use tracing;
 
- pub use super::manager::{find_cell_by_type, spawn_detached};
+ pub use super::manager::{find_cell_by_type, notify_scheduled_tasks, spawn_detached};
 }
 
 pub mod test_helpers {