Time to acquire system "drawable" resource each frame

[benjamin-heasly]

This issue is to capture some observations and research about frame timing. Specifically, we've seen some long delays when our Metal app tries to acquire a system "drawable" resource during each frame -- sometimes as much as 7ms or 14ms. For now, this is just documentation of what we've seen, with no obvious action to take next.

Observations started with our render pipeline test, for example testing how long it takes to a blt an arbitrary full-screen-sized texture to the screen on each frame. This can be tested with

mglTestRenderPipeline('runTests', 4)

Here are some sample results from an M1 iMac (24-inch, 2021, 8GB memory) with macOS Monterey 12.4 and Matlab R2021b.

The timing of "Draw commands Processed" is unexpected -- ie the green dots are too high up. In these tests the textures are pre-loaded ahead of time, so the command to draw / blt the texture should be very small. Why then does it take some 7ms for the Metal app to report that the drawing command has been issued, each frame?

Digging in, it seems this time is spent when our Metal app is blocked, waiting to acquire a system "drawable" resource, which is required for onscreen rendering. Our Metal code starts here.

It's not clear yet why we end up blocking on this call. We think we're following the relevant guidance from Apple about how to work with the drawable:

• MTKView
• CAMetalLayer Keeping References to Drawables
• Drawables best practices

Specifically, we are avoiding accessing the drawable as long as we can, until we actually start issuing drawing commands. And, we are allowing the drawable to be released as soon as we're done, using the recommended autoreleasepool {} pattern.

Here are a few more informal observations about the behavior we've seen:

• This seems to happen when using a large amount of video memory. In this example, we have 30 textures 2240 x 1260 pixels 4 rgba channels * 4 bytes per float channel, which amounts to >1GB of textures.
• This seems to go away when either: reducing the number of textures, reducing the sizes of the textures, and/or when running the same test on a machine with more memory.
• The time spent waiting for the drawable seems somewhat consistent, taking either <1ms, ~7ms, or ~14ms. The time remains consistent at one of these values for several seconds at a time.
• Every few seconds a dropped frame might occur, after which the app will settle into a new run, taking on a different one of those three times.
• Even when in a run of ~14ms, this test doesn't necessarily drop more frames than otherwise.

So -- is this simply what to expect on a relatively non-powerful iMac using >10% of its total memory for MGL textures? Or, is there something more we can learn / do to address this blocking time?

[justingardner]

Not sure if the specific observations have been resolved or not, but going to close this out and come back to it if issues arise over frame timing in the future.