Add subcommand to visualize the requests running concurrently using a trace file

Showing the list of active requests didn’t turn out to be very useful for debugging. What is more useful, however, is to visualize the requests as the get enqueued and handled in a trace chart. This gives a very intuitive view of which request is blocking another request from getting executed.

Author: ahoppen

Sources/Diagnose/ActiveRequestsCommand.swift

@@ -1,5 +1,4 @@
 add_library(Diagnose STATIC
-  ActiveRequestsCommand.swift
   CommandLineArgumentsReducer.swift
   DebugCommand.swift
   DiagnoseCommand.swift
@@ -19,7 +18,8 @@ add_library(Diagnose STATIC
   SourceReducer.swift
   StderrStreamConcurrencySafe.swift
   SwiftFrontendCrashScraper.swift
-  Toolchain+SwiftFrontend.swift)
+  Toolchain+SwiftFrontend.swift
+  TraceFromSignpostsCommand.swift)
 
 set_target_properties(Diagnose PROPERTIES
   INTERFACE_INCLUDE_DIRECTORIES ${CMAKE_Swift_MODULE_DIRECTORY})

Sources/Diagnose/CMakeLists.txt

@@ -21,11 +21,11 @@ package struct DebugCommand: ParsableCommand {
     commandName: "debug",
     abstract: "Commands to debug sourcekit-lsp. Intended for developers of sourcekit-lsp",
     subcommands: [
-      ActiveRequestsCommand.self,
       IndexCommand.self,
       ReduceCommand.self,
       ReduceFrontendCommand.self,
       RunSourceKitdRequestCommand.self,
+      TraceFromSignpostsCommand.self,
     ]
   )
 

Sources/Diagnose/DebugCommand.swift

