Framerate too *high* and unsmooth playback in temporal/spatial deinterlace

[StrangeNoises]

I've had this for the last few builds I think; I didn't notice it right away. In fact, I'd very occasionally had this problem for ages, but these days I seem to get it most of the time:

When playing interlaced content with Temporal/Spatial deinterlace enabled, I notice a slight unsmoothness with the playback, and on hitting codec-info, I see that the frame rate is too high. For 50i content I'd expect to see 50fps (or small fluctuations around that). Instead I see values ranging typically from about 70fps to well over 100fps. (170fps seen once; usually settles around 70-80fps though)

Switching deinterlace method to vdpau bob and back again, or cycling through all the deinterlace methods, usually (ie: not always) fixes it for the remainder of the video currently playing.

It's a bit of a heisenbug: when i disabled pvr and restarted earlier to get a small log showing it, it promptly stopped happening, re-enabled pvr and it continued to not happen, but now a few hours and a more unwieldy logfile-size later, it's happening again. I wonder if it might be precisely something that only starts happening after XBMC has been running for a while. (BTW GPU temp 47% while this is going on)

When it does happen, it happens across all interlaced content; SD as well as HD; live tv as well as tv rips and blu-ray/dvd rips. It actually looks almost right, as you might expect with a too high framerate, which is why I'm not sure when it started happening a lot rather than very rarely; it's just when things are supposed to be very smooth I can notice small discontinuities because it's not well-synced to the actual refresh rate, that alert me that it might be happening. I'm sure it's not right. :-)

This is (once again) on my core-i7x4 machine with an nvidia GT520, using the latest ppa-testing build on ubuntu raring. Normally on an insufficient gpu, the framerate is too low. I don't know how to interpret the frame rate being too high!

Log file: http://paste.ubuntu.com/5582754/

The affected playback starts at 17:11:19, line 26632. I don't think it's specific to the media file here; it affects long-known-good media when it happens, and this media file has at other times played just fine, eg: from line 570 in the same logfile.

(Looking at the log makes me wonder if it might not be doing the right thing with audio either - it's ac3 audio and should be being passed-through the optical connector but looks like it may not be, but I expect that's a separate issue.)

[FernetMenta]

I do a lot of refactoring and changes in order to get the buffing into mainline. It's hard to follow the log when not knowing exactly the version. Could you rebase and post a new log if the issue is still present?

[StrangeNoises]

i thought the version was at the top of the logs ;-) but anyway, after posting the issue I've also built from source and am waiting to see if/when it happens again with this build. (XBMC (13.0-ALPHA1 Git:20130303-abb9a8c), Platform: Linux (Ubuntu Raring Ringtail (development branch), 3.8.0-9-generic x86_64). Built on Mar 3 2013). As other builds at-least-sometimes only exhibited the problem after a few hours of runtime, I'm waiting to see.

[FernetMenta]

can you set vsync to always (system - video). I am wondering how fps can go that high if vsync is working. Upgrading NVidia driver should be worth a try. Users reported performance improvements and I see those in your log: CVDPAU::DrawSlice - VdpDecoderRender long decoding: 33 ms, dec: 3, proc: 0, rend: 0

[FernetMenta]

i thought the version was at the top of the logs ;-)

sure, the version is in the log but not in my head. only can remember current :)

[StrangeNoises]

vsync was set to "let driver choose" - which thinking about it you probably already knew from the logs. Set it to always and restarted. Will observe and see if it recurs.

I've often wondered why fps wanders at all; eg: when I'm not encountering the problem, it still fluctuates by up to about .4 fps either side. That is normal isn't it? or should it be hard-locked onto 50fps?

[FernetMenta]

fps on codec screen is calculated not very precisely. .4 up/down is not problem.

[StrangeNoises]

ok, after a day on the latest build (as of yesterday) and with vsync set to always-enabled, it is happening again.

I see in the meantime there have been new commits, so i'll catch up with that now, but if there's an issue with this thing arising after a number of hours of runtime and commits keep happening, we're never gonna catch up. ;-)

Log: http://paste.ubuntu.com/5585678/

Playback where it goes wrong starts at line 72960; earlier in the same log are instances where the same file plays fine. From that point, it plays with the wrong too-high framerate, then I cycle through the interlace methods, and when it gets back to temporal/spatial it's fine from then on. NB: Along the way it isn't fine on all the other deinterlace methods every time; but I suspect that something gets reset as it goes via a method that drops the frame rate (that it should have) to 25 as opposed to 50.

