Playback skips on M1 Max with 64MB & SSD

18.0.1

Hi Folks
I've got a "big mac" 16" MBP M1 Max w/64GB memory and 1TB free on the internal SSD.
I'm using 2K H.264 proxies made by internal generation.

Only 20GB of system memory is in use. About 85% CPU idle.

The playback fps indicator shows a solid green 25fps. No errors. Yet visual playback stutters.
If I turn on "Stop playback when a dropped frame is detected" playback is not stopped.

So... what's going on? I'm currently on macOS 12.5 but this has been happening on 12.4 as well.
One novel thing is I have 9 channels of audio in the proxies - even though they're not used as it's getting its audio from the original audio files - also on the fast internal drive.

Here's a log in case that sheds some light: https://drive.google.com/file/d/1PNF7db ... sp=sharing

And here's the MediaInfo for one of the proxy files:

MediaInfo.txt.zip

(1.45 KiB) Downloaded 34 times

Here's a log from when it DID stop playback due to a dropped frame: https://drive.google.com/file/d/1PSEEE5 ... sp=sharing

Hi Joe, not quite sure sorry, that sounds very annoying!

If you watch playback via SDI or HDMI out does it stutter? Or is it just in the GUI?

You could try going into preferences > Playback settings and adjust those settings to see if it helps.

Are all your frame rate settings the same (timeline, playback) etc.? As well as the camera source?
Assuming too there are no speed changes in the timeline.

Also, just curious as to why you would make h.264 proxies when something like prores(proxy) is much easier to decode?

I let Resolve make H.264 proxies as they're smaller so the media can easily fit in my internal drive, and the M1 Max should be decoding in hardware. Note that I'm using Resolve Studio. The Proxy Generator is defaulting to H.264 now anyway as smaller files are important to the new collaborative workflow so this should be a well-supported situation.

I also notice that the stuttering gets worse after I make an edit - if I play it a few times the stuttering reduces. So it sounds like a reading into memory thing? Even though there's scads of memory available.

Given that I'm on a beefy machine that Resolve has been optimized for, I'd think BMD would like to find out what's going on rather than me fiddling around trying to get rid of the symptom. The timeline is also long - 90 min. I know I could and perhaps will split it into reels but I don't see why Resolve wouldn't be able to handle this situation easily.

Just found this in the logs:
0x1727bb000 | LsManager | WARN | 2022-08-17 18:04:28,313 | Timeout waiting for interop lookahead (AVSyncCount = 24218)
0x1185d0580 | UI | INFO | 2022-08-17 18:04:28,801 | Stop playback as we seem to have dropped a frame

You said Resolve does not detect the skipping playback (other than when you have a dropped frame)? Is it possibly related to screen refresh / pro motion of the Mac?

It mostly plays without detecting dropped frames. So I guess I might be seeing two different things.

Would promotion issues be random or have a distinct pattern? What I’m seeing varies over time even when playing the same footage.

I think I’ll turn off Live save and backups next time it starts happening. Have already turned off and deleted any caching I can find. Thought for a moment it might be the fusion cache even though I don’t have any comps or titles - though I do have some smooth cuts. They’re fusion, right?


Sent from my iPhone using Tapatalk

I would also say that it's probably a OS screen refresh issue when you're looking at the viewer window. Checking with an I/O device would help.

I actually do have one so I'll give that a shot.
Either way though I hope this gets ironed out as the M1 MBP is clearly a favored platform for Resolve.

Actually... I can't find it so far. An UltraStudio Mini Monitor. It's pretty old at this point anyway... wonder if it'd work with this new MBP?

Tried turning off ProMotion. At first I thought that fixed it - but no.
Perhaps restarting Resolve puts it off for a while.
Things were fine for a bit and then it started happening again. I took a logfile snapshot and saw these appearing again - seemingly in sync with when it started happening:

Code: Select all

0x118f48580    | BtCommon             | WARN  | 2022-08-17 23:06:00,198 | Negative duration
0x118f48580    | SyManager.Signals    | INFO  | 2022-08-17 23:06:08,335 | Main view page is changed to 14
0x2890ef000    | LsManager            | WARN  | 2022-08-17 23:06:13,760 | Timeout waiting for interop lookahead (AVSyncCount = 13503)
0x2890ef000    | LsManager            | WARN  | 2022-08-17 23:06:16,044 | Timeout waiting for interop lookahead (AVSyncCount = 13535)
0x2890ef000    | LsManager            | WARN  | 2022-08-17 23:06:19,129 | Timeout waiting for interop lookahead (AVSyncCount = 13587)
0x2890ef000    | LsManager            | WARN  | 2022-08-17 23:06:23,713 | Timeout waiting for interop lookahead (AVSyncCount = 13677)
0x2890ef000    | LsManager            | WARN  | 2022-08-17 23:06:28,810 | Timeout waiting for interop lookahead (AVSyncCount = 13791)
0x118f48580    | SyManager.Signals    | INFO  | 2022-08-17 23:06:30,269 | Main view page is changed to 2


