Report os_signposts on Darwin, split warmup reporting

Sources/Benchmark/BenchmarkReporter.swift

@@ -14,9 +14,19 @@
 
 import Foundation
 
+#if canImport(OSLog)
+    import OSLog
+#endif
+
 protocol ProgressReporter {
-    mutating func report(running name: String, suite: String)
-    mutating func report(finishedRunning name: String, suite: String, nanosTaken: UInt64)
+    mutating func reportWillBeginBenchmark(_ benchmark: AnyBenchmark, suite: BenchmarkSuite)
+    mutating func reportFinishedBenchmark(nanosTaken: UInt64)
+
+    mutating func reportWarmingUp()
+    mutating func reportFinishedWarmup(nanosTaken: UInt64)
+
+    mutating func reportRunning()
+    mutating func reportFinishedRunning(nanosTaken: UInt64)
 }
 
 protocol BenchmarkReporter {
@@ -25,32 +35,84 @@ protocol BenchmarkReporter {
 
 struct VerboseProgressReporter<Output: FlushableTextOutputStream>: ProgressReporter {
     var output: Output
+    var currentBenchmarkQualifiedName: String
+    #if canImport(OSLog)
+        var currentOSLog: Any?
+    #endif
 
     init(output: Output) {
         self.output = output
+        self.currentBenchmarkQualifiedName = ""
+        self.currentOSLog = nil
     }
 
-    mutating func report(running name: String, suite: String) {
+    mutating func reportWillBeginBenchmark(_ benchmark: AnyBenchmark, suite: BenchmarkSuite) {
+
         let prefix: String
-        if suite != "" {
-            prefix = "\(suite): "
+        if suite.name != "" {
+            prefix = "\(suite.name): "
         } else {
             prefix = ""
         }
-        print("running \(prefix)\(name)...", terminator: "", to: &output)
+        self.currentBenchmarkQualifiedName = "\(prefix)\(benchmark.name)"
+        #if canImport(OSLog)
+            if #available(macOS 10.14, iOS 12.0, watchOS 5.0, tvOS 12.0, *) {
+                currentOSLog = OSLog(
+                    subsystem: currentBenchmarkQualifiedName, category: .pointsOfInterest)
+            }
+        #endif
+    }
+
+    mutating func reportWarmingUp() {
+        print("Warming up... ", terminator: "", to: &output)
+        output.flush()
+        #if canImport(OSLog)
+            if #available(macOS 10.14, iOS 12.0, watchOS 5.0, tvOS 12.0, *) {
+                os_signpost(.begin, log: currentOSLog as! OSLog, name: "Warmup")
+            }
+        #endif
+    }
+
+    mutating func reportFinishedWarmup(nanosTaken: UInt64) {
+        #if canImport(OSLog)
+            if #available(macOS 10.14, iOS 12.0, watchOS 5.0, tvOS 12.0, *) {
+                os_signpost(.end, log: currentOSLog as! OSLog, name: "Warmup")
+            }
+        #endif
+    }
+
+    mutating func reportRunning() {
+        print("Running \(currentBenchmarkQualifiedName)... ", terminator: "", to: &output)
         output.flush()
+        #if canImport(OSLog)
+            if #available(macOS 10.14, iOS 12.0, watchOS 5.0, tvOS 12.0, *) {
+                os_signpost(.begin, log: currentOSLog as! OSLog, name: "Benchmark")
+            }
+        #endif
+    }
+
+    mutating func reportFinishedRunning(nanosTaken: UInt64) {
+        #if canImport(OSLog)
+            if #available(macOS 10.14, iOS 12.0, watchOS 5.0, tvOS 12.0, *) {
+                os_signpost(.end, log: currentOSLog as! OSLog, name: "Benchmark")
+            }
+        #endif
     }
 
