Log when the build graph starts being generated and when it finishes

The signposts aren’t easily visible in the log (you need to add `--signpost` to `log show`) and don’t get logged on non-Darwin platforms at all. Add logging for it.

Author: ahoppen

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,29 +189,38 @@ 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 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 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()
   }

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)