@@ -0,0 +1,257 @@
+//===----------------------------------------------------------------------===//
+//
+// This source file is part of the Swift.org open source project
+//
+// Copyright (c) 2014 - 2024 Apple Inc. and the Swift project authors
+// Licensed under Apache License v2.0 with Runtime Library Exception
+//
+// See https://swift.org/LICENSE.txt for license information
+// See https://swift.org/CONTRIBUTORS.txt for the list of Swift project authors
+//
+//===----------------------------------------------------------------------===//
+
+#if compiler(>=6)
+package import ArgumentParser
+import Foundation
+import RegexBuilder
+
+import class TSCBasic.Process
+#else
+import ArgumentParser
+import Foundation
+import RegexBuilder
+
+import class TSCBasic.Process
+#endif
+
+/// Shared instance of the regex that is used to extract Signpost lines from `log stream --signpost`.
+fileprivate struct LogParseRegex {
+  @MainActor static let shared = LogParseRegex()
+
+  let dateComponent = Reference(Substring.self)
+  let processIdComponent = Reference(Substring.self)
+  let signpostIdComponent = Reference(Substring.self)
+  let eventTypeComponent = Reference(Substring.self)
+  let categoryComponent = Reference(Substring.self)
+  let messageComponent = Reference(Substring.self)
+  private(set) var regex:
+    Regex<Regex<(Substring, Substring, Substring, Substring, Substring, Substring, Substring, Substring)>.RegexOutput>!
+
+  private init() {
+    regex = Regex {
+      Capture(as: dateComponent) {
+        #/[-0-9]+ [0-9:.-]+/#
+      }
+      " "
+      #/[0-9a-fx]+/#  // Thread ID
+      ZeroOrMore(.whitespace)
+      "Signpost"
+      ZeroOrMore(.whitespace)
+      #/[0-9a-fx]+/#  // Activity
+      ZeroOrMore(.whitespace)
+      Capture(as: processIdComponent) {
+        ZeroOrMore(.digit)
+      }
+      ZeroOrMore(.whitespace)
+      ZeroOrMore(.digit)  // TTL
+      ZeroOrMore(.whitespace)
+      "[spid 0x"
+      Capture(as: signpostIdComponent) {
+        OneOrMore(.hexDigit)
+      }
+      ", process, "
+      ZeroOrMore(.whitespace)
+      Capture(as: eventTypeComponent) {
+        #/(begin|event|end)/#
+      }
+      "]"
+      ZeroOrMore(.whitespace)
+      ZeroOrMore(.whitespace.inverted)  // Process name
+      ZeroOrMore(.whitespace)
+      "["
+      ZeroOrMore(.any)  // subsystem
+      ":"
+      Capture(as: categoryComponent) {
+        ZeroOrMore(.any)
+      }
+      "]"
+      Capture(as: messageComponent) {
+        ZeroOrMore(.any)
+      }
+    }
+  }
+}
+
+/// A signpost event extracted from a log.
+fileprivate struct Signpost {
+  /// ID that identifies the signpost across the log.
+  ///
+  /// There might be multiple signposts with the same `signpostId` across multiple processes.
+  struct ID: Hashable {
+    let processId: Int
+    let signpostId: Int
+  }
+
+  enum EventType: String {
+    case begin
+    case event
+    case end
+  }
+
+  let date: Date
+  let processId: Int
+  let signpostId: Int
+  let eventType: EventType
+  let category: String
+  let message: String
+
+  var id: ID {
+    ID(processId: processId, signpostId: signpostId)
+  }
+
+  @MainActor
+  init?(logLine line: Substring) {
+    let regex = LogParseRegex.shared
+    let dateFormatter = DateFormatter()
+    dateFormatter.dateFormat = "yyyy-MM-dd HH:mm:ss.SSSZ"
+    guard let match = try? regex.regex.wholeMatch(in: line) else {
+      return nil
+    }
+    guard let date = dateFormatter.date(from: String(match[regex.dateComponent])),
+      let processId = Int(match[regex.processIdComponent]),
+      let signpostId = Int(match[regex.signpostIdComponent], radix: 16),
+      let eventType = Signpost.EventType(rawValue: String(match[regex.eventTypeComponent]))
+    else {
+      return nil
+    }
+    self.date = date
+    self.processId = processId
+    self.signpostId = signpostId
+    self.eventType = eventType
+    self.category = String(match[regex.categoryComponent])
+    self.message = String(match[regex.messageComponent])
+  }
+}
+
+/// A trace event in the *Trace Event Format* that can be opened using Perfetto.
+/// https://docs.google.com/document/d/1CvAClvFfyA5R-PhYUmn5OOQtYMH4h6I0nSsKchNAySU/mobilebasic
+fileprivate struct TraceEvent: Codable {
+  enum EventType: String, Codable {
+    case begin = "B"
+    case end = "E"
+  }
+
+  /// The name of the event, as displayed in Trace Viewer
+  let name: String?
+  /// The event categories.
+  ///
+  /// This is a comma separated list of categories for the event.
+  /// The categories can be used to hide events in the Trace Viewer UI.
+  let cat: String
+
+  /// The event type.
+  ///
+  /// This is a single character which changes depending on the type of event being output.
+  let ph: EventType
+
+  /// The process ID for the process that output this event.
+  let pid: Int
+
+  /// The thread ID for the thread that output this event.
+  ///
+  /// We use the signpost IDs as thread IDs to show each signpost on a single lane in the trace.
+  let tid: Int
+
+  /// The tracing clock timestamp of the event. The timestamps are provided at microsecond granularity.
+  let ts: Double
+
+  init(beginning signpost: Signpost) {
+    self.name = signpost.message
+    self.cat = signpost.category
+    self.ph = .begin
+    self.pid = signpost.processId
+    self.tid = signpost.signpostId
+    self.ts = signpost.date.timeIntervalSince1970 * 1_000_000
+  }
+
+  init(ending signpost: Signpost) {
+    self.name = nil
+    self.cat = signpost.category
+    self.ph = .end
+    self.pid = signpost.processId
+    self.tid = signpost.signpostId
+    self.ts = signpost.date.timeIntervalSince1970 * 1_000_000
+  }
+}
+
+package struct TraceFromSignpostsCommand: AsyncParsableCommand {
+  package static let configuration: CommandConfiguration = CommandConfiguration(
+    commandName: "trace-from-signposts",
+    abstract: "Generate a Trace Event Format file from signposts captured using OS Log",
+    discussion: """
+      Extracts signposts captured using 'log stream --signpost ..' and generates a trace file that can be opened using \
+      Perfetto to visualize which requests were running concurrently.
+      """
+  )
+
+  @Option(name: .customLong("log-file"), help: "The log file that was captured using 'log stream --signpost ...'")
+  var logFile: String
+
+  @Option(help: "The trace output file to generate")
+  var output: String
+
+  @Option(
+    name: .customLong("category-filter"),
+    help: "If specified, only include signposts from this logging category in the output file"
+  )
+  var categoryFilter: String?
+
+  package init() {}
+
+  private func traceEvents(from signpostsById: [Signpost.ID: [Signpost]]) -> [TraceEvent] {
+    var traceEvents: [TraceEvent] = []
+    for signposts in signpostsById.values {
+      guard let begin = signposts.filter({ $0.eventType == .begin }).only else {
+        continue
+      }
+      // Each begin event should to be paired with an end event.
+      // If a begin event exists before the previous begin event is ended, a nested timeline is shown.
+      // We display signpost events to last until the next signpost event.
+      let events = signposts.filter { $0.eventType == .event }
+      traceEvents.append(TraceEvent(beginning: begin))
+      var hadPreviousEvent = false
+      for event in events {
+        if hadPreviousEvent {
+          traceEvents.append(TraceEvent(ending: event))
+        }
+        hadPreviousEvent = true
+        traceEvents.append(TraceEvent(beginning: event))
+      }
+      if let end = signposts.filter({ $0.eventType == .end }).only {
+        if hadPreviousEvent {
+          traceEvents.append(TraceEvent(ending: end))
+        }
+        traceEvents.append(TraceEvent(ending: end))
+      }
+    }
+    return traceEvents
+  }
+
+  @MainActor
+  package func run() async throws {
+    let log = try String(contentsOf: URL(fileURLWithPath: logFile), encoding: .utf8)
+
+    var signpostsById: [Signpost.ID: [Signpost]] = [:]
+    for line in log.split(separator: "\n") {
+      guard let signpost = Signpost(logLine: line) else {
+        continue
+      }
+      if let categoryFilter, signpost.category != categoryFilter {
+        continue
+      }
+      signpostsById[signpost.id, default: []].append(signpost)
+    }
+    let traceEvents = traceEvents(from: signpostsById)
+    try JSONEncoder().encode(traceEvents).write(to: URL(fileURLWithPath: output))
+  }
+}