Merge pull request #1343 from ahoppen/generating-build-graph-logging

Author: ahoppen

Sources/SKTestSupport/TestSourceKitLSPClient.swift

@@ -248,15 +248,16 @@ public final class TestSourceKitLSPClient: MessageHandler {
     return try await nextNotification(ofType: PublishDiagnosticsNotification.self, timeout: timeout)
   }
 
-  /// Waits for the next notification of the given type to be sent to the client. Ignores any notifications that are of
-  /// a different type.
+  /// Waits for the next notification of the given type to be sent to the client that satisfies the given predicate.
+  /// Ignores any notifications that are of a different type or that don't satisfy the predicate.
   public func nextNotification<ExpectedNotificationType: NotificationType>(
     ofType: ExpectedNotificationType.Type,
+    satisfying predicate: (ExpectedNotificationType) -> Bool = { _ in true },
     timeout: TimeInterval = defaultTimeout
   ) async throws -> ExpectedNotificationType {
     while true {
       let nextNotification = try await nextNotification(timeout: timeout)
-      if let notification = nextNotification as? ExpectedNotificationType {
+      if let notification = nextNotification as? ExpectedNotificationType, predicate(notification) {
         return notification
       }
     }

Sources/SemanticIndex/PreparationTaskDescription.swift

@@ -74,10 +74,7 @@ public struct PreparationTaskDescription: IndexTaskDescription {
     // Only use the last two digits of the preparation ID for the logging scope to avoid creating too many scopes.
     // See comment in `withLoggingScope`.
     // The last 2 digits should be sufficient to differentiate between multiple concurrently running preparation operations
-    await withLoggingSubsystemAndScope(
-      subsystem: "org.swift.sourcekit-lsp.indexing",
-      scope: "preparation-\(id % 100)"
-    ) {
+    await withLoggingSubsystemAndScope(subsystem: indexLoggingSubsystem, scope: "preparation-\(id % 100)") {
       let targetsToPrepare = await targetsToPrepare.asyncFilter {
         await !preparationUpToDateStatus.isUpToDate($0)
       }.sorted(by: {
@@ -98,10 +95,13 @@ public struct PreparationTaskDescription: IndexTaskDescription {
       let signposter = Logger(subsystem: LoggingScope.subsystem, category: "preparation").makeSignposter()
       let signpostID = signposter.makeSignpostID()
       let state = signposter.beginInterval("Preparing", id: signpostID, "Preparing \(targetsToPrepareDescription)")
+      let startDate = Date()
       defer {
+        logger.log(
+          "Finished preparation in \(Date().timeIntervalSince(startDate) * 1000, privacy: .public)ms: \(targetsToPrepareDescription)"
+        )
         signposter.endInterval("Preparing", state)
       }
-      let startDate = Date()
       do {
         try await buildSystemManager.prepare(
           targets: targetsToPrepare,
@@ -116,9 +116,6 @@ public struct PreparationTaskDescription: IndexTaskDescription {
       if !Task.isCancelled {
         await preparationUpToDateStatus.markUpToDate(targetsToPrepare, updateOperationStartDate: startDate)
       }
-      logger.log(
-        "Finished preparation in \(Date().timeIntervalSince(startDate) * 1000, privacy: .public)ms: \(targetsToPrepareDescription)"
-      )
     }
   }
 

Sources/SemanticIndex/SemanticIndexManager.swift

@@ -15,6 +15,9 @@ import LSPLogging
 import LanguageServerProtocol
 import SKCore
 
+/// The logging subsystem that should be used for all index-related logging.
+let indexLoggingSubsystem = "org.swift.sourcekit-lsp.indexing"
+
 /// A wrapper around `QueuedTask` that only allows equality comparison and inspection whether the `QueuedTask` is
 /// currently executing.
 ///
@@ -186,28 +189,40 @@ public final actor SemanticIndexManager {
   /// This method is intended to initially update the index of a project after it is opened.
   public func scheduleBuildGraphGenerationAndBackgroundIndexAllFiles() async {
     generateBuildGraphTask = Task(priority: .low) {
-      let signposter = Logger(subsystem: LoggingScope.subsystem, category: "preparation").makeSignposter()
-      let signpostID = signposter.makeSignpostID()
-      let state = signposter.beginInterval("Preparing", id: signpostID, "Generating build graph")
-      defer {
-        signposter.endInterval("Preparing", state)
-      }
-      await orLog("Generating build graph") { try await self.buildSystemManager.generateBuildGraph() }
-      // Ensure that we have an up-to-date indexstore-db. Waiting for the indexstore-db to be updated is cheaper than
-      // potentially not knowing about unit files, which causes the corresponding source files to be re-indexed.
-      index.pollForUnitChangesAndWait()
-      let index = index.checked(for: .modifiedFiles)
-      let filesToIndex = await self.buildSystemManager.sourceFiles().lazy.map(\.uri)
-        .filter { uri in
-          guard let url = uri.fileURL else {
-            // The URI is not a file, so there's nothing we can index.
-            return false
-          }
-          return !index.hasUpToDateUnit(for: url)
+      await withLoggingSubsystemAndScope(subsystem: indexLoggingSubsystem, scope: "build-graph-generation") {
+        logger.log(
+          "Starting build graph generation with priority \(Task.currentPriority.rawValue, privacy: .public)"
+        )
+        let signposter = logger.makeSignposter()
+        let signpostID = signposter.makeSignpostID()
+        let state = signposter.beginInterval("Preparing", id: signpostID, "Generating build graph")
+        let startDate = Date()
+        defer {
+          logger.log(
+            "Finished build graph generation in \(Date().timeIntervalSince(startDate) * 1000, privacy: .public)ms"
+          )
+          signposter.endInterval("Preparing", state)
         }
-      await scheduleBackgroundIndex(files: filesToIndex)
-      generateBuildGraphTask = nil
+        await testHooks.buildGraphGenerationDidStart?()
+        await orLog("Generating build graph") { try await self.buildSystemManager.generateBuildGraph() }
+        // Ensure that we have an up-to-date indexstore-db. Waiting for the indexstore-db to be updated is cheaper than
+        // potentially not knowing about unit files, which causes the corresponding source files to be re-indexed.
+        index.pollForUnitChangesAndWait()
+        await testHooks.buildGraphGenerationDidFinish?()
+        let index = index.checked(for: .modifiedFiles)
+        let filesToIndex = await self.buildSystemManager.sourceFiles().lazy.map(\.uri)
+          .filter { uri in
+            guard let url = uri.fileURL else {
+              // The URI is not a file, so there's nothing we can index.
+              return false
+            }
+            return !index.hasUpToDateUnit(for: url)
+          }
+        await scheduleBackgroundIndex(files: filesToIndex)
+        generateBuildGraphTask = nil
+      }
     }
+    indexStatusDidChange()
   }
 
   /// Wait for all in-progress index tasks to finish.

Sources/SemanticIndex/TestHooks.swift

@@ -12,6 +12,10 @@
 
 /// Callbacks that allow inspection of internal state modifications during testing.
 public struct IndexTestHooks: Sendable {
+  public var buildGraphGenerationDidStart: (@Sendable () async -> Void)?
+
+  public var buildGraphGenerationDidFinish: (@Sendable () async -> Void)?
+
   public var preparationTaskDidStart: (@Sendable (PreparationTaskDescription) async -> Void)?
 
   public var preparationTaskDidFinish: (@Sendable (PreparationTaskDescription) async -> Void)?
@@ -22,11 +26,15 @@ public struct IndexTestHooks: Sendable {
   public var updateIndexStoreTaskDidFinish: (@Sendable (UpdateIndexStoreTaskDescription) async -> Void)?
 
   public init(
+    buildGraphGenerationDidStart: (@Sendable () async -> Void)? = nil,
+    buildGraphGenerationDidFinish: (@Sendable () async -> Void)? = nil,
     preparationTaskDidStart: (@Sendable (PreparationTaskDescription) async -> Void)? = nil,
     preparationTaskDidFinish: (@Sendable (PreparationTaskDescription) async -> Void)? = nil,
     updateIndexStoreTaskDidStart: (@Sendable (UpdateIndexStoreTaskDescription) async -> Void)? = nil,
     updateIndexStoreTaskDidFinish: (@Sendable (UpdateIndexStoreTaskDescription) async -> Void)? = nil
   ) {
+    self.buildGraphGenerationDidStart = buildGraphGenerationDidStart
+    self.buildGraphGenerationDidFinish = buildGraphGenerationDidFinish
     self.preparationTaskDidStart = preparationTaskDidStart
     self.preparationTaskDidFinish = preparationTaskDidFinish
     self.updateIndexStoreTaskDidStart = updateIndexStoreTaskDidStart

Sources/SemanticIndex/UpdateIndexStoreTaskDescription.swift

@@ -134,10 +134,7 @@ public struct UpdateIndexStoreTaskDescription: IndexTaskDescription {
     // Only use the last two digits of the indexing ID for the logging scope to avoid creating too many scopes.
     // See comment in `withLoggingScope`.
     // The last 2 digits should be sufficient to differentiate between multiple concurrently running indexing operation.
-    await withLoggingSubsystemAndScope(
-      subsystem: "org.swift.sourcekit-lsp.indexing",
-      scope: "update-indexstore-\(id % 100)"
-    ) {
+    await withLoggingSubsystemAndScope(subsystem: indexLoggingSubsystem, scope: "update-indexstore-\(id % 100)") {
       let startDate = Date()
 
       await testHooks.updateIndexStoreTaskDidStart?(self)

Sources/SourceKitLSP/IndexProgressManager.swift

@@ -93,7 +93,7 @@ actor IndexProgressManager {
       }
     }
 
-    if indexTasks.isEmpty {
+    if indexTasks.isEmpty && !isGeneratingBuildGraph {
       // Nothing left to index. Reset the target count and dismiss the work done progress.
       queuedIndexTasks = 0
       workDoneProgress = nil
@@ -104,7 +104,12 @@ actor IndexProgressManager {
     // `indexTasksWereScheduled` calls yet but the semantic index managers already track them in their in-progress tasks.
     // Clip the finished tasks to 0 because showing a negative number there looks stupid.
     let finishedTasks = max(queuedIndexTasks - indexTasks.count, 0)
-    var message = "\(finishedTasks) / \(queuedIndexTasks)"
+    var message: String
+    if isGeneratingBuildGraph {
+      message = "Generating build graph"
+    } else {
+      message = "\(finishedTasks) / \(queuedIndexTasks)"
+    }
 
     if await sourceKitLSPServer.options.indexOptions.showActivePreparationTasksInProgress {
       var inProgressTasks: [String] = []
@@ -121,7 +126,12 @@ actor IndexProgressManager {
       message += "\n\n" + inProgressTasks.joined(separator: "\n")
     }
 
-    let percentage = Int(Double(finishedTasks) / Double(queuedIndexTasks) * 100)
+    let percentage: Int
+    if queuedIndexTasks != 0 {
+      percentage = Int(Double(finishedTasks) / Double(queuedIndexTasks) * 100)
+    } else {
+      percentage = 0
+    }
     if let workDoneProgress {
       workDoneProgress.update(message: message, percentage: percentage)
     } else {

Sources/SourceKitLSP/SourceKitLSPServer.swift

@@ -508,6 +508,9 @@ public actor SourceKitLSPServer {
   private var workspacesAndIsImplicit: [(workspace: Workspace, isImplicit: Bool)] = [] {
     didSet {
       uriToWorkspaceCache = [:]
+      // `indexProgressManager` iterates over all workspaces in the SourceKitLSPServer. Modifying workspaces might thus
+      // update the index progress status.
+      indexProgressManager.indexStatusDidChange()
     }
   }
 

Tests/SourceKitLSPTests/BackgroundIndexingTests.swift

@@ -333,6 +333,21 @@ final class BackgroundIndexingTests: XCTestCase {
   }
 
   func testBackgroundIndexingStatusWorkDoneProgress() async throws {
+    let receivedBeginProgressNotification = self.expectation(
+      description: "Received work done progress saying build graph generation"
+    )
+    let receivedReportProgressNotification = self.expectation(
+      description: "Received work done progress saying indexing"
+    )
+    var serverOptions = backgroundIndexingOptions
+    serverOptions.indexTestHooks = IndexTestHooks(
+      buildGraphGenerationDidFinish: {
+        await self.fulfillment(of: [receivedBeginProgressNotification], timeout: defaultTimeout)
+      },
+      updateIndexStoreTaskDidFinish: { _ in
+        await self.fulfillment(of: [receivedReportProgressNotification], timeout: defaultTimeout)
+      }
+    )
     let project = try await SwiftPMTestProject(
       files: [
         "MyFile.swift": """
@@ -343,36 +358,55 @@ final class BackgroundIndexingTests: XCTestCase {
         """
       ],
       capabilities: ClientCapabilities(window: WindowClientCapabilities(workDoneProgress: true)),
-      serverOptions: backgroundIndexingOptions,
+      serverOptions: serverOptions,
+      pollIndex: false,
       preInitialization: { testClient in
         testClient.handleMultipleRequests { (request: CreateWorkDoneProgressRequest) in
           return VoidResponse()
         }
       }
     )
-    var indexingWorkDoneProgressToken: ProgressToken? = nil
-    var didGetEndWorkDoneProgress = false
-    // Loop terminates when we see the work done end progress or if waiting for the next notification times out
-    LOOP: while true {
-      let workDoneProgress = try await project.testClient.nextNotification(ofType: WorkDoneProgress.self)
-      switch workDoneProgress.value {
-      case .begin(let data):
-        if data.title == "Indexing" {
-          XCTAssertNil(indexingWorkDoneProgressToken, "Received multiple work done progress notifications for indexing")
-          indexingWorkDoneProgressToken = workDoneProgress.token
-        }
-      case .report:
-        // We ignore progress reports in the test because it's non-deterministic how many we get
-        break
-      case .end:
-        if workDoneProgress.token == indexingWorkDoneProgressToken {
-          didGetEndWorkDoneProgress = true
-          break LOOP
+
+    let beginNotification = try await project.testClient.nextNotification(
+      ofType: WorkDoneProgress.self,
+      satisfying: { notification in
+        guard case .begin(let data) = notification.value else {
+          return false
         }
+        return data.title == "Indexing"
       }
+    )
+    receivedBeginProgressNotification.fulfill()
+    guard case .begin(let beginData) = beginNotification.value else {
+      XCTFail("Expected begin notification")
+      return
     }
-    XCTAssertNotNil(indexingWorkDoneProgressToken, "Expected to receive a work done progress start")
-    XCTAssert(didGetEndWorkDoneProgress, "Expected end work done progress")
+    XCTAssertEqual(beginData.message, "Generating build graph")
+    let indexingWorkDoneProgressToken = beginNotification.token
+
+    _ = try await project.testClient.nextNotification(
+      ofType: WorkDoneProgress.self,
+      satisfying: { notification in
+        guard notification.token == indexingWorkDoneProgressToken,
+          case .report(let reportData) = notification.value,
+          reportData.message == "0 / 1"
+        else {
+          return false
+        }
+        return true
+      }
+    )
+    receivedReportProgressNotification.fulfill()
+
+    _ = try await project.testClient.nextNotification(
+      ofType: WorkDoneProgress.self,
+      satisfying: { notification in
+        guard notification.token == indexingWorkDoneProgressToken, case .end = notification.value else {
+          return false
+        }
+        return true
+      }
+    )
 
     withExtendedLifetime(project) {}
   }