Verified that turning off Live Save and Project Backups doesn't get rid of this issue.

Only the UltraStudio Mini Monitor 3G will work with Apple silicon.

Oh good now I can stop looking!


Sent from my iPhone using Tapatalk

Looks from logs like Live Save does - at least sometimes - cause dropped frames during playback.

Code: Select all

0x118228580    | SyManager.ProjectManager | INFO  | 2022-08-18 09:06:13,075 | Start saving project anamnesis joe edit
0x171707000    | SyManager.ActionExecutor | INFO  | 2022-08-18 09:06:13,092 | Database transaction is ongoing, user initiated action SmActIOCPSigInvoker is postponed
0x118228580    | SyManager.ActionExecutor | INFO  | 2022-08-18 09:06:13,138 | Database transaction completed, enqueueing 1 postponed actions
0x118228580    | SyManager.ProjectManager | INFO  | 2022-08-18 09:06:13,138 | Saving project took 63 ms
2022-08-18 09:06:27.049 Resolve[19320:374242] Invalid state set [-100].
2022-08-18 09:06:27.069 Resolve[19320:374242] Invalid state set [-100].
0x118228580    | SyManager.Signals    | INFO  | 2022-08-18 09:06:27,078 | Main view page is changed to 14
0x118228580    | UI                   | INFO  | 2022-08-18 09:06:27,100 | Stop playback as we seem to have dropped a frame


Yet another log - just hoping this will help BMD get to the bottom of what's going on.
https://drive.google.com/file/d/1PZaE3V ... sp=sharing

And another - this one I let skip for about 10 seconds.
https://drive.google.com/file/d/1PgSYQ4 ... sp=sharing

During that whole time I see

Code: Select all

Timeout waiting for interop lookahead

warnings in the log.

The funny thing about this one (to me) is...
BMD may already have figured it out - from others' if not my copious amounts of info about it.
But we won't know to stop providing info because... well... they don't tell us they've figured it out.

Joe, as an owner of a Studio license, you could go the route of opening a support case and pointing them to this thread. This way support would email you with findings and presumably close the loop a bit faster than just happening upon your post (this is a user forum). Does that make sense or has the oxygen level in my office dropped again?

I've tried that in the past but the forum has seemed to be a closer connection to the Resolve team than going that route. Though maybe I'll try it. After a PM I think.

They used to be more responsive and seemed to have a ticket system to track issues. Not as much lately (maybe a sign of being overwhelmed with more users of the product?).

That could be. My impression is they're field offices and perhaps more hardware oriented. Software and field offices don't really go together.


Sent from my iPhone using Tapatalk

I've tried two new things:
1. Attached a second monitor through the OS'es display support. Apparently my UltraStudio Mini Monitor isn't current enough to work on the new M1 macs so I can't try it without OS support.
2. Regenerated my proxies as ProRes Proxy - very lightweight.

Also turned off Live Save and Backups just to take them out of the equation.

The result is the same. The skipping still happens - coupled with these timeout messages in the log:

Code: Select all

0x16db7f000    | LsManager            | WARN  | 2022-08-19 21:39:18,790 | Timeout waiting for interop lookahead (AVSyncCount = 462552)
0x16db7f000    | LsManager            | WARN  | 2022-08-19 21:39:20,029 | Timeout waiting for interop lookahead (AVSyncCount = 462577)
0x16db7f000    | LsManager            | WARN  | 2022-08-19 21:39:24,923 | Timeout waiting for interop lookahead (AVSyncCount = 462676)
0x16db7f000    | LsManager            | WARN  | 2022-08-19 21:39:28,789 | Timeout waiting for interop lookahead (AVSyncCount = 462750)
0x16db7f000    | LsManager            | WARN  | 2022-08-19 21:39:30,025 | Timeout waiting for interop lookahead (AVSyncCount = 462775)
0x16db7f000    | LsManager            | WARN  | 2022-08-19 21:39:35,625 | Timeout waiting for interop lookahead (AVSyncCount = 462887)


Just copied a scene from the long timeline to its own and the stuttering remains. This without restarting Resolve. Usually restarting improves things for about 5 min. I'll try that and see if the short timeline will still stutter.

I sent the project and a bit of the media in to BMD and... they found the problem - which was mine not theirs.

It's not playing in realtime due to the timeline Film Grain OFX node you are using.

DOH! That'd do it! Here's the story behind how it got there - plus a request which I'll post in the requests subforum:

So… I got that correction from the DP to get the footage “in the ballpark” of what he wants it to look like. So it’s not me but him who added that node.

Can you guess what my next observation/question is?

