Search code examples
xcodeinstrumentsxcode-instruments

Xcode Instruments “Points of Interest” dropping intervals

tl;dr

When logging large numbers of intervals in “Points of Interest” tool, I am seeing intervals randomly getting omitted from the graph in the main pane. Are others seeing this problem? Am I doing something wrong?

I use Xcode Instruments pretty extensively to monitor asynchronous work with “Points of Interest” intervals. See How to identify key events in Xcode Instruments?

(For the record, there are other tools, such as those outlined in WWDC 2022’s Visualize and optimize Swift concurrency, but for me, intervals are still my “go to” tool.)

Anyway, I can create a points of interest OSSignposter (previously, OSLog):

import os.log

let poi = OSSignposter(subsystem: "…", category: .pointsOfInterest)

And then I can do things like:

let id = poi.makeSignpostID()
let state = poi.beginInterval(#function, id: id, "\(value)")

…

poi.endInterval(#function, state)

I can then profile the app in Instruments (from Xcode’s “Product” » “Profile” or command-i), start with the “Time profiling” template, and I get a nice timeline of the execution of my app. (You can also do things like right-click on an interval and set the inspection range, thereby narrowing your investigation of CPU or RAM or whatever, to some well-defined interval of code execution.)

So, for example, I ran foo, then bar, and finally baz, each logging their intervals and yielding the following in Instruments:

enter image description here

That’s all fine. (I kind of wish this graph was in chronological order, not alphabetical order. I also occasionally see frameworks logging to Points of Interest, which is exceedingly distracting when trying to diagnose issues in my own code. But neither of these are relevant to my question here.)

But recently, I have increasingly seen a loss of intervals in the graph. For example, here I ran 50 iterations, each with four concurrent tasks, with a pause in between each iteration, yielding the following:

enter image description here

But notice that at iterations 2, 16, 20, 40 and 46, there are missing intervals in the graph. These intervals are omitted somewhat randomly, anywhere between 5-15% of the time. Down in the lower “Detail” panel, I can see that all the intervals are actually captured by Instruments successfully, but some simply are not represented in the visual graph in the main pane. (And, only by doing large intervals did I finally notice a correlation between a missing interval and the fact that Instruments stopped using that lane and created a new lane.)

Some things I’ve tested include:

  • Changing the device doesn't appear to make a difference. I see this on iOS device, simulator, or just a macOS app. They all show the similar behavior.
  • I originally experienced this when testing a computationally intensive parallel calculations, but realize I experience the same problem with something that has negligible CPU impact (e.g., the above was with Task.sleep).
  • I know that this is not a “must be done on the same thread” problem, because I see this problem when using intervals with synchronous code, too (where I am obviously on the same thread).
  • I tested with both deferred and immediate logging modes in Instruments. (I generally use the former as the latter can result in dropped events under heavy load.)
  • I first noticed this with Xcode 15.0, but 15.0.1 has the same issue.
  • There are no errors or messages in the console.

Have others experienced this behavior? What is going on?

For those who are interested, this is the code that generated the above screen snapshot in Instruments:

import SwiftUI
import os.log

let poi = OSSignposter(subsystem: "Test", category: .pointsOfInterest)

struct ContentView: View {
    @State var status = "Not started…"
    @State var buttonsDisabled = false
    
    var body: some View {
        VStack {
            Text("Instruments’ “Points of Interest” experiment")
            Text(status)
            Button("Test Async-Await 100 Times") {
                Task {
                    status = "Starting"
                    buttonsDisabled = true

                    for iteration in 0 ..< 100 {
                        try await fourConcurrentTasks(for: iteration)
                        status = "Finished \(iteration) … still running"
                        try await Task.sleep(for: .seconds(0.25))
                    }

                    status = "All done"
                    buttonsDisabled = false
                }
            }
            .disabled(buttonsDisabled)
        }
        .padding()
    }

    func fourConcurrentTasks(for iteration: Int) async throws {
        try await withThrowingTaskGroup(of: Void.self) { group in
            for index in 0..<4 {
                group.addTask {
                    let id = poi.makeSignpostID()
                    let state = poi.beginInterval(#function, id: id, "\(iteration): \(index)")

                    try await Task.sleep(for: .seconds(0.25))
                    
                    poi.endInterval(#function, state)
                }
            }
            
            try await group.waitForAll()
        }
    }
}
Solution

  • Prior to iOS 18 and macOS 15, OSSignposter was not thread-safe. The docs did not make any reference to thread-safety, one way or the other. It was not Sendable, either (the standard convention nowadays for a class to inform us that it is thread-safe). And if you use it in a Swift concurrency codebase from a non-actor-isolated context, the “Strict Concurrency Checking” build setting of “Complete” will often warn you of this misuse.

    As a general rule, a type can only be considered thread-safe if the documentation makes assurances to that end (or, obviously, it is marked Sendable).

    I confirmed this problem manifests itself only when intervals were started in parallel and at the same time. I also notice that when I added synchronization round the OSSignposter and its API, the problem disappeared.

    But, as of iOS 18 and macOS 15, OSSignposter (and Logger) are now Sendable, and no longer manifest this behavior.

    I must confess that I originally assumed that this was merely a bug in the “Points of Interest” tool because:

    • The details pane in Instruments reported all the intervals correctly.

    • My own primitive custom Instruments tool (that used the same signpost schema, os-signpost-point-schema that the standard “Points of Interest” tool uses) does not manifest the problem.

    enter image description here

    But in retrospect, this is classic “race condition” sort of behavior. And given the lack of any assurances regarding thread-safety, that makes perfect sense.