Xcode Instruments “Points of Interest” dropping intervals

Question

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:

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:

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)
            .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()
        }
    }
}

Answer 1

I confess that had concluded that this was simply 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.

My conclusion was that Instruments was fine, but the problem must rest in the “Points of Interest” tool, itself.

That having been said, I noticed that the problem appeared to manifest itself when intervals started at the same time in parallel (e.g., I was doing repeated iterations of launching four tasks in parallel). But, that smells suspiciously like a race condition. Indeed, the problem disappeared when I added some synchronization around the makeSignpostID/beginInterval and endInterval to eliminate the potential race.