Please add a feature that tells me why Resolve can’t play my footage or timeline in real time. Imagine how much less support load you’d have if the program did this. Plus the more users you add the more helpful this feature becomes.

I’ll post this as a feature request. Of course people will say that it’s the user’s own fault etc etc but oh well.

Thanks again for tracking this down.

Feature request: viewtopic.php?f=33&t=166193

yeah that could be cool as an option, to see how much processing each node is taking up (optional of course) like how new AE shows in ms how long each layer takes to render the frame to track down things slowing it down.

NOT SOLVED after all. Happens less frequently now but it still happens.
And when it does I always find those timeout messages in the log right when the skipping is happening.

Joe, could you please post some updated logs after you removed the film grain Fx? Also can you try disabling all Fx and see if it happens, if so post logs for that?

There are some references in your logs to cloud-based assets, e.g, Google Drive, CloudDocs, etc. Is it possible that trying to access some cloud-based asset is intermittently slowing it down?

When you do the playback test, I suggest you do identical tests from the color page and edit page. It seems to do more logging during color page playback.

Some of your logs contain: "VTDecompressionSessionCreate dvh3 return -12907". That is a MacOS Video ToolBox API to set up reading from a compressed codec. The -12907 return code means "Could not create instance"; I don't know if that's meaningful or expected in some cases. I checked for all other return codes for that call and don't see any in your logs, just that one value.

On Resolve Studio 18.0.1, I can cause the LsManager "Timeout waiting for interop lookahead" (AVSyncCount = xxxx) messages on my M1 Ultra if fast forwarding or reversing through a difficult codec. In your case does playback skip at 1x speed or only at faster playback speeds?

I know your test media is 2k H264 proxies, but I noticed when I use the REDCINE-X Pro player on REDRAW material, it shows the prefetcher activity as a bar graph ahead of the current playhead position. When you reverse directions with JKL you can see the prefetcher start over and try to keep up with the new direction and playback speed. I imagine the Resolve LsManager interop lookahead warnings relate to a similar prefetch thread. I don't know if that is expected in some cases. It is classified as a warning not an error.

As a test could you try ProRes proxies instead of H264? The M1 Max has separate encode/decode accelerators for that. Admittedly 2k H264 proxies should work fine but trying ProRes proxies might provide a useful data point.

[Peter Chamberlain]

A link to the problem media, inc audio, might help.

Also whats happening on the color page? is it locked at 25fps?

I'm still exploring the suggestions Joe posted in his very thorough comment.
I tried reproducing the stutter in the Color Page but so far it's been dead-on steady. If that persists I'm guessing it rules out quite a few things as I imagine they share a great deal of play logic.

I still haven't seen it skip without seeing the timeout messages in the log.
Likewise, when I played about 20 min stutter-free in the Color Page there were no timeouts present in the log.

It did finally stutter while playing in the Color page. Slightly different log message:

Code: Select all

0x11c124580    | UI.MainViewer.Transport | INFO  | 2022-08-22 20:53:56,071 | Color Page playback has started
0x16eb87000    | LsManager            | WARN  | 2022-08-22 20:53:56,972 | /Users/jenkins/jenkins/workspace/resolve/Resolve/Cyclone/LsManager/LsDataHandler.cpp(1849): discard 7(26)
0x16eb87000    | LsManager            | WARN  | 2022-08-22 20:53:56,976 | /Users/jenkins/jenkins/workspace/resolve/Resolve/Cyclone/LsManager/LsDataHandler.cpp(1849): discard 7(27)
0x11c124580    | UI.MainViewer.Transport | INFO  | 2022-08-22 20:53:56,976 | Color Page playback has stopped
0x11c124580    | UI.MainViewer.Transport | INFO  | 2022-08-22 20:53:58,640 | Color Page playback has started
0x16eb87000    | LsManager            | WARN  | 2022-08-22 20:57:08,179 | /Users/jenkins/jenkins/workspace/resolve/Resolve/Cyclone/LsManager/LsDataHandler.cpp(1849): discard 9(4742)
0x11c124580    | UI.MainViewer.Transport | INFO  | 2022-08-22 20:57:08,190 | Color Page playback has stopped
0x11c124580    | SyManager.AutoSave   | INFO  | 2022-08-22 20:57:09,111 | Start autosave
0x11c124580    | SyManager.AutoSave   | INFO  | 2022-08-22 20:57:09,112 | Auto saving current project <anamnesis joe edit>


Here are the logs from that run: https://drive.google.com/file/d/1cD7n7_ ... sp=sharing

I'm now going to move my Project backup location from my iCloud folder to a totally local folder and see if that has any effect. I doubt it though since it stutters even when backups and live save are turned off.

A link to the problem media, inc audio, might help.

I don't think the media is a problem - but Dwaine has a .dra of the project along with some sample media.

