[BuildOperation] Include in the build log a summary about the cache hit/miss metrics

This is only when compilation caching is in effect.

rdar://147356859

Author: akyrtzi

Sources/SWBBuildSystem/BuildOperation.swift

@@ -665,8 +665,31 @@ package final class BuildOperation: BuildSystemOperation {
             }
         }
 
+        do {
+            let swiftCacheHits = self.delegate.aggregatedCounters[.swiftCacheHits, default: 0]
+            let swiftCacheMisses = self.delegate.aggregatedCounters[.swiftCacheMisses, default: 0]
+            let clangCacheHits = self.delegate.aggregatedCounters[.clangCacheHits, default: 0]
+            let clangCacheMisses = self.delegate.aggregatedCounters[.clangCacheMisses, default: 0]
+            if swiftCacheHits + swiftCacheMisses > 0 || clangCacheHits + clangCacheMisses > 0 {
+                adaptor.withActivity(ruleInfo: "CompilationCacheMetrics", executionDescription: "Report compilation cache metrics", signature: "compilation_cache_metrics", target: nil, parentActivity: nil) { activity in
+                    func getSummary(hits: Int, misses: Int) -> String {
+                        let hitPercent = Int((Double(hits) / Double(hits + misses) * 100).rounded())
+                        return "\(hits) hit\(hits == 1 ? "" : "s") (\(hitPercent)%), \(misses) miss\(misses == 1 ? "" : "es")"
+                    }
+                    if swiftCacheHits + swiftCacheMisses > 0 {
+                        delegate.emit(data: ByteString(encodingAsUTF8: "Swift compiler: \(getSummary(hits: swiftCacheHits, misses: swiftCacheMisses))").bytes, for: activity, signature: "compilation_cache_metrics")
+                    }
+                    if clangCacheHits + clangCacheMisses > 0 {
+                        delegate.emit(data: ByteString(encodingAsUTF8: "Clang compiler: \(getSummary(hits: clangCacheHits, misses: clangCacheMisses))").bytes, for: activity, signature: "compilation_cache_metrics")
+                    }
+                    return .succeeded
+                }
+
+            }
+        }
+
         if SWBFeatureFlag.enableCacheMetricsLogs.value {
-            adaptor.withActivity(ruleInfo: "CacheMetrics", executionDescription: "Report cache metrics", signature: "cache_metrics", target: nil, parentActivity: nil) { activity in
+            adaptor.withActivity(ruleInfo: "RawCacheMetrics", executionDescription: "Report raw cache metrics", signature: "raw_cache_metrics", target: nil, parentActivity: nil) { activity in
                 struct AllCounters: Encodable {
                     var global: [String: Double] = [:]
                     var tasks: [String: [String: Double]] = [:]
@@ -682,7 +705,7 @@ package final class BuildOperation: BuildSystemOperation {
                     }
                     serializedCounters.tasks[taskId] = serialTaskCounters
                 }
-                delegate.emit(data: ByteString(encodingAsUTF8: "\(serializedCounters)").bytes, for: activity, signature: "cache_metrics")
+                delegate.emit(data: ByteString(encodingAsUTF8: "\(serializedCounters)").bytes, for: activity, signature: "raw_cache_metrics")
                 return .succeeded
             }
         }

Sources/SWBTestSupport/BuildOperationTester.swift

@@ -136,6 +136,9 @@ package final class BuildOperationTester {
         /// A generic activity produced a diagnostic.
         case activityHadDiagnostic(ActivityID, Diagnostic)
 
+        /// A generic activity produced output.
+        case activityEmittedData(ruleInfo: String, [UInt8])
+
         /// A generic activity ended.
         case activityEnded(ruleInfo: String, status: BuildOperationTaskEnded.Status)
 
@@ -179,6 +182,8 @@ package final class BuildOperationTester {
                 return "activityStarted(\(ruleInfo))"
             case .activityHadDiagnostic(let activityID, let diagnostic):
                 return "activityHadDiagnostic(\(activityID),\(diagnostic))"
+            case .activityEmittedData(ruleInfo: let ruleInfo, let bytes):
+                return "activityEmittedData(\(ruleInfo), bytes: \(ByteString(bytes).asString)"
             case .activityEnded(ruleInfo: let ruleInfo):
                 return "activityEnded(\(ruleInfo))"
             case .emittedBuildBacktraceFrame(identifier: let id, previousFrameIdentifier: let previousID, category: let category, description: let description):
@@ -2156,7 +2161,11 @@ private final class BuildOperationTesterDelegate: BuildOperationDelegate {
 
     func emit(data: [UInt8], for activity: ActivityID, signature: ByteString) {
         queue.async {
-            // FIXME.
+            guard let ruleInfo = self.activitiesByActivityID[activity.rawValue] else {
+                assertionFailure("Received emit message for activity id '\(activity.rawValue)' but it was not started, or has already ended")
+                return
+            }
+            self.events.append(.activityEmittedData(ruleInfo: ruleInfo, data))
         }
     }
 

Tests/SWBBuildSystemTests/ClangCompilationCachingTests.swift

@@ -234,6 +234,7 @@ fileprivate struct ClangCompilationCachingTests: CoreBasedTests {
                 // Make sure scanning happens before compilation...
                 results.check(event: .taskHadEvent(scanTask, event: .completed), precedes: .taskHadEvent(compileTask, event: .started))
 
+                results.check(contains: .activityEmittedData(ruleInfo: "CompilationCacheMetrics", ByteString(encodingAsUTF8: "Clang compiler: 0 hits (0%), 1 miss").bytes))
                 results.checkCompileCacheMiss(compileTask)
                 results.checkNoDiagnostics()
             }
@@ -261,6 +262,7 @@ fileprivate struct ClangCompilationCachingTests: CoreBasedTests {
                     // Make sure scanning happens before compilation.
                     results.check(event: .taskHadEvent(scanTask, event: .completed), precedes: .taskHadEvent(compileTask, event: .started))
 
+                    results.check(contains: .activityEmittedData(ruleInfo: "CompilationCacheMetrics", ByteString(encodingAsUTF8: "Clang compiler: 1 hit (100%), 0 misses").bytes))
                     results.checkCompileCacheHit(compileTask)
                 }
                 results.checkNoDiagnostics()

Tests/SWBBuildSystemTests/SwiftCompilationCachingTests.swift

@@ -109,6 +109,8 @@ fileprivate struct SwiftCompilationCachingTests: CoreBasedTests {
                     numCompile += tasks.count
                 }
 
+                results.check(contains: .activityEmittedData(ruleInfo: "CompilationCacheMetrics", ByteString(encodingAsUTF8: "Swift compiler: 0 hits (0%), 4 misses").bytes))
+
                 results.checkNoTask()
             }
             #expect(try readMetrics("one").contains("\"swiftCacheHits\":0,\"swiftCacheMisses\":\(numCompile)"))
@@ -118,7 +120,9 @@ fileprivate struct SwiftCompilationCachingTests: CoreBasedTests {
             try await tester.checkBuild(runDestination: .macOS, buildCommand: .cleanBuildFolder(style: .regular), body: { _ in })
 
             tester.userInfo = rawUserInfo.withAdditionalEnvironment(environment: metricsEnv("two"))
-            try await tester.checkBuild(runDestination: .anyiOSDevice, persistent: true) { _ in }
+            try await tester.checkBuild(runDestination: .anyiOSDevice, persistent: true) { results in
+                results.check(contains: .activityEmittedData(ruleInfo: "CompilationCacheMetrics", ByteString(encodingAsUTF8: "Swift compiler: 4 hits (100%), 0 misses").bytes))
+            }
             #expect(try readMetrics("two").contains("\"swiftCacheHits\":\(numCompile),\"swiftCacheMisses\":0"))
         }
     }