Metal (TracyMetal.hmm): GPU zones are heavily time-shifted after replacing gputime withProfiler::GetTime() (GPU no longer aligns with CPU)

[Hanflipped]

Hi Tracy team,

I modified Tracy’s Metal integration (TracyMetal.hmm) and now GPU zone timestamps are badly misaligned with CPU zones.

I changed the Collect() logic in TracyMetal.hmm to use MTLCommandBuffer::addCompletedHandler to measure the GPU execution duration of a frame. The completion handler provides timing in CFTimeInterval

Because of that change, I replaced the original gputime timestamp source with Profiler::GetTime() (so both CPU zones and the GPU context would use the same clock). which is MemWrite(&item->gpuNewContext.gpuTime， Profiler::GetTime())

After replacing gputime with Profiler::GetTime(), GPU zones appear far earlier (many seconds, ~20s+) than they should, and they no longer line up with CPU zones, even though both are now using Profiler::GetTime()

Are there recommended debugging/visualization techniques inside Tracy to diagnose CPU/GPU misalignment,I ’ve already tried many different alignment/conversion changes, but none of them had any effect
Any help or guidance would be greatly appreciated—thank you for your time

[wolfpld]

@slomp

[Hanflipped]

This is how I changed the way GPU time is calculated.

GPU Frame Time

[slomp]

@Hanflipped This seems to be a problem related to timestamp domains.

The completion handler provides timing in CFTimeInterval

According to https://developer.apple.com/documentation/CoreFoundation/CFTimeInterval:

typealias CFAbsoluteTime
Type used to represent a specific point in time relative to the absolute reference date of 1 Jan 2001 00:00:00 GMT

TracyMetal uses Metal command queries to retrieve timestamps, and these "raw" GPU timestamps (MTLTimestamp) are unrelated to CFTimeInterval timestamps:
https://developer.apple.com/documentation/metal/mtltimestamp?language=objc

The type of absolute time a Metal timestamp uses can vary with a system’s configuration, but it’s consistent for a configuration.

In other words, there's no formal specification for MTLTimestamp: they could be in any unit, and anchored to any epoch, and can vary depending on the Metal version, driver, and GPU hardware.

Tracy needs to calibrate (correlate) its CPU with GPU time in order to properly align things in the GUI.
In the case of Metal, we rely on the following to get a "good enough" pair of (cpu, gpu) timestamps:
https://developer.apple.com/documentation/metal/mtldevice/sampletimestamps:gputimestamp:

If you really want to feed CFTimeInterval timestamps to Tracy, you will have to establish a "mapping" from one to the other. There are several ways of doing this, but in its simplest form, it boils down to finding a proper multiplier. Before you go that route, why doesn't the current TracyMetal Collect workflow insufficient for you? In a way, TracyMetal Collect is doing precisely that, in the encoder level.

[Hanflipped]

@Hanflipped This seems to be a problem related to timestamp domains.

The completion handler provides timing in CFTimeInterval

According to https://developer.apple.com/documentation/CoreFoundation/CFTimeInterval:

typealias CFAbsoluteTime
Type used to represent a specific point in time relative to the absolute reference date of 1 Jan 2001 00:00:00 GMT

TracyMetal uses Metal command queries to retrieve timestamps, and these "raw" GPU timestamps (MTLTimestamp) are unrelated to CFTimeInterval timestamps: https://developer.apple.com/documentation/metal/mtltimestamp?language=objc

The type of absolute time a Metal timestamp uses can vary with a system’s configuration, but it’s consistent for a configuration.

In other words, there's no formal specification for MTLTimestamp: they could be in any unit, and anchored to any epoch, and can vary depending on the Metal version, driver, and GPU hardware.

Tracy needs to calibrate (correlate) its CPU with GPU time in order to properly align things in the GUI. In the case of Metal, we rely on the following to get a "good enough" pair of (cpu, gpu) timestamps: https://developer.apple.com/documentation/metal/mtldevice/sampletimestamps:gputimestamp:

If you really want to feed CFTimeInterval timestamps to Tracy, you will have to establish a "mapping" from one to the other. There are several ways of doing this, but in its simplest form, it boils down to finding a proper multiplier. Before you go that route, why doesn't the current TracyMetal Collect workflow insufficient for you? In a way, TracyMetal Collect is doing precisely that, in the encoder level.

The reason the current TracyMetal Collect workflow is insufficient for my case is that I want the GPU time for rendering an entire frame (command buffer level), not just per-pass timings.

From what I understand, the current Metal integration collects timings around passes/encoders (it requires passing a PassDescriptor*), so it naturally measures pass durations rather than the full command buffer GPU execution time.

To get a per-frame GPU duration, I added an [cmdBuffer addCompletedHandler:] inside my metalZoneScope
[cmdBuffer addCompletedHandler:^(id<MTLCommandBuffer> cb) { if (cb.status == MTLCommandBufferStatusCompleted) { uint64_t gpuTime = static_cast<uint64_t>( (cb.GPUEndTime - cb.GPUStartTime) * 1000 * 1000 * 1000 ); capturedCtx->QueriesGpuTimes[qid].store(gpuTime, std::memory_order_release); } } ];

use:

duration = cb.GPUEndTime - cb.GPUStartTime

I only use CFTimeInterval here to compute the duration, then convert it to ns:

uint64_t durationNs = (cb.GPUEndTime - cb.GPUStartTime) * 1e9;

For the zone timestamps, I tried to anchor them on the CPU timeline:

• On each metalZoneScope, I record the CPU start time using Profiler::GetTime() into m_start[].

• In Collect(), when writing timestamps, I do:

  start = m_start[m_tail];
  end = m_start[m_tail - 1] + durationNs;

So I’m not trying to treat CFTimeInterval as an absolute timestamp, only as a duration.

However, the GPU zones still show up heavily time-shifted vs CPU in Tracy.
Does this mean that Tracy’s GPU context for Metal does not accept CPU-domain timestamps for GPU zones,
thanks for your replay！❤

[slomp]

I want the GPU time for rendering an entire frame (command buffer level), not just per-pass timings.

This is not how Tracy GPU was designed. The GPU timeline is to show and track less granular zones than the whole frame.
Even if you go through the hoops and get your command buffer zones to appear in the timeline, you will end up clobbering the less granular encoder zones.

I record the CPU start time using Profiler::GetTime() into m_start[].

Tracy's Profiler::GetTime() is not measured in units of nanoseconds. It's measured in whatever unknown units the best high frequency ticker available in the platform may be. You'd have to run some calibration yourself to measure how many Profiler::GetTime() ticks happen in 1 nanosecond, and then use that to convert your durationNs to the correct tick duration unit.

---

One final note: even if you go through all of the trouble to hack Tracy to do what you want and render the durations properly, please not that what you'll end up measuring based on your description above will not align with the CPU. The GPU runs asynchronously to the CPU:

On each metalZoneScope, I record the CPU start time using Profiler::GetTime() into m_start[].

Your duration would show up aligned at the exact instant the CPU executed metalZoneScope, and this is always going to be before the GPU actually starts executing those commands. Depending on how many frames in flight you have, this could be 1 to 2 whole frames (dozens of milliseconds) before the GPU starts executing the commands.

[slomp]

I think we can close this issue now.