NB: Although the file is 1080i bbc hd off-air, I believe the actual content to have originated as progressive (turning deinterlace off, I can't find any combing artifacts) as I believe the bbc have decided to do this a lot more for stuff that's "for keeps" (or at least, for release on itunes). Nevertheless the problem happens, both on material like this and on material (eg: live studio stuff) that most definitely is interlaced.

[StrangeNoises]

btw i still have problems getting the up to date code from git; your rebases making git pull nonfunctional, or at least it used to, as I understand. git checkout -f origin followed by a git reset --hard used to work, but the first checkout step of that no longer does, talking about detached heads, which having done that I think is foxing my subsequent attempts to get things back in sync. (In the interim I upgraded to raring, so possible new-git-version issues there. git version 1.8.1.2)

So I resort to wiping it out completely and doing a fresh git clone every time, which takes ages. Is there an actual definitive way this is supposed to work?

(I don't actually want to make code changes, I just want to be able to check out and build the most current source)

[StrangeNoises]

(true to form, the new build (13.0-ALPHA1 Git:20130304-c07a7f7) is not yet exhibiting the problem...)

[StrangeNoises]

One extra detail that may help pin down where the error is happening - noticed yesterday, it's still not yet happening with this current build: During playback when this problem is happening, if I escape and go to system info (ie: with the video still playing in the background) and go to the Video section, the fps figure at the end of the screen resolution line matches that seen in codec info. eg:

Screen resolution: 1920x1080@50.00Hz - Full screen (76.94 fps)

(the 76.94 in this example is just made up for illustration; point is, it fluctuates in that clearly-wrong far-too-high range here as well as in codec info. Dunno if that helps locate the issue in the whole playback process.

(NB: No refresh-rate changes involved along the way: I have it set that the default refresh rate for xbmc is 50Hz, to match the most common refresh rate of the media I play.)

[FernetMenta]

ok, there is a problem. will investigate ...

[StrangeNoises]

meanwhile i've now installed nvidia-310 to see if it occurs on that too. waiting to disprove a negative...

[FernetMenta]

use my osd branch, this should work

[StrangeNoises]

current master still exhibits the bug when used with nvidia-310. building and installing current osd branch now, will wait to see... though presumably this is to narrow down the real problem; it's not so much that i'm badly inconvenienced by the problem personally, more that we obviously want it fixed in master, so hopefully this is for diagnostic purposes. :-)

[FernetMenta]

what have you done while recording this log? http://paste.ubuntu.com/5585678/ changed setting "prefer mixer"? does that trigger the issue?

[StrangeNoises]

i certainly wouldn't have done that deliberately. (and can't find "prefer mixer" in that log). In short, it's nothing I'm doing. :-}

The first time I ran it against nvidia-310 i lost audio config, which is odd: I had it configured for optical, and the optical interface is on the mobo, not the nvidia card. But it had failed to enumerate audio devices properly. On quitting and restarting, I was able to select the correct audio outputs again and since then it's worked. But that was all more recent than that log anyway, which is from when I was still running nvidia-304.

[StrangeNoises]

Of course, I have been observing that it only happens after a number of hours of use. In fact usually it strikes the following day. of course, during that time the TV and amp are turned off for several hours, and then turned on again. On that thought I tried triggering it earlier by turning it off and on again, but it didn't cause any immediate problem on the interlaced media I played afterwards.

[FernetMenta]

Playback where it goes wrong starts at line 72960

at this point in the log is menu navigation in OSD video settings and the following is not long enough to tell what's wrong. Can you record a new log and keep it going wild for some minutes.

Strange is that it can't go above refresh rate, that's limited by OpenGL

[StrangeNoises]

My actions in past examples would have been:

1. Start playing the 'test' video. (there's nothing particular about that one i think, it's just for consistent reporting.)
2. Hit O
3. Watch for a few seconds to see if the framerate settles to around 50fps or in the 70-80fps range. (even when it doesn't end up wrong, it usually fluctuates a lot in the first few seconds.)
4. Hit M (leaving codec-info on the screen.)
5. Go to video settings, down to interlace method, and cycle through the deinterlace methods available.
6. During this cycle through the interlace methods, it seems to sort itself out. Sometimes it sorts itself out when i reach VDPAU Bob, sometimes it doesn't, but it always seems to do so when I reach one of the lesser methods that only produce a 25fps output. then as I continue and cycle all the way back around to Temporal/Spatial, that then is fine, for the remainder of playback of that video.
7. Close the OSD and codec info and watch my programme.

So that's what the user-interface activity would have been after the problem occurred. Beforehand, nothing special, just normal usage.

Next time i see it, i'll wait and leave it going longer. I can take a screenshot too if you like, to prove it's doing it? :)

