From dfc53319bd7dd75ecd009a398394c447609cfc3c Mon Sep 17 00:00:00 2001 From: Tobias Koppers Date: Mon, 21 Oct 2024 14:02:24 +0200 Subject: [PATCH] [Turbopack] add more tracing to dirty flagging (#71482) ### What? trace make task dirty add tracing why tasks are marked as dirty report reason when a page is reloaded --- .../src/server/dev/hot-reloader-turbopack.ts | 1 + .../next/src/server/dev/hot-reloader-types.ts | 1 + .../src/server/dev/hot-reloader-webpack.ts | 10 ++- .../next/src/server/dev/turbopack-utils.ts | 46 +++++++++---- .../turbo-tasks-backend/src/backend/mod.rs | 22 ++++-- .../backend/operation/aggregation_update.rs | 25 +++++-- .../backend/operation/cleanup_old_edges.rs | 15 ++-- .../src/backend/operation/invalidate.rs | 68 +++++++++++++++++-- .../src/backend/operation/mod.rs | 6 ++ .../src/backend/operation/update_cell.rs | 10 ++- .../src/backend/operation/update_output.rs | 27 ++++++-- 11 files changed, 187 insertions(+), 44 deletions(-) diff --git a/packages/next/src/server/dev/hot-reloader-turbopack.ts b/packages/next/src/server/dev/hot-reloader-turbopack.ts index a0b0f1c33fabf..2824854db4897 100644 --- a/packages/next/src/server/dev/hot-reloader-turbopack.ts +++ b/packages/next/src/server/dev/hot-reloader-turbopack.ts @@ -484,6 +484,7 @@ export async function createHotReloaderTurbopack( // reload, only this client is out of date. const reloadAction: ReloadPageAction = { action: HMR_ACTIONS_SENT_TO_BROWSER.RELOAD_PAGE, + data: `error in HMR event subscription for ${id}: ${e}`, } sendToClient(client, reloadAction) client.close() diff --git a/packages/next/src/server/dev/hot-reloader-types.ts b/packages/next/src/server/dev/hot-reloader-types.ts index e1494075e632a..58f0a0c297859 100644 --- a/packages/next/src/server/dev/hot-reloader-types.ts +++ b/packages/next/src/server/dev/hot-reloader-types.ts @@ -76,6 +76,7 @@ interface RemovedPageAction { export interface ReloadPageAction { action: HMR_ACTIONS_SENT_TO_BROWSER.RELOAD_PAGE + data: string } interface ServerComponentChangesAction { diff --git a/packages/next/src/server/dev/hot-reloader-webpack.ts b/packages/next/src/server/dev/hot-reloader-webpack.ts index 88b833e62c344..a7e9e3d29d67c 100644 --- a/packages/next/src/server/dev/hot-reloader-webpack.ts +++ b/packages/next/src/server/dev/hot-reloader-webpack.ts @@ -408,7 +408,10 @@ export default class HotReloaderWebpack implements NextJsHotReloaderInterface { public clearHmrServerError(): void { if (this.hmrServerError) { this.setHmrServerError(null) - this.send({ action: HMR_ACTIONS_SENT_TO_BROWSER.RELOAD_PAGE }) + this.send({ + action: HMR_ACTIONS_SENT_TO_BROWSER.RELOAD_PAGE, + data: 'clear hmr server error', + }) } } @@ -1359,7 +1362,10 @@ export default class HotReloaderWebpack implements NextJsHotReloaderInterface { this.serverPrevDocumentHash = documentChunk.hash || null // Notify reload to reload the page, as _document.js was changed (different hash) - this.send({ action: HMR_ACTIONS_SENT_TO_BROWSER.RELOAD_PAGE }) + this.send({ + action: HMR_ACTIONS_SENT_TO_BROWSER.RELOAD_PAGE, + data: '_document has changed', + }) } ) diff --git a/packages/next/src/server/dev/turbopack-utils.ts b/packages/next/src/server/dev/turbopack-utils.ts index f5ef19282fe06..f5eb125ec23b2 100644 --- a/packages/next/src/server/dev/turbopack-utils.ts +++ b/packages/next/src/server/dev/turbopack-utils.ts @@ -479,8 +479,11 @@ export async function handleRouteType({ pages: [page], } }, - () => { - return { action: HMR_ACTIONS_SENT_TO_BROWSER.RELOAD_PAGE } + (e) => { + return { + action: HMR_ACTIONS_SENT_TO_BROWSER.RELOAD_PAGE, + data: `error in ${page} data subscription: ${e}`, + } } ) hooks?.subscribeToChanges( @@ -492,8 +495,11 @@ export async function handleRouteType({ event: HMR_ACTIONS_SENT_TO_BROWSER.CLIENT_CHANGES, } }, - () => { - return { action: HMR_ACTIONS_SENT_TO_BROWSER.RELOAD_PAGE } + (e) => { + return { + action: HMR_ACTIONS_SENT_TO_BROWSER.RELOAD_PAGE, + data: `error in ${page} html subscription: ${e}`, + } } ) if (entrypoints.global.document) { @@ -502,10 +508,16 @@ export async function handleRouteType({ false, entrypoints.global.document, () => { - return { action: HMR_ACTIONS_SENT_TO_BROWSER.RELOAD_PAGE } + return { + action: HMR_ACTIONS_SENT_TO_BROWSER.RELOAD_PAGE, + data: '_document has changed (page route)', + } }, - () => { - return { action: HMR_ACTIONS_SENT_TO_BROWSER.RELOAD_PAGE } + (e) => { + return { + action: HMR_ACTIONS_SENT_TO_BROWSER.RELOAD_PAGE, + data: `error in _document subscription (page route): ${e}`, + } } ) } @@ -1075,6 +1087,7 @@ export async function handlePagesErrorRoute({ () => { return { action: HMR_ACTIONS_SENT_TO_BROWSER.RELOAD_PAGE, + data: '_app has changed (error route)', } } ) @@ -1096,10 +1109,16 @@ export async function handlePagesErrorRoute({ false, entrypoints.global.document, () => { - return { action: HMR_ACTIONS_SENT_TO_BROWSER.RELOAD_PAGE } + return { + action: HMR_ACTIONS_SENT_TO_BROWSER.RELOAD_PAGE, + data: '_document has changed (error route)', + } }, - () => { - return { action: HMR_ACTIONS_SENT_TO_BROWSER.RELOAD_PAGE } + (e) => { + return { + action: HMR_ACTIONS_SENT_TO_BROWSER.RELOAD_PAGE, + data: `error in _document subscription (error route): ${e}`, + } } ) } @@ -1122,8 +1141,11 @@ export async function handlePagesErrorRoute({ // https://github.com/vercel/next.js/blob/08d7a7e5189a835f5dcb82af026174e587575c0e/packages/next/src/client/page-bootstrap.ts#L69-L71 return { event: HMR_ACTIONS_SENT_TO_BROWSER.CLIENT_CHANGES } }, - () => { - return { action: HMR_ACTIONS_SENT_TO_BROWSER.RELOAD_PAGE } + (e) => { + return { + action: HMR_ACTIONS_SENT_TO_BROWSER.RELOAD_PAGE, + data: `error in _error subscription: ${e}`, + } } ) } diff --git a/turbopack/crates/turbo-tasks-backend/src/backend/mod.rs b/turbopack/crates/turbo-tasks-backend/src/backend/mod.rs index b571bf06005ca..11f44213b7d1b 100644 --- a/turbopack/crates/turbo-tasks-backend/src/backend/mod.rs +++ b/turbopack/crates/turbo-tasks-backend/src/backend/mod.rs @@ -41,7 +41,7 @@ use crate::{ operation::{ get_aggregation_number, is_root_node, AggregatedDataUpdate, AggregationUpdateJob, AggregationUpdateQueue, CleanupOldEdgesOperation, ConnectChildOperation, - ExecuteContext, ExecuteContextImpl, Operation, OutdatedEdge, TaskGuard, + ExecuteContext, ExecuteContextImpl, Operation, OutdatedEdge, TaskDirtyCause, TaskGuard, }, storage::{get, get_many, get_mut, iter_many, remove, Storage}, }, @@ -779,7 +779,11 @@ impl TurboTasksBackendInner { task_id: TaskId, turbo_tasks: &dyn TurboTasksBackendApi>, ) { - operation::InvalidateOperation::run(smallvec![task_id], self.execute_context(turbo_tasks)); + operation::InvalidateOperation::run( + smallvec![task_id], + TaskDirtyCause::Unknown, + self.execute_context(turbo_tasks), + ); } fn invalidate_tasks( @@ -789,6 +793,7 @@ impl TurboTasksBackendInner { ) { operation::InvalidateOperation::run( tasks.iter().copied().collect(), + TaskDirtyCause::Unknown, self.execute_context(turbo_tasks), ); } @@ -800,6 +805,7 @@ impl TurboTasksBackendInner { ) { operation::InvalidateOperation::run( tasks.iter().copied().collect(), + TaskDirtyCause::Unknown, self.execute_context(turbo_tasks), ); } @@ -817,9 +823,11 @@ impl TurboTasksBackendInner { task.invalidate_serialization(); } - fn get_task_description(&self, task: TaskId) -> std::string::String { - let task_type = self.lookup_task_type(task).expect("Task not found"); - task_type.to_string() + fn get_task_description(&self, task_id: TaskId) -> std::string::String { + self.lookup_task_type(task_id).map_or_else( + || format!("{task_id:?} transient"), + |task_type| task_type.to_string(), + ) } fn try_get_function_id(&self, task_id: TaskId) -> Option { @@ -1163,7 +1171,7 @@ impl TurboTasksBackendInner { .get(&cell.type_id) .map_or(false, |range| range.contains(&cell.index)) => { - Some(OutdatedEdge::RemovedCellDependent(task)) + Some(OutdatedEdge::RemovedCellDependent(task, cell.type_id)) } _ => None, }, @@ -1194,7 +1202,7 @@ impl TurboTasksBackendInner { .get(&cell.type_id) .map_or(false, |range| range.contains(&cell.index)) => { - Some(OutdatedEdge::RemovedCellDependent(task)) + Some(OutdatedEdge::RemovedCellDependent(task, cell.type_id)) } _ => None, }) diff --git a/turbopack/crates/turbo-tasks-backend/src/backend/operation/aggregation_update.rs b/turbopack/crates/turbo-tasks-backend/src/backend/operation/aggregation_update.rs index d1619b0854872..b01d8bf4f4b85 100644 --- a/turbopack/crates/turbo-tasks-backend/src/backend/operation/aggregation_update.rs +++ b/turbopack/crates/turbo-tasks-backend/src/backend/operation/aggregation_update.rs @@ -8,11 +8,14 @@ use indexmap::map::Entry; use rustc_hash::{FxHashMap, FxHashSet}; use serde::{Deserialize, Serialize}; use smallvec::SmallVec; -use turbo_tasks::{FxIndexMap, FxIndexSet, SessionId, TaskId}; +use turbo_tasks::{FxIndexMap, FxIndexSet, SessionId, TaskId, TraitTypeId}; use crate::{ backend::{ - operation::{invalidate::make_task_dirty, ExecuteContext, Operation, TaskGuard}, + operation::{ + invalidate::{make_task_dirty, TaskDirtyCause}, + ExecuteContext, Operation, TaskGuard, + }, storage::{get, get_many, iter_many, remove, update, update_count}, TaskDataCategory, }, @@ -101,8 +104,9 @@ pub enum AggregationUpdateJob { upper_ids: Vec, update: AggregatedDataUpdate, }, - Invalidate { + InvalidateDueToCollectiblesChange { task_ids: SmallVec<[TaskId; 4]>, + collectible_type: TraitTypeId, }, BalanceEdge { upper_id: TaskId, @@ -284,8 +288,9 @@ impl AggregatedDataUpdate { } ); if !dependent.is_empty() { - queue.push(AggregationUpdateJob::Invalidate { + queue.push(AggregationUpdateJob::InvalidateDueToCollectiblesChange { task_ids: dependent, + collectible_type: ty, }) } } @@ -556,9 +561,17 @@ impl AggregationUpdateQueue { AggregationUpdateJob::AggregatedDataUpdate { upper_ids, update } => { self.aggregated_data_update(upper_ids, ctx, update); } - AggregationUpdateJob::Invalidate { task_ids } => { + AggregationUpdateJob::InvalidateDueToCollectiblesChange { + task_ids, + collectible_type, + } => { for task_id in task_ids { - make_task_dirty(task_id, self, ctx); + make_task_dirty( + task_id, + TaskDirtyCause::CollectiblesChange { collectible_type }, + self, + ctx, + ); } } } diff --git a/turbopack/crates/turbo-tasks-backend/src/backend/operation/cleanup_old_edges.rs b/turbopack/crates/turbo-tasks-backend/src/backend/operation/cleanup_old_edges.rs index dc7e6c70fb152..20003523bef07 100644 --- a/turbopack/crates/turbo-tasks-backend/src/backend/operation/cleanup_old_edges.rs +++ b/turbopack/crates/turbo-tasks-backend/src/backend/operation/cleanup_old_edges.rs @@ -1,7 +1,7 @@ use std::mem::take; use serde::{Deserialize, Serialize}; -use turbo_tasks::TaskId; +use turbo_tasks::{TaskId, ValueTypeId}; use crate::{ backend::{ @@ -10,7 +10,7 @@ use crate::{ get_aggregation_number, get_uppers, is_aggregating_node, AggregationUpdateJob, AggregationUpdateQueue, }, - invalidate::make_task_dirty, + invalidate::{make_task_dirty, TaskDirtyCause}, AggregatedDataUpdate, ExecuteContext, Operation, TaskGuard, }, storage::{update, update_count}, @@ -41,7 +41,7 @@ pub enum OutdatedEdge { CellDependency(CellRef), OutputDependency(TaskId), CollectiblesDependency(CollectiblesRef), - RemovedCellDependent(TaskId), + RemovedCellDependent(TaskId, ValueTypeId), } impl CleanupOldEdgesOperation { @@ -177,8 +177,13 @@ impl Operation for CleanupOldEdgesOperation { }); } } - OutdatedEdge::RemovedCellDependent(task_id) => { - make_task_dirty(task_id, queue, ctx); + OutdatedEdge::RemovedCellDependent(task_id, value_type) => { + make_task_dirty( + task_id, + TaskDirtyCause::CellRemoved { value_type }, + queue, + ctx, + ); } } } diff --git a/turbopack/crates/turbo-tasks-backend/src/backend/operation/invalidate.rs b/turbopack/crates/turbo-tasks-backend/src/backend/operation/invalidate.rs index 829602599f9bd..4e2de9fc6509b 100644 --- a/turbopack/crates/turbo-tasks-backend/src/backend/operation/invalidate.rs +++ b/turbopack/crates/turbo-tasks-backend/src/backend/operation/invalidate.rs @@ -1,6 +1,8 @@ +use std::fmt::Display; + use serde::{Deserialize, Serialize}; use smallvec::SmallVec; -use turbo_tasks::TaskId; +use turbo_tasks::{registry, TaskId, TraitTypeId, ValueTypeId}; use crate::{ backend::{ @@ -22,6 +24,7 @@ pub enum InvalidateOperation { // TODO DetermineActiveness MakeDirty { task_ids: SmallVec<[TaskId; 4]>, + cause: TaskDirtyCause, }, AggregationUpdate { queue: AggregationUpdateQueue, @@ -31,8 +34,12 @@ pub enum InvalidateOperation { } impl InvalidateOperation { - pub fn run(task_ids: SmallVec<[TaskId; 4]>, mut ctx: impl ExecuteContext) { - InvalidateOperation::MakeDirty { task_ids }.execute(&mut ctx) + pub fn run( + task_ids: SmallVec<[TaskId; 4]>, + cause: TaskDirtyCause, + mut ctx: impl ExecuteContext, + ) { + InvalidateOperation::MakeDirty { task_ids, cause }.execute(&mut ctx) } } @@ -41,10 +48,10 @@ impl Operation for InvalidateOperation { loop { ctx.operation_suspend_point(&self); match self { - InvalidateOperation::MakeDirty { task_ids } => { + InvalidateOperation::MakeDirty { task_ids, cause } => { let mut queue = AggregationUpdateQueue::new(); for task_id in task_ids { - make_task_dirty(task_id, &mut queue, ctx); + make_task_dirty(task_id, cause, &mut queue, ctx); } if queue.is_empty() { self = InvalidateOperation::Done @@ -66,8 +73,50 @@ impl Operation for InvalidateOperation { } } +#[derive(Serialize, Deserialize, Clone, Copy, Debug)] +pub enum TaskDirtyCause { + InitialDirty, + CellChange { value_type: ValueTypeId }, + CellRemoved { value_type: ValueTypeId }, + OutputChange, + CollectiblesChange { collectible_type: TraitTypeId }, + Unknown, +} + +impl Display for TaskDirtyCause { + fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { + match self { + TaskDirtyCause::InitialDirty => write!(f, "initial dirty"), + TaskDirtyCause::CellChange { value_type } => { + write!( + f, + "{} cell changed", + registry::get_value_type(*value_type).name + ) + } + TaskDirtyCause::CellRemoved { value_type } => { + write!( + f, + "{} cell removed", + registry::get_value_type(*value_type).name + ) + } + TaskDirtyCause::OutputChange => write!(f, "task output changed"), + TaskDirtyCause::CollectiblesChange { collectible_type } => { + write!( + f, + "{} collectible changed", + registry::get_trait(*collectible_type).name + ) + } + TaskDirtyCause::Unknown => write!(f, "unknown"), + } + } +} + pub fn make_task_dirty( task_id: TaskId, + cause: TaskDirtyCause, queue: &mut AggregationUpdateQueue, ctx: &mut impl ExecuteContext, ) { @@ -77,13 +126,14 @@ pub fn make_task_dirty( let mut task = ctx.task(task_id, TaskDataCategory::All); - make_task_dirty_internal(&mut task, task_id, true, queue, ctx); + make_task_dirty_internal(&mut task, task_id, true, cause, queue, ctx); } pub fn make_task_dirty_internal( task: &mut impl TaskGuard, task_id: TaskId, make_stale: bool, + cause: TaskDirtyCause, queue: &mut AggregationUpdateQueue, ctx: &impl ExecuteContext, ) { @@ -126,6 +176,12 @@ pub fn make_task_dirty_internal( } _ => unreachable!(), }; + let _span = tracing::trace_span!( + "make task dirty", + name = ctx.get_task_description(task_id), + cause = cause.to_string() + ) + .entered(); let aggregated_update = dirty_container.update_with_dirty_state(&DirtyState { clean_in_session: None, }); diff --git a/turbopack/crates/turbo-tasks-backend/src/backend/operation/mod.rs b/turbopack/crates/turbo-tasks-backend/src/backend/operation/mod.rs index 2319673cb979f..d2ae862c7bd96 100644 --- a/turbopack/crates/turbo-tasks-backend/src/backend/operation/mod.rs +++ b/turbopack/crates/turbo-tasks-backend/src/backend/operation/mod.rs @@ -84,6 +84,7 @@ pub trait ExecuteContext<'e>: Sized { run: impl FnOnce(&mut ExecuteContextImpl<'_, '_, Self::Backend>), ); fn get_task_desc_fn(&self, task_id: TaskId) -> impl Fn() -> String + Send + Sync + 'static; + fn get_task_description(&self, task_id: TaskId) -> String; } pub struct ParentRef<'a> { @@ -333,6 +334,10 @@ where fn get_task_desc_fn(&self, task_id: TaskId) -> impl Fn() -> String + Send + Sync + 'static { self.backend.get_task_desc_fn(task_id) } + + fn get_task_description(&self, task_id: TaskId) -> String { + self.backend.get_task_description(task_id) + } } pub trait TaskGuard: Debug { @@ -653,6 +658,7 @@ pub use self::{ get_aggregation_number, is_root_node, AggregatedDataUpdate, AggregationUpdateJob, }, cleanup_old_edges::OutdatedEdge, + invalidate::TaskDirtyCause, update_cell::UpdateCellOperation, update_collectible::UpdateCollectibleOperation, }; diff --git a/turbopack/crates/turbo-tasks-backend/src/backend/operation/update_cell.rs b/turbopack/crates/turbo-tasks-backend/src/backend/operation/update_cell.rs index e64c8eac8faa4..634726e836966 100644 --- a/turbopack/crates/turbo-tasks-backend/src/backend/operation/update_cell.rs +++ b/turbopack/crates/turbo-tasks-backend/src/backend/operation/update_cell.rs @@ -2,7 +2,7 @@ use turbo_tasks::{backend::CellContent, CellId, TaskId}; use crate::{ backend::{ - operation::{ExecuteContext, InvalidateOperation, TaskGuard}, + operation::{invalidate::TaskDirtyCause, ExecuteContext, InvalidateOperation, TaskGuard}, storage::{get_many, remove}, TaskDataCategory, }, @@ -48,6 +48,12 @@ impl UpdateCellOperation { drop(task); drop(old_content); - InvalidateOperation::run(dependent, ctx); + InvalidateOperation::run( + dependent, + TaskDirtyCause::CellChange { + value_type: cell.type_id, + }, + ctx, + ); } } diff --git a/turbopack/crates/turbo-tasks-backend/src/backend/operation/update_output.rs b/turbopack/crates/turbo-tasks-backend/src/backend/operation/update_output.rs index e5992ebe74c29..980b2ee403720 100644 --- a/turbopack/crates/turbo-tasks-backend/src/backend/operation/update_output.rs +++ b/turbopack/crates/turbo-tasks-backend/src/backend/operation/update_output.rs @@ -7,7 +7,7 @@ use turbo_tasks::{util::SharedError, RawVc, TaskId}; use crate::{ backend::{ operation::{ - invalidate::{make_task_dirty, make_task_dirty_internal}, + invalidate::{make_task_dirty, make_task_dirty_internal, TaskDirtyCause}, AggregationUpdateQueue, ExecuteContext, Operation, TaskGuard, }, storage::{get, get_many}, @@ -108,7 +108,14 @@ impl UpdateOutputOperation { let mut queue = AggregationUpdateQueue::new(); - make_task_dirty_internal(&mut task, task_id, false, &mut queue, &ctx); + make_task_dirty_internal( + &mut task, + task_id, + false, + TaskDirtyCause::InitialDirty, + &mut queue, + &ctx, + ); drop(task); drop(old_content); @@ -134,7 +141,12 @@ impl Operation for UpdateOutputOperation { ref mut queue, } => { if let Some(dependent_task_id) = dependent_tasks.pop() { - make_task_dirty(dependent_task_id, queue, ctx); + make_task_dirty( + dependent_task_id, + TaskDirtyCause::OutputChange, + queue, + ctx, + ); } if dependent_tasks.is_empty() { self = UpdateOutputOperation::EnsureUnfinishedChildrenDirty { @@ -150,7 +162,14 @@ impl Operation for UpdateOutputOperation { if let Some(child_id) = children.pop() { let mut child_task = ctx.task(child_id, TaskDataCategory::Data); if !child_task.has_key(&CachedDataItemKey::Output {}) { - make_task_dirty_internal(&mut child_task, child_id, false, queue, ctx); + make_task_dirty_internal( + &mut child_task, + child_id, + false, + TaskDirtyCause::InitialDirty, + queue, + ctx, + ); } } if children.is_empty() {