Audio/Video sync problems especially after seeking to start of recording

[dmoo1790@…]

I have A/V sync problems after upgrading from 0.23 to 0.25. Most noticeable when seeking back to the start of a recording but under other circumstances also. See this post: http://www.mythtv.org/pipermail/mythtv-users/2012-June/334992.html

[dmoo1790@…]

mythfrontend log

[David Moore <dmoo1790@…>]

Analysis of log file

[David Moore <dmoo1790@…>]

I tried analysing the log file and found some weird things with timecodes. See attached file log_analysis.txt. This file has extracts from filtering with egrep 'audio timecode|video timecode|DoPlayerSeek?|behind|error' mythfrontend.20120604155806.2992.log

It seems to me there is a genuine bug rather than a config problem on my system. Three reasons: (1) the odd sequence of video/audio timecodes in the log, (2) no problem before upgrading to 0.25 and (3) others in NZ have reported the same behaviour when trying to seek back to the start of a recording.

[tralph]

Could you try the FORCE_DTS_TIMESTAMPS=1 environment variable? Just run the following command.

FORCE_DTS_TIMESTAMPS=1 mythfrontend

Thanks.

[David Moore <dmoo1790@…>]

Replying to tralph:

Could you try the FORCE_DTS_TIMESTAMPS=1 environment variable? Just run the following command.

FORCE_DTS_TIMESTAMPS=1 mythfrontend

Thanks.

I tried it. Didn't seem to make any difference. Would you like any log info? If so, which log options?

[tralph]

You need to provide a frontend log with --loglevel debug -v playback,timestamp.

[David Moore <dmoo1790@…>]

Replying to tralph:

You need to provide a frontend log with --loglevel debug -v playback,timestamp.

Done.

[David Moore <dmoo1790@…>]

Replying to David Moore <dmoo1790@…>:

Replying to tralph:

You need to provide a frontend log with --loglevel debug -v playback,timestamp.

Done.

Oops. Ignore the file. Forget the enviro variable. Wait one...

[David Moore <dmoo1790@…>]

This one has FORCE_DTS_TIMESTAMPS=1

[David Moore <dmoo1790@…>]

Replying to David Moore <dmoo1790@…>:

Replying to David Moore <dmoo1790@…>:

Replying to tralph:

You need to provide a frontend log with --loglevel debug -v playback,timestamp.

Done.

Oops. Ignore the file. Forget the enviro variable. Wait one...

OK. File uploaded with FORCE_DTS_TIMESTAMPS=1 set.

[tralph]

So the log below definitely shows a timestamp issue right after the audio decoding errors. The audio timestamp jumps way back in time after the decoding error. These errors and timestamps are provided by the ffmpeg demuxer. So it appears that the regression is probably due to the ffmpeg sync done for 0.25. I'm not sure how this should be handled because it's really an ffmpeg bug. The first step is to create a small sample that triggers the issue and then see if the ffmpeg devs might be interested in looking at it.

