2010-11-08, 21:15
3 vblanks take about 125 ms, add 30% of a refresh interval before it triggers you get to 137 ms.
2010-11-09, 02:33
bobo1on1 Wrote:3 vblanks take about 125 ms, add 30% of a refresh interval before it triggers you get to 137 ms.
Yes but one of those is the duration between vblanks anyway. 157ms between two vblanks when it should be 42ms implies 105ms discrepancy - that is 2 missed followed by a late notification. The m_CurrTime gets thrown out by one period for every GetTime() (eg GetClock()) call that are issued when lateness is detected. This seems to be a potential cause of problems. I will produce a patch for you to look at tomorrow time permitting.
2010-11-09, 17:51
I don't see that happening here, do you still have my interpolation patch applied?
2010-11-09, 18:44
bobo1on1 Wrote:I don't see that happening here, do you still have my interpolation patch applied?
No, and now I have moved over to the new svn with your drift fix. Can you not see the issue with the way the clock will increment based on missed vblanks for every GetTime() call that notices lateness?
2010-11-09, 20:44
When I check the difference between CurrentHostCounter() and m_CurrTime in RunGLX right after UpdateClock, I see a slow drift and no sudden jumps, even if it's missing vblanks.
I think I know the problem here, glXGetVideoSyncSGI possibly takes a long time to return, but the counter it returns did not update accordingly, but it might update correctly during the next iteration of RunGLX.
I think I know the problem here, glXGetVideoSyncSGI possibly takes a long time to return, but the counter it returns did not update accordingly, but it might update correctly during the next iteration of RunGLX.
2010-11-09, 21:29
bobo1on1 Wrote:When I check the difference between CurrentHostCounter() and m_CurrTime in RunGLX right after UpdateClock, I see a slow drift and no sudden jumps, even if it's missing vblanks.
I think I know the problem here, glXGetVideoSyncSGI possibly takes a long time to return, but the counter it returns did not update accordingly, but it might update correctly during the next iteration of RunGLX.
Yes I see the same - the patch I have started looks to find a reliable time using rolling average (and the rounded refresh rate based estimate) to base everything else on (eg to then know that the glXGetVideoSyncSGI returned late and thus to not rely on that one etc).
2010-11-09, 21:43
Or you can just continue from the top of the loop if GlxGetVideoSyncSGI takes too long.
2010-11-10, 00:53
bobo1on1 Wrote:Or you can just continue from the top of the loop if GlxGetVideoSyncSGI takes too long.
I don't know what you mean - doesn't the call block?
2010-11-10, 01:29
What I mean is, measure the time that glxGetVideoSyncSGI takes to return, if it's too long then ignore it.
But I just figured out glxGetVideoSyncSGI itself isn't the problem, it's the counter that doesn't increment properly, and it only seems to happen when VDPAU is in use.
This must be a recent regression from Nvidia, because it never happened at the time I wrote this code.
An easy way to test it is to run XBMC windowed, then keep dragging another window over XBMC, you'll get lots of missed vblanks.
It might pay to look into why this is happening, instead of trying to work around the brokenness.
But I just figured out glxGetVideoSyncSGI itself isn't the problem, it's the counter that doesn't increment properly, and it only seems to happen when VDPAU is in use.
This must be a recent regression from Nvidia, because it never happened at the time I wrote this code.
An easy way to test it is to run XBMC windowed, then keep dragging another window over XBMC, you'll get lots of missed vblanks.
It might pay to look into why this is happening, instead of trying to work around the brokenness.
2010-11-10, 02:34
bobo1on1 Wrote:What I mean is, measure the time that glxGetVideoSyncSGI takes to return, if it's too long then ignore it.
But I just figured out glxGetVideoSyncSGI itself isn't the problem, it's the counter that doesn't increment properly, and it only seems to happen when VDPAU is in use.
This must be a recent regression from Nvidia, because it never happened at the time I wrote this code.
An easy way to test it is to run XBMC windowed, then keep dragging another window over XBMC, you'll get lots of missed vblanks.
It might pay to look into why this is happening, instead of trying to work around the brokenness.
The timing of the call would be expected to be long as it waits though wouldn't it? Note that windows with dxva misses more vblanks than linux - I am not using latest nvidia drivers on linux coz they are crap (I am still on 195.36 and only rarely get missed vblanks but when they occur they are not handled very well if GetTime kicks in during lateness period). Oh and watching the NVidia forum I would say they care about HTPC close to zero% - its all about games for them and even then people seem mighty pee'd off these days (it would seem the driver quality has nose dived in recent times).
2010-11-10, 15:29
Well it seems the current situation is that, glXWaitVideoSyncSGI waits for one or more vertical blanks, but you don't know how many since you can't trust the counters, and there's jitter in the timing, but the average timing is ok.
CVideoReferenceClock correctly detects if any vblank signals are late or completely missed, however the correction mechanism fails since it assumes that the counter from glXGetVideoSyncSGI is always correct.
CVideoReferenceClock correctly detects if any vblank signals are late or completely missed, however the correction mechanism fails since it assumes that the counter from glXGetVideoSyncSGI is always correct.
2010-11-10, 19:25
bobo1on1 Wrote:Well it seems the current situation is that, glXWaitVideoSyncSGI waits for one or more vertical blanks, but you don't know how many since you can't trust the counters, and there's jitter in the timing, but the average timing is ok.
CVideoReferenceClock correctly detects if any vblank signals are late or completely missed, however the correction mechanism fails since it assumes that the counter from glXGetVideoSyncSGI is always correct.
Yes I agree (mostly), but also the calls to GetTime increment the missed count if late so if there happened to be multiple calls to GetTime in this window (possibly due to threads being scheduled late or whatever other reason GetTime() might get called after lateness) the m_CurrTime can get incremented more times than it should...
2010-11-10, 20:00
No it can't, it's all done inside a lock and m_VblankTime is incremented by one period for every missed vblank.
2010-11-10, 20:16
bobo1on1 Wrote:No it can't, it's all done inside a lock and m_VblankTime is incremented by one period for every missed vblank.
Here is some debug I have from when I trapped it:
Code:
12:16:48 T:2949741424 M:1861206016 DEBUG: ASB: CVideoReferenceClock::UpdateClock Now: 49571237557897 m_CurrTime: 49571256501160 m_VblankTime: 49571237556086 NrVBlanks: 1 m_MissedVblanks: 0 m_TotalMissedVblanks: 0 m_RefreshRate: 24 m_fineadjust: 1.000000 m_AdjustedFrequency: 1001000000 m_VblankInterval: 41657858 GetRefreshFrameTimeNs(): 41708333.333333336
12:16:48 T:2949741424 M:1861079040 DEBUG: ASB: CVideoReferenceClock::UpdateClock Now: 49571279133970 m_CurrTime: 49571298209494 m_VblankTime: 49571279132172 NrVBlanks: 1 m_MissedVblanks: 0 m_TotalMissedVblanks: 0 m_RefreshRate: 24 m_fineadjust: 1.000000 m_AdjustedFrequency: 1001000000 m_VblankInterval: 41576086 GetRefreshFrameTimeNs(): 41708333.333333336
12:16:48 T:2949741424 M:1860952064 DEBUG: ASB: CVideoReferenceClock::UpdateClock Now: 49571320890404 m_CurrTime: 49571339917827 m_VblankTime: 49571320887619 NrVBlanks: 1 m_MissedVblanks: 0 m_TotalMissedVblanks: 0 m_RefreshRate: 24 m_fineadjust: 1.000000 m_AdjustedFrequency: 1001000000 m_VblankInterval: 41755447 GetRefreshFrameTimeNs(): 41708333.333333336
12:16:48 T:2949741424 M:1860825088 DEBUG: ASB: CVideoReferenceClock::UpdateClock Now: 49571362579366 m_CurrTime: 49571381626160 m_VblankTime: 49571362576774 NrVBlanks: 1 m_MissedVblanks: 0 m_TotalMissedVblanks: 0 m_RefreshRate: 24 m_fineadjust: 1.000000 m_AdjustedFrequency: 1001000000 m_VblankInterval: 41689155 GetRefreshFrameTimeNs(): 41708333.333333336
12:16:48 T:2949741424 M:1860698112 DEBUG: ASB: CVideoReferenceClock::UpdateClock Now: 49571404260643 m_CurrTime: 49571423334494 m_VblankTime: 49571404258267 NrVBlanks: 1 m_MissedVblanks: 0 m_TotalMissedVblanks: 0 m_RefreshRate: 24 m_fineadjust: 1.000000 m_AdjustedFrequency: 1001000000 m_VblankInterval: 41681493 GetRefreshFrameTimeNs(): 41708333.333333336
12:16:48 T:2949741424 M:1860571136 DEBUG: ASB: CVideoReferenceClock::UpdateClock Now: 49571446026080 m_CurrTime: 49571465042827 m_VblankTime: 49571446023559 NrVBlanks: 1 m_MissedVblanks: 0 m_TotalMissedVblanks: 0 m_RefreshRate: 24 m_fineadjust: 1.000000 m_AdjustedFrequency: 1001000000 m_VblankInterval: 41765292 GetRefreshFrameTimeNs(): 41708333.333333336
12:16:49 T:3079272320 M:1860571136 DEBUG: ASB: CVideoReferenceClock::GetTime Waiting for NextVBlank to be in the future. Now: 49571599692110 NextVblank: 49571500190224
12:16:49 T:3079272320 M:1860571136 DEBUG: ASB: CVideoReferenceClock::UpdateClock Not-CheckMissed NrVBlanks: 1 m_VblankTime: 49571487788851 m_VblankInterval: 41765292
12:16:49 T:3079272320 M:1860571136 DEBUG: ASB: CVideoReferenceClock::UpdateClock Now: 49571600017443 m_CurrTime: 49571506751160 m_VblankTime: 49571487788851 NrVBlanks: 1 m_MissedVblanks: 1 m_TotalMissedVblanks: 1 m_RefreshRate: 24 m_fineadjust: 1.000000 m_AdjustedFrequency: 1001000000 m_VblankInterval: 41765292 GetRefreshFrameTimeNs(): 41708333.333333336
12:16:49 T:3079272320 M:1860571136 DEBUG: ASB: CVideoReferenceClock::GetTime Waiting for NextVBlank to be in the future. Now: 49571599692110 NextVblank: 49571541955516
12:16:49 T:3079272320 M:1860571136 DEBUG: ASB: CVideoReferenceClock::UpdateClock Not-CheckMissed NrVBlanks: 1 m_VblankTime: 49571529554143 m_VblankInterval: 41765292
12:16:49 T:3079272320 M:1860571136 DEBUG: ASB: CVideoReferenceClock::UpdateClock Now: 49571600536100 m_CurrTime: 49571548459494 m_VblankTime: 49571529554143 NrVBlanks: 1 m_MissedVblanks: 2 m_TotalMissedVblanks: 2 m_RefreshRate: 24 m_fineadjust: 1.000000 m_AdjustedFrequency: 1001000000 m_VblankInterval: 41765292 GetRefreshFrameTimeNs(): 41708333.333333336
12:16:49 T:3079272320 M:1860571136 DEBUG: ASB: CVideoReferenceClock::GetTime Waiting for NextVBlank to be in the future. Now: 49571599692110 NextVblank: 49571583720808
12:16:49 T:3079272320 M:1860571136 DEBUG: ASB: CVideoReferenceClock::UpdateClock Not-CheckMissed NrVBlanks: 1 m_VblankTime: 49571571319435 m_VblankInterval: 41765292
12:16:49 T:3079272320 M:1860571136 DEBUG: ASB: CVideoReferenceClock::UpdateClock Now: 49571601029492 m_CurrTime: 49571590167827 m_VblankTime: 49571571319435 NrVBlanks: 1 m_MissedVblanks: 3 m_TotalMissedVblanks: 3 m_RefreshRate: 24 m_fineadjust: 1.000000 m_AdjustedFrequency: 1001000000 m_VblankInterval: 41765292 GetRefreshFrameTimeNs(): 41708333.333333336
12:16:49 T:2949741424 M:1860571136 DEBUG: ASB: CVideoReferenceClock::UpdateClock Now: 49571603870636 m_CurrTime: 49571590167827 m_VblankTime: 49571571319435 NrVBlanks: -2 m_MissedVblanks: 0 m_TotalMissedVblanks: 3 m_RefreshRate: 24 m_fineadjust: 1.000000 m_AdjustedFrequency: 1001000000 m_VblankInterval: 41765292 GetRefreshFrameTimeNs(): 41708333.333333336
12:16:49 T:2949741424 M:1860571136 DEBUG: ASB: CVideoReferenceClock::UpdateClock Now: 49571611903250 m_CurrTime: 49571715292827 m_VblankTime: 49571611900765 NrVBlanks: 3 m_MissedVblanks: 0 m_TotalMissedVblanks: 3 m_RefreshRate: 24 m_fineadjust: 1.000000 m_AdjustedFrequency: 1001000000 m_VblankInterval: 13527110 GetRefreshFrameTimeNs(): 41708333.333333336
12:16:49 T:2949741424 M:1860317184 DEBUG: ASB: CVideoReferenceClock::UpdateClock Now: 49571654719501 m_CurrTime: 49571757001160 m_VblankTime: 49571654716890 NrVBlanks: 1 m_MissedVblanks: 0 m_TotalMissedVblanks: 3 m_RefreshRate: 24 m_fineadjust: 1.000000 m_AdjustedFrequency: 1001000000 m_VblankInterval: 42816125 GetRefreshFrameTimeNs(): 41708333.333333336
12:16:49 T:2949741424 M:1860317184 DEBUG: ASB: CVideoReferenceClock::UpdateClock Now: 49571694454681 m_CurrTime: 49571798709494 m_VblankTime: 49571694452931 NrVBlanks: 1 m_MissedVblanks: 0 m_TotalMissedVblanks: 3 m_RefreshRate: 24 m_fineadjust: 1.000000 m_AdjustedFrequency: 1001000000 m_VblankInterval: 39736041 GetRefreshFrameTimeNs(): 41708333.333333336
2010-11-10, 20:36
There's only one thread there calling GetTime.
The problem there is that when RunGLX calls UpdateClock right after the 3 detected missed vblanks, it should have updated the clock by 3 vblanks, however it only updates it by 1 vblank, and then updates it by 3 on the next iteration, the correction mechanism for missed vblanks can't handle that correctly.
The problem there is that when RunGLX calls UpdateClock right after the 3 detected missed vblanks, it should have updated the clock by 3 vblanks, however it only updates it by 1 vblank, and then updates it by 3 on the next iteration, the correction mechanism for missed vblanks can't handle that correctly.
