[bobo1on1]

Check CXBMCRenderManager::WaitPresentTime in RenderManager.cpp in trunk (not Dharma), if it's set to false it adjusts the clock speed to the video timestamps, instead of calculating an offset.

[TheSwissKnife]

Check CXBMCRenderManager::WaitPresentTime in RenderManager.cpp in trunk (not Dharma), if it's set to false it adjusts the clock speed to the video timestamps, instead of calculating an offset.

I see that - and it uses FineAdjust so it changes a little how the video clock works, but what I don't see is how the audio is then sync'd (as per the description in DVDClock.h "CDVDPayerAudio synchronzies the audio stream to the clock"... etc.) - or this comment misleading?

EDIT: I just had a go with the changes you suggested but now my audio discontinuities have become +6 to +15ms per minute (with no change to my refresh rate or file). I will look into it in more detail tomorrow but it looks even more broken now. Is that the clock fighting you were referring to (as I still have my code to detect 1ms+ discontinuities)?

And this time the vblank count was 270355 for the same period! How can this code change affect the number of vblanks?

EDIT2: Discount this for now as I have noticed that my monthly filesystem maintenance kicked off (zfs scrub) around the time and still going after 10 hours. I have now stopped it and will re-test. It does raise the question though if the backend file feed can't keep up where is that logged (possibly "CDVDPlayer::SetCaching")?

[bobo1on1]

I see that - and it uses FineAdjust so it changes a little how the video clock works, but what I don't see is how the audio is then sync'd (as per the description in DVDClock.h "CDVDPayerAudio synchronzies the audio stream to the clock"... etc.) - or this comment misleading?

It changes the clock speed to match the timestamps, so it automatically corrects for any errors due to rounding and loss of precision, audio is still kept in sync in the same way.

EDIT: I just had a go with the changes you suggested but now my audio discontinuities have become +6 to +15ms per minute (with no change to my refresh rate or file). I will look into it in more detail tomorrow but it looks even more broken now. Is that the clock fighting you were referring to (as I still have my code to detect 1ms+ discontinuities)?

That's why I increased the discontinuity limit to one refresh period, if you get a discontinuity the error will wrap in the rendermanager and the two sync methods won't fight each other.

And this time the vblank count was 270355 for the same period! How can this code change affect the number of vblanks?

How are you counting them?

EDIT2: Discount this for now as I have noticed that my monthly filesystem maintenance kicked off (zfs scrub) around the time and still going after 10 hours. I have now stopped it and will re-test. It does raise the question though if the backend file feed can't keep up where is that logged (possibly "CDVDPlayer::SetCaching")?

You'll see this in the log:

Code:

WARNING: CDVDMessageQueue(audio)::Get - asked for new data packet, with nothing available
WARNING: CDVDMessageQueue(video)::Get - asked for new data packet, with nothing available

[TheSwissKnife]

It changes the clock speed to match the timestamps, so it automatically corrects for any errors due to rounding and loss of precision, audio is still kept in sync in the same way.

So the header file comment is very misleading.

That's why I increased the discontinuity limit to one refresh period, if you get a discontinuity the error will wrap in the rendermanager and the two sync methods won't fight each other.

I haven't got my head around that yet...I am sure it will sink in soon. But I think you are saying that I can't now try to keep the discontinuities within 1ms with this method. But I am trying to make the sync more smooth and track the drift -so this isn't helping much. Which issue is this trying to fix - just the rounding error sync drift?

How are you counting them?

VblankCount in RunGLX. Also checking the missed value too and various other places.

[TheSwissKnife]

You'll see this in the log:

Code:

WARNING: CDVDMessageQueue(audio)::Get - asked for new data packet, with nothing available
WARNING: CDVDMessageQueue(video)::Get - asked for new data packet, with nothing available

Ok I see 77 of those along with the subsequent SetCaching debug from when the maintenance kicked off interestingly only for audio and not video!

[TheSwissKnife]

Playing for one hour with no master clock and the frametime cap as per the patch (without my 1ms code)...here is the debug for the discontinuities. It does not look pretty.

Code:

