diff --git a/Sources/BrowserServicesKit/ContentBlocking/ContentBlockerDebugEvents.swift b/Sources/BrowserServicesKit/ContentBlocking/ContentBlockerDebugEvents.swift index 8e5e572ed..f148115a9 100644 --- a/Sources/BrowserServicesKit/ContentBlocking/ContentBlockerDebugEvents.swift +++ b/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) } diff --git a/Sources/BrowserServicesKit/ContentBlocking/ContentBlockerRulesManager.swift b/Sources/BrowserServicesKit/ContentBlocking/ContentBlockerRulesManager.swift index c7cb04bd9..5fc32c28b 100644 --- a/Sources/BrowserServicesKit/ContentBlocking/ContentBlockerRulesManager.swift +++ b/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) } } diff --git a/Sources/BrowserServicesKit/ContentBlocking/ContentBlockingRulesCompilationTask.swift b/Sources/BrowserServicesKit/ContentBlocking/ContentBlockingRulesCompilationTask.swift index eee791ff5..357d36aed 100644 --- a/Sources/BrowserServicesKit/ContentBlocking/ContentBlockingRulesCompilationTask.swift +++ b/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 + } + } } diff --git a/Sources/BrowserServicesKit/ContentBlocking/ContentBlockingRulesLookupTask.swift b/Sources/BrowserServicesKit/ContentBlocking/ContentBlockingRulesLookupTask.swift index fadfc6fbf..e0296d6bb 100644 --- a/Sources/BrowserServicesKit/ContentBlocking/ContentBlockingRulesLookupTask.swift +++ b/Sources/BrowserServicesKit/ContentBlocking/ContentBlockingRulesLookupTask.swift @@ -24,15 +24,13 @@ 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 { @@ -40,7 +38,7 @@ extension ContentBlockerRulesManager { 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) diff --git a/Tests/BrowserServicesKitTests/ContentBlocker/ContentBlockerRulesManagerInitialCompilationTests.swift b/Tests/BrowserServicesKitTests/ContentBlocker/ContentBlockerRulesManagerInitialCompilationTests.swift index 455734d9b..772481b17 100644 --- a/Tests/BrowserServicesKitTests/ContentBlocker/ContentBlockerRulesManagerInitialCompilationTests.swift +++ b/Tests/BrowserServicesKitTests/ContentBlocker/ContentBlockerRulesManagerInitialCompilationTests.swift @@ -62,8 +62,8 @@ final class ContentBlockerRulesManagerInitialCompilationTests: XCTestCase { let errorHandler = EventMapping { 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 { 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 { 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)") } diff --git a/Tests/BrowserServicesKitTests/ContentBlocker/ContentBlockerRulesManagerTests.swift b/Tests/BrowserServicesKitTests/ContentBlocker/ContentBlockerRulesManagerTests.swift index 15321e1ba..a3424bb03 100644 --- a/Tests/BrowserServicesKitTests/ContentBlocker/ContentBlockerRulesManagerTests.swift +++ b/Tests/BrowserServicesKitTests/ContentBlocker/ContentBlockerRulesManagerTests.swift @@ -205,7 +205,6 @@ class ContentBlockerRulesManagerLoadingTests: ContentBlockerRulesManagerTests { errorExp.isInverted = true let lookupAndFetchExp = expectation(description: "Look and Fetch rules failed") - let compilationTimeExp = expectation(description: "Compilation Time reported") let errorHandler = EventMapping { event, _, params, _ in if case .contentBlockingCompilationFailed(let listName, let component) = event { XCTAssertEqual(listName, DefaultContentBlockerRulesListsSource.Constants.trackerDataSetRulesListName) @@ -216,11 +215,10 @@ class ContentBlockerRulesManagerLoadingTests: ContentBlockerRulesManagerTests { XCTFail("Unexpected component: \(component)") } - } else if case .contentBlockingCompilationTime = event { - XCTAssertNotNil(params?["compilationTime"]) - compilationTimeExp.fulfill() } else if case .contentBlockingLRCMissing = event { lookupAndFetchExp.fulfill() + } else if case .contentBlockingCompilationTaskPerformance(let iterationCount, _) = event { + XCTAssertEqual(iterationCount, 1) } else { XCTFail("Unexpected event: \(event)") } @@ -231,7 +229,7 @@ class ContentBlockerRulesManagerLoadingTests: ContentBlockerRulesManagerTests { updateListener: rulesUpdateListener, errorReporting: errorHandler) - wait(for: [exp, errorExp, compilationTimeExp, lookupAndFetchExp], timeout: 15.0) + wait(for: [exp, errorExp, lookupAndFetchExp], timeout: 15.0) XCTAssertNotNil(cbrm.currentRules) XCTAssertEqual(cbrm.currentRules.first?.etag, mockRulesSource.trackerData?.etag) @@ -270,8 +268,8 @@ class ContentBlockerRulesManagerLoadingTests: ContentBlockerRulesManagerTests { XCTFail("Unexpected component: \(component)") } - } else if case .contentBlockingCompilationTime = event { - XCTAssertNotNil(params?["compilationTime"]) + } else if case .contentBlockingCompilationTaskPerformance(let iterationCount, _) = event { + XCTAssertEqual(iterationCount, 2) } else if case .contentBlockingLRCMissing = event { lookupAndFetchExp.fulfill() } else { @@ -546,7 +544,7 @@ class ContentBlockerRulesManagerLoadingTests: ContentBlockerRulesManagerTests { } let errorExp = expectation(description: "Error reported") - errorExp.expectedFulfillmentCount = 5 + errorExp.expectedFulfillmentCount = 4 let lookupAndFetchExp = expectation(description: "Look and Fetch rules failed") @@ -562,11 +560,10 @@ class ContentBlockerRulesManagerLoadingTests: ContentBlockerRulesManagerTests { XCTFail("Unexpected component: \(component)") } - } else if case .contentBlockingCompilationTime = event { - XCTAssertNotNil(params?["compilationTime"]) - errorExp.fulfill() } else if case .contentBlockingLRCMissing = event { lookupAndFetchExp.fulfill() + } else if case .contentBlockingCompilationTaskPerformance(let iterationCount, _) = event { + XCTAssertEqual(iterationCount, 5) } else { XCTFail("Unexpected event: \(event)") } @@ -631,7 +628,7 @@ class ContentBlockerRulesManagerLoadingTests: ContentBlockerRulesManagerTests { } let errorExp = expectation(description: "Error reported") - errorExp.expectedFulfillmentCount = 4 + errorExp.expectedFulfillmentCount = 3 let lookupAndFetchExp = expectation(description: "Look and Fetch rules failed") @@ -647,9 +644,8 @@ class ContentBlockerRulesManagerLoadingTests: ContentBlockerRulesManagerTests { XCTFail("Unexpected component: \(component)") } - } else if case .contentBlockingCompilationTime = event { - XCTAssertNotNil(params?["compilationTime"]) - errorExp.fulfill() + } else if case .contentBlockingCompilationTaskPerformance(let iterationCount, _) = event { + XCTAssertEqual(iterationCount, 4) } else if case .contentBlockingLRCMissing = event { lookupAndFetchExp.fulfill() } else