As already noted, I'm running the osd branch right now. Should I change back to master if you know that osd won't exhibit the problem?

[FernetMenta]

Seems I was chasing a different problem. Nevertheless would be good to know if you could reproduce with OSD:

[StrangeNoises]

ok, the osd branch is exhibiting the problem too. Encountered on first attempt to play something after turning on the tv this morning. As per previous I'm just letting it play for a while without messing with it before uploading a log. That to follow soon.

Then I might as well go back to master.

[StrangeNoises]

http://paste.ubuntu.com/5589848/

playback with the problem occurring starts at line 61772. It was left to play for about 15 mins (with codec-info open). Then I started playing an SD pvr channel and that seems to be OK (but has exhibited the problem in the past).

[FernetMenta]

Maybe a issue with the screen saver. Could you check fps of the gui before starting a movie? Just enable debugging in system settings.

[StrangeNoises]

turned that on, though can't promise to keep it on all day waiting for this to happen. :-) (it moves up and down by a line every few seconds, is that normal?)

In the meantime: My screensaver mode is "black". And I've seen this happen sometimes when I've gone from playing TV to going to play something from the library, with only the navigation between them, and no time for screensaving taking place.

But I'll keep an eye out.

[StrangeNoises]

ok, findings:

I turned on debug while watching a programme, and fps stayed steady at 50 for the duration of that programme.

When I stopped playback, the FPS went all over the place (mostly too-high, often over 100fps, occasionally too-low, on the main menu. But if i went into System->System Info (which also shows FPS) it would then drop down to 50, matching what system info said, but then go up again as soon as I went back up to the main menu.

Navigated to a (50i) tv show, fps stayed fluctuating high while navigating menus, and showed high when playing the video, as already reported. FPS shown by debug lines matched that showed by codec info.

However, if I go to play a 25p tv show - ie: progressive but not requiring a refresh-rate change - the framerate drops to 25.0 as you'd expect. Then exit, menus show it wildly all over the place, go back to another 50i tv show, framerate remains wild.

Log of the session with all this lot going on here: http://paste.ubuntu.com/5593065/ (I've committed the sin of editing the log thusly for both our sanities: "grep -v -e PVR -e EPG .xbmc/temp/xbmc.log | pastebinit")

[FernetMenta]

btw, what are you doing with this useless GPU temp? Are you feeling happy if temp is high or low? :) I have seen systems stuttering caused by this command. Spawning a process is a heavy operation for just getting temparature. Please drop this.

How long have you been using Raring? IMO Quantal was already carp, this is why I still on Precise, the last version of Ubuntu before I move away from this distro.

Those shouldn't be in the log: CVDPAU::DrawSlice - VdpDecoderRender long decoding: 38 ms, dec: 2, proc: 1, rend: 0 38 ms for decoding of a single frame. Something must block the GPU.

[StrangeNoises]

yes, i'm a bit of an upgrade-addict. Also, this machine isn't a single-purpose media player. (it's a full pc with ten hard drives falling out of it and a number of jobs, and 10m cables connecting it from a cupboard in the next room to the tv. :-)

People will want to run xbmc on raring one day, even if i was one of the first; so I'm a mine canary. :-) BTW I note future fun and games with ubuntu's upcoming Mir thing, but it seems to me maybe in the long run it'll work out better for XBMC; as the need to disable composite is a bit of a bugger at the moment.

I shall disable that gpu temp command. i think i picked that up from the forum or wiki page or somesuch once upon a time, and i was interested in how hot it got when i first installed it given the GPU is fanless, but no, i don't obsessively watch it and i was unaware of the overhead, so i'll disable that. We'll see if that makes a difference. (FWIW if i'd thought about it i'd have expected it only to poll while on the System Info->Video screen.)

NB: After restarting XBMC i find that on the menus the fps fluctuates comfortably below the refresh rate, which I expect is normal, and then goes up to the refresh rate when there's video to play. It remains the case that things seem to go wrong later rather than sooner; though I wasn't able to trigger it sooner by eg: turning off the tv/receiver and turning them on again.

[FernetMenta]

I don't think AMD or NVidia will support that Mir crap -> bye bye Ubutnu.

Can you try pulling and re-plugging the HDMI cable when the issue shows next time?

[StrangeNoises]

Still waiting for it to recur. Did you at all expect disabling the gputemp command to make that kind of difference or was it just out of general dislike? :-)

