add user level tracing (vercel/turborepo#6701)

### Description

Add a few user-focused info level spans that can be used to trace a
normal build


Closes PACK-2082

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

@@ -58,7 +58,7 @@ use tokio::{
     io::{AsyncBufReadExt, AsyncReadExt, BufReader},
     sync::{RwLock, RwLockReadGuard},
 };
-use tracing::{instrument, Level};
+use tracing::{instrument, Instrument, Level};
 use turbo_tasks::{
     mark_stateful, spawn_thread, trace::TraceRawVcs, Completion, InvalidationReason, Invalidator,
     ReadRef, ValueToString, Vc,
@@ -591,7 +591,13 @@ impl FileSystem for DiskFileSystem {
         self.register_invalidator(&full_path)?;
 
         let _lock = self.lock_path(&full_path).await;
-        let content = match retry_future(|| File::from_path(full_path.clone())).await {
+        let content = match retry_future(|| File::from_path(full_path.clone()))
+            .instrument(tracing::info_span!(
+                "read file",
+                path = display(full_path.display())
+            ))
+            .await
+        {
             Ok(file) => FileContent::new(file),
             Err(e) if e.kind() == ErrorKind::NotFound => FileContent::NotFound,
             Err(e) => {
@@ -609,7 +615,13 @@ impl FileSystem for DiskFileSystem {
 
         // we use the sync std function here as it's a lot faster (600%) in
         // node-file-trace
-        let read_dir = match retry_blocking(&full_path, |path| std::fs::read_dir(path)).await {
+        let read_dir = match retry_blocking(
+            &full_path,
+            tracing::info_span!("read directory", path = display(full_path.display())),
+            |path| std::fs::read_dir(path),
+        )
+        .await
+        {
             Ok(dir) => dir,
             Err(e)
                 if e.kind() == ErrorKind::NotFound
@@ -660,7 +672,13 @@ impl FileSystem for DiskFileSystem {
         self.register_invalidator(&full_path)?;
 
         let _lock = self.lock_path(&full_path).await;
-        let link_path = match retry_future(|| fs::read_link(&full_path)).await {
+        let link_path = match retry_future(|| fs::read_link(&full_path))
+            .instrument(tracing::info_span!(
+                "read symlink",
+                path = display(full_path.display())
+            ))
+            .await
+        {
             Ok(res) => res,
             Err(_) => return Ok(LinkContent::NotFound.cell()),
         };
@@ -762,7 +780,13 @@ impl FileSystem for DiskFileSystem {
         // be freed immediately. Given this is an output file, it's unlikely any Turbo
         // code will need to read the file from disk into a Vc<FileContent>, so we're
         // not wasting cycles.
-        let compare = content.streaming_compare(full_path.clone()).await?;
+        let compare = content
+            .streaming_compare(full_path.clone())
+            .instrument(tracing::info_span!(
+                "read file before write",
+                path = display(full_path.display())
+            ))
+            .await?;
         if compare == FileComparison::Equal {
             if !old_invalidators.is_empty() {
                 let key = path_to_key(&full_path);
@@ -780,6 +804,10 @@ impl FileSystem for DiskFileSystem {
                 if create_directory {
                     if let Some(parent) = full_path.parent() {
                         retry_future(move || fs::create_dir_all(parent))
+                            .instrument(tracing::info_span!(
+                                "create directory",
+                                path = display(parent.display())
+                            ))
                             .await
                             .with_context(|| {
                                 format!(
@@ -817,11 +845,19 @@ impl FileSystem for DiskFileSystem {
                         Ok::<(), io::Error>(())
                     }
                 })
+                .instrument(tracing::info_span!(
+                    "write file",
+                    path = display(full_path.display())
+                ))
                 .await
                 .with_context(|| format!("failed to write to {}", full_path.display()))?;
             }
             FileContent::NotFound => {
                 retry_future(|| fs::remove_file(full_path.clone()))
+                    .instrument(tracing::info_span!(
+                        "remove file",
+                        path = display(full_path.display())
+                    ))
                     .await
                     .or_else(|err| {
                         if err.kind() == ErrorKind::NotFound {
@@ -861,6 +897,10 @@ impl FileSystem for DiskFileSystem {
         if create_directory {
             if let Some(parent) = full_path.parent() {
                 retry_future(move || fs::create_dir_all(parent))
+                    .instrument(tracing::info_span!(
+                        "create directory",
+                        path = display(parent.display())
+                    ))
                     .await
                     .with_context(|| {
                         format!(
@@ -880,22 +920,26 @@ impl FileSystem for DiskFileSystem {
                 } else {
                     PathBuf::from(unix_to_sys(target).as_ref())
                 };
-                retry_blocking(&target_path, move |target_path| {
-                    // we use the sync std method here because `symlink` is fast
-                    // if we put it into a task, it will be slower
-                    #[cfg(not(target_family = "windows"))]
-                    {
-                        std::os::unix::fs::symlink(target_path, &full_path)
-                    }
-                    #[cfg(target_family = "windows")]
-                    {
-                        if link_type.contains(LinkType::DIRECTORY) {
-                            std::os::windows::fs::symlink_dir(target_path, &full_path)
-                        } else {
-                            std::os::windows::fs::symlink_file(target_path, &full_path)
+                retry_blocking(
+                    &target_path,
+                    tracing::info_span!("write symlink", path = display(full_path.display())),
+                    move |target_path| {
+                        // we use the sync std method here because `symlink` is fast
+                        // if we put it into a task, it will be slower
+                        #[cfg(not(target_family = "windows"))]
+                        {
+                            std::os::unix::fs::symlink(target_path, &full_path)
                         }
-                    }
-                })
+                        #[cfg(target_family = "windows")]
+                        {
+                            if link_type.contains(LinkType::DIRECTORY) {
+                                std::os::windows::fs::symlink_dir(target_path, &full_path)
+                            } else {
+                                std::os::windows::fs::symlink_file(target_path, &full_path)
+                            }
+                        }
+                    },
+                )
                 .await
                 .with_context(|| format!("create symlink to {}", target))?;
             }
@@ -925,6 +969,10 @@ impl FileSystem for DiskFileSystem {
 
         let _lock = self.lock_path(&full_path).await;
         let meta = retry_future(|| fs::metadata(full_path.clone()))
+            .instrument(tracing::info_span!(
+                "read metadata",
+                path = display(full_path.display())
+            ))
             .await
             .with_context(|| format!("reading metadata for {}", full_path.display()))?;
 

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

@@ -23,18 +23,25 @@ where
     }
 }
 
-pub(crate) async fn retry_blocking<R, F>(path: impl AsRef<Path>, func: F) -> io::Result<R>
+pub(crate) async fn retry_blocking<R, F>(
+    path: impl AsRef<Path>,
+    span: tracing::Span,
+    func: F,
+) -> io::Result<R>
 where
     F: Fn(&Path) -> io::Result<R> + Send + 'static,
     R: Send + 'static,
 {
     let path = path.as_ref().to_owned();
 
+    let current_span = tracing::Span::current();
     asyncify(move || {
+        let _entered = current_span.entered();
+        let _entered = span.entered();
         let mut attempt = 1;
 
         loop {
-            return match func(&path) {
+            return match { func(&path) } {
                 Ok(r) => Ok(r),
                 Err(err) => {
                     if attempt < MAX_RETRY_ATTEMPTS && can_retry(&err) {

crates/turbo-tasks/src/manager.rs

@@ -20,7 +20,7 @@ use futures::FutureExt;
 use nohash_hasher::BuildNoHashHasher;
 use serde::{de::Visitor, Deserialize, Serialize};
 use tokio::{runtime::Handle, select, task_local};
-use tracing::{instrument, trace_span, Instrument, Level};
+use tracing::{info_span, instrument, trace_span, Instrument, Level};
 
 use crate::{
     backend::{Backend, CellContent, PersistentTaskType, TransientTaskType},
@@ -1427,7 +1427,7 @@ pub async fn spawn_blocking<T: Send + 'static>(func: impl FnOnce() -> T + Send +
 
 pub fn spawn_thread(func: impl FnOnce() + Send + 'static) {
     let handle = Handle::current();
-    let span = trace_span!("thread").or_current();
+    let span = info_span!("thread").or_current();
     thread::spawn(move || {
         let span = span.entered();
         let guard = handle.enter();

crates/turbopack-build/Cargo.toml

@@ -31,6 +31,7 @@ swc_core = { workspace = true, features = [
   "ecma_minifier",
   "ecma_minifier_concurrent",
 ] }
+tracing = { workspace = true }
 
 turbo-tasks = { workspace = true }
 turbo-tasks-fs = { workspace = true }

crates/turbopack-build/src/chunking_context.rs

@@ -2,7 +2,8 @@ use std::iter::once;
 
 use anyhow::{bail, Context, Result};
 use serde::{Deserialize, Serialize};
-use turbo_tasks::{trace::TraceRawVcs, TaskInput, Value, Vc};
+use tracing::Instrument;
+use turbo_tasks::{trace::TraceRawVcs, TaskInput, Value, ValueToString, Vc};
 use turbo_tasks_fs::FileSystemPath;
 use turbo_tasks_hash::DeterministicHash;
 use turbopack_core::{
@@ -312,24 +313,29 @@ impl ChunkingContext for BuildChunkingContext {
         module: Vc<Box<dyn ChunkableModule>>,
         availability_info: Value<AvailabilityInfo>,
     ) -> Result<Vc<OutputAssets>> {
-        let MakeChunkGroupResult { chunks } = make_chunk_group(
-            Vc::upcast(self),
-            [Vc::upcast(module)],
-            availability_info.into_value(),
-        )
-        .await?;
-
-        let mut assets: Vec<Vc<Box<dyn OutputAsset>>> = chunks
-            .iter()
-            .map(|chunk| self.generate_chunk(*chunk))
-            .collect();
+        let span = tracing::info_span!("chunking", module = *module.ident().to_string().await?);
+        async move {
+            let MakeChunkGroupResult { chunks } = make_chunk_group(
+                Vc::upcast(self),
+                [Vc::upcast(module)],
+                availability_info.into_value(),
+            )
+            .await?;
+
+            let mut assets: Vec<Vc<Box<dyn OutputAsset>>> = chunks
+                .iter()
+                .map(|chunk| self.generate_chunk(*chunk))
+                .collect();
+
+            // Resolve assets
+            for asset in assets.iter_mut() {
+                *asset = asset.resolve().await?;
+            }
 
-        // Resolve assets
-        for asset in assets.iter_mut() {
-            *asset = asset.resolve().await?;
+            Ok(Vc::cell(assets))
         }
-
-        Ok(Vc::cell(assets))
+        .instrument(span)
+        .await
     }
 
     #[turbo_tasks::function]

crates/turbopack-core/src/chunk/mod.rs

@@ -550,7 +550,7 @@ impl Visit<ChunkContentGraphNode, ()> for ChunkContentVisit {
 
     fn span(&mut self, node: &ChunkContentGraphNode) -> Span {
         if let ChunkContentGraphNode::ChunkItem { ident, .. } = node {
-            info_span!("module", name = display(ident))
+            info_span!("chunking module", name = display(ident))
         } else {
             Span::current()
         }

crates/turbopack-core/src/resolve/mod.rs

@@ -1014,13 +1014,28 @@ pub async fn resolve(
     request: Vc<Request>,
     options: Vc<ResolveOptions>,
 ) -> Result<Vc<ResolveResult>> {
-    let raw_result = resolve_internal_inline(lookup_path, request, options)
-        .await?
-        .resolve()
-        .await?;
-    let result =
-        handle_resolve_plugins(lookup_path, reference_type, request, options, raw_result).await?;
-    Ok(result)
+    let span = {
+        let lookup_path = lookup_path.to_string().await?;
+        let request = request.to_string().await?;
+        tracing::info_span!(
+            "resolving",
+            lookup_path = *lookup_path,
+            request = *request,
+            reference_type = display(&*reference_type)
+        )
+    };
+    async {
+        let raw_result = resolve_internal_inline(lookup_path, request, options)
+            .await?
+            .resolve()
+            .await?;
+        let result =
+            handle_resolve_plugins(lookup_path, reference_type, request, options, raw_result)
+                .await?;
+        Ok(result)
+    }
+    .instrument(span)
+    .await
 }
 
 #[turbo_tasks::function]