improve output when resolving packages (#3427)

motivation: when resolving packages, the output is lacking key information about computing the appropriate package version. this can mislead users about what SwiftPM is doing and where the time is spent.

changes:
1. expose willComputeVersion/didComputeVersion on WorkspaceDelegate
2. use willComputeVersion/didComputeVersion in SwiftTool::ToolWorkspaceDelegate to print information about the version computation stage
3. add duration information to WorkspaceDelegate::fetchingDidFinish and WorkspaceDelegate::repositoryDidUpdate
4. print duration infortmation SwiftTool::ToolWorkspaceDelegate about fetching and updating, in addition to computing
5. remove empty delegates since they are potentialy hiding dperecations
6. adjust test

Author: tomerd

Sources/Basics/DispatchTimeInterval+Extensions.swift

@@ -57,3 +57,13 @@ extension DispatchTimeInterval {
         }
     }
 }
+
+// remove when available to all platforms
+#if os(Linux) || os(Windows) || os(Android)
+extension DispatchTime {
+    public func distance(to: DispatchTime) -> DispatchTimeInterval {
+        let duration = to.uptimeNanoseconds - self.uptimeNanoseconds
+        return .nanoseconds(duration >= Int.max ? Int.max : Int(duration))
+    }
+}
+#endif

Sources/Commands/SwiftTool.swift

@@ -30,7 +30,6 @@ import Basics
 typealias Diagnostic = TSCBasic.Diagnostic
 
 private class ToolWorkspaceDelegate: WorkspaceDelegate {
-
     /// The stream to use for reporting progress.
     private let stdoutStream: ThreadSafeOutputByteStream
 
@@ -73,7 +72,12 @@ private class ToolWorkspaceDelegate: WorkspaceDelegate {
         }
     }
 