[FernetMenta]

I just wanted to rule that out because I have already investigated cases where this turned out to be the issue.

[StrangeNoises]

well, it's not run long enough to prove the negative yet, but if it lasts to the end of today it'll have done better than i've seen lately.

[StrangeNoises]

Sad to report, the problem has just recurred - with gputemp undefined, remember, so it's not that.

I didn't have the on-screen debug info on screen before I played a track where it happened, so I can't categorically say it was happening before i played (but after I finished playing the track before, which was 25p and showed that fps throughout). But then I enabled it and stopped playback and took a screenshot:

inline screenshot uploading seems to be taking forever... so try:

Point is, I wasn't seeing this before on the menus before now.

And in fact after a few minutes - the time taken to get to a computer and type as far as here, it's now settled down to fluctuating under 50fps again. In previous occasions it hasn't done that. Also, when i now play the same track again, it's now playing at 50fps just fine. Again, previously, it didn't do that; it would stay wrong.

So it's possible that disabling gputemp has helped, in that it seems to correct itself, maybe. Which is a mixed and rather annoying result.

FWIW the log of this session: http://paste.ubuntu.com/5597077/ playback of affected media starts on line 24047 (as before, pasted via grep -v -e PVR -e EPG for sanity)

[FernetMenta]

The frame limiter kicks in at 100fps but this can only happen if you lost vsync. Rendering at a higher rate puts more load on the GPU and would also explain the long decoding times in vdpau. In this case we can't do much at the application level. When did you upgrade to Raring? Did you notice this issue before?

[FernetMenta]

You run XMBC in standalone mode, right? Can you try launching it from Fluxbox?

[StrangeNoises]

I upgraded this machine to raring before it got put back onto media-player duty; the previous time it was doing that job was a few months ago, when we were communicating about deinterlacing issues at the time. I'd also upgraded the mac mini (nvidia-320m) before then too, with no apparent problems. Reminder: That machine can't do temporal/spatial deinterlacing (frame rate too low there!), and this problem seems related to that (although I don't know the relationship between that and the high framerates also seen in the menus sometimes; but certainly i've never seen it with progressive content or with other deinterlacing methods.)

I usually run it standalone - as in launched from lightdm. Running it in fluxbox now. (Actually the current ppa testing build as that's the one in the menu, but it's at the same commit right now)

BTW I was also running a lubuntu desktop in a standalone vncserver (ie: not connected to any physical screen). I've tried disabling that for now too.

Now we wait to see if it happens again... Of course the fact that it only seems to arise after approx a day of uptime, and i run a branch that has almost daily updates, can make it rarely seen. :-)

Here's a thought I just had about vsync. Because it's noisy, the computer is connected to the TV with a 10m HDMI cable. Specifically one of these: http://www.amazon.co.uk/gp/product/B002EA4276

Generally it works fine, but I wonder if that slight extra signal delay might add up to something over time until xbmc gets a reason to reset something. (Although you'd think the TV being periodically switched off would be more important for vsync purposes; but merely doing that doesn't seem to trigger it.)

[FernetMenta]

If your xorg log shows nothing about hotplug events, it's probably not the cable.

[StrangeNoises]

root@twilight:/var/log# grep -i hotplug Xorg*.log*
root@twilight:/var/log# 

guess not. :-)

[FernetMenta]

not sure if "hotplug" is the term to search for. Do you see anything suspicious in the log?

[StrangeNoises]

