From 96be4d788003f00dc67f0835ddedd9c79ccb70a0 Mon Sep 17 00:00:00 2001 From: Cy-Tek Date: Wed, 21 May 2025 14:28:55 -0400 Subject: [PATCH 1/2] Update the messaging UX on messaging for timing writing files to disk Additional Changes: * Changed severity of "Starting the compilation events sever" to `info` to match other messaging like it * Began printing all compilation events now that it has been proven to work correctly * Added a `TimingEvent` for these types of messages - Made the messaging follow the rules for timing information from how Next.js formats timing info --- crates/napi/src/next_api/project.rs | 19 +++---- .../next/src/build/turbopack-build/impl.ts | 23 +++++++- .../crates/turbo-tasks/src/message_queue.rs | 54 ++++++++++++++++++- 3 files changed, 79 insertions(+), 17 deletions(-) diff --git a/crates/napi/src/next_api/project.rs b/crates/napi/src/next_api/project.rs index 55099d5a616eb..dcec9518bbc3b 100644 --- a/crates/napi/src/next_api/project.rs +++ b/crates/napi/src/next_api/project.rs @@ -31,7 +31,7 @@ use turbo_rcstr::RcStr; use turbo_tasks::{ Completion, Effects, FxIndexSet, OperationVc, ReadRef, ResolvedVc, TransientInstance, TryJoinIterExt, UpdateInfo, Vc, get_effects, - message_queue::{CompilationEvent, DiagnosticEvent, Severity}, + message_queue::{CompilationEvent, DiagnosticEvent, Severity, TimingEvent}, }; use turbo_tasks_fs::{ DiskFileSystem, FileContent, FileSystem, FileSystemPath, get_relative_path_to, @@ -405,8 +405,8 @@ pub async fn project_new( )?; turbo_tasks.send_compilation_event(Arc::new(DiagnosticEvent::new( - "Starting the compilation events server...".to_owned(), - Severity::Trace, + Severity::Info, + "Starting the compilation events server ...".to_owned(), ))); let stats_path = std::env::var_os("NEXT_TURBOPACK_TASK_STATISTICS"); @@ -850,21 +850,14 @@ pub async fn project_write_all_entrypoints_to_disk( // Start timing writing the files to disk let now = Instant::now(); - compilation_event_sender.send_compilation_event(Arc::new(DiagnosticEvent::new( - "Starting to write all entrypoints to disk...".to_owned(), - Severity::Event, - ))); // Write the files to disk effects.apply().await?; // Send a compilation event to indicate that the files have been written to disk - compilation_event_sender.send_compilation_event(Arc::new(DiagnosticEvent::new( - format!( - "Finished writing all entrypoints to disk in {:?}", - now.elapsed() - ), - Severity::Event, + compilation_event_sender.send_compilation_event(Arc::new(TimingEvent::new( + "Finished writing all entrypoints to disk".to_owned(), + now.elapsed(), ))); Ok((entrypoints.clone(), issues.clone(), diagnostics.clone())) diff --git a/packages/next/src/build/turbopack-build/impl.ts b/packages/next/src/build/turbopack-build/impl.ts index 712014c0bc0a5..a3a0f4915a3be 100644 --- a/packages/next/src/build/turbopack-build/impl.ts +++ b/packages/next/src/build/turbopack-build/impl.ts @@ -91,8 +91,27 @@ export async function turbopackBuild(): Promise<{ try { ;(async function logCompilationEvents() { for await (const event of project.compilationEventsSubscribe()) { - if (event.severity === 'EVENT') { - Log.event(event.message) + switch (event.severity) { + case 'EVENT': + Log.event(event.message) + break + case 'TRACE': + Log.trace(event.message) + break + case 'INFO': + Log.info(event.message) + break + case 'WARNING': + console.warn(event.message) + break + case 'ERROR': + Log.error(event.message) + break + case 'FATAL': + Log.error(event.message) + break + default: + break } } })() diff --git a/turbopack/crates/turbo-tasks/src/message_queue.rs b/turbopack/crates/turbo-tasks/src/message_queue.rs index 54f7ee391209f..ef4eabc7a651f 100644 --- a/turbopack/crates/turbo-tasks/src/message_queue.rs +++ b/turbopack/crates/turbo-tasks/src/message_queue.rs @@ -1,4 +1,4 @@ -use std::{any::Any, collections::VecDeque, fmt::Display, sync::Arc}; +use std::{any::Any, collections::VecDeque, fmt::Display, sync::Arc, time::Duration}; use dashmap::DashMap; use tokio::sync::{Mutex, mpsc}; @@ -141,6 +141,56 @@ impl Display for Severity { } } +#[derive(Debug, Clone, serde::Serialize, serde::Deserialize)] +/// Compilation event that is used to log the duration of a task +pub struct TimingEvent { + /// Message of the event without the timing information + /// + /// Example: + /// ```rust + /// let event = TimingEvent::new("Compiled successfully".to_string(), Duration::from_millis(100)); + /// let message = event.message(); + /// assert_eq!(message, "Compiled successfully in 100ms"); + /// ``` + pub message: String, + /// Duration in milliseconds + pub duration: Duration, +} + +impl TimingEvent { + pub fn new(message: String, duration: Duration) -> Self { + Self { message, duration } + } +} + +impl CompilationEvent for TimingEvent { + fn type_name(&self) -> &'static str { + "TimingEvent" + } + + fn severity(&self) -> Severity { + Severity::Event + } + + fn message(&self) -> String { + let duration_secs = self.duration.as_secs_f64(); + let duration_string = if duration_secs > 120.0 { + format!("{:.1}min", duration_secs / 60.0) + } else if duration_secs > 40.0 { + format!("{duration_secs:.0}s") + } else if duration_secs > 2.0 { + format!("{duration_secs:.1}s") + } else { + format!("{:.0}ms", duration_secs * 1000.0) + }; + format!("{} in {}", self.message, duration_string) + } + + fn to_json(&self) -> String { + serde_json::to_string(self).unwrap() + } +} + #[derive(Debug, Clone, serde::Serialize, serde::Deserialize)] pub struct DiagnosticEvent { pub message: String, @@ -148,7 +198,7 @@ pub struct DiagnosticEvent { } impl DiagnosticEvent { - pub fn new(message: String, severity: Severity) -> Self { + pub fn new(severity: Severity, message: String) -> Self { Self { message, severity } } } From de28d75ac6a2460e3c61ed65eeacc74eaf199cd4 Mon Sep 17 00:00:00 2001 From: Joshua Hannaford Date: Fri, 23 May 2025 16:49:11 -0400 Subject: [PATCH 2/2] Update packages/next/src/build/turbopack-build/impl.ts Co-authored-by: Niklas Mischkulnig <4586894+mischnic@users.noreply.github.com> --- .../next/src/build/turbopack-build/impl.ts | 2 +- .../crates/turbo-tasks/src/message_queue.rs | 28 +++++++++++++++++++ 2 files changed, 29 insertions(+), 1 deletion(-) diff --git a/packages/next/src/build/turbopack-build/impl.ts b/packages/next/src/build/turbopack-build/impl.ts index a3a0f4915a3be..47cf2d84ac051 100644 --- a/packages/next/src/build/turbopack-build/impl.ts +++ b/packages/next/src/build/turbopack-build/impl.ts @@ -102,7 +102,7 @@ export async function turbopackBuild(): Promise<{ Log.info(event.message) break case 'WARNING': - console.warn(event.message) + Log.warn(event.message) break case 'ERROR': Log.error(event.message) diff --git a/turbopack/crates/turbo-tasks/src/message_queue.rs b/turbopack/crates/turbo-tasks/src/message_queue.rs index ef4eabc7a651f..d1f404bcb04a8 100644 --- a/turbopack/crates/turbo-tasks/src/message_queue.rs +++ b/turbopack/crates/turbo-tasks/src/message_queue.rs @@ -220,3 +220,31 @@ impl CompilationEvent for DiagnosticEvent { serde_json::to_string(self).unwrap() } } + +#[cfg(test)] +mod tests { + use super::*; + + #[test] + fn test_timing_event_string_formatting() { + let tests = vec![ + (Duration::from_nanos(1588), "0ms"), + (Duration::from_nanos(1022616), "1ms"), + (Duration::from_millis(100), "100ms"), + (Duration::from_millis(1000), "1000ms"), + (Duration::from_millis(10000), "10.0s"), + (Duration::from_millis(20381), "20.4s"), + (Duration::from_secs(60), "60s"), + (Duration::from_secs(100), "100s"), + (Duration::from_secs(125), "2.1min"), + ]; + + for (duration, expected) in tests { + let event = TimingEvent::new("Compiled successfully".to_string(), duration); + assert_eq!( + event.message(), + format!("Compiled successfully in {expected}") + ); + } + } +}