-    func fetchingDidFinish(repository: String, fetchDetails: RepositoryManager.FetchDetails?, diagnostic: Diagnostic?) {
+    func fetchingDidFinish(repository: String, fetchDetails: RepositoryManager.FetchDetails?, diagnostic: Diagnostic?, duration: DispatchTimeInterval) {
+        queue.async {
+            self.stdoutStream <<< "Fetched \(repository) (\(duration.descriptionInSeconds))"
+            self.stdoutStream <<< "\n"
+            self.stdoutStream.flush()
+        }
     }
 
     func repositoryWillUpdate(_ repository: String) {
@@ -84,7 +88,12 @@ private class ToolWorkspaceDelegate: WorkspaceDelegate {
         }
     }
 
-    func repositoryDidUpdate(_ repository: String) {
+    func repositoryDidUpdate(_ repository: String, duration: DispatchTimeInterval) {
+        queue.async {
+            self.stdoutStream <<< "Updated \(repository) (\(duration.descriptionInSeconds))"
+            self.stdoutStream <<< "\n"
+            self.stdoutStream.flush()
+        }
     }
 
     func dependenciesUpToDate() {
@@ -104,8 +113,15 @@ private class ToolWorkspaceDelegate: WorkspaceDelegate {
     }
 
     func willCheckOut(repository: String, revision: String, at path: AbsolutePath) {
+        // noop
+    }
+
+    func didCheckOut(repository: String, revision: String, at path: AbsolutePath, error: Diagnostic?) {
+        guard case .none = error else {
+            return // error will be printed before hand
+        }
         queue.async {
-            self.stdoutStream <<< "Resolving \(repository) at \(revision)"
+            self.stdoutStream <<< "Working copy of \(repository) resolved at \(revision)"
             self.stdoutStream <<< "\n"
             self.stdoutStream.flush()
         }
@@ -185,6 +201,22 @@ private class ToolWorkspaceDelegate: WorkspaceDelegate {
         }
     }
 
+    func willComputeVersion(package: PackageIdentity, location: String) {
+        queue.async {
+            self.stdoutStream <<< "Computing version for \(location)"
+            self.stdoutStream <<< "\n"
+            self.stdoutStream.flush()
+        }
+    }
+
+    func didComputeVersion(package: PackageIdentity, location: String, version: String, duration: DispatchTimeInterval) {
+        queue.async {
+            self.stdoutStream <<< "Computed \(location) at \(version) (\(duration.descriptionInSeconds))"
+            self.stdoutStream <<< "\n"
+            self.stdoutStream.flush()
+        }
+    }
+
     func downloadingBinaryArtifact(from url: String, bytesDownloaded: Int64, totalBytesToDownload: Int64?) {
         queue.async {
             if let totalBytesToDownload = totalBytesToDownload {
@@ -209,6 +241,13 @@ private class ToolWorkspaceDelegate: WorkspaceDelegate {
             self.downloadProgress.removeAll()
         }
     }
+
+    // noop
+    
+    func willLoadManifest(packagePath: AbsolutePath, url: String, version: Version?, packageKind: PackageReference.Kind) {}
+    func didLoadManifest(packagePath: AbsolutePath, url: String, version: Version?, packageKind: PackageReference.Kind, manifest: Manifest?, diagnostics: [Diagnostic]) {}
+    func didCreateWorkingCopy(repository url: String, at path: AbsolutePath, error: Diagnostic?) {}
+    func resolvedFileChanged() {}
 }
 
 /// Handler for the main DiagnosticsEngine used by the SwiftTool class.
@@ -888,3 +927,24 @@ extension Diagnostic.Message {
         .warning("\(flag) is an *unsupported* option which can be removed at any time; do not rely on it")
     }
 }
+
+extension DispatchTimeInterval {
+    var descriptionInSeconds: String {
+        switch self {
+        case .seconds(let value):
+            return "\(value)s"
+        case .milliseconds(let value):
+            return String(format: "%.2f", Double(value)/Double(1000)) + "s"
+        case .microseconds(let value):
+            return String(format: "%.2f", Double(value)/Double(1_000_000)) + "s"
+        case .nanoseconds(let value):
+            return String(format: "%.2f", Double(value)/Double(1_000_000_000)) + "s"
+        case .never:
+            return "n/a"
+        #if os(macOS) || os(iOS) || os(tvOS) || os(watchOS)
+        @unknown default:
+            return "n/a"
+        #endif
+        }
+    }
+}

Sources/PackageGraph/DependencyResolver.swift

@@ -8,8 +8,9 @@
  See http://swift.org/CONTRIBUTORS.txt for Swift project authors
 */
 
-import TSCBasic
+import Dispatch
 import PackageModel
+import TSCBasic
 
 public protocol DependencyResolver {
     typealias Binding = (package: PackageReference, binding: BoundVersion, products: ProductFilter)
@@ -32,14 +33,14 @@ extension DependencyResolverError: CustomStringConvertible {
 
 public protocol DependencyResolverDelegate {
     func willResolve(term: Term)
-    func didResolve(term: Term, version: Version)
+    func didResolve(term: Term, version: Version, duration: DispatchTimeInterval)
 
     func derived(term: Term)
     func conflict(conflict: Incompatibility)
-    func satisfied(term: Term, by: Assignment, incompatibility: Incompatibility)
-    func partiallySatisfied(term: Term, by: Assignment, incompatibility: Incompatibility, difference: Term)
+    func satisfied(term: Term, by assignment: Assignment, incompatibility: Incompatibility)
+    func partiallySatisfied(term: Term, by assignment: Assignment, incompatibility: Incompatibility, difference: Term)
     func failedToResolve(incompatibility: Incompatibility)
-    func computed(bindings: [DependencyResolver.Binding])
+    func solved(result: [DependencyResolver.Binding])
 }
 
 public struct TracingDependencyResolverDelegate: DependencyResolverDelegate {
@@ -57,7 +58,7 @@ public struct TracingDependencyResolverDelegate: DependencyResolverDelegate {
         self.log("resolving: \(term.node.package.location)")
     }
 
-    public func didResolve(term: Term, version: Version) {
+    public func didResolve(term: Term, version: Version, duration: DispatchTimeInterval) {
         self.log("resolved: \(term.node.package.location) @ \(version)")
     }
 
@@ -85,10 +86,10 @@ public struct TracingDependencyResolverDelegate: DependencyResolverDelegate {
         log("CR: new incompatibility \(incompatibility)")
     }
 
-    public func computed(bindings: [DependencyResolver.Binding]) {
+    public func solved(result: [DependencyResolver.Binding]) {
         self.log("solved:")
-        for (container, binding, _) in bindings {
-            self.log("\(container) \(binding)")
+        for (package, binding, _) in result {
+            self.log("\(package) \(binding)")
         }
     }
 
@@ -97,3 +98,44 @@ public struct TracingDependencyResolverDelegate: DependencyResolverDelegate {
         self.stream.flush()
     }
 }
+
+public struct MultiplexResolverDelegate: DependencyResolverDelegate {
+    private let underlying: [DependencyResolverDelegate]
+
+    public init (_ underlying: [DependencyResolverDelegate]) {
+        self.underlying = underlying
+    }
+
+    public func willResolve(term: Term) {
+        underlying.forEach { $0.willResolve(term: term)  }
+    }
+
+    public func didResolve(term: Term, version: Version, duration: DispatchTimeInterval) {
+        underlying.forEach { $0.didResolve(term: term, version: version, duration: duration)  }
+    }
+
+    public func derived(term: Term) {
+        underlying.forEach { $0.derived(term: term)  }
+    }
+
+    public func conflict(conflict: Incompatibility) {
+        underlying.forEach { $0.conflict(conflict: conflict)  }
+    }
+
+    public func satisfied(term: Term, by assignment: Assignment, incompatibility: Incompatibility) {
+        underlying.forEach { $0.satisfied(term: term, by: assignment, incompatibility: incompatibility)  }
+    }
+
+    public func partiallySatisfied(term: Term, by assignment: Assignment, incompatibility: Incompatibility, difference: Term) {
+        underlying.forEach { $0.partiallySatisfied(term: term, by: assignment, incompatibility: incompatibility, difference: difference)  }
+    }
+
+    public func failedToResolve(incompatibility: Incompatibility) {
+        underlying.forEach { $0.failedToResolve(incompatibility: incompatibility)  }
+    }
+
+    public func solved(result: [(package: PackageReference, binding: BoundVersion, products: ProductFilter)]) {
+        underlying.forEach { $0.solved(result: result)  }
+    }
+
+}

Sources/PackageGraph/Pubgrub/PubgrubDependencyResolver.swift

@@ -238,7 +238,7 @@ public struct PubgrubDependencyResolver {
             finalAssignments.append((identifier, override.version, override.products))
         }
 
-        self.delegate?.computed(bindings: finalAssignments)
+        self.delegate?.solved(result: finalAssignments)
 
         return (finalAssignments, state)
     }
@@ -632,6 +632,7 @@ public struct PubgrubDependencyResolver {
         // get conflicts (if any) sooner.
         self.computeCounts(for: undecided) { result in
             do {
+                let start = DispatchTime.now()
                 let counts = try result.get()
                 // forced unwraps safe since we are testing for count and errors above
                 let pkgTerm = undecided.min { counts[$0]! < counts[$1]! }!
@@ -670,7 +671,7 @@ public struct PubgrubDependencyResolver {
 
                 // Decide this version if there was no conflict with its dependencies.
                 if !haveConflict {
-                    self.delegate?.didResolve(term: pkgTerm, version: version)
+                    self.delegate?.didResolve(term: pkgTerm, version: version, duration: start.distance(to: .now()))
                     state.decide(pkgTerm.node, at: version)
                 }
 

Sources/SPMTestSupport/MockWorkspace.swift

@@ -592,6 +592,10 @@ public final class MockWorkspaceDelegate: WorkspaceDelegate {
         self.append("updating repo: \(repository)")
     }
 
+    public func repositoryDidUpdate(_ repository: String, duration: DispatchTimeInterval) {
+        self.append("finished updating repo: \(repository)")
+    }
+
     public func dependenciesUpToDate() {
         self.append("Everything is already up-to-date")
     }
@@ -600,18 +604,26 @@ public final class MockWorkspaceDelegate: WorkspaceDelegate {
         self.append("fetching repo: \(repository)")
     }
 
-    public func fetchingDidFinish(repository: String, fetchDetails: RepositoryManager.FetchDetails?, diagnostic: Diagnostic?) {
+    public func fetchingDidFinish(repository: String, fetchDetails: RepositoryManager.FetchDetails?, diagnostic: Diagnostic?, duration: DispatchTimeInterval) {
         self.append("finished fetching repo: \(repository)")
     }
 
     public func willCreateWorkingCopy(repository url: String, at path: AbsolutePath) {
         self.append("creating working copy for: \(url)")
     }
 
+    public func didCreateWorkingCopy(repository url: String, at path: AbsolutePath, error: Diagnostic?) {
+        self.append("finished creating working copy for: \(url)")
+    }
+
     public func willCheckOut(repository url: String, revision: String, at path: AbsolutePath) {
         self.append("checking out repo: \(url)")
     }
 
+    public func didCheckOut(repository url: String, revision: String, at path: AbsolutePath, error: Diagnostic?) {
+        self.append("finsihed checking out repo: \(url)")
+    }
+
     public func removing(repository: String) {
         self.append("removing repo: \(repository)")
     }
@@ -628,6 +640,26 @@ public final class MockWorkspaceDelegate: WorkspaceDelegate {
         self.append("did load manifest for \(packageKind) package: \(url)")
     }
 
+    public func willComputeVersion(package: PackageIdentity, location: String) {
+        // noop
+    }
+
+    public func didComputeVersion(package: PackageIdentity, location: String, version: String, duration: DispatchTimeInterval) {
+        // noop
+    }
+
+    public func resolvedFileChanged() {
+        // noop
+    }
+
+    public func downloadingBinaryArtifact(from url: String, bytesDownloaded: Int64, totalBytesToDownload: Int64?) {
+        // noop
+    }
+
+    public func didDownloadBinaryArtifacts() {
+        // noop
+    }
+
     private func append(_ event: String) {
         self.lock.withLock {
             self._events.append(event)