From 2b63dfd71784dbaa3e56258257d87b8964e5594b Mon Sep 17 00:00:00 2001
From: konsti <konstin@mailbox.org>
Date: Fri, 28 Jun 2024 16:45:30 +0200
Subject: [PATCH] Log fork timings (#4618)

This includes a functional change, we now skip the forked state pop/push
if we didn't fork.

From transformers:

```
DEBUG Pre-fork split universal took 0.036s
DEBUG Split python_version >= '3.10' and python_version >= '3.10' and platform_system == 'Darwin' and python_version >= '3.11' and python_version >= '3.12' and python_version >= '3.6' and platform_system == 'Linux' and platform_machine == 'aarch64' took 0.048s
DEBUG Split python_version <= '3.9' and platform_system == 'Darwin' and platform_machine == 'arm64' and python_version >= '3.7' and python_version >= '3.8' and python_version >= '3.9' took 0.038s
```

The messages could use simplification from
https://github.com/astral-sh/uv/issues/4536

We can consider nested spans in the future but this works nicely for
now.
---
 crates/uv-resolver/src/resolver/mod.rs | 26 +++++++++++++++++++++++---
 1 file changed, 23 insertions(+), 3 deletions(-)

diff --git a/crates/uv-resolver/src/resolver/mod.rs b/crates/uv-resolver/src/resolver/mod.rs
index 1c116c600..efb15a9ed 100644
--- a/crates/uv-resolver/src/resolver/mod.rs
+++ b/crates/uv-resolver/src/resolver/mod.rs
@@ -5,6 +5,7 @@ use std::collections::{BTreeMap, VecDeque};
 use std::fmt::{Display, Formatter};
 use std::ops::Bound;
 use std::sync::Arc;
+use std::time::Instant;
 use std::{iter, thread};
 
 use dashmap::DashMap;
@@ -336,6 +337,7 @@ impl<InstalledPackages: InstalledPackagesProvider> ResolverState<InstalledPackag
         }
 
         'FORK: while let Some(mut state) = forked_states.pop() {
+            let start = Instant::now();
             loop {
                 // Run unit propagation.
                 state
@@ -364,6 +366,11 @@ impl<InstalledPackages: InstalledPackagesProvider> ResolverState<InstalledPackag
                     if enabled!(Level::DEBUG) {
                         prefetcher.log_tried_versions();
                     }
+                    debug!(
+                        "Split {} took {:.3}s",
+                        state.markers,
+                        start.elapsed().as_secs_f32()
+                    );
                     resolutions.push(state.into_resolution());
                     continue 'FORK;
                 };
@@ -539,7 +546,7 @@ impl<InstalledPackages: InstalledPackagesProvider> ResolverState<InstalledPackag
                                     version.clone(),
                                     UnavailableReason::Version(reason),
                                 ));
-                            forked_states.push(state);
+                            continue;
                         }
                         ForkedDependencies::Unforked(dependencies) => {
                             state.add_package_version_dependencies(
@@ -560,7 +567,7 @@ impl<InstalledPackages: InstalledPackagesProvider> ResolverState<InstalledPackag
                                 let url = package.name().and_then(|name| state.fork_urls.get(name));
                                 self.visit_package(package, url, &request_sink)?;
                             }
-                            forked_states.push(state);
+                            continue;
                         }
                         ForkedDependencies::Forked {
                             forks,
@@ -580,6 +587,7 @@ impl<InstalledPackages: InstalledPackagesProvider> ResolverState<InstalledPackag
                             // as it needs to be. We basically move the state
                             // into `forked_states`, and then only clone it if
                             // there is at least one more fork to visit.
+                            let markers = state.markers.clone();
                             let mut cur_state = Some(state);
                             let forks_len = forks.len();
                             for (i, fork) in forks.into_iter().enumerate() {
@@ -612,9 +620,21 @@ impl<InstalledPackages: InstalledPackagesProvider> ResolverState<InstalledPackag
                                 }
                                 forked_states.push(forked_state);
                             }
+                            if markers.is_universal() {
+                                debug!(
+                                    "Pre-fork split universal took {:.3}s",
+                                    start.elapsed().as_secs_f32()
+                                );
+                            } else {
+                                debug!(
+                                    "Pre-fork split {} took {:.3}s",
+                                    markers,
+                                    start.elapsed().as_secs_f32()
+                                );
+                            }
+                            continue 'FORK;
                         }
                     }
-                    continue 'FORK;
                 }
                 // `dep_incompats` are already in `incompatibilities` so we know there are not satisfied
                 // terms and can add the decision directly.