Ticket #14978 (assigned Bugs)

Opened 7 months ago

Last modified 5 months ago

OSX - audio (passthrough) out of sync after seek

Reported by: Memphiz Owned by: elupus
Priority: 4 - Normal Milestone: 13.0 "Gotham"
Component: Mac OS X specific feature Version: 13.0 "Gotham" RC1
Severity: Normal Keywords:
Cc: jmarshall, FernetMenta, fritsch, davilla, elupus, Blocked By:
Blocking: Platform: All
Revision:

Description

This was reported in the forum here:

 http://forum.xbmc.org/showthread.php?tid=186201

It seems that with ActiveAE on osx the audio gets out of sync when passed through and seeked.

Change History

comment:1 Changed 7 months ago by FernetMenta

Are we looking for an a/v desync of 100ms or a couple of seconds. The forum thread is not clear about this. Does the user have an AVR connected?

comment:2 Changed 7 months ago by FernetMenta

"For me DTS and DD have sync issues in 1080p. The 720p content I tested in DTS or DD seem bang on." ( http://forum.xbmc.org/showthread.php?tid=186201&pid=1641372#pid1641372)

how should we interpret this? from an audio point of view 720/1080 does not matter.

comment:3 Changed 7 months ago by fritsch

We need someone, that can reproduce. Make sure you log out GetDelay, then we can clearly see what's going on.

comment:4 Changed 7 months ago by Rassi

I can reproduce with XBMC 13 nightly (xbmc-20140306-1cba479-Gotham-i386.dmg) on Mac Mini 5,1 with OS X 10.7.5 with hdmi to TV.

 Log with "Adjust refresh" turned on (sync issues)

 Log with "Adjust refresh" turned off (no issues)

Also posted on  http://forum.xbmc.org/showthread.php?tid=186201&pid=1654016#pid1654016

Don't know how to log GetDelay. Please advise if necessary.

comment:5 Changed 7 months ago by FernetMenta

again: Are we looking for an a/v desync of 100ms or a couple of seconds?

comment:6 Changed 7 months ago by Rassi

Multiple seconds on seek (especially seek back). Everything seems in sync on start.

comment:7 Changed 7 months ago by fritsch

Please provide a new logfile with latest code.

comment:8 Changed 7 months ago by SpaceMonkey

My tests with beta 2:

  • When audio is in sync, it's in sync
  • Pausing video and SmallStepBack always causes the audio go out of sync. Hard to estimate but i'd say between 500ms-1s.
  • Both (Big)StepForwards/Backwards seem to be ok 100% of the time
  • (Big)StepForwards/Backwards get the audio back to sync
  • Seeking at any rate to any direction is not always affected, seems random when it goes out of sync

Debug log from beta 2:  http://pastebin.com/JLRRDPiy

  • Start video
  • 2x BigStepForward (ok)
  • Pause video (out of sync)
  • StepForward (ok)
  • SmallStepBack (out of sync)
  • Not sure what i did after that, either StepBackward or StepForward (ok)

comment:9 Changed 7 months ago by Rassi

Nightly 0316  http://xbmclogs.com/show.php?id=150461

Steps:

  • StepForward
  • SmallStepBack
  • Rewind

CodecInfo shows stable error around 500% after SmallStepBack, and 20000% after Rewind.

comment:10 Changed 7 months ago by Rassi

I concur in SpaceMonkey's findings.

comment:11 Changed 7 months ago by FernetMenta

looks like dropping of late video frames does not work for some reason

comment:12 Changed 7 months ago by FernetMenta

You use VDA decoder, right. Could you try with software decoding?

comment:13 Changed 7 months ago by SpaceMonkey

It's fine without VDA decoder. With it disabled, when you pause and resume playback. it seems the sync would be off, but it very quickly "fastforwards" to catch up with audio.

comment:14 Changed 7 months ago by FernetMenta

When you have VDA decoder enabled and a/v sync is off, what about the skip and drop counters on the codec screen.

comment:15 Changed 7 months ago by SpaceMonkey

Skip counter stays the same, but drop counter increases 5-10 per second.

comment:16 Changed 7 months ago by Memphiz

  • Cc davilla, added

@davilla - vda frame dropping issue?

comment:17 Changed 7 months ago by FernetMenta

I am wondering if the drop counter lies to us. If it drops this rapidly video catches up in general. Is the video still smooth when this happens? Would you say there are any dropped frames not looking at the drop counter?

comment:18 Changed 7 months ago by SpaceMonkey

Hmm, need to check later today, but I'd say I cannot see dropped frames and it's still smooth. Something else I noticed, on 24p material the value on the bottom row fluctuates between 23 and well over 24. But I cannot see that one in motion either.

But I haven't been looking at codec info screen in months, If not years so not sure what it's supposed to say.

comment:19 Changed 7 months ago by SpaceMonkey

I'm little bit embarrassed to say but it seems if you wait long enough (5-10 seconds) it gets back to sync. But still, this is definitely a new feature with the new audio engine.

Anyway my tests:

  • VDA off: you can skip, seek and pause all you want. There are only 2-3 drops all together. W(fps) value stays at pretty constant 23.98-24. Only after seeking it can dive to around 20. Motion is always smooth.
  • VDA on: packets start to drop at rate of 5-10 per second after pausing etc. Dropping stops when you skip to any direction. W(fps) fluctuates constantly between around 23.3 and 24.5 or so. Motion seems smooth to me when during all this, i'm pretty sensitive about missed frames.

comment:20 Changed 7 months ago by FernetMenta

13:54:17 T:4688990208 DEBUG: CDVDPlayerAudio:: Discontinuity1 - was:127445687.910333, should be:135472000.000000, error:8026312.089667

Oops, we are 8 seconds off. Memphiz, I think GetDelay returns wrong values.

comment:21 Changed 7 months ago by Memphiz

But osxsink doesn't know anything about VDA? *wonders*

comment:22 Changed 7 months ago by Memphiz

Well i really tried hard to reproduce that issue on my macmini + mavericks - but no dice - it was always in sync. But here is a testbuild which you could try please. It has some debug output added. (so after the issue happened please provide a new debug log):

 http://mirrors.xbmc.org/test-builds/osx/x86_64/xbmc-20140317-93a3b51-osxresetondrain-x86_64.dmg

comment:23 Changed 7 months ago by Rassi

0317 resetondrain build:  http://pastebin.com/v9ZPzSkL

Steps:

  • StepForward (ok)
  • SmallStepBack (out of sync 1 second)
  • Rewind shortly (out of sync 5 seconds)

comment:24 Changed 7 months ago by Memphiz

@fernetmenta see that log - this are the printouts:

 https://github.com/Memphiz/xbmc/commit/93a3b515c6d628d52f0b152b3c38ab76b78628c8

GetDelay is never logged...

comment:25 Changed 7 months ago by FernetMenta

@Memphiz this big discontinuity can't be caused by GetDelay. can you provide a test build with this change included:  https://github.com/FernetMenta/xbmc/commit/3183cdaad9d9ae2df640df289eb366007894895b

comment:27 Changed 7 months ago by SpaceMonkey

This 3183cda build sort of fixes it for me. Now after pausing and unpausing and smallstepback video catches with audio and is back in sync. Video fast forwards and this brief fast forwarding is clearly seen.

There's no more drops, skip counter increases by 10 when unpausing, and with smallstepback around 5 or so.

 http://pastebin.com/gEYc8NgK

comment:28 Changed 7 months ago by Rassi

Initially I saw the same as SpaceMonkey (on 3183cda), but then I tried a little more, and came to the (confusing) conclusion that the problem persisted as long as I had debug disabled...

Here's a log file of me trying furiously to reproduce, and then after playing the video 3 times, turning of debugging and trying again:

 http://xbmclogs.com/show.php?id=152234

It does seem, though, that information is still being logged, so perhaps you can use it still.

One other thing I noticed on this build is that rewind is very slow/erratic compared to nightly.

comment:29 Changed 7 months ago by FernetMenta

Actually rewind is broken on the nightlies. It never has worked. Rewind goes wrong speed, much too fast and if you watch carefully, you see forward motion. The patch provided gives you a different experience but is is correct. You can't decode backwards only forwards. Actually rewind is seeking small steps backward. On the nightlies you see forward motion between the backward seeks which is wrong. The problem with seeking backwards is that you need an I-Frame to start decoding. Means that material with less time between I-Frames rewind better.

comment:30 follow-up: ↓ 31 Changed 7 months ago by Memphiz

What do you mean with "the problem persisted as long as i had debug disabled"? Does this mean that with debugging enabled audio was in sync (e.x. that bug this is all about was fixed) and when turning debugging off the bug returned (e.x. audio autofsync > 2 secs)?

comment:31 in reply to: ↑ 30 Changed 6 months ago by Rassi

Replying to Memphiz:

What do you mean with "the problem persisted as long as i had debug disabled"? Does this mean that with debugging enabled audio was in sync (e.x. that bug this is all about was fixed) and when turning debugging off the bug returned (e.x. audio autofsync > 2 secs)?

I know it sounds incredulous, but yes.

With debug enabled, in order to provide a log file, and seeking many times, audio was in sync (quickly catching up and approaching 0% error).

And with debug disabled, SmallStepBack caused out of sync audio and error% to get stuck at 300-600. And likewise Rewind caused out of sync, and error% of more than 10000%.

I'll attempt some more this evening in order to make absolutely sure.

Last edited 6 months ago by Rassi (previous) (diff)

comment:32 Changed 6 months ago by SpaceMonkey

For me it's fine even with debugging disabled. I've watched couple of hours on it and no issues.

comment:33 Changed 6 months ago by Rassi

Ok, I tried reproducing some more on build 3183cda.

With debug enabled, I simply could not reproduce. I probably attempted 10 times.

With debug disabled it only took a couple of SmallStepBacks or rewinds before it would be out of sync again.

One thing I did notice was that when out of sync, CodecInfo would report a high error%, which would then fall somewhat, until it would level at some high value. At this point the dropped frames counter would begin incrementing at around 5-10/sec. With debug enabled, I never saw any significant dropped frames.

If I can provide you with any more information please advise.

One difference between SpaceMonkey's setup and mine, is that my mini has an Intel HD3000 graphics card whereas SpaceMonkey's is an Nvidia 320M. I've had some issues with this in past versions of XBMC (green line artifacts etc). Don't know if this just confuses the issue more...

comment:34 follow-up: ↓ 36 Changed 6 months ago by FernetMenta

Can you reproduce the issue without mixing SmallStepBack or rewind? Try either one or the other but don't mix the commands.

comment:35 Changed 6 months ago by fritsch

  • Cc elupus added
  • Owner changed from davilla to elupus
  • Status changed from new to assigned

elupus added. Root cause seems to be a bug in dvdplayer.

comment:36 in reply to: ↑ 34 Changed 6 months ago by Rassi

Replying to FernetMenta:

Can you reproduce the issue without mixing SmallStepBack or rewind? Try either one or the other but don't mix the commands.

SmallStepBack only:  http://xbmclogs.com/show.php?id=153118

Rewind only:  http://xbmclogs.com/show.php?id=153124

comment:37 follow-up: ↓ 38 Changed 6 months ago by FernetMenta

What did you observe? Does the issue show in one or the other case?

comment:38 in reply to: ↑ 37 Changed 6 months ago by Rassi

Replying to FernetMenta:

What did you observe? Does the issue show in one or the other case?

Yes, both SmallStepBack and rewind results in out of sync after a couple of attempts.

SmallStepBack:

  • reproducability: perhaps 50-70%
  • out of sync: .5-2 seconds
  • dropping frames: 5-10/second
  • error%: 200-600

Rewind:

  • reproducability: perhaps 50-70%
  • out of sync: 1-6 seconds
  • dropping frames: 5-10/second
  • error%: 600-10000
Last edited 6 months ago by Rassi (previous) (diff)

comment:39 Changed 6 months ago by FernetMenta

@Memphiz can you create a test build from this branch?  https://github.com/FernetMenta/xbmc/commits/osx2 The 5 commits on top are of interest.

comment:41 Changed 6 months ago by Rassi

Issue still present on build 7f00dff.

SmallStepBack:  http://xbmclogs.com/show.php?id=153834

Rewind:  http://xbmclogs.com/show.php?id=153835

Last edited 6 months ago by Rassi (previous) (diff)

comment:42 Changed 6 months ago by FernetMenta

do you still see the dropping counter increasing? video still smooth?

comment:43 Changed 6 months ago by Rassi

Yes, dropped frames increasing, and video smooth with audio out of sync.

comment:44 Changed 6 months ago by Rassi

Since a video might be worth a thousand words, and it is a whole lot easier than trying to explain what I see, here you go:

 https://www.dropbox.com/s/cg439dabezugkfa/SmallStepBack.MOV

 https://www.dropbox.com/s/8391woffi11m83f/Rewind.MOV

comment:45 follow-up: ↓ 46 Changed 6 months ago by SpaceMonkey

Did you try without "sync playback to display" on? I have it disabled.

comment:46 in reply to: ↑ 45 Changed 6 months ago by Rassi

Replying to SpaceMonkey:

Did you try without "sync playback to display" on? I have it disabled.

I just tried turning it off, and it did not help. SmallStepBack and rewind still caused a/v to get out of sync.

comment:47 follow-up: ↓ 48 Changed 6 months ago by FernetMenta

Thanks, those videos are great. Could you please record the same scenarios with VDA switched off?

comment:48 in reply to: ↑ 47 Changed 6 months ago by Rassi

Replying to FernetMenta:

Thanks, those videos are great. Could you please record the same scenarios with VDA switched off?

 https://www.dropbox.com/s/b2xlidpahfvtgvw/SmallStepBack_noVDA.MOV

 https://www.dropbox.com/s/4l6ehblbixynl1j/Rewind_noVDA.MOV

comment:49 Changed 6 months ago by FernetMenta

@Memphiz I have added this change to my osx2 branch:  https://github.com/FernetMenta/xbmc/commit/9fa5389dfe7f312c24342f7cd9425a0136cf1d5e

Please create a new test build.

comment:51 Changed 6 months ago by FernetMenta

I don't think anything has changed with the last build.

comment:52 Changed 6 months ago by Memphiz

@FernetMenta based on his logs i am sure he is using CDVDVideoCodecVDA not the VDA.cpp one ...

comment:53 Changed 6 months ago by FernetMenta

I am not familiar with CDVDVideoCodecVDA and I have no Mac here. But I am quite sure this is related to timestamps coming out of VDA decoder. The videos and the log clearly show that video player can't catch up. You see pc: none on the codec screen. This means that player has not been able to detect a pattern in timestamps. Until player keeps trying decoder drop is disabled. (this is only the case if refresh rate switching or sync playback to display is enabled) This and the fact that sw decoder does not show the issue clearly point in direction of an issue of VDA decoder.

comment:54 Changed 6 months ago by Memphiz

Another one - please try this testbuild and disable VDA Decoding but instead enable the new setting "VDAffmpeg"

 http://mirrors.xbmc.org/test-builds/osx/x86_64/xbmc-20140321-9cfb42f-osxffmpegvda-x86_64.dmg

and report back.

comment:55 follow-up: ↓ 57 Changed 6 months ago by Memphiz

it needs settings level advanced to see the new setting - just as a hint...

comment:56 Changed 6 months ago by Rassi

Build 9fa5389: No change

Build 9cfb42f-osxffmpegvda: Crashed on playback with VDAffmpeg setting on

Log:  http://xbmclogs.com/show.php?id=155137 Crashreporter log:  http://pastebin.com/7Sj5hYY7

comment:57 in reply to: ↑ 55 Changed 6 months ago by Rassi

Replying to Memphiz:

it needs settings level advanced to see the new setting - just as a hint...

And just FYI (after searching for the setting for some time) it needs settings level expert.

comment:58 Changed 6 months ago by elupus

Strange that it crashed. What sample are you using for that? could it be changing resolution or similar?

comment:60 Changed 6 months ago by Memphiz

Both movies are working fine for me with ffmpegvda ... using mavericks 10.9.2 on macmini late 2012 (intel hd 4000).

comment:61 Changed 6 months ago by FernetMenta

There is a fix upstream for segfault after dropping a frame:  https://github.com/FFmpeg/FFmpeg/commit/31a0ca9e75e4c91437c8681b9655a67f09b693dd

comment:62 Changed 6 months ago by Memphiz

I have backported that patch:

Please anybody test with this test build (disable VDA Decoding but instead enable the new setting "VDAffmpeg")

 http://mirrors.xbmc.org/test-builds/osx/x86_64/xbmc-20140325-c49edc4-osxffmpegvda-x86_64.dmg

comment:63 Changed 6 months ago by SpaceMonkey

There's no such toggle on my (Snow Leopard) installation.

comment:64 Changed 6 months ago by Memphiz

Ensure you are using confluence and have settings level set to expert. (its definitly there and doesn't matter if you are using snow leopard ;) ).

comment:65 Changed 6 months ago by Rassi

xbmc-20140325-c49edc4-osxffmpegvda crashes with same callstack:

Log:  http://xbmclogs.com/show.php?id=158176

Crash report:  http://pastebin.com/MdXkwiYv

comment:66 Changed 6 months ago by Memphiz

The outcome seems to be highly dependend on the used hardware:

ERROR: VDA::CDecoder - Failed to init VDA decoder: -12473

Out of clues for now...

comment:67 Changed 6 months ago by davilla

kVDADecoderDecoderFailedErr = -12473

"kVDADecoderDecoderFailedErr - An error was returned by the decoder layer. This may happen for example because of bitstream/data errors during a decode operation. This error may also be returned from VDADecoderCreate when hardware decoder resources are available on the system but currently in use by another process."

Smells like VDADecoderCreate did it. This can happen when decoder hung up or in use by other apps. Generally, reboot the box. Can happen a lot when debugging and crashing as the decoder might not get freed correctly.

comment:68 Changed 6 months ago by Rassi

Sadly, still crashes after reboot.

Log:  http://xbmclogs.com/show.php?id=159077

Crash report:  http://pastebin.com/ZTvEbBFn

I can tell you that VDA in 12.0 (which I ran before) works perfectly on my hardware.

comment:69 Changed 6 months ago by Rassi

Forum user found out that it is not connected (as such) to adjust refresh, but the fact that media is running 24hz:  http://forum.xbmc.org/showthread.php?tid=186201&pid=1671657#pid1671657

comment:70 Changed 5 months ago by mou

I'm having The same problem. Been pressent since i jumped on beta 1 (including RC1) FYI: Mac Mini 2012 (HD4000).

comment:71 Changed 5 months ago by Martijn

  • Version changed from 13.0 "Gotham" Alpha10 to 13.0 "Gotham" RC1
Note: See TracTickets for help on using tickets.