Emit signposts for request handling

This allows you to trace sourcekit-lsp in Instruments to get a feeling for how long requests take to be handled.

Author: ahoppen

Sources/LSPLogging/Logging.swift

@@ -27,9 +27,17 @@ import os  // os_log
 
 public typealias LogLevel = os.OSLogType
 public typealias Logger = os.Logger
+public typealias Signposter = OSSignposter
+
+extension os.Logger {
+  public func makeSignposter() -> Signposter {
+    return OSSignposter(logger: self)
+  }
+}
 #else
 public typealias LogLevel = NonDarwinLogLevel
 public typealias Logger = NonDarwinLogger
+public typealias Signposter = NonDarwinSignposter
 #endif
 
 /// The logger that is used to log any messages.

Sources/LSPLogging/NonDarwinLogging.swift

@@ -330,4 +330,35 @@ public struct NonDarwinLogger {
   public static func flush() {
     loggingQueue.sync {}
   }
+
+  public func makeSignposter() -> NonDarwinSignposter {
+    return NonDarwinSignposter()
+  }
+}
+
+// MARK: - Signposter
+
+public struct NonDarwinSignpostID {}
+
+public struct NonDarwinSignpostIntervalState {}
+
+/// A type that is API-compatible to `OSLogMessage` for all uses within sourcekit-lsp.
+///
+/// Since non-Darwin platforms don't have signposts, the type just has no-op operations.
+public struct NonDarwinSignposter {
+  public func makeSignpostID() -> NonDarwinSignpostID {
+    return NonDarwinSignpostID()
+  }
+
+  public func beginInterval(
+    _ name: StaticString,
+    id: NonDarwinSignpostID,
+    _ message: NonDarwinLogMessage
+  ) -> NonDarwinSignpostIntervalState {
+    return NonDarwinSignpostIntervalState()
+  }
+
+  public func emitEvent(_ name: StaticString, id: NonDarwinSignpostID, _ message: NonDarwinLogMessage = "") {}
+
+  public func endInterval(_ name: StaticString, _ state: NonDarwinSignpostIntervalState, _ message: StaticString) {}
 }

Sources/SourceKitD/SourceKitD.swift

@@ -68,6 +68,10 @@ extension SourceKitD {
   public func send(_ req: SKDRequestDictionary) async throws -> SKDResponseDictionary {
     logRequest(req)
 
+    let signposter = logger.makeSignposter()
+    let signpostID = signposter.makeSignpostID()
+    let signposterState = signposter.beginInterval("sourcekitd-request", id: signpostID, "Start")
+
     let sourcekitdResponse: SKDResponse = try await withCancellableCheckedThrowingContinuation { continuation in
       var handle: sourcekitd_request_handle_t? = nil
       api.send_request(req.dict, &handle) { _resp in
@@ -81,9 +85,11 @@ extension SourceKitD {
     logResponse(sourcekitdResponse)
 
     guard let dict = sourcekitdResponse.value else {
+      signposter.endInterval("sourcekitd-request", signposterState, "Error")
       throw sourcekitdResponse.error!
     }
 
+    signposter.endInterval("sourcekitd-request", signposterState, "Done")
     return dict
   }
 }

Sources/SourceKitLSP/SourceKitServer.swift

@@ -628,11 +628,17 @@ extension SourceKitServer: MessageHandler {
       self.cancelRequest(params)
     }
 
+    let notificationID = getNextNotificationIDForLogging()
+
+    let signposter = Logger(subsystem: subsystem, category: "notification-\(notificationID)").makeSignposter()
+    let signpostID = signposter.makeSignpostID()
+    let state = signposter.beginInterval("Notification", id: signpostID, "\(type(of: params))")
     messageHandlingQueue.async(metadata: TaskMetadata(params)) {
-      let notificationID = getNextNotificationIDForLogging()
+      signposter.emitEvent("Start handling", id: signpostID)
 
       await withLoggingScope("notification-\(notificationID)") {
         await self.handleImpl(params, from: clientID)
+        signposter.endInterval("Notification", state, "Done")
       }
     }
   }
@@ -676,9 +682,15 @@ extension SourceKitServer: MessageHandler {
     from clientID: ObjectIdentifier,
     reply: @escaping (LSPResult<R.Response>) -> Void
   ) {
+    let signposter = Logger(subsystem: subsystem, category: "request-\(id)").makeSignposter()
+    let signpostID = signposter.makeSignpostID()
+    let state = signposter.beginInterval("Request", id: signpostID, "\(R.self)")
+
     let task = messageHandlingQueue.async(metadata: TaskMetadata(params)) {
+      signposter.emitEvent("Start handling", id: signpostID)
       await withLoggingScope("request-\(id)") {
         await self.handleImpl(params, id: id, from: clientID, reply: reply)
+        signposter.endInterval("Request", state, "Done")
       }
       // We have handled the request and can't cancel it anymore.
       // Stop keeping track of it to free the memory.