Initial tracing implementation (#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

Cargo.toml

@@ -152,6 +152,7 @@ concurrent-queue = "2.1.0"
 console = "0.15.5"
 console-subscriber = "0.1.8"
 criterion = "0.4.0"
+crossbeam-channel = "0.5.8"
 dashmap = "5.4.0"
 dialoguer = "0.10.3"
 dunce = "1.0.3"
@@ -172,6 +173,7 @@ parking_lot = "0.12.1"
 pathdiff = "0.2.1"
 pin-project-lite = "0.2.9"
 port_scanner = "0.1.5"
+postcard = "1.0.4"
 predicates = "2.1.5"
 pretty_assertions = "1.3.0"
 proc-macro2 = "1.0.51"
@@ -194,6 +196,7 @@ tiny-gradient = "0.1.0"
 tokio = "1.25.0"
 tokio-util = { version = "0.7.7", features = ["io"] }
 tracing = "0.1.37"
+tracing-appender = "0.2.2"
 tracing-subscriber = "0.3.16"
 url = "2.2.2"
 urlencoding = "2.1.2"

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 }