Audio sync problems when screen set to 24 Hz (4 Viewers)

[technick]

I idea : be carreful to the bios and the bus optimisation. Mine can change automaticaly video clock +5% : disabled. FYI I have also a sync problem if I use post postprocessing.

 

[Scythe42]

Odd, as when the bug would be in the EVR presenter it should be as buggy on all files. So, there should be some external dependancy as well that causes the issue to appear.
[..]
V-sync is driven by the display drivers, EVR presenter cannot change that. There could be a bug in the code that fails to schedule the samples to be displayed, but I still haven't figured out how such could affect the audio / video sync.

Yeah, it's a really strange bug. Complicated to find the root cause. But I'm sure once identified it's a simple thing to fix as it is most of the times.

There is without question a relation between the content and the EVR rendering. The higher the resolution the sooner the problem comes up, but only on x264 23.976fps files so far with DD or DTS sound. HD XVIDs are doing much better than x264 and only fall out of sync rarely which could be a simple codec issue. Main difference here is that the files are compressed more. With blu-rays muxed to MKV and audio transcoded to FLAC on the other hand the issue does not come up at all. But I only re-muxed a few BRs so far (ran out of storage).

Scheduler seems an interesting idea. If it displays a frame now and then multiple times but never skipping one it would cause an audio drift. But then I should have seen a lot of judder.

Is there any debug/trace code in the dshowhelper.dll (I assume it contains the renderer interface)? I have Visual Studio 2008 installed on my machine and can compile MediaPortal SVN and also try out some stuff in the code if you point me roughly in the right direction where to look.

Have you tested the analog audio output?

If I decode the sound instead of passthrough (so I can listed over headphones and the analog outputs of the HTPC) the effect is a little bit different. When the video starts to go out of sync, the internal player pauses for a fraction of a second and then continues, like it wants to catch up with audio. But sometimes it failed to do so (probably the drift is already too big) and pauses for nearly a second before continuing with the next frame resulting in being completly out of sync. This repeats over and over again. The effect here is similar to skip forward/skip backwards where audio and video are completly out of sync when using EVR. With VMR the problem does not come up.

I glady would use VMR only but I have some issues here as well (see recent post in the bug repor forum), when returning from the player (plus some one with the OSDs while inside the player).

I idea : be carreful to the bios and the bus optimisation. Mine can change automaticaly video clock +5% : disabled. FYI I have also a sync problem if I use post postprocessing.

Interesting idea. It could be that the drift only occurs when hardware acceleration is in place. Need to check some BIOS settings and turn of anything that "boots" or "optimizes" and could have an effect of the video clock speed. Cannot hurt to check. Thanks for the idea.

 

[tourettes]

Is there any debug/trace code in the dshowhelper.dll (I assume it contains the renderer interface)? I have Visual Studio 2008 installed on my machine and can compile MediaPortal SVN and also try out some stuff in the code if you point me roughly in the right direction where to look.

dshowhelper.dll is the component where EVR presenter code is. There is also some debug logging in EVR presenter code that could be enabled.

Would be nice if someone who actually can reproduce this issue (I cannot as I don't have 24Hz capable display in my dev PC) could debug it a little bit.

Currently I'm working with some other EVR presenter related improvements (those are at too early stages to be discussed in the public) and within those changes there is going to be much improved rendering statistic gathering / presentation available.

 

[Scythe42]

I try to take a look at the code if I see something. I play around with it a bit. But I'm not very fluent in D3D. Guess I need to visit MSDN first for a crash course.

Anyway below is the EVR debug log from a playback. Maybe it gives you some ideas.

I started playback of movie with AVC video and AC3 audio this time. I resumed where I last left off. Horrible out of sync and slowly started to drift even more. I paused the movie and resumed, no difference. I then skipped back a little to get it in sync again. It was still a bit off and slowly drifted out of sync again for about the next 60-90 seconds. Then there were two judders. The first one was maybe just a few frames long and afterwards audio didn't seem to drift further. The second judder a few seconds later was way longer and skipped a lot of frames (including audio). After the larger one the audio was nearly back in sync (probably off due to processing, but anything that's constant I can compensate) and didn't drift any further. There were a few dropped frames about every 30 seconds from now on. Processor usage was between 5% and 10% all the time. With VMR way more processor usage but no skipped frames and everything in sync except for a constant processing delay.