2012-06-09 13:29:34.008873 D [3337/3401] Decoder avformatdecoder.cpp:3138 (ProcessVideoPacket) - AFD: video packet timestamps reordered 435110682 pts 435134082 dts 435116082 (dts forced)
2012-06-09 13:29:34.008889 I [3337/3401] Decoder avformatdecoder.cpp:3245 (ProcessVideoFrame) - AFD: video timecode 435116082 4834623 4834623 4834503
2012-06-09 13:29:34.009287 I [3337/3401] Decoder avformatdecoder.cpp:4248 (ProcessAudioPacket) - AFD: audio timecode 435115988 435115988 4834622 4834664
2012-06-09 13:29:34.009586 I [3337/3401] Decoder avformatdecoder.cpp:4248 (ProcessAudioPacket) - AFD: audio timecode 435119828 435119828 4834664 4834706
2012-06-09 13:29:34.009874 I [3337/3401] Decoder avformatdecoder.cpp:4248 (ProcessAudioPacket) - AFD: audio timecode 435123668 435123668 4834707 4834749
2012-06-09 13:29:34.015554 D [3337/3401] Decoder avformatdecoder.cpp:3138 (ProcessVideoPacket) - AFD: video packet timestamps reordered 435117882 pts 435126882 dts 435119682 (dts forced)
2012-06-09 13:29:34.015572 I [3337/3401] Decoder avformatdecoder.cpp:3245 (ProcessVideoFrame) - AFD: video timecode 435119682 4834663 4834663 4834623
2012-06-09 13:29:34.016136 I [3337/3401] Decoder avformatdecoder.cpp:4248 (ProcessAudioPacket) - AFD: audio timecode 435127508 435127508 4834750 4834792
2012-06-09 13:29:34.021747 D [3337/3401] Decoder avformatdecoder.cpp:3138 (ProcessVideoPacket) - AFD: video packet timestamps reordered 435121482 pts 435123282 dts 435123282 (dts forced)
2012-06-09 13:29:34.021765 I [3337/3401] Decoder avformatdecoder.cpp:3245 (ProcessVideoFrame) - AFD: video timecode 435123282 4834703 4834703 4834663
2012-06-09 13:29:34.021853 E [3337/3401] Decoder avformatdecoder.cpp:4216 (ProcessAudioPacket) - AFD: Unknown audio decoding error
2012-06-09 13:29:34.021860 E [3337/3401] Decoder avformatdecoder.cpp:4216 (ProcessAudioPacket) - AFD: Unknown audio decoding error
2012-06-09 13:29:34.022245 I [3337/3401] Decoder avformatdecoder.cpp:4248 (ProcessAudioPacket) - AFD: audio timecode 424763348 424763348 4719592 4719634
2012-06-09 13:29:34.022602 I [3337/3401] Decoder avformatdecoder.cpp:4248 (ProcessAudioPacket) - AFD: audio timecode 424767188 424767188 4719635 4719677
2012-06-09 13:29:34.023178 I [3337/3401] Decoder avformatdecoder.cpp:4248 (ProcessAudioPacket) - AFD: audio timecode 424774868 424774868 4719720 4719762

[steven@…]

I'm also based in NZ and updated to 0.25 today. I haven't tried any DVB-T recordings yet, but with DVB-S material off TVNZ i'm seeing exactly the same issue.

At the moment the only way to re-sync is to exit playback and re-open the file. As soon as I skip forwards, for example to bypass an advert, then sync is totally lost.

[Steven Ellis <steven@…>]

I've upgraded from MythTV 0.23 to 0.25 and I'm seeing the issue on existing as well as new DVB-S MPEG-2 recordings with MP2 audio.

I'm running a GT220 card with an M2NPV-VM board and an Athlon X2 5050BE CPU.

I noticed that my de-interlacers were disabled during the upgrade so I've turned Advanced 2x back on. Display is generally 1920x1080 50Hz unless I'm watching US content.

All my audio is going out over SPDIF to my amp. I haven't setup audio over HDMI yet with the new upgrade.

In order to get any reasonable sync I need to exit playback and re-enter the file. Otherwise its a real mess.

[Steven Ellis <steven@…>]

Ok I think I have a fix. Checking logs I saw the following alsa error

Jun 17 20:30:10 mythtv mythfrontend[20861]: E CoreContext audio/audiooutputalsa.cpp:545 (OpenDevice) ALSA: Unable to sufficiently increase ALSA hardware buffer size - underruns are likely

and recommendation

Jun 17 22:36:39 mythtv mythfrontend[26876]: E CoreContext audio/audiooutputalsa.cpp:213 (SetPreallocBufferSize) ALSA: Try to manually increase audio buffer with: echo 128 | sudo tee /proc/asound/card0/pcm1p/sub0/prealloc

I've actually bumped the prealloc up a bit higher to be certain

 echo 256 > /proc/asound/card0/pcm1p/sub0/prealloc

Just tested some files and sync is close to perfect and I'm not seeing any audio centric errors.

Steve

[beirdo]

Closing as the problem seems to be solved.

[peper03@…]

Setting the audio buffers to 256 does not solve the problem on my system (they were already set to 256). Even setting them to the maximum of 32768 didn't make any difference. Disabling the setting 'Separate video modes for GUI and TV playback' does seem to fix it but I think there are several variables involved which makes tracking down the cause difficult. See ​http://www.gossamer-threads.com/lists/mythtv/users/522376#522376

[danielk]

I can still reproduce this.

Steps:

Skip forward 10 minutes Skip back 1 minute Wait 2 seconds Skip back 10 minutes Wait 1 second Skip back 10 minutes

The A/V sync will now be out for a second or two and then jump back into sync.

[mark@…]

I have the same issue as well. I have tried increasing the prealloc setting to 256, but I'm still seeing AV Sync issues, so I don't think this is fixed.