-    mutating func report(finishedRunning name: String, suite: String, nanosTaken: UInt64) {
+    mutating func reportFinishedBenchmark(nanosTaken: UInt64) {
         let timeDuration = String(format: "%.2f ms", Float(nanosTaken) / 1000000.0)
-        print(" done! (\(timeDuration))", to: &output)
+        print("Done! (\(timeDuration))", to: &output)
         output.flush()
     }
 }
 
 struct QuietReporter: ProgressReporter, BenchmarkReporter {
-    mutating func report(running name: String, suite: String) {}
-    mutating func report(finishedRunning name: String, suite: String, nanosTaken: UInt64) {}
+    mutating func reportWillBeginBenchmark(_ benchmark: AnyBenchmark, suite: BenchmarkSuite) {}
+    mutating func reportWarmingUp() {}
+    mutating func reportFinishedWarmup(nanosTaken: UInt64) {}
+    mutating func reportRunning() {}
+    mutating func reportFinishedRunning(nanosTaken: UInt64) {}
+    mutating func reportFinishedBenchmark(nanosTaken: UInt64) {}
     mutating func report(results: [BenchmarkResult]) {}
 }
 

Sources/Benchmark/BenchmarkRunner.swift

@@ -85,15 +85,21 @@ public struct BenchmarkRunner {
             return
         }
 