This is bit unusual than most times because of the large resync attempt after which the drifting stops. Usually there are a few subtle attempts for resync without any judder (probably just one frame) that reset the audio drift very little but it continues to drift again right way. In this cases the playback starts in sync before drifting.

One thing I also observe is that with 60Hz, there are a lot of skipped frames in the beginning right after playback trying to get everything into sync while audio is running. Looks like the first second of video playback time is accelerated. With 24Hz there is a pause at the beginning. All frames are skipped until playback starts. Audio comes in a little bit earlier. Same happens when skipping forwards and backwards which is basically starting playback at another position.

 

[tourettes]

Something odd as the video samples seems to get late, and that gap increases. Is the audio playing ahead of the video? To me it looks like EVR presenter is scheduling the samples wrongly, unfortunately I cannot see from the code whay would be wrong. It would be helpful if I could debug the issue.

ScheduleSample is only called from ProcessInputNotify which is triggered by the MS EVR code. So, why would that be late?

You could try changing few parameters. just for fun (try both, smaller and bigger values)

MAX_PRERUN
MAX_WAIT
MIN_TIME_TO_PROCESS

 

[DMember 49125]

I started playback of movie with AVC video and AC3 audio this time. I resumed where I last left off. Horrible out of sync and slowly started to drift even more. I paused the movie and resumed, no difference. I then skipped back a little to get it in sync again. It was still a bit off and slowly drifted out of sync again for about the next 60-90 seconds.

I can confirm that. I have exactly that behavior in my htpc. When I skip -15 sec the sync is ok.

 

[tourettes]

I started playback of movie with AVC video and AC3 audio this time. I resumed where I last left off. Horrible out of sync and slowly started to drift even more. I paused the movie and resumed, no difference. I then skipped back a little to get it in sync again. It was still a bit off and slowly drifted out of sync again for about the next 60-90 seconds.

I can confirm that. I have exactly that behavior in my htpc. When I skip -15 sec the sync is ok.

I would assume that the sync starts to drift after such seek? At least the posted log shows that the sync started to drift again after a seeking.

Was the audio later or early? Logs would show that audio might be early as the video frames are reported to be late.

 

[Scythe42]

Something odd as the video samples seems to get late, and that gap increases. Is the audio playing ahead of the video? To me it looks like EVR presenter is scheduling the samples wrongly, unfortunately I cannot see from the code whay would be wrong. It would be helpful if I could debug the issue.

Yes, audio is playing ahead of video and the gap keeps on increasing the longer the video plays. When it really gets bad some attempt to correct this is being bade. I assume this is the one second thingy in GetTimeToSchedule.

You could try changing few parameters. just for fun (try both, smaller and bigger values)

Changing these values doesn't have any constant effect unless I change them dramatically which screws up things even more but don't have any affect on the drift.

I digged a little deeper into CheckForScheduledSample because if a video lag is detected is must be corrected. If frames cannot be displayed and are behind more than the frequency you have to drop them.

I changed:

        //too late, but present anyway
        Log("frame is too late for %I64d ms, last sleep time %d ms.", -*pNextSampleTime/10000, msLastSleepTime );
        CHECK_HR(PresentSample(pSample), "PresentSample failed");

to:

       //too late, but present anyway
        Log("frame is too late for %I64d ms, last sleep time %d ms.", -*pNextSampleTime/10000, msLastSleepTime );
        m_didSkip = true;
        Log( "skipping frame, behind %I64d ms, last sleep time %d ms.", -*pNextSampleTime/10000, msLastSleepTime );
