Initial changes for compilation time tracking.

Sources/BrowserServicesKit/ContentBlocking/ContentBlockerDebugEvents.swift

@@ -46,10 +46,9 @@ public enum ContentBlockerDebugEvents {
 
     case contentBlockingCompilationFailed(listName: String, component: Component)
 
-    case contentBlockingCompilationTime
-
     case contentBlockingLookupRulesSucceeded
     case contentBlockingFetchLRCSucceeded
     case contentBlockingLRCMissing
     case contentBlockingNoMatchInLRC
+    case contentBlockingCompilationTaskPerformance(iterationCount: Int, timeBucketAggregation: Double)
 }

Sources/BrowserServicesKit/ContentBlocking/ContentBlockerRulesManager.swift

@@ -79,7 +79,7 @@ public class ContentBlockerRulesManager: CompiledRuleListsSource {
             self.identifier = identifier
         }
 
-        internal init(compilationResult: (compiledRulesList: WKContentRuleList, model: ContentBlockerRulesSourceModel)) {
+        internal init(compilationResult: CompilationResult) {
             let surrogateTDS = ContentBlockerRulesManager.extractSurrogates(from: compilationResult.model.tds)
             let encodedData = try? JSONEncoder().encode(surrogateTDS)
             let encodedTrackerData = String(data: encodedData!, encoding: .utf8)!
@@ -130,7 +130,6 @@ public class ContentBlockerRulesManager: CompiledRuleListsSource {
     public var sourceManagers = [String: ContentBlockerRulesSourceManager]()
 
     private var currentTasks = [CompilationTask]()
-    private var compilationStartTime: TimeInterval?
 
     private let workQueue = DispatchQueue(label: "ContentBlockerManagerQueue", qos: .userInitiated)
 
@@ -229,7 +228,6 @@ public class ContentBlockerRulesManager: CompiledRuleListsSource {
         }
 
         state = .recompiling(currentTokens: [token])
-        compilationStartTime = compilationStartTime ?? CACurrentMediaTime()
         lock.unlock()
         return true
     }
@@ -243,10 +241,8 @@ public class ContentBlockerRulesManager: CompiledRuleListsSource {
         prepareSourceManagers()
         let initialCompilationTask = LookupRulesTask(sourceManagers: Array(sourceManagers.values))
 
-        let result: [LookupRulesTask.LookupResult]
-
         do {
-            result = try initialCompilationTask.lookupCachedRulesLists()
+            let result = try initialCompilationTask.lookupCachedRulesLists()
 
             let rules = result.map(Rules.init(compilationResult:))
             Logger.contentBlocking.debug("🟩 Lookup Found \(rules.count, privacy: .public) rules")
@@ -301,7 +297,6 @@ public class ContentBlockerRulesManager: CompiledRuleListsSource {
     }
 
     private func startCompilationProcess() {
-        Logger.contentBlocking.debug("Starting compilataion process")
         prepareSourceManagers()
 
         // Prepare compilation tasks based on the sources
@@ -361,10 +356,11 @@ public class ContentBlockerRulesManager: CompiledRuleListsSource {
                 Logger.contentBlocking.debug("Failed to complete task \(task.rulesList.name, privacy: .public)")
                 return nil
             }
+
             let rules = Rules(compilationResult: result)
 
             let diff: ContentBlockerRulesIdentifier.Difference
-            if let id = _currentRules.first(where: {$0.name == task.rulesList.name })?.identifier {
+            if let id = _currentRules.first(where: { $0.name == task.rulesList.name })?.identifier {
                 diff = id.compare(with: result.model.rulesIdentifier)
             } else {
                 diff = result.model.rulesIdentifier.compare(with: ContentBlockerRulesIdentifier(name: task.rulesList.name,
@@ -374,6 +370,15 @@ public class ContentBlockerRulesManager: CompiledRuleListsSource {
                                                                                                 unprotectedSitesHash: nil))
             }
 
+            if task.rulesList.name == DefaultContentBlockerRulesListsSource.Constants.trackerDataSetRulesListName &&
+                result.resultType == .rulesCompilation {
+                if let perfInfo = result.performanceInfo {
+                    self.errorReporting?.fire(.contentBlockingCompilationTaskPerformance(iterationCount: perfInfo.iterationCount,
+                                                                                         timeBucketAggregation: perfInfo.compilationTime),
+                                              parameters: ["compilationTime": String(perfInfo.compilationTime)])
+                }
+            }
+
             changes[task.rulesList.name] = diff
             return rules
         }
@@ -390,7 +395,6 @@ public class ContentBlockerRulesManager: CompiledRuleListsSource {
         _currentRules = rules
 
         let completionTokens: [CompletionToken]
-        let compilationTime = compilationStartTime.map { start in CACurrentMediaTime() - start }
         switch state {
         case .recompilingAndScheduled(let currentTokens, let pendingTokens):
             // New work has been scheduled - prepare for execution.
@@ -400,12 +404,10 @@ public class ContentBlockerRulesManager: CompiledRuleListsSource {
 
             completionTokens = currentTokens
             state = .recompiling(currentTokens: pendingTokens)
-            compilationStartTime = CACurrentMediaTime()
 
         case .recompiling(let currentTokens):
             completionTokens = currentTokens
             state = .idle
-            compilationStartTime = nil
 
         case .idle:
             assertionFailure("Unexpected state")
@@ -418,10 +420,6 @@ public class ContentBlockerRulesManager: CompiledRuleListsSource {
         updatesSubject.send(UpdateEvent(rules: rules, changes: changes, completionTokens: completionTokens))
 
         DispatchQueue.main.async {
-            if let compilationTime = compilationTime {
-                self.errorReporting?.fire(.contentBlockingCompilationTime, parameters: ["compilationTime": String(compilationTime)])
-            }
-
             self.cleanup(currentIdentifiers: currentIdentifiers)
         }
     }

Sources/BrowserServicesKit/ContentBlocking/ContentBlockingRulesCompilationTask.swift

@@ -24,17 +24,42 @@ import os.log
 
 extension ContentBlockerRulesManager {
 
+    internal struct CompilationResult {
+        let compiledRulesList: WKContentRuleList
+        let model: ContentBlockerRulesSourceModel
+        let resultType: ResultType
+        let performanceInfo: PerformanceInfo?
+
+        struct PerformanceInfo {
+            let compilationTime: TimeInterval
+            let iterationCount: Int
+
+            // default iterationCount = 1 for successful compilation on one try
+                init(compilationTime: TimeInterval, iterationCount: Int = 1) {
+                    self.compilationTime = compilationTime
+                    self.iterationCount = iterationCount
+                }
+        }
+
+        enum ResultType {
+            case cacheLookup
+            case rulesCompilation
+        }
+    }
+
     /**
      Encapsulates compilation steps for a single Task
      */
     internal class CompilationTask {
         typealias Completion = (_ task: CompilationTask, _ success: Bool) -> Void
+
         let workQueue: DispatchQueue
         let rulesList: ContentBlockerRulesList
         let sourceManager: ContentBlockerRulesSourceManager
         var isCompleted: Bool { result != nil || compilationImpossible }
         private(set) var compilationImpossible = false
-        private(set) var result: (compiledRulesList: WKContentRuleList, model: ContentBlockerRulesSourceModel)?
+        private(set) var result: CompilationResult?
+        private(set) var compilationStartTime: TimeInterval?
 
         init(workQueue: DispatchQueue,
              rulesList: ContentBlockerRulesList,
@@ -53,6 +78,8 @@ extension ContentBlockerRulesManager {
                     return
                 }
 
+                self.compilationStartTime = CACurrentMediaTime()
+
                 guard !ignoreCache else {
                     Logger.contentBlocking.log("❗️ ignoring cache")
                     self.workQueue.async {
@@ -65,10 +92,14 @@ extension ContentBlockerRulesManager {
                 DispatchQueue.main.async {
                     let identifier = model.rulesIdentifier.stringValue
                     Logger.contentBlocking.debug("Lookup CBR with \(identifier, privacy: .public)")
+
                     WKContentRuleListStore.default()?.lookUpContentRuleList(forIdentifier: identifier) { ruleList, _ in
                         if let ruleList = ruleList {
                             Logger.contentBlocking.log("🟢 CBR loaded from cache: \(self.rulesList.name, privacy: .public)")
-                            self.compilationSucceeded(with: ruleList, model: model, completionHandler: completionHandler)
+                            self.compilationSucceeded(with: ruleList,
+                                                      model: model,
+                                                      resultType: .cacheLookup,
+                                                      completionHandler: completionHandler)
                         } else {
                             self.workQueue.async {
                                 self.compile(model: model, completionHandler: completionHandler)
@@ -81,9 +112,12 @@ extension ContentBlockerRulesManager {
 
         private func compilationSucceeded(with compiledRulesList: WKContentRuleList,
                                           model: ContentBlockerRulesSourceModel,
+                                          resultType: CompilationResult.ResultType,
                                           completionHandler: @escaping Completion) {
             workQueue.async {
-                self.result = (compiledRulesList, model)
+                self.result = self.getCompilationResult(ruleList: compiledRulesList,
+                                                        model: model,
+                                                        resultType: resultType)
                 completionHandler(self, true)
             }
         }
@@ -131,7 +165,10 @@ extension ContentBlockerRulesManager {
 
                     if let ruleList = ruleList {
                         Logger.contentBlocking.log("🟢 CBR compilation for \(self.rulesList.name, privacy: .public) succeeded")
-                        self.compilationSucceeded(with: ruleList, model: model, completionHandler: completionHandler)
+                        self.compilationSucceeded(with: ruleList,
+                                                  model: model,
+                                                  resultType: .rulesCompilation,
+                                                  completionHandler: completionHandler)
                     } else if let error = error {
                         self.compilationFailed(for: model, with: error, completionHandler: completionHandler)
                     } else {
@@ -140,6 +177,41 @@ extension ContentBlockerRulesManager {
                 }
             }
         }
+
+        func getCompilationResult(ruleList: WKContentRuleList,
+                                  model: ContentBlockerRulesSourceModel,
+                                  resultType: CompilationResult.ResultType) -> CompilationResult {
+            let compilationTime = self.compilationStartTime.map { CACurrentMediaTime() - $0 }
+
+            let perfInfo = compilationTime.map {
+                CompilationResult.PerformanceInfo(compilationTime: $0,
+                                                  iterationCount: getCompilationIterationCount())
+            }
+
+            return CompilationResult(compiledRulesList: ruleList,
+                                            model: model,
+                                            resultType: resultType,
+                                     performanceInfo: perfInfo)
+
+        }
+
+        func getCompilationIterationCount() -> Int {
+            guard let brokenSources = sourceManager.brokenSources else {
+                // if none of the sources are broken, we do 1 successful iteration and do not do any retries
+                return 1
+            }
+
+            let identifiers = [
+                brokenSources.allowListIdentifier,
+                brokenSources.tempListIdentifier,
+                brokenSources.unprotectedSitesIdentifier,
+                brokenSources.tdsIdentifier
+            ]
+
+            // Add one to account for the first compilation aside from any retries
+            return (identifiers.compactMap { $0 }.count) + 1
+        }
+
     }
 
 }

Sources/BrowserServicesKit/ContentBlocking/ContentBlockingRulesLookupTask.swift

@@ -24,23 +24,21 @@ extension ContentBlockerRulesManager {
 
     final class LookupRulesTask {
 
-        typealias LookupResult = (compiledRulesList: WKContentRuleList, model: ContentBlockerRulesSourceModel)
-
         private let sourceManagers: [ContentBlockerRulesSourceManager]
 
         init(sourceManagers: [ContentBlockerRulesSourceManager]) {
             self.sourceManagers = sourceManagers
         }
 
-        func lookupCachedRulesLists() throws -> [LookupResult]  {
+        func lookupCachedRulesLists() throws -> [CompilationResult]  {
 
             let models = sourceManagers.compactMap { $0.makeModel() }
             if models.count != sourceManagers.count {
                 // We should only load rule lists, in case we can match every one of the expected ones
                 throw WKError(.contentRuleListStoreLookUpFailed)
             }
 
-            var result = [LookupResult]()
+            var result = [CompilationResult]()
             let group = DispatchGroup()
 
             for model in models {
@@ -54,10 +52,14 @@ extension ContentBlockerRulesManager {
                             return
                         }
 
-                        result.append((ruleList, model))
+                        result.append(CompilationResult(compiledRulesList: ruleList,
+                                                        model: model,
+                                                        resultType: .cacheLookup,
+                                                        performanceInfo: nil))
                         group.leave()
                     }
                 }
+
             }
 
             let operationResult = group.wait(timeout: .now() + 6)

Tests/BrowserServicesKitTests/ContentBlocker/ContentBlockerRulesManagerInitialCompilationTests.swift

@@ -62,8 +62,8 @@ final class ContentBlockerRulesManagerInitialCompilationTests: XCTestCase {
         let errorHandler = EventMapping<ContentBlockerDebugEvents> { event, _, params, _ in
             if case .contentBlockingLRCMissing = event {
                 lookupAndFetchExp.fulfill()
-            } else if case .contentBlockingCompilationTime = event {
-                XCTAssertNotNil(params?["compilationTime"])
+            } else if case .contentBlockingCompilationTaskPerformance(let iterationCount, _) = event {
+                XCTAssertEqual(iterationCount, 1)
             } else {
                 XCTFail("Unexpected event: \(event)")
             }
@@ -123,8 +123,6 @@ final class ContentBlockerRulesManagerInitialCompilationTests: XCTestCase {
                         XCTFail("Should  not fetch LRC")
                     } else if case .contentBlockingLookupRulesSucceeded = event {
                         lookupAndFetchExp.fulfill()
-                    } else if case .contentBlockingCompilationTime = event {
-                        XCTAssertNotNil(params?["compilationTime"])
                     } else {
                         XCTFail("Unexpected event: \(event)")
                     }
@@ -211,10 +209,10 @@ final class ContentBlockerRulesManagerInitialCompilationTests: XCTestCase {
         let errorHandler = EventMapping<ContentBlockerDebugEvents> { event, _, params, _ in
             if case .contentBlockingFetchLRCSucceeded = event {
                 XCTFail("Should  not fetch LRC")
+            } else if case .contentBlockingCompilationTaskPerformance(let iterationCount, _) = event {
+                XCTAssertEqual(iterationCount, 1)
             } else if case .contentBlockingNoMatchInLRC = event {
                 lookupAndFetchExp.fulfill()
-            } else if case .contentBlockingCompilationTime = event {
-                XCTAssertNotNil(params?["compilationTime"])
             } else {
                 XCTFail("Unexpected event: \(event)")
             }
@@ -271,8 +269,8 @@ final class ContentBlockerRulesManagerInitialCompilationTests: XCTestCase {
             let errorHandler = EventMapping<ContentBlockerDebugEvents> { event, _, params, _ in
                 if case .contentBlockingFetchLRCSucceeded = event {
                     lookupAndFetchExp.fulfill()
-                } else if case .contentBlockingCompilationTime = event {
-                    XCTAssertNotNil(params?["compilationTime"])
+                } else if case .contentBlockingCompilationTaskPerformance(let iterationCount, _) = event {
+                    XCTAssertEqual(iterationCount, 1)
                 } else {
                     XCTFail("Unexpected event: \(event)")
                 }