I am seeing that sort of thing with respect to the controller on the end of the 10m USB extension cable, which I already knew about but doubted was significant to display issues. In fact apart from the log-spamming it surprisingly doesn't even seem to affect the operation of the controller, be it a flirc.tv or (currently) an IR keyboard. And in timing it doesn't correlate at all with when the issue occurs. (it's pretty much happening all the time.)

But not seeing anything like that with respect to the display, no.

[FernetMenta]

Have you tried pulling/replugging the HDMI cable when the issue is present?

[StrangeNoises]

Running in fluxbox still: The problem just recurred, sooner after a restart than I'd seen before, but I don't know if that's just random chance or fluxbox makes it worse. :-)

Unplugging HDMI at the TV end, for a few seconds, and plugging it back in again... it reverted back to a (correct) 50Hz... but only for a short while, maybe as long as a minute, then started to drift upwards again. Watching over time it's doing that anyway right now: sometimes going back down to 50Hz, then going up again; so I'm not sure the unplug/replug made any difference.

Interestingly this time, unlike previously, cycling through the deinterlace methods didn't seem to make things OK again, but turning deinterlace off entirely, and on again, does seem to have done so.

(logfile taken after this: http://paste.ubuntu.com/5598872/ playback of this video starts at 8827; I think the tv being unplugged starts at 9032 and is plugged back in at 9035.

[StrangeNoises]

Thought I'd disable VDPAU entirely, given i have a 3Ghz core-i7x4, and see what happens. (without restarting xbmc as i'd have to wait possibly hours for a recurrence.)

It still happens, but with some differences in detail. eg:

"Software Blend" 25.0fps "De-interlace (Half)" 25.0fps "De-interlace" 50.0fps "Bob" and "Bob (inverted)" 125-160fps range "Weave" and "Weave (inverted) approx 100-160fps range "Blend" 25.0fps "Auto select" 160-ish fps (so presumably automatically using bob or weave)

Cycling through them doesn't seem to reset anything. each time round, the ones that are wrong are consistently wrong... until I restart xbmc, then everything's fine again.

But at least I think this is telling us the problem isn't in your VDPAU changes, as it happens - albeit with different numbers - with entirely software-based decode/render. I think you already felt that way anyway and were suspecting the newer Xorg in raring (and yet hating on the idea of Mir ;-))

[FernetMenta]

Can you try to fix this USB issue which may bother the x server in a way that it loses vsync. I am sure yo have a cable somewhere shorter than 10m :)

[StrangeNoises]

sure i do, but it won't reach the living room. :-)

I'll do it to prove the point and use xbmc commander for the time being - which works as long as i don't need to relaunch... but as i said, the high fps issue is relatively rare considering the usb reconnect thing is pretty much constant.

unplugging...

[StrangeNoises]

... didn't help. The problem has recurred, with that long usb cable unplugged. The only activity in Xorg.0.log since that unplugging is when the TV was switched on again after i switched it off earlier.

Also, generally, it seems the main difference fluxbox has made is that it makes the issue happen sooner and more reliably than when xbmc runs standalone. :-)

[fritsch]

@StrangeNoises: Do you have GLSL enabled? Could you set this back to Auto?

[FernetMenta]

fritsch, high fps in the menu can only happen when vsync does not work. The question is why does it not work.

[fritsch]

The original starting post speaks of high framenumbers during playback.

[StrangeNoises]

it was first noticed during playback, and later discovered to be happening in the menus as well; and does appear to be linked. (ie: now i can tell that playback will be wrong if its wrong in the menus first.)

Changing other stuff (eg: running it in fluxbox) seems to make minor differences to this behaviour, like how likely it is to happen, or how soon it starts happening after start, and whether it sorts itself out when i cycle deinterlace methods or only when deinterlace is turned off completely and back on again, or whether over time the framerate settles back to what it should be on its own or just stays wrong until a restart, etc. As fluxbox seems to make the problem easier to reproduce, I've left it running there for the time being.

It is a subtle effect of course, given the problem is too high framerates, it's hard for the eye to spot: When I wasn't looking for it, I only started to suspect something was wrong during playback of smooth-motion sequences that seemed vaguely less smooth than they should be, given all those problems were considered solved in the past. I checked codec info and saw framerate was wildly too high. So it's possible I'm not the only person encountering this, just the first to notice it. ;-)

I certainly haven't enabled GLSL by myself and I have no idea how to disable it. There's no mention of it in xorg.conf nor in the output of nvidia-settings --query all or nvidia-setting --glxinfo, nor in Xorg.0.log, for instance, and for once Google isn't being terribly helpful. In XBMC itself, render method has been left at Auto Select.

I'm actually still running pretty much the xorg.conf from our earlier deinterlace testing, with the exception that the raring installer commented out the InputDevice sections and InputDevice lines in ServerLayout with the message "commented out by ubuntu-release-upgrader, HAL is now used and auto-detects devices"

btw, recall that raring's nvidia-current is still nvidia-304, same as quantal at least; and this was what was running when I encountered and first reported the error. I only upgraded to nvidia-310 to see if it made a difference; it didn't, either way. It also didn't give me a specific reason to downgrade again so I left it.

[StrangeNoises]

nb: i'm not physically in front of the right computer right now, and the above checks etc. done via ssh; i'll need to get back in front of it to properly verify what the gui settings are; though here's the guisettings.xml file that i may just not be reading right:

http://paste.ubuntu.com/5601561/