15:03:22 T:2934545264 M:1901268992   DEBUG: CDVDPlayerAudio:: Discontinuity - was:0.000000, should be:0.000000, error:0.000000
15:37:57 T:2934545264 M:1833664512   DEBUG: CDVDPlayerAudio:: Discontinuity - was:2075698637.491000, should be:2075656669.265578, error:-41968.225422 limit: 41707.664833
16:06:30 T:2934545264 M:1817104384   DEBUG: CDVDPlayerAudio:: Discontinuity - was:3788534762.494578, should be:3787317333.333333, error:-1217429.161245
16:06:35 T:2934545264 M:1829789696   DEBUG: CDVDPlayerAudio:: Discontinuity - was:3792116573.237333, should be:3792288000.000000, error:171426.762667
16:06:36 T:2934545264 M:1831751680   DEBUG: CDVDPlayerAudio:: Discontinuity - was:3793332832.424000, should be:3793261485.646985, error:-71346.777015 limit: 41707.664833
16:06:40 T:2934545264 M:1840873472   DEBUG: CDVDPlayerAudio:: Discontinuity - was:3797306818.733984, should be:3797184041.665852, error:-122777.068132
16:07:16 T:2934545264 M:1840123904   DEBUG: CDVDPlayerAudio:: Discontinuity - was:3833079161.175852, should be:3832085333.333333, error:-993827.842519
16:07:30 T:2934545264 M:1841221632   DEBUG: CDVDPlayerAudio:: Discontinuity - was:3846215973.713334, should be:3846048000.000000, error:-167973.713334
16:07:31 T:2934545264 M:1840078848   DEBUG: CDVDPlayerAudio:: Discontinuity - was:3847091229.105000, should be:3847044327.445144, error:-46901.659856 limit: 41707.664833
16:07:40 T:2934545264 M:1830346752   DEBUG: CDVDPlayerAudio:: Discontinuity - was:3855854583.656144, should be:3856000000.000000, error:145416.343856
16:07:46 T:2934545264 M:1838960640   DEBUG: CDVDPlayerAudio:: Discontinuity - was:3862191040.870000, should be:3862144441.800484, error:-46599.069516 limit: 41707.664833
16:07:50 T:2934545264 M:1839161344   DEBUG: CDVDPlayerAudio:: Discontinuity - was:3866739231.793484, should be:3866016000.000000, error:-723231.793484
16:09:26 T:2934545264 M:1850634240   DEBUG: CDVDPlayerAudio:: Discontinuity - was:3962291684.802000, should be:3962249736.958576, error:-41947.843424 limit: 41707.664833

[bobo1on1]

So the header file comment is very misleading.

I don't see how it's misleading, it just states that the rendermanager needs to know if CDVDPlayerAudio is changing the audio stream to keep it in sync with the clock (by using the resample or drop dupe sync method), or if it's changing the clock to keep it in sync with the audio (by using the audio clock sync method).

I haven't got my head around that yet...I am sure it will sink in soon. But I think you are saying that I can't now try to keep the discontinuities within 1ms with this method. But I am trying to make the sync more smooth and track the drift -so this isn't helping much. Which issue is this trying to fix - just the rounding error sync drift?

Yes, it wants every presenttime to fall exactly in between two vertical blank timestamps, it does this by changing the clock speed of the videoreferenceclock slightly.
However, since dvdclock is referenced to the videoreferenceclock, this will cause a desync between dvdclock and the playing audio stream.
So if CDVDPlayerAudio starts doing 1 ms discontinuities, it will effectively cancel out the speed change from the rendermanager, that's what I mean when I say that the two sync methods start fighting each other.
However, if you make a discontinuity big enough so that a frame will be presented roughly one vblank later or earlier, then the rendermanager is fine, since it wants a presenttime to fall in between two vblank timestamps, and it doesn't care if that's one vblank earlier or later.

There's really no use for doing 1 ms discontinuities, a new videoframe will only be presented on the screen after a vertical blank, those happen at a fixed interval, XBMC has no control over it, so if you set the clock back by 1 ms a frame won't be presented 1 ms earlier.

You need to realize that all this a/v sync stuff consists of compromises, you have a soundcard that plays at a fixed rate, you have a display that refreshes at a fixed rate, those two are running from different clocks and are not synchronized to each other, and you have no control over either.

So basically, if you want perfectly smooth playback, want it perfectly synchronized, you don't want to resample the audio, and have no control over the hardware, you're in a situation that is impossible to solve.

VblankCount in RunGLX. Also checking the missed value too and various other places.

That's a system counter, you need to check how much it increments over a given period, and even if that value is wrong I have no control over it.

Playing for one hour with no master clock and the frametime cap as per the patch (without my 1ms code)...here is the debug for the discontinuities. It does not look pretty.

Code:

15:03:22 T:2934545264 M:1901268992   DEBUG: CDVDPlayerAudio:: Discontinuity - was:0.000000, should be:0.000000, error:0.000000
15:37:57 T:2934545264 M:1833664512   DEBUG: CDVDPlayerAudio:: Discontinuity - was:2075698637.491000, should be:2075656669.265578, error:-41968.225422 limit: 41707.664833
16:06:30 T:2934545264 M:1817104384   DEBUG: CDVDPlayerAudio:: Discontinuity - was:3788534762.494578, should be:3787317333.333333, error:-1217429.161245
16:06:35 T:2934545264 M:1829789696   DEBUG: CDVDPlayerAudio:: Discontinuity - was:3792116573.237333, should be:3792288000.000000, error:171426.762667
16:06:36 T:2934545264 M:1831751680   DEBUG: CDVDPlayerAudio:: Discontinuity - was:3793332832.424000, should be:3793261485.646985, error:-71346.777015 limit: 41707.664833
16:06:40 T:2934545264 M:1840873472   DEBUG: CDVDPlayerAudio:: Discontinuity - was:3797306818.733984, should be:3797184041.665852, error:-122777.068132
16:07:16 T:2934545264 M:1840123904   DEBUG: CDVDPlayerAudio:: Discontinuity - was:3833079161.175852, should be:3832085333.333333, error:-993827.842519
16:07:30 T:2934545264 M:1841221632   DEBUG: CDVDPlayerAudio:: Discontinuity - was:3846215973.713334, should be:3846048000.000000, error:-167973.713334
16:07:31 T:2934545264 M:1840078848   DEBUG: CDVDPlayerAudio:: Discontinuity - was:3847091229.105000, should be:3847044327.445144, error:-46901.659856 limit: 41707.664833
16:07:40 T:2934545264 M:1830346752   DEBUG: CDVDPlayerAudio:: Discontinuity - was:3855854583.656144, should be:3856000000.000000, error:145416.343856
16:07:46 T:2934545264 M:1838960640   DEBUG: CDVDPlayerAudio:: Discontinuity - was:3862191040.870000, should be:3862144441.800484, error:-46599.069516 limit: 41707.664833
16:07:50 T:2934545264 M:1839161344   DEBUG: CDVDPlayerAudio:: Discontinuity - was:3866739231.793484, should be:3866016000.000000, error:-723231.793484
16:09:26 T:2934545264 M:1850634240   DEBUG: CDVDPlayerAudio:: Discontinuity - was:3962291684.802000, should be:3962249736.958576, error:-41947.843424 limit: 41707.664833

That doesn't look right, it could be a bug somewhere, did you revert your changes regarding the window size?

[TheSwissKnife]

I don't see how it's misleading, it just states that the rendermanager needs to know if CDVDPlayerAudio is changing the audio stream to keep it in sync with the clock (by using the resample or drop dupe sync method), or if it's changing the clock to keep it in sync with the audio (by using the audio clock sync method).

DVDClock.h states that "when it's false, CDVDPayerAudio synchronzies the audio stream to the clock". This is only true for resample & drop/dup. It does not say that this actually depends on the sync method.

There's really no use for doing 1 ms discontinuities, a new videoframe will only be presented on the screen after a vertical blank, those happen at a fixed interval, XBMC has no control over it, so if you set the clock back by 1 ms a frame won't be presented 1 ms earlier.

You need to realize that all this a/v sync stuff consists of compromises, you have a soundcard that plays at a fixed rate, you have a display that refreshes at a fixed rate, those two are running from different clocks and are not synchronized to each other, and you have no control over either.

I understand that part but I want to have a way to see the discrepancy between real video and audio clock stabilize - so that I can tune the video refresh rate accordingly since this in fact is not really completely fixed (it has some reasonable degree of freedom)

That's a system counter, you need to check how much it increments over a given period, and even if that value is wrong I have no control over it.

But I check that this is incrementing correctly also (eg a line count of debug messages). I didn't think you had any control over it - I just can't understand why it should vary playing the same file multiple times - but perhaps the packets not being available added up to that much...I will check again.

That doesn't look right, it could be a bug somewhere, did you revert your changes regarding the window size?

I commented out my stuff.

[TheSwissKnife]

BTW, is there a reason that the video pts "half vblank reduction" in CDVDPlayerVideo::OutputPicture does not try to incorporate the clock speed value and thus sets the pts back a little inaccurately. I guess it is not very significant but I would think it clearer to incorporate the m_AdjustedFrequency or better the simple speed value into the adjustment.

[bobo1on1]

Nice catch, I forgot about it.

