print timing

Author: mischnic

turbopack/crates/turbopack-core/src/module_graph/merged_modules.rs

@@ -73,6 +73,8 @@ pub async fn compute_merged_modules(module_graph: Vc<ModuleGraph>) -> Result<Vc<
         included_modules = tracing::field::Empty
     );
 
+    let start = std::time::Instant::now();
+
     let span = span_outer.clone();
     async move {
         let async_module_info = module_graph.async_module_info().await?;
@@ -99,6 +101,7 @@ pub async fn compute_merged_modules(module_graph: Vc<ModuleGraph>) -> Result<Vc<
         let mut entry_modules =
             FxHashSet::with_capacity_and_hasher(module_count, Default::default());
 
+        let inner_span = tracing::info_span!("collect mergeable modules");
         let mergeable = graphs
             .iter()
             .flat_map(|g| g.iter_nodes())
@@ -113,10 +116,13 @@ pub async fn compute_merged_modules(module_graph: Vc<ModuleGraph>) -> Result<Vc<
                 Ok(None)
             })
             .try_flat_join()
+            .instrument(inner_span)
             .await?
             .into_iter()
             .collect::<FxHashSet<_>>();
 
+        let inner_span = tracing::info_span!("fixed point traversal").entered();
+
         let mut next_index = 0u32;
         let visit_count = module_graph.traverse_edges_fixed_point_with_priority(
             entries.iter().map(|e| (*e, 0)),
@@ -197,6 +203,11 @@ pub async fn compute_merged_modules(module_graph: Vc<ModuleGraph>) -> Result<Vc<
             |_, _| Ok(0),
         )?;
 
+        drop(inner_span);
+        let inner_span = tracing::info_span!("chunk group collection").entered();
+
+        let after_fixed_point = std::time::Instant::now();
+
         span.record("visit_count", visit_count);
 
         #[derive(Debug, PartialEq, Eq, Hash, PartialOrd, Ord)]
@@ -313,6 +324,11 @@ pub async fn compute_merged_modules(module_graph: Vc<ModuleGraph>) -> Result<Vc<
             )?;
         }
 
+        drop(inner_span);
+        let inner_span = tracing::info_span!("exposed computation").entered();
+
+        let after_chunk_groups = std::time::Instant::now();
+
         // We use list.pop() below, so reverse order using negation
         lists_reverse_indices
             .sort_by_cached_key(|_, b| b.iter().map(|o| o.entry).min().map(|v| -(v as i64)));
@@ -363,6 +379,8 @@ pub async fn compute_merged_modules(module_graph: Vc<ModuleGraph>) -> Result<Vc<
             },
         )?;
 
+        drop(inner_span);
+        let inner_span = tracing::info_span!("reconciliation").entered();
         while let Some((_, common_occurrences)) = lists_reverse_indices.pop() {
             if common_occurrences.len() < 2 {
                 // Module exists only in one list, no need to split
@@ -485,10 +503,7 @@ pub async fn compute_merged_modules(module_graph: Vc<ModuleGraph>) -> Result<Vc<
                     lists.push(after_list.clone());
                     for (i, &m) in after_list.iter().enumerate() {
                         let Some(occurrences) = lists_reverse_indices.get_mut(&m) else {
-                            bail!(
-                                "Couldn't find module in list {:?}",
-                                m.ident().to_string().await?,
-                            );
+                            bail!("Couldn't find module in reverse list");
                         };
 
                         let removed = occurrences.swap_remove(&ListOccurrence {
@@ -509,6 +524,10 @@ pub async fn compute_merged_modules(module_graph: Vc<ModuleGraph>) -> Result<Vc<
         // Dedupe the lists
         let lists = lists.into_iter().collect::<FxHashSet<_>>();
 
+        let after_reconcile = std::time::Instant::now();
+
+        drop(inner_span);
+        let inner_span = tracing::info_span!("merging");
         // Call MergeableModule impl to merge the modules.
         let result = lists
             .into_iter()
@@ -570,6 +589,7 @@ pub async fn compute_merged_modules(module_graph: Vc<ModuleGraph>) -> Result<Vc<
                 )))
             })
             .try_join()
+            .instrument(inner_span)
             .await?;
 
         #[allow(clippy::type_complexity)]
@@ -593,6 +613,23 @@ pub async fn compute_merged_modules(module_graph: Vc<ModuleGraph>) -> Result<Vc<
         span.record("merged_groups", replacements.len());
         span.record("included_modules", included.len());
 
+        let end = std::time::Instant::now();
+
+        println!(
+            "Merged modules groups in {} ms (fixed_point: {}, chunk_groups: {}, reconcile: {}), \
+             {} modules, {} visits",
+            after_fixed_point.duration_since(start).as_millis(),
+            after_chunk_groups
+                .duration_since(after_fixed_point)
+                .as_millis(),
+            after_reconcile
+                .duration_since(after_chunk_groups)
+                .as_millis(),
+            end.duration_since(start).as_millis(),
+            module_count,
+            visit_count
+        );
+
         Ok(MergedModuleInfo {
             replacements,
             replacements_to_original,