This may sound crazy but is there any possibility that after creating proxies you did not do Playback>Proxy Handling>Prefer Proxies? It defaults to "Disable All Proxies", even after you generate them.

In the media page you can verify proxies exist for each clip by selecting List View, then right-click on the column names and enable "Proxy Media Path". That should point to a valid proxy file corresponding to the "File Path" column for each original media file.

The M1 Max is so fast that in some cases you could generate proxies and not always perceive they aren't working, esp if the background and other caching functions make original resolution pretty fast most of the time.

In this case the original media isn’t online.
I generated H.264 proxies and then made a .dra with proxies but not media checked as suggested in the Resolve 18 manual.

At first everything was offline and I thought the proxies hadn’t been connected but then realized I had to separately copy over the synced sound files. This might be a good option to handle in the Create Project Archive dialog.

So there’s no possibility I’m using the original media as - for the restored .dra - the H.264 proxies ARE the original media.

Afterwards I did generate ProRes Proxy proxies to try the even lighter-weight solution. At that point I did at least once forget to turn on Prefer Proxies. But this just gets me the H.264 media - not the ProRes 4444 media that’s the original source.

PS generating new proxies is how I found this issue that I reported:


Sent from my iPhone using Tapatalk

Just to be clear - with ProRes proxies, you don't get the skipping, correct?

I do still get the skipping actually.
Mostly right after I change something. It’s as if there’s some sort of cache miss - but all caching is disabled. If I were low on Ram I’d say the program got paged out but I’ve got like 40GB free ram.

And it’s much worse in the Edit page. It almost never skips in the Color page.


Sent from my iPhone using Tapatalk

I do still get the skipping actually...

Can it be reproduced on a timeline with all effects disabled? If yes that could imply it's a possible decode issue with the playback engine or the framework, OS and hardware layers below that.

If it only happens with certain effects maybe that is a lead to pursue.

Another thing to try is examining the CacheClip folder at different points. If caching is really disabled that should not be changing. One trick is periodically duplicating that folder and doing a diff vs the previous states. Various tools can be used, but a good one is Beyond Compare: https://www.scootersoftware.com

Is it possible you could shoot an iPhone video at 240 fps of the problem? That might help determine if it's really a stutter or something that looks similar, like a frame order problem or a frame cadence problem. It would also allow comparison of the timecode display vs the visual frame sequence on the monitor.

It’s definitely not just frame order. By stutter I really mean that frames are dropped - potentially quite a few of them. So one shot will freeze, then be replaced by the subsequent shot with about a second of frames not having been shown.

It doesn’t happen only on effects - it happens throughout the 90 min timeline, most of which is straight cuts. It seems to happen more frequently across cuts but that’s not the only place it happens.

Once it starts happening it persists skipping. It doesn’t seem to recover once it starts skipping - but I haven’t let it run for more than 10 seconds so I can’t be sure of that. Quitting and restarting cures it for a few minutes.


Sent from my iPhone using Tapatalk

Here's a screen cap of Resolve skipping in the Source Viewer playing a proxy encoded as 2K ProRes 422 Proxy.
This again is on a 16" mbp m1max with 64gb memory of which 35gb is in use. Resolve is using only 4gb and cached files are using 27gb - probably on behalf of Resolve.
640gb free on the internal drive which is where all the files reside.

Hey Joe,

I know this probably won't help the way you'd like it to, but I'm on a M1 (not "max") and I can read without any stuttering at all 4K 25 fps easily. That, you knew but just FYI prior to any comment (see below the main reason I mention it).
Now, whenever I saw these kind of random skips (not on an M1 btw), the main hint was the access bottlenecked by any weakness in the config...
Now, my present config is quite basic but seems robust : any footage is on a external nvme SSD on the TB3 port, thus the routes from Resolve to ram and caches is not the same as the footage one. Maybe you could give a try to this kind of config too ?

While I normally keep the footage I'm currently working on a 2 TB NVme connected by Thunderbolt too, I don't see such problems with footage on a simple Samsung T5 either.

Is it possible the 9 audio tracks in the proxy cause some issue? It's the only thing that jumped out at me as being different (other than 2K rather than HD or UHD).

BTW, Joe, what is your timeline resolution?

I have to admit that I was startled by the hiccups you demonstrate in your video.

Hi everyone
Thanks for your feedback!
What you see in the video is the Source Viewer. So the timeline doesn’t even figure in to this. The timeline resolution is 2K as well so it matches the footage.

I agree that the 9 channels of sound is “interesting” so here are my next two tests:

1. Unsync the sound and see if the clip plays cleanly
2. Put the footage on an external nvme ssd and see if the clip plays cleanly

Cheers!


Sent from my iPhone using Tapatalk

Haven't been able to repro the behavior all day - same system no changes. Clearly the bug is frightened!