[TheSwissKnife]

I have temporarily reverted to using the MasterClock method. I tweaked the code minimally to get the sync (avgerror) drift 32x better and thus essentially close enough to almost never be an issue.

In case you are interested the adjustments are as follows (changes/adjustments in bold):

1. In CDVDClock::UpdateFramerate fix the source of the initial rounding error that occurs in the calculation of the speed value by simply looking to see if it is in the range that should match the 1.001 standard speed factor eg

Code:

double speed = (double)rate / (fps * weight);

[b]if ( abs(speed - 1.001) < 0.00000003 )
      speed = 1.001;[/b]

This improves things by a factor of 4 straight off.

2. add a new int64_t variable to VideoReferenceClock.h for storing fine grain current clock time eg.

Code:

[b]int64_t m_CurrTimeFine;[/b]

3. Adjust CVideoReferenceClock:rocess so that it initialises this fine grain variable to 1000 x m_CurrTime eg

Code:

m_CurrTime = Now + m_ClockOffset;
[b]m_CurrTimeFine =  m_CurrTime * 1000;[/b]

4. Adjust CVideoReferenceClock::UpdateClock so that it increments this fine grain variable by 1000 x "the usual nanosecond based expression". Then set the m_CurrTime to this divided by 1000 (in place of its current assignment) eg.

Code:

[b]m_CurrTimeFine += (int64_t)NrVBlanks * (int64_t)((double)(m_AdjustedFrequency * 1000) * m_fineadjust) / m_RefreshRate;
m_CurrTime = (m_CurrTimeFine / 1000)[/b];

This improves by a further factor of 8, giving a total improvement from avgerror of -0.000003197 down 32x to -0.000000101. At 24p this is 0.9% of a frame per hour. Thus very unlikely to ever cause a wrap during a movie.


EDIT: And by adjusting the error integral factor in WaitPresentTime from 0.01 to 0.03 (which I did to get the sync value to stabilise more quickly) the avgerror value drops further to -0.000000033. This part now works well, so I assume I can go back to using 1ms discontinuities - or does the clock fighting blight the MasterClock mode too?

[bobo1on1]

The clock fighting only happens when masterclock is false and the sync method is set to audio clock.
It would be nice if my patch worked ok (it works for me), because that automatically compensates for a wrongly reported fps, but it could also cause extra problems if the video timestamps are not completely perfect.

[TheSwissKnife]

Well I will have another go with it. But ideally it would be nice to have both options and possibly selectable via advancedsettings.xml.

I will now begin to look at the detailed pts values and adjustments and the sync difference between audio pts and video pts etc. I would like to be able to print out the pts (ideally tracked back to the original file pts'es) at last possible time prior to them being released to the device drivers in both audio and video cases. So far I have seen the video looks to be just after WaitPresentTime completes - is there anywhere further on you might suggest, and audio in the core audio renderer? Basically I want to test the sync difference is constant through different files and after pause/play cycles.

[bobo1on1]

HandleSyncError and WaitPresentTime seem to be best suited for that.

[TheSwissKnife]

I was using those -and they tend to show a 70ms discrepancy between audio pts and video. I have not yet accounted for all the adjustments (from the original file ones) and their purpose but if you think they closely reflect the real events going to the hardware then I will go from there.

EDIT: I have been looking at the audio code that shoves packets onto the output queue CPTSOutputQueue::Add and the though I need to better understand the function of the CDVDAudio::GetDelay() and the audio frameduration adjustments (used for the delay parameter in the call) I can see that the timestamp field in the object is set in DVDClock time (with video refresh rate sized ticks). The Current() call only advances when the timestamp of the front of the queue is smaller than the current DVDClock time. I can see that there is an issue then that can occur (more so with relatively large audio frame and video frame durations) where the current value can stay the same over an audio packet period (eg 32ms) or it can move double the audio frame duration (eg 64ms) in the same period. I presume this would be no big deal if it were not for the reliance of the Current pts value used in the discontinuity calculation, which can then become greater even than a whole video frame length (eg 41ms) when in fact there was really no discontinuity at all - and then of course the video will drop/dup etc. This is a bug as far as I can tell, and explains my issue number 2. earlier.

All of the problems due to the lack of granularity in the DVDClock would surely be solved by including a system time delta adjustment (eg delta from vBlankTime capped at video frameduration) (ie so that GetClock and GetAbsoluteClock actually return values that can be in between the Video reference clock tick values). I am probably not explaining this very well so tomorrow I will attempt to test this theory.