diff --git a/shell_integration/MacOSX/NextcloudFileProviderKit/Sources/NextcloudFileProviderKit/Database/FilesDatabaseManager.swift b/shell_integration/MacOSX/NextcloudFileProviderKit/Sources/NextcloudFileProviderKit/Database/FilesDatabaseManager.swift index 589ff35ce4bf7..38767454a53f9 100644 --- a/shell_integration/MacOSX/NextcloudFileProviderKit/Sources/NextcloudFileProviderKit/Database/FilesDatabaseManager.swift +++ b/shell_integration/MacOSX/NextcloudFileProviderKit/Sources/NextcloudFileProviderKit/Database/FilesDatabaseManager.swift @@ -31,7 +31,7 @@ public final class FilesDatabaseManager: Sendable { ) } - private static let schemaVersion = SchemaVersion.addedCanonicalPathKeysToRealmItemMetadata + private static let schemaVersion = SchemaVersion.addedNormalizedFileNameIndexToRealmItemMetadata let logger: FileProviderLogger let account: Account @@ -269,14 +269,18 @@ public final class FilesDatabaseManager: Sendable { existingMetadatas: Results, updatedMetadatas: [SendableItemMetadata] ) -> [RealmItemMetadata] { + // O(1) membership test instead of a per-existing linear scan of `updatedMetadatas`. The previous + // `updatedMetadatas.contains(where:)` made this loop O(existing × updated) — with the linear scan + // in `processItemMetadatasToUpdate` it was the dominant cost of a large non-paginated depth-1 + // write (measured ≈19 min, never completing, for a 6982-item flat folder; no index can fix an + // in-memory scan). `existingMetadata` is already the managed row from the caller's `database` + // handle and is value-copied before the write, so it is used directly — this also removes the + // per-item `itemMetadatas` (`ncDatabase()`) re-open the old `.where{}.first` fetch incurred. + let updatedOcIds = Set(updatedMetadatas.map(\.ocId)) var deletedMetadatas: [RealmItemMetadata] = [] - for existingMetadata in existingMetadatas { - guard !updatedMetadatas.contains(where: { $0.ocId == existingMetadata.ocId }), - let metadataToDelete = itemMetadatas.where({ $0.ocId == existingMetadata.ocId }).first - else { continue } - - deletedMetadatas.append(metadataToDelete) + for existingMetadata in existingMetadatas where !updatedOcIds.contains(existingMetadata.ocId) { + deletedMetadatas.append(existingMetadata) logger.debug("Deleting item metadata during update.", [.item: existingMetadata.ocId]) } @@ -289,8 +293,22 @@ public final class FilesDatabaseManager: Sendable { var returningUpdatedMetadatas: [SendableItemMetadata] = [] var directoriesNeedingRename: [SendableItemMetadata] = [] + // O(1) ocId lookup instead of `existingMetadatas.first(where:)` — the old per-item linear scan of + // a Realm `Results` was O(updated × existing), the other half of the measured O(N²) large-folder + // write. Keyed once up front (first occurrence wins, matching `.first(where:)`). + var existingByOcId: [String: RealmItemMetadata] = [:] + existingByOcId.reserveCapacity(existingMetadatas.count) + for existingMetadata in existingMetadatas where existingByOcId[existingMetadata.ocId] == nil { + existingByOcId[existingMetadata.ocId] = existingMetadata + } + + // `inheritedKeepDownloaded` depends on the item only through (account, parent serverUrl); every + // child of a folder shares one serverUrl, so cache per serverUrl to collapse N parent lookups + // (each a DB query) to one per distinct parent. + var inheritedKeepDownloadedByServerUrl: [String: Bool] = [:] + for var updatedMetadata in updatedMetadatas { - if let existingMetadata = existingMetadatas.first(where: { $0.ocId == updatedMetadata.ocId }) { + if let existingMetadata = existingByOcId[updatedMetadata.ocId] { if existingMetadata.status == Status.normal.rawValue, !existingMetadata.isInSameDatabaseStoreableRemoteState(updatedMetadata) { let pathChanged = !updatedMetadata.hasSameLocation(as: existingMetadata) @@ -325,7 +343,13 @@ public final class FilesDatabaseManager: Sendable { } else { // This is a new metadata // Inherit the parent's "Always keep downloaded" flag so a file surfacing here via remote enumeration acquires the same pin as its already-pinned siblings (#10054). - updatedMetadata.keepDownloaded = inheritedKeepDownloaded(for: updatedMetadata) + if let cached = inheritedKeepDownloadedByServerUrl[updatedMetadata.serverUrl] { + updatedMetadata.keepDownloaded = cached + } else { + let inherited = inheritedKeepDownloaded(for: updatedMetadata) + inheritedKeepDownloadedByServerUrl[updatedMetadata.serverUrl] = inherited + updatedMetadata.keepDownloaded = inherited + } returningNewMetadatas.append(updatedMetadata) diff --git a/shell_integration/MacOSX/NextcloudFileProviderKit/Sources/NextcloudFileProviderKit/Database/SchemaVersion.swift b/shell_integration/MacOSX/NextcloudFileProviderKit/Sources/NextcloudFileProviderKit/Database/SchemaVersion.swift index 40cacb36d37f8..88c4ac2da1030 100644 --- a/shell_integration/MacOSX/NextcloudFileProviderKit/Sources/NextcloudFileProviderKit/Database/SchemaVersion.swift +++ b/shell_integration/MacOSX/NextcloudFileProviderKit/Sources/NextcloudFileProviderKit/Database/SchemaVersion.swift @@ -10,4 +10,5 @@ enum SchemaVersion: UInt64 { case addedLockTokenPropertyToRealmItemMetadata = 201 case addedIsLockFileOfLocalOriginToRealmItemMetadata = 202 case addedCanonicalPathKeysToRealmItemMetadata = 203 + case addedNormalizedFileNameIndexToRealmItemMetadata = 204 } diff --git a/shell_integration/MacOSX/NextcloudFileProviderKit/Sources/NextcloudFileProviderKit/Enumeration/Enumerator+ItemEnumeration.swift b/shell_integration/MacOSX/NextcloudFileProviderKit/Sources/NextcloudFileProviderKit/Enumeration/Enumerator+ItemEnumeration.swift index 1508504496287..1ac511ae1e56f 100644 --- a/shell_integration/MacOSX/NextcloudFileProviderKit/Sources/NextcloudFileProviderKit/Enumeration/Enumerator+ItemEnumeration.swift +++ b/shell_integration/MacOSX/NextcloudFileProviderKit/Sources/NextcloudFileProviderKit/Enumeration/Enumerator+ItemEnumeration.swift @@ -67,6 +67,21 @@ extension Enumerator { logger.debug("Enumerating page: \(String(data: page.rawValue, encoding: .utf8) ?? "")", [.account: account.ncKitAccount, .url: serverUrl]) Task { + // Bound the synchronous page work (cursor decode + capabilities + network + convert + + // persist) for a trace, and record its wall-clock for the JSONL fallback. The `defer` ends + // the interval on every exit — including the error returns below — so no interval dangles. + // The trailing observer conversion/report runs in a detached Task and is captured by the + // separate `ToFileProviderItems` / `ObserverReport` signposts. + let signposter = EnumerationSignposter.signposter + let pageWorkState = signposter.beginInterval( + "EnumeratePageWork", + id: signposter.makeSignpostID(), + "serverUrl=\(self.serverUrl, privacy: .public)" + ) + defer { signposter.endInterval("EnumeratePageWork", pageWorkState) } + let pageWorkClock = ContinuousClock() + let pageWorkStart = pageWorkClock.now + let cursor = paginationCursor(from: page) // Check server version to determine if pagination should be enabled. @@ -149,6 +164,12 @@ extension Enumerator { rawNextPage = nil } + let pageWorkElapsed = pageWorkClock.now - pageWorkStart + logger.performance( + "PERF EnumeratePageWork items=\(items.count) page_work_s=\(pageWorkElapsed.fpSeconds) hasNextPage=\(rawNextPage != nil)", + [.url: self.serverUrl] + ) + completeEnumerationObserver(observer, nextPage: rawNextPage, itemMetadatas: items) } } diff --git a/shell_integration/MacOSX/NextcloudFileProviderKit/Sources/NextcloudFileProviderKit/Enumeration/Enumerator+ObserverReporting.swift b/shell_integration/MacOSX/NextcloudFileProviderKit/Sources/NextcloudFileProviderKit/Enumeration/Enumerator+ObserverReporting.swift index 62c73d0b1d3bb..13192a1481d72 100644 --- a/shell_integration/MacOSX/NextcloudFileProviderKit/Sources/NextcloudFileProviderKit/Enumeration/Enumerator+ObserverReporting.swift +++ b/shell_integration/MacOSX/NextcloudFileProviderKit/Sources/NextcloudFileProviderKit/Enumeration/Enumerator+ObserverReporting.swift @@ -24,17 +24,30 @@ extension Enumerator { handleInvalidParent: Bool = true ) { Task { + let signposter = EnumerationSignposter.signposter + let toItemsState = signposter.beginInterval( + "ToFileProviderItems", + id: signposter.makeSignpostID(), + "count=\(itemMetadatas.count)" + ) do { let items = try await itemMetadatas.toFileProviderItems( account: account, remoteInterface: remoteInterface, dbManager: dbManager, log: self.logger.log ) + signposter.endInterval("ToFileProviderItems", toItemsState) Task { @MainActor in + // Begin/end stay in this MainActor scope; both observer calls are synchronous. + let reportState = signposter.beginInterval( + "ObserverReport", id: signposter.makeSignpostID(), "items=\(items.count)" + ) observer.didEnumerate(items) logger.info("Did enumerate \(items.count) items. Next page is nil: \(nextPage == nil)") observer.finishEnumerating(upTo: nextPage) + signposter.endInterval("ObserverReport", reportState) } } catch let error as NSError { // This error can only mean a missing parent item identifier + signposter.endInterval("ToFileProviderItems", toItemsState) guard handleInvalidParent else { logger.info("Not handling invalid parent in enumeration.") observer.finishEnumeratingWithError(error) diff --git a/shell_integration/MacOSX/NextcloudFileProviderKit/Sources/NextcloudFileProviderKit/Enumeration/Enumerator+SyncEngine.swift b/shell_integration/MacOSX/NextcloudFileProviderKit/Sources/NextcloudFileProviderKit/Enumeration/Enumerator+SyncEngine.swift index e455a2b370b73..956ca3dfd9272 100644 --- a/shell_integration/MacOSX/NextcloudFileProviderKit/Sources/NextcloudFileProviderKit/Enumeration/Enumerator+SyncEngine.swift +++ b/shell_integration/MacOSX/NextcloudFileProviderKit/Sources/NextcloudFileProviderKit/Enumeration/Enumerator+SyncEngine.swift @@ -6,7 +6,7 @@ import NextcloudKit extension Enumerator { static func handlePagedReadResults( - files: [NKFile], pageIndex: Int, dbManager: FilesDatabaseManager + files: [NKFile], pageIndex: Int, dbManager: FilesDatabaseManager, log: any FileProviderLogging ) -> (metadatas: [SendableItemMetadata]?, error: NKError?) { // First PROPFIND contains the target item, but we do not want to report this in the // retrieved metadatas (the enumeration observers don't expect you to enumerate the @@ -40,10 +40,44 @@ extension Enumerator { // `keepDownloaded == false` for items that are pinned in the // database, leaving the OS view (`isKeepDownloaded`, `contentPolicy`) // out of sync with the local truth. - let metadatas = files[startIndex...].map { file -> SendableItemMetadata in - dbManager.addItemMetadataPreservingLocalState(file.toItemMetadata()) + // + // Conversion and persistence are timed separately (convAccum / dbAccum) so the JSONL PERF + // line splits CPU spent building metadata from CPU spent in Realm. Today each item opens its + // own write transaction inside `addItemMetadataPreservingLocalState`; `db_items_per_s` is the + // throughput number to watch, and the enclosing `ConvertAndPersistPage` signpost bounds the + // whole page for Instruments. (Phase 2 batches these into one transaction per page.) + let signposter = EnumerationSignposter.signposter + let convAndPersistState = signposter.beginInterval( + "ConvertAndPersistPage", + id: signposter.makeSignpostID(), + "pageIndex=\(pageIndex) files=\(files.count)" + ) + + let clock = ContinuousClock() + var convAccum: Duration = .zero + var dbAccum: Duration = .zero + var metadatas: [SendableItemMetadata] = [] + metadatas.reserveCapacity(max(0, files.count - startIndex)) + + for file in files[startIndex...] { + let convStart = clock.now + let itemMetadata = file.toItemMetadata() + convAccum += clock.now - convStart + + let dbStart = clock.now + metadatas.append(dbManager.addItemMetadataPreservingLocalState(itemMetadata)) + dbAccum += clock.now - dbStart } + signposter.endInterval("ConvertAndPersistPage", convAndPersistState, "items=\(metadatas.count)") + + let itemCount = metadatas.count + let dbSeconds = dbAccum.fpSeconds + let dbRate = dbSeconds > 0 ? Double(itemCount) / dbSeconds : 0 + FileProviderLogger(category: "Enumerator", log: log).performance( + "PERF ConvertAndPersistPage pageIndex=\(pageIndex) items=\(itemCount) conv_s=\(convAccum.fpSeconds) db_s=\(dbSeconds) db_items_per_s=\(dbRate)" + ) + return (metadatas, nil) } @@ -68,11 +102,23 @@ extension Enumerator { if let pageIndex { let (metadatas, error) = - handlePagedReadResults(files: files, pageIndex: pageIndex, dbManager: dbManager) + handlePagedReadResults(files: files, pageIndex: pageIndex, dbManager: dbManager, log: log) return (metadatas, nil, error) } - guard var (directory, _, files) = await files.toSendableDirectoryMetadata(account: account, directoryToRead: serverUrl) else { + // Non-paginated path (older servers / change enumeration): conversion is parallelized and the + // persist is a single batched transaction. Signpost each so its cost is comparable, in a trace, + // against the paginated path's per-item behavior. + let signposter = EnumerationSignposter.signposter + let convDirState = signposter.beginInterval( + "ConvertDirectoryMetadata", + id: signposter.makeSignpostID(), + "serverUrl=\(serverUrl, privacy: .public) files=\(files.count)" + ) + let convertedDirectory = await files.toSendableDirectoryMetadata(account: account, directoryToRead: serverUrl) + signposter.endInterval("ConvertDirectoryMetadata", convDirState) + + guard var (directory, _, files) = convertedDirectory else { logger.error("Failed to convert array of NKFile to directory and files metadata objects!") return (nil, nil, .invalidData) } @@ -92,12 +138,31 @@ extension Enumerator { files.insert(directory, at: 0) + let batchClock = ContinuousClock() + let batchStart = batchClock.now + let batchWriteState = signposter.beginInterval( + "Depth1BatchWrite", + id: signposter.makeSignpostID(), + "serverUrl=\(serverUrl, privacy: .public) items=\(files.count)" + ) let changes = dbManager.depth1ReadUpdateItemMetadatas( account: account.ncKitAccount, serverUrl: serverUrl, updatedMetadatas: files, keepExistingDownloadState: true ) + signposter.endInterval("Depth1BatchWrite", batchWriteState) + + // The non-paginated depth-1 write (change / working-set full-folder re-read) is the measured + // enumeration bottleneck: its per-item logical-dedup scans are O(N²) over a flat folder. Log its + // wall-clock + items/sec so the effect of the normalizedFileName index is visible in the JSONL + // (the `Depth1BatchWrite` signpost shows the same in Instruments). + let batchElapsed = batchClock.now - batchStart + let batchRate = batchElapsed.fpSeconds > 0 ? Double(files.count) / batchElapsed.fpSeconds : 0 + logger.performance( + "PERF Depth1BatchWrite items=\(files.count) write_s=\(batchElapsed.fpSeconds) items_per_s=\(batchRate)", + [.url: serverUrl] + ) return (files, changes, nil) } @@ -140,6 +205,21 @@ extension Enumerator { .init() } + // Signpost + wall-clock the network read in isolation so a trace (or the JSONL PERF line) can + // attribute enumeration latency to the paginated PROPFIND (server-bound) versus the local + // conversion + Realm persistence (CPU-bound). begin/end stay in this one function scope so the + // non-Sendable interval state never crosses the `await`'s potential thread hop. + let pageIndexForLog = pageSettings?.index ?? 0 + let signposter = EnumerationSignposter.signposter + let propfindSignpostID = signposter.makeSignpostID() + let propfindState = signposter.beginInterval( + "PROPFIND", + id: propfindSignpostID, + "serverUrl=\(serverUrl, privacy: .public) index=\(pageIndexForLog) depth=\(depth.rawValue, privacy: .public)" + ) + let networkClock = ContinuousClock() + let networkStart = networkClock.now + let (_, files, data, error) = await remoteInterface.enumerate( remotePath: serverUrl, depth: depth, @@ -159,6 +239,13 @@ extension Enumerator { } ) + let networkElapsed = networkClock.now - networkStart + signposter.endInterval("PROPFIND", propfindState, "files=\(files.count)") + logger.performance( + "PERF PROPFIND index=\(pageIndexForLog) net_s=\(networkElapsed.fpSeconds) files=\(files.count) depth=\(depth.rawValue)", + [.url: serverUrl] + ) + guard error == .success else { logger.error("Read of URL did fail.", [.error: error, .url: serverUrl]) return RemoteReadResult(error: error) @@ -259,7 +346,7 @@ extension Enumerator { ) } else if let pageIndex = pageSettings?.index { let (metadatas, error) = handlePagedReadResults( - files: files, pageIndex: pageIndex, dbManager: dbManager + files: files, pageIndex: pageIndex, dbManager: dbManager, log: log ) return RemoteReadResult(metadatas: metadatas, nextPage: nextPage, error: error) } else { diff --git a/shell_integration/MacOSX/NextcloudFileProviderKit/Sources/NextcloudFileProviderKit/Log/EnumerationSignposter.swift b/shell_integration/MacOSX/NextcloudFileProviderKit/Sources/NextcloudFileProviderKit/Log/EnumerationSignposter.swift new file mode 100644 index 0000000000000..a92cac0f74790 --- /dev/null +++ b/shell_integration/MacOSX/NextcloudFileProviderKit/Sources/NextcloudFileProviderKit/Log/EnumerationSignposter.swift @@ -0,0 +1,43 @@ +// SPDX-FileCopyrightText: 2026 Nextcloud GmbH and Nextcloud contributors +// SPDX-License-Identifier: LGPL-3.0-or-later + +import Foundation +import os + +/// +/// Process-global `OSSignposter` for the enumeration hot path. +/// +/// The enumeration + persistence work runs across `static func`s that receive no `self`, so a +/// shared signposter is the least invasive way to instrument them without threading a handle +/// through every signature. `OSSignposter` (and the `OSSignpostID`s it vends) are `Sendable`, so a +/// global `let` is safe under Swift 6 strict concurrency and usable from any isolation domain. +/// +/// The subsystem mirrors ``FileProviderLogger`` (the extension bundle identifier) so signposts and +/// log messages share the same subsystem in Instruments and `log stream`. The `"PointsOfInterest"` +/// category makes intervals appear in the built-in *Points of Interest* instrument with no extra +/// configuration. +/// +/// Signposts are near-zero cost when no Instruments trace (or `log stream --signpost`) is attached: +/// `signposter.signpostsEnabled` is `false` and the interval calls become cheap branches, and the +/// message interpolations are only evaluated when a consumer is present. They are therefore safe to +/// ship enabled — no `#if DEBUG` gate. +/// +enum EnumerationSignposter { + static let signposter = OSSignposter( + subsystem: Bundle.main.bundleIdentifier ?? "", + category: "PointsOfInterest" + ) +} + +extension Duration { + /// + /// This duration expressed as fractional seconds, for human-readable performance logging. + /// + /// `components` yields whole seconds plus attoseconds; recombine them into a `Double`. Precision + /// loss at the attosecond scale is irrelevant for wall-clock timings measured in milliseconds. + /// + var fpSeconds: Double { + let parts = components + return Double(parts.seconds) + Double(parts.attoseconds) / 1e18 + } +} diff --git a/shell_integration/MacOSX/NextcloudFileProviderKit/Sources/NextcloudFileProviderKit/Log/FileProviderLog.swift b/shell_integration/MacOSX/NextcloudFileProviderKit/Sources/NextcloudFileProviderKit/Log/FileProviderLog.swift index 62323511cc661..24990a185f47c 100644 --- a/shell_integration/MacOSX/NextcloudFileProviderKit/Sources/NextcloudFileProviderKit/Log/FileProviderLog.swift +++ b/shell_integration/MacOSX/NextcloudFileProviderKit/Sources/NextcloudFileProviderKit/Log/FileProviderLog.swift @@ -100,6 +100,18 @@ public actor FileProviderLog: FileProviderLogging { /// nonisolated(unsafe) var debugLoggingObservation: NSKeyValueObservation? + /// + /// Whether performance-timing messages are written; see ``FileProviderLogging/performanceLoggingEnabled``. + /// + /// Read live from `UserDefaults.standard` (key `"performanceLoggingEnabled"`) on each access rather than cached + /// via KVO like ``debugLoggingEnabled``: performance lines are emitted at most a couple of times per enumerated + /// page, so a live read is cheap and picks up `defaults write` immediately without any observation machinery. + /// Defaults to `false` when the key is unset or not a boolean, in both DEBUG and release builds. + /// + public var performanceLoggingEnabled: Bool { + (UserDefaults.standard.object(forKey: "performanceLoggingEnabled") as? NSNumber)?.boolValue ?? false + } + /// /// Initialize a new log file abstraction. /// diff --git a/shell_integration/MacOSX/NextcloudFileProviderKit/Sources/NextcloudFileProviderKit/Log/FileProviderLogger.swift b/shell_integration/MacOSX/NextcloudFileProviderKit/Sources/NextcloudFileProviderKit/Log/FileProviderLogger.swift index f09cdd19c5197..a9bff5664f4b5 100644 --- a/shell_integration/MacOSX/NextcloudFileProviderKit/Sources/NextcloudFileProviderKit/Log/FileProviderLogger.swift +++ b/shell_integration/MacOSX/NextcloudFileProviderKit/Sources/NextcloudFileProviderKit/Log/FileProviderLogger.swift @@ -58,16 +58,39 @@ public struct FileProviderLogger: Sendable { /// - line: Implementations should have `#line` as the default value for this. /// public func debug(_ message: String, _ details: [FileProviderLogDetailKey: (any Sendable)?] = [:], file: StaticString = #filePath, function: StaticString = #function, line: UInt = #line) { - Task { - guard await log.debugLoggingEnabled else { - return - } + // Gate synchronously BEFORE dispatching the Task. The previous form always spawned a Task and + // only checked the gate inside it, so a hot loop of disabled debug calls (e.g. one per item + // during a large enumeration) still paid a Task allocation + actor hop per call. Reading the + // user default directly is allocation-free and picks up `defaults write` live; the actor's + // `write` still backstops the `.debug` gate. The build-configuration fallback mirrors + // `FileProviderLog` (enabled in DEBUG, disabled in release) so behaviour is unchanged. + guard debugLoggingEnabledFastPath else { + return + } + Task { writeToUnifiedLoggingSystem(level: .debug, message: message, details: details, file: file, function: function, line: line) await log.write(category: category, level: .debug, message: message, details: details, file: file, function: function, line: line) } } + /// + /// Synchronous fast-path mirror of ``FileProviderLog/debugLoggingEnabled``, used to gate ``debug(_:_:file:function:line:)`` + /// before a Task is spawned. Reads the process-global `debugLoggingEnabled` user default live; when unset it falls back to + /// the build-configuration default (enabled in DEBUG, disabled in release), exactly as `FileProviderLog` does at startup. + /// + private var debugLoggingEnabledFastPath: Bool { + if let number = UserDefaults.standard.object(forKey: "debugLoggingEnabled") as? NSNumber { + return number.boolValue + } + + #if DEBUG + return true + #else + return false + #endif + } + /// /// Dispatch a task to write a message with the level `OSLogType.info`. /// @@ -119,6 +142,33 @@ public struct FileProviderLogger: Sendable { } } + /// + /// Dispatch a task to write a performance-timing message at `OSLogType.info`, gated by ``FileProviderLogging/performanceLoggingEnabled``. + /// + /// Use this for wall-clock timing summaries (e.g. per-page network / conversion / database durations during enumeration). + /// Unlike ``debug(_:_:file:function:line:)`` this gates *inside* the Task via the actor flag rather than a synchronous fast-path: + /// performance lines are emitted at most a couple of times per enumerated page, so the Task overhead is negligible and not + /// worth a second user-default fast-path. The flag is independent of `debugLoggingEnabled` so a measurement run is not polluted + /// by the per-item debug traces that flag enables. + /// + /// - Parameters: + /// - message: A human-readable message; interpolate the timing numbers directly (the structured `details` channel has no numeric branch). + /// - details: Structured and contextual details about a message. + /// - file: Implementations should have `#filePath` as the default value for this. + /// - function: Implementations should have `#function` as the default value for this. + /// - line: Implementations should have `#line` as the default value for this. + /// + public func performance(_ message: String, _ details: [FileProviderLogDetailKey: (any Sendable)?] = [:], file: StaticString = #filePath, function: StaticString = #function, line: UInt = #line) { + Task { + guard await log.performanceLoggingEnabled else { + return + } + + writeToUnifiedLoggingSystem(level: .info, message: message, details: details, file: file, function: function, line: line) + await log.write(category: category, level: .info, message: message, details: details, file: file, function: function, line: line) + } + } + private func writeToUnifiedLoggingSystem(level: OSLogType, message: String, details: [FileProviderLogDetailKey: (any Sendable)?], file: StaticString, function: StaticString, line: UInt) { if details.isEmpty { logger.log(level: level, "\(message, privacy: .public)\n\n\(file, privacy: .public):\(line, privacy: .public) \(function, privacy: .public)") diff --git a/shell_integration/MacOSX/NextcloudFileProviderKit/Sources/NextcloudFileProviderKit/Log/FileProviderLogging.swift b/shell_integration/MacOSX/NextcloudFileProviderKit/Sources/NextcloudFileProviderKit/Log/FileProviderLogging.swift index ee75f10b28671..39efa32b78eb6 100644 --- a/shell_integration/MacOSX/NextcloudFileProviderKit/Sources/NextcloudFileProviderKit/Log/FileProviderLogging.swift +++ b/shell_integration/MacOSX/NextcloudFileProviderKit/Sources/NextcloudFileProviderKit/Log/FileProviderLogging.swift @@ -15,6 +15,15 @@ public protocol FileProviderLogging: Actor { /// var debugLoggingEnabled: Bool { get } + /// + /// Whether performance-timing messages emitted by ``FileProviderLogger/performance(_:_:file:function:line:)`` are written. + /// + /// Controlled at runtime via the `performanceLoggingEnabled` user default and defaults to `false`, so the extra + /// per-page timing lines only appear when explicitly requested for a measurement run — independent of `debugLoggingEnabled`, + /// which floods the log with per-item traces that would themselves distort the timings. + /// + var performanceLoggingEnabled: Bool { get } + /// /// Write a message to the current JSON Lines log file. /// diff --git a/shell_integration/MacOSX/NextcloudFileProviderKit/Sources/NextcloudFileProviderKit/Metadata/RealmItemMetadata.swift b/shell_integration/MacOSX/NextcloudFileProviderKit/Sources/NextcloudFileProviderKit/Metadata/RealmItemMetadata.swift index abe9fc1256a7c..f499fc9769a0c 100644 --- a/shell_integration/MacOSX/NextcloudFileProviderKit/Sources/NextcloudFileProviderKit/Metadata/RealmItemMetadata.swift +++ b/shell_integration/MacOSX/NextcloudFileProviderKit/Sources/NextcloudFileProviderKit/Metadata/RealmItemMetadata.swift @@ -53,7 +53,13 @@ class RealmItemMetadata: Object, ItemMetadata { @Persisted var path = "" @Persisted var permissions = "" @Persisted(indexed: true) var normalizedServerUrl = "" - @Persisted var normalizedFileName = "" + // Indexed because it is the selective key for logical-address lookups + // (`RealmItemMetadata.hasLocation`) within a single directory. `normalizedServerUrl`'s index is + // useless for a large *flat* folder — every child shares the parent url, so it narrows to the whole + // sibling set — whereas the (near-unique) file name lets Realm's planner drive off this index + // instead of scanning all siblings. This is what collapses the O(N²) per-item eviction/dedup scans + // during enumeration of a big folder (e.g. /Talk). + @Persisted(indexed: true) var normalizedFileName = "" @Persisted var quotaUsedBytes: Int64 = 0 @Persisted var quotaAvailableBytes: Int64 = 0 @Persisted var resourceType = "" diff --git a/shell_integration/MacOSX/NextcloudFileProviderKit/Sources/NextcloudFileProviderKitMocks/FileProviderLogMock.swift b/shell_integration/MacOSX/NextcloudFileProviderKit/Sources/NextcloudFileProviderKitMocks/FileProviderLogMock.swift index 7a4b1068a359b..83376131f8834 100644 --- a/shell_integration/MacOSX/NextcloudFileProviderKit/Sources/NextcloudFileProviderKitMocks/FileProviderLogMock.swift +++ b/shell_integration/MacOSX/NextcloudFileProviderKit/Sources/NextcloudFileProviderKitMocks/FileProviderLogMock.swift @@ -7,6 +7,7 @@ import os public actor FileProviderLogMock: FileProviderLogging { public let debugLoggingEnabled: Bool = true + public let performanceLoggingEnabled: Bool = true let logger: Logger diff --git a/shell_integration/MacOSX/NextcloudFileProviderKit/Tests/NextcloudFileProviderKitTests/EnumeratorTests.swift b/shell_integration/MacOSX/NextcloudFileProviderKit/Tests/NextcloudFileProviderKitTests/EnumeratorTests.swift index d8ed18350fe91..92ecbd6e49ae3 100644 --- a/shell_integration/MacOSX/NextcloudFileProviderKit/Tests/NextcloudFileProviderKitTests/EnumeratorTests.swift +++ b/shell_integration/MacOSX/NextcloudFileProviderKit/Tests/NextcloudFileProviderKitTests/EnumeratorTests.swift @@ -417,7 +417,7 @@ final class EnumeratorTests: NextcloudFileProviderKitTestCase { // 2. Act let firstPageFiles = [parentNKFile] + childrenNKFiles let (firstPageResult, firstPageError) = Enumerator.handlePagedReadResults( - files: firstPageFiles, pageIndex: 0, dbManager: dbManager + files: firstPageFiles, pageIndex: 0, dbManager: dbManager, log: FileProviderLogMock() ) // 3. Assert @@ -441,7 +441,7 @@ final class EnumeratorTests: NextcloudFileProviderKitTestCase { // --- Scenario B: Follow-up Page (pageIndex > 0) --- // 4. Act let (followUpPageResult, followUpPageError) = Enumerator.handlePagedReadResults( - files: followUpChildrenNKFiles, pageIndex: 1, dbManager: dbManager + files: followUpChildrenNKFiles, pageIndex: 1, dbManager: dbManager, log: FileProviderLogMock() ) // 5. Assert @@ -462,7 +462,7 @@ final class EnumeratorTests: NextcloudFileProviderKitTestCase { rootNKFile.path = Self.account.davFilesUrl let (rootResult, rootError) = Enumerator.handlePagedReadResults( - files: [rootNKFile], pageIndex: 0, dbManager: dbManager + files: [rootNKFile], pageIndex: 0, dbManager: dbManager, log: FileProviderLogMock() ) // 7. Assert @@ -520,7 +520,7 @@ final class EnumeratorTests: NextcloudFileProviderKitTestCase { } let (returnedMetadatas, error) = Enumerator.handlePagedReadResults( - files: [parentNKFile] + childrenNKFiles, pageIndex: 0, dbManager: dbManager + files: [parentNKFile] + childrenNKFiles, pageIndex: 0, dbManager: dbManager, log: FileProviderLogMock() ) XCTAssertNil(error) @@ -570,7 +570,7 @@ final class EnumeratorTests: NextcloudFileProviderKitTestCase { } let (returnedMetadatas, error) = Enumerator.handlePagedReadResults( - files: followUpChildrenNKFiles, pageIndex: 1, dbManager: dbManager + files: followUpChildrenNKFiles, pageIndex: 1, dbManager: dbManager, log: FileProviderLogMock() ) XCTAssertNil(error) @@ -602,7 +602,7 @@ final class EnumeratorTests: NextcloudFileProviderKitTestCase { let parentNKFile = remoteFolder.toNKFile() let (_, error) = Enumerator.handlePagedReadResults( - files: [parentNKFile], pageIndex: 0, dbManager: dbManager + files: [parentNKFile], pageIndex: 0, dbManager: dbManager, log: FileProviderLogMock() ) XCTAssertNil(error) diff --git a/shell_integration/MacOSX/NextcloudFileProviderKit/Tests/NextcloudFileProviderKitTests/KeepDownloadedRecursiveTests.swift b/shell_integration/MacOSX/NextcloudFileProviderKit/Tests/NextcloudFileProviderKitTests/KeepDownloadedRecursiveTests.swift index 7f44aae28a30f..d968b16d14e29 100644 --- a/shell_integration/MacOSX/NextcloudFileProviderKit/Tests/NextcloudFileProviderKitTests/KeepDownloadedRecursiveTests.swift +++ b/shell_integration/MacOSX/NextcloudFileProviderKit/Tests/NextcloudFileProviderKitTests/KeepDownloadedRecursiveTests.swift @@ -519,7 +519,8 @@ final class KeepDownloadedRecursiveTests: NextcloudFileProviderKitTestCase { let (_, error) = Enumerator.handlePagedReadResults( files: [folderMock.toNKFile(), directChildMock.toNKFile(), subfolderMock.toNKFile()], pageIndex: 0, - dbManager: Self.dbManager + dbManager: Self.dbManager, + log: FileProviderLogMock() ) XCTAssertNil(error)