improve output when resolving packages (#3427) (#3446)

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.
@@ -920,3 +959,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)