-        progress.report(running: benchmark.name, suite: suite.name)
+        progress.reportWillBeginBenchmark(benchmark, suite: suite)
         let totalStart = now()
 
         var warmupState: BenchmarkState? = nil
         if settings.warmupIterations > 0 {
-            warmupState = doNIterations(
+            progress.reportWarmingUp()
+            let state = doNIterations(
                 settings.warmupIterations, benchmark: benchmark, suite: suite, settings: settings)
+            let warmupElapsed = state.endTime - state.startTime
+            progress.reportFinishedWarmup(nanosTaken: warmupElapsed)
+            warmupState = state
         }
 
+        progress.reportRunning()
+
         var state: BenchmarkState
         if let n = settings.iterations {
             state = doNIterations(n, benchmark: benchmark, suite: suite, settings: settings)
@@ -105,8 +111,8 @@ public struct BenchmarkRunner {
         let totalEnd = now()
         let totalElapsed = totalEnd - totalStart
 
-        progress.report(
-            finishedRunning: benchmark.name, suite: suite.name, nanosTaken: totalElapsed)
+        progress.reportFinishedRunning(nanosTaken: state.endTime - state.startTime)
+        progress.reportFinishedBenchmark(nanosTaken: totalElapsed)
 
         let result = BenchmarkResult(
             benchmarkName: benchmark.name,

Tests/BenchmarkTests/CMakeLists.txt

@@ -7,6 +7,7 @@ add_library(BenchmarkTests
   BenchmarkSuiteTests.swift
   CustomBenchmarkTests.swift
   MockTextOutputStream.swift
+  ProgressReporterTests.swift
   StatsTests.swift
   XCTTestManifests.swift)
 

Tests/BenchmarkTests/ProgressReporterTests.swift

@@ -0,0 +1,139 @@
+// Copyright 2022 Google LLC
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+//      http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+
+import XCTest
+
+@testable import Benchmark
+
+final class ProgressReporterTests: XCTestCase {
+
+    fileprivate var dummySuite: BenchmarkSuite {
+        BenchmarkSuite(name: "SomeSuite") { suite in
+            suite.benchmark("SomeBenchmark") { /* No-op */  }
+            suite.benchmark("AnotherBenchmark") { /* No-op */  }
+        }
+    }
+
+    open class DummyProgressReporterBase: ProgressReporter {
+        var didReportWillBegin = false
+        var didReportWarmingUp = false
+        var didReportFinishedWarmup = false
+        var didReportRunning = false
+        var didReportFinishedRunning = false
+        var benchmarksFinished = 0
+
+        init() {}
+
+        private func resetCallbackFlags() {
+            didReportWillBegin = false
+            didReportWarmingUp = false
+            didReportFinishedWarmup = false
+            didReportRunning = false
+            didReportFinishedRunning = false
+        }
+
+        open func reportWillBeginBenchmark(_ benchmark: AnyBenchmark, suite: BenchmarkSuite) {
+            resetCallbackFlags()
+            didReportWillBegin = true
+        }
+
+        open func reportFinishedBenchmark(nanosTaken: UInt64) {
+            resetCallbackFlags()
+            benchmarksFinished += 1
+        }
+
+        open func reportWarmingUp() {
+            didReportWarmingUp = true
+        }
+
+        open func reportFinishedWarmup(nanosTaken: UInt64) {
+            didReportFinishedWarmup = true
+        }
+
+        open func reportRunning() {
+            didReportRunning = true
+        }
+
+        open func reportFinishedRunning(nanosTaken: UInt64) {
+            didReportFinishedRunning = true
+        }
+    }
+
+    func testProgressReportNoWarmup() throws {
+
+        class Reporter: DummyProgressReporterBase {
+            var remainingBenchmarks = ["SomeBenchmark", "AnotherBenchmark"]
+
+            override func reportWillBeginBenchmark(
+                _ benchmark: AnyBenchmark, suite: BenchmarkSuite
+            ) {
+                super.reportWillBeginBenchmark(benchmark, suite: suite)
+                XCTAssertEqual(benchmark.name, remainingBenchmarks.removeFirst())
+                XCTAssertEqual(suite.name, "SomeSuite")
+            }
+            override func reportFinishedBenchmark(nanosTaken: UInt64) {
+                XCTAssertTrue(didReportWillBegin)
+                XCTAssertFalse(didReportWarmingUp)
+                XCTAssertFalse(didReportFinishedWarmup)
+                XCTAssertTrue(didReportRunning)
+                XCTAssertTrue(didReportFinishedRunning)
+                super.reportFinishedBenchmark(nanosTaken: nanosTaken)
+            }
+        }
+
+        let reporter = Reporter()
+        var runner = BenchmarkRunner(suites: [dummySuite], settings: [Iterations(5)])
+        runner.progress = reporter
+        try runner.run()
+        XCTAssertEqual(reporter.remainingBenchmarks, [])
+        XCTAssertEqual(reporter.benchmarksFinished, 2)
+    }
+
+    func testProgressReportWithWarmup() throws {
+
+        class Reporter: DummyProgressReporterBase {
+            var remainingBenchmarks = ["SomeBenchmark", "AnotherBenchmark"]
+
+            override func reportWillBeginBenchmark(
+                _ benchmark: AnyBenchmark, suite: BenchmarkSuite
+            ) {
+                super.reportWillBeginBenchmark(benchmark, suite: suite)
+                XCTAssertEqual(benchmark.name, remainingBenchmarks.removeFirst())
+                XCTAssertEqual(suite.name, "SomeSuite")
+            }
+            override func reportFinishedBenchmark(nanosTaken: UInt64) {
+                XCTAssertTrue(didReportWillBegin)
+                XCTAssertTrue(didReportWarmingUp)
+                XCTAssertTrue(didReportFinishedWarmup)
+                XCTAssertTrue(didReportRunning)
+                XCTAssertTrue(didReportFinishedRunning)
+                super.reportFinishedBenchmark(nanosTaken: nanosTaken)
+            }
+        }
+
+        let reporter = Reporter()
+        var runner = BenchmarkRunner(
+            suites: [dummySuite], settings: [WarmupIterations(42), Iterations(5)]
+        )
+        runner.progress = reporter
+        try runner.run()
+        XCTAssertEqual(reporter.remainingBenchmarks, [])
+        XCTAssertEqual(reporter.benchmarksFinished, 2)
+    }
+
+    static var allTests = [
+        ("testProgressReportNoWarmup", testProgressReportNoWarmup),
+        ("testProgressReportWithWarmup", testProgressReportWithWarmup),
+    ]
+}

Tests/BenchmarkTests/XCTTestManifests.swift

@@ -24,6 +24,7 @@ import XCTest
             testCase(BenchmarkSettingTests.allTests),
             testCase(BenchmarkSuiteTests.allTests),
             testCase(CustomBenchmarkTests.allTests),
+            testCase(ProgressReporterTests.allTests),
             testCase(StatsTests.allTests),
         ]
     }