//        CHECK_HR(PresentSample(pSample), "PresentSample failed");

This skips late frames as an attempt to resync and writes something to the logs. Crude but effective for debugging. When the lag is really being bad it can take some seconds before playback is back in sync. For a workaround a smoother implementation is needed.

If I now take a look at the evr.log I see that late frames are skipped until playback is back in sync. It also works when skipping forwards or backwards in steps. Not as smooth at 60Hz where playback seems to be accelerated until in sync. But probably this only happens because of the highter refresh rate of 60Hz when playing back 23.976fps material. With the higher vsync the presenter is able of presenting more late frames from a 23.976 perspective at 60Hz than at 24Hz. This is probably why the bug is undetected at 60Hz and playback gets in sync quickly. So the bug is cancelled out by having a higher refresh rate running (just a guess)...

For the evr.log you can see that playback started at 02:20:09, frames got dropped until they are back in sync and then playback keeps in sync until I stopped at 02:20:23.

10-09-2009 02:20:09.286 [dd4]OnClockRestart
10-09-2009 02:20:09.321 [bc8]dangerous and unlikely time to schedule [0D909258]: 1597710534. scheduled time: 1597970384, now: 259850
10-09-2009 02:20:09.321 [bc8]Flushing: size=3
10-09-2009 02:20:09.444 [d08]Scheduling sample from the past (133 ms, last call to NotifyWorker: 155 ms)
10-09-2009 02:20:09.444 [bc8]frame is too late for 133 ms, last sleep time 20 ms.
10-09-2009 02:20:09.444 [bc8]skipping frame, behind 133 ms, last sleep time 20 ms.
10-09-2009 02:20:09.449 [d08]Scheduling sample from the past (96 ms, last call to NotifyWorker: 5 ms)
10-09-2009 02:20:09.450 [bc8]frame is too late for 96 ms, last sleep time 20 ms.
10-09-2009 02:20:09.450 [bc8]skipping frame, behind 96 ms, last sleep time 20 ms.
10-09-2009 02:20:09.454 [d08]Scheduling sample from the past (60 ms, last call to NotifyWorker: 4 ms)
10-09-2009 02:20:09.454 [bc8]frame is too late for 60 ms, last sleep time 20 ms.
10-09-2009 02:20:09.454 [bc8]skipping frame, behind 60 ms, last sleep time 20 ms.
10-09-2009 02:20:09.459 [d08]Scheduling sample from the past (23 ms, last call to NotifyWorker: 5 ms)
10-09-2009 02:20:23.633 [dd4]OnClockPause

One question: why are late frames displayed anyway? I don't really understand the reason for this. At least when frames are continously late skipping needs to occur. Unless a higher refresh rate can compensate for it. Then it would make sense just to display the frames for an accelerated playback (see assumption futher up). But this would break as soon as the problems occur on the material's native rate with a lag higher than the time a single frame is displayed.

The evr.log on 60Hz with 24p material should show similar stuff and could proof this idea. Anyone can try this. Just check the evr.log on MP in Debug Logging and see if you have decreasing "frame is too late" at the beginning of playback.

It also doesn't explain why I couldn't reproduce the issue under Win 7 so far. Maybe it's a Vista/Splitter combination thingy with 23.976fps material and set 23.976Hz/24Hz refresh rate during initialization of the playback where video frames are send too late in general. And because the code doesn't really compensate for late frames, the frames stay late. When playback starts in sync it stays in sync. About one out of ten times the file I used to reproduce the issue starts in sync and stays that way. Again the root cause here is unknown.

This is where a workaround could be implemented even though the root cause is not known. Either skipping frames on playback start or ignoring vsync and display samples immediately until playback is in sync. The lag increases because nothing is early enough for compensation (vsync might play a role here), but I won't investigate this one because it's only a side effect. Focus should be on being in sync in the first place or getting there after playbacks starts as quick and smooth as possible.

