add duration to build complete message (#3832)

motivation: give users more information

changes: record build duration and include it in CLI output

Author: tomerd

Sources/Basics/DispatchTimeInterval+Extensions.swift

@@ -56,6 +56,25 @@ extension DispatchTimeInterval {
             return nil
         }
     }
+
+    public 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
+        }
+    }
 }
 
 // remove when available to all platforms
@@ -67,3 +86,4 @@ extension DispatchTime {
     }
 }
 #endif
+

Sources/Build/BuildOperation.swift

@@ -16,6 +16,7 @@ import SPMBuildCore
 import SPMLLBuild
 import TSCBasic
 import TSCUtility
+import Foundation
 
 public final class BuildOperation: PackageStructureDelegate, SPMBuildCore.BuildSystem, BuildErrorAdviceProvider {
 
@@ -130,19 +131,24 @@ public final class BuildOperation: PackageStructureDelegate, SPMBuildCore.BuildS
 
     /// Perform a build using the given build description and subset.
     public func build(subset: BuildSubset) throws {
+        let buildStartTime = DispatchTime.now()
+
         // Create the build system.
         let buildDescription = try self.getBuildDescription()
         let buildSystem = try self.createBuildSystem(buildDescription: buildDescription)
         self.buildSystem = buildSystem
 
-        buildSystemDelegate?.buildStart(configuration: self.buildParameters.configuration)
+        // delegate is only available after createBuildSystem is called
+        self.buildSystemDelegate?.buildStart(configuration: self.buildParameters.configuration)
 
         // Perform the build.
         let llbuildTarget = try computeLLBuildTargetName(for: subset)
         let success = buildSystem.build(target: llbuildTarget)
 
-        buildSystemDelegate?.buildComplete(success: success)
-        delegate?.buildSystem(self, didFinishWithResult: success)
+        let duration = buildStartTime.distance(to: .now())
+
+        self.buildSystemDelegate?.buildComplete(success: success, duration: duration)
+        self.delegate?.buildSystem(self, didFinishWithResult: success)
         guard success else { throw Diagnostics.fatalError }
 
         // Create backwards-compatibility symlink to old build path.

Sources/Build/BuildOperationBuildSystemDelegateHandler.swift

@@ -9,14 +9,14 @@
 */
 
 import Basics
-import TSCBasic
-import TSCUtility
-import SPMLLBuild
-import PackageModel
 import Dispatch
 import Foundation
 import LLBuildManifest
+import PackageModel
 import SPMBuildCore
+import SPMLLBuild
+import TSCBasic
+import TSCUtility
 
 #if canImport(llbuildSwift)
 typealias LLBuildBuildSystemDelegate = llbuildSwift.BuildSystemDelegate
@@ -635,12 +635,12 @@ final class BuildOperationBuildSystemDelegateHandler: LLBuildBuildSystemDelegate
         }
     }
 
-    func buildComplete(success: Bool) {
+    func buildComplete(success: Bool, duration: DispatchTimeInterval) {
         queue.sync {
             self.progressAnimation.complete(success: success)
             if success {
                 self.progressAnimation.clear()
-                self.outputStream <<< "Build complete!\n"
+                self.outputStream <<< "Build complete! (\(duration.descriptionInSeconds))\n"
                 self.outputStream.flush()
             }
         }

Sources/Commands/SwiftTool.swift

@@ -1046,28 +1046,6 @@ extension Basics.Diagnostic {
     }
 }
 
-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
-        }
-    }
-}
-
-
 // MARK: - Diagnostics
 
 private struct SwiftToolObservability: ObservabilityHandlerProvider, DiagnosticsHandler {

Tests/CommandsTests/BuildToolTests.swift

@@ -272,15 +272,17 @@ final class BuildToolTests: CommandsTestCase {
         fixture(name: "DependencyResolution/Internal/Simple") { path in
             do {
                 let result = try execute([], packagePath: path)
-                // Number of steps must be greater than 0. e.g., [8/8] Build complete!
-                XCTAssertMatch(result.stdout, .regex("\\[[1-9][0-9]*\\/[1-9][0-9]*\\] Linking Foo"))
-                XCTAssertMatch(result.stdout, .suffix("\nBuild complete!\n"))
+                XCTAssertMatch(result.stdout, .regex("\\[[1-9][0-9]*\\/[1-9][0-9]*\\] Compiling"))
+                let lines = result.stdout.split(separator: "\n")
+                XCTAssertMatch(String(lines.last!), .regex("Build complete! \\([0-9]*\\.[0-9]*s\\)"))
             }
 
             do {
-                let result = try execute([], packagePath: path)
                 // test second time, to make sure message is presented even when nothing to build (cached)
-                XCTAssertMatch(result.stdout, .equal("[1/1] Planning build\nBuilding for debugging...\nBuild complete!\n"))
+                let result = try execute([], packagePath: path)
+                XCTAssertNoMatch(result.stdout, .regex("\\[[1-9][0-9]*\\/[1-9][0-9]*\\] Compiling"))
+                let lines = result.stdout.split(separator: "\n")
+                XCTAssertMatch(String(lines.last!), .regex("Build complete! \\([0-9]*\\.[0-9]*s\\)"))
             }
         }
     }