This also explains why other players with a EVR renderer don't show a 24p problem. They probably just skipping late frames before they display the first one and therefore the problem cannot be seen.

I also checked some other material. It seems to be a general issue. When a movie starts perfectly in sync it stays in sync. (unless there is an external effect on the HTPC which brings stuff out of sync). The drift only occurs once a frame is later than the frequency. Some movies start more likely out of sync than others for yet unknown reasons. But again, the EVR presenter has to take care of syncing the playback.

 

[Scythe42]

Update:

The quick fix seems to work for me. I tested it with a couple of different files. Audio is always perfectly in sync shortly after playback started and stays this way. How many frames are skipped depends on how far it was off in the first place when playback started. Of course you need to adjust for any general processing delay to get audio perfectly spot on.

Because of the late frames some frames get dropped every now and then. The reason for the late frames is still unknown (machine is nearly idle). But at least I have an acceptable workaround for now and we can investigate the reason for the late frames in more detail. It's a crude patch but it does its job for now.

I also tried it with 60Hz. Same happens. Late frames but because of the higher refresh rate they get presented anyway resulting in speed up segments instead of dropped frames and some judder when this happens. IMHO not better because playback is not smooth either way. The frames shouldn't be late in the first place (especially not at the beginning of playback).

So it looks like a general bug, but this needs to be confirmed by others first.

Index: EVRCustomPresenter.cpp
===================================================================
--- EVRCustomPresenter.cpp	(revision 23545)
+++ EVRCustomPresenter.cpp	(working copy)
@@ -1347,8 +1347,13 @@
       else
       {
         //too late, but present anyway
-        Log("frame is too late for %I64d ms, last sleep time %d ms.", -*pNextSampleTime/10000, msLastSleepTime );
-        CHECK_HR(PresentSample(pSample), "PresentSample failed");
+        //Log("frame is too late for %I64d ms, last sleep time %d ms.", -*pNextSampleTime/10000, msLastSleepTime );
+        //CHECK_HR(PresentSample(pSample), "PresentSample failed");
+
+        //too late, don't present
+        m_iFramesDropped++;
+        m_didSkip = true;
+        Log( "skipping frame, behind %I64d ms, last sleep time %d ms.", -*pNextSampleTime/10000, msLastSleepTime );
       }
     } 
     else

In case someone wants to try this, I attached the patched dshowhelper.dll I'm using under MP 1.0.10 Beta right now. If you try this let me know if it fixes similar problems on your end or if it breaks anything else. If you don't have similar problems I suggest you don't try the patched DLL.

 

[tourettes]

One question: why are late frames displayed anyway? I don't really understand the reason for this. At least when frames are continously late skipping needs to occur. Unless a higher refresh rate can compensate for it. Then it would make sense just to display the frames for an accelerated playback (see assumption futher up). But this would break as soon as the problems occur on the material's native rate with a lag higher than the time a single frame is displayed.

I agree that those late samples should be dropped, there is no need for rendering those. I guess the reason why those aren't dropped is that there haven't been before any other reason for the late frames than busy CPU / GPU... until the 24 fps issue did arise.

So, after some testing the patch (proposed in your next post) should be added to SVN. It's relatively safe and shows the dropped frame stats increasing (that is easier to notice than the slowly drifting audio, so it will even help debugging the real issue later on).

This is where a workaround could be implemented even though the root cause is not known. Either skipping frames on playback start or ignoring vsync and display samples immediately until playback is in sync. The lag increases because nothing is early enough for compensation (vsync might play a role here), but I won't investigate this one because it's only a side effect. Focus should be on being in sync in the first place or getting there after playbacks starts as quick and smooth as possible.

Dropping frames is the only good way as we cannot disable v-sync (DirectX handles it for us, so it will be always "forced", which is a good thing that we don't have to handle it).