Commit 759fea8 breaks LiveTV transitions

[Peter Townsend <elpinkus@…>]

After commit 759fea8fee3d45ea7accc1aa8cf4d6e984982d0b, LiveTV freezes then exits to the main menu on program transitions with an error:

Video frame buffering failed too many times.

Currently on v0.25-beta-182-g759fea8. v0.25-beta-181-g43b55c9 works fine.

Frontend and backend logs attached. I had to cut out about 22MB worth of:

Decoder avformatdecoder.cpp:4374 (GetFrame?) - decoding error

eno: Input/output error (5)

at the point where playback dies to get the size down.

[Peter Townsend <elpinkus@…>]

backend and frontend logs

[Peter Townsend <elpinkus@…>]

--version output

[lomion@…]

I have this problem as well but falling back to 43b55c9 does not solve anything for me. It doesn't seem to be related to tralph's commit (alone).

[lomion@…]

What I said the other day was not correct.

I did some testing in my environment today and found out that either forcing discontiuity=true as well as forcing newtype=true - which is what 43b55c9 does basically - made the transition work in my environment (DVB-S backend with VDPAU stand-alone frontend).

Discontiuity=true results in a bit faster transition I believe.

In my opinion the problem is not commit 759fea8 but that GetSwitchProgram?() does not return the appropiate values for discontinuity and newtype ... can somebody who knows that code have a look please!

[danielk]

From some testing here it looks like our VDPAU renderer just doesn't support seamless transitions. On my system it does manage to make the transition, but with lots of complaining and a gap in the playback, while ffmpeg+XVideo is seamless with only a little complaining.

Can you test with ffmpeg decoding with XVideo for display to confirm we're seeing the same issue?

[danielk]

Debugging patch -- forces livetv transition every 30 seconds.

[danielk]

The livetv.patch should accelerate the test, it forces use of a new file in livetv every 30 seconds so you don't have to wait for the next program before seeing the problem.

[danielk]

Scratch that, my frontend wasn't up to date for my test. I'm seeing the same error now.

[danielk]

Debug + fix

[danielk]

Please try the 10490-debug.patch​. It includes both the frequent livetv transitions debugging (starting at 90 seconds and then transitioning every 30 seconds), and a fix for LiveTV not starting.

I don't expect the transitions to be smooth. There appears to be a separate issue with file read buffering, but it shouldn't dump you back to the menu with this applied.

[danielk]

Updated patch.. this avoids extra FinishedRecording? calls

[danielk]

Just the testing part of the previous patch (the fix portions of which have been applied).

[danielk]

commit [c3eaf781ca5cb6e95069063b77bee0e6a5e66de6] Author: Daniel Thor Kristjansson <dkristjansson@…> Date: Fri Mar 30 09:13:24 2012 -0400

Refs #10490. At least a partial LiveTV startup fix.

When we call FinishedRecording?() early it appears to cause an extra empty file to be generated at least some of the time. I'm not exactly sure how this happens, but calling FinishedRecording? before the recording is finished is actually a bug itself. This fixes this in the case where I was able to

reproduce the problem Peter Townsend experienced. I also tried some other LiveTV actions without seeing duplicate FinishedRecordings? calls, but I may have missed some code paths.

commit [d0df4ce8ee416f3aa37bb04bc4be30b9cb2b8456] Author: Daniel Thor Kristjansson <dkristjansson@…> Date: Fri Mar 30 08:58:07 2012 -0400

Refs #10490. Debugging fixes. Makes it easier to track which recordings are being started and stopped.

---

Note I'm reducing the priority since I believe this is fixed. I'm not closing it as fixed since I don't have confirmation from the reporter and it is a pretty complicated interaction that causes the problem.

Peter please report back on whether LiveTV is working for you.

[freddie@…]

I have also been experiencing this problem since switching to 0.25. With

MythTV Version : v0.25-rc-111-gc7a1e81

(which I believe contains the above fix) the behaviour at program boundaries is unchanged. My logs are virtually identical to those given above. I am also using VDPAU. During the changeover mythfrontend gobbles up ~3GiB of memory before being returned to the main menu.

[Peter Townsend <elpinkus@…>]

Sorry about the delay, I haven't had the chance to test anything in the last couple of days.

Updated to v0.25-rc-108-g5439b8b, just before your commits and no patches. Just being thorough. Found a program that was due to end in three minutes and playback froze and eventually dropped back to the menu right on schedule.

Added 10490-debug.patch and rebuilt. 5-10s pauses every 30s, played a few minutes of live TV before dropping back to the menu. This line appeared in the backend log:

2012-03-31 03:02:17.934408 E [12990/13073] DVBRead dvbstreamhandler.cpp:215 (RunTS) - DVBSH(/dev/dvb/adapter1/frontend0): Device EOF detected

It appeared during the transition where the frontend exited to the menu and not during the earlier transitions where it only paused briefly.

Removed 10490-debug.patch and applied 10490-debug-v2.patch. Live TV worked for about ten minutes, pausing briefly every 30 seconds, before the frontend exited to the menu with that same device EOF error on the backend. Again, it's only present at the point where the frontend exited.

Looking at the logs I originally attached to this ticket, the device EOF line is in that backend log too. Googling the error turned up ticket #10453, FYI.

I will build the latest git head with your commits tomorrow - it's 5am.

[danielk]

commit [98c855e5f28f53455b803a7c4cddf42bdb5c0ccb] Author: Daniel Kristjansson <danielk@…> Date: Mon Apr 2 17:18:23 2012 -0400

Refs #10490. Fix for LiveTV abort on empty recordings.

[c3eaf781ca] avoids creating empty recordings in some cases when it isn't necessary. But it is still possible for these to be created legitamitely when you start livetv near a program transition so this change makes the frontend skip those empty recordings in a LiveTV chain.

[danielk]

Peter the device EOF message is really a separate issue. That could be a driver issue or some issue in the DVB Recorder.

Am I right in assuming you no longer see the avformatdecoder decoder error message?

[Peter Townsend <elpinkus@…>]

I just had two frontends playing Live TV and one died at 7:02pm and the other at 7:03pm, likely at program transitions. The Ion box drops back to the menu with "Video frame buffering failed too many times" and the AMD E-350 using ffmpeg/opengl quits to the command line with a simple "Aborted".

Once again, lots of

avformatdecoder.cpp:4374 (GetFrame?) - decoding error

eno: Input/output error (5)

cut out to prevent filesizes from being silly.

[Peter Townsend <elpinkus@…>]

backend log

[Peter Townsend <elpinkus@…>]

Ion2 using VDPAU

[Peter Townsend <elpinkus@…>]

AMD E-350 using ffmpeg/opengl

[Scott <snharris99@…>]

I can confirm that I have not seen any change with this issue with the latest changes. I've attached the back end log of my most recent (10 minutes ago) test of Live TV making it through a program transition which ultimately went back to the main menu with the "Video frame buffer failed too many times" error.

MythTV Version : v0.25-rc-126-g711386d MythTV Branch : master Network Protocol : 72 Library API : 0.25.20120315-2 QT Version : 4.6.2 Options compiled in:

linux profile use_hidesyms using_alsa using_oss using_pulse using_pulseoutput u sing_backend using_bindings_perl using_bindings_python using_bindings_php using_ crystalhd using_dvb using_firewire using_frontend using_hdhomerun using_ceton us ing_hdpvr using_iptv using_ivtv using_joystick_menu using_libcrypto using_libdns _sd using_libxml2 using_lirc using_mheg using_opengl_video using_qtwebkit using_ qtscript using_qtdbus using_v4l2 using_v4l1 using_x11 using_xrandr using_xv usin g_bindings_perl using_bindings_python using_bindings_php using_mythtranscode usi ng_opengl using_vdpau using_ffmpeg_threads using_live using_mheg using_libxml2

[Jim Stichnoth]

Mythfrontend log, "-v general,playback", latest master with the every-30-sec program transition patch

[Jim Stichnoth]

Corresponding section of mythbackend log

[Jim Stichnoth]

Search for 'hdpvr' to find the start of live TV recording on channel 12720.

[danielk]

stichnot,

 2012-04-06 06:33:58.461628 D [32364/378] RingBuffer ringbuffer.cpp:925 (run) - RingBuf(/storage3/recordings/12720_20120406063356.mpg): setting ateof (read_return == 0)

Looks like the smoking gun.. There are two ways this could happen, either oldfile is set or stopreads is set when the previous FileRingBuffer::safe_read(int fd...) is called.

Commenting out lines 456 & 457 in fileringbuffer.cpp should confirm the oldfile hypothesis and commenting out 473 & 474 should confirm the stopreads hypothesis.

Can you try commenting out one, then the other, and if that neither of those work work, comment out both?

[Jim Stichnoth]

Already communicated on IRC. For those still experiencing the problem, commenting out lines 456 & 457 allowed a Live TV session for 5-6 hours, with 10490-debug-start-new-rec-every-30-sec.patch​ applied, until I manually exited. No failing back to the main menu with "Video frame buffering failed too many times."

[JYA]

Just a note that the issue occurs regularly on a purely digital setup (DVB-T) over the past few days, when it didn't used to occur.

[danielk]

commit [640b0cdf6652d12ecd5caf33cc27c71190237fb8] Author: Daniel Kristjansson <danielk@…> Date: Thu Apr 5 15:14:22 2012 -0400

Refs #10490. Switch ringbuffers a little earlier in LiveTV.

commit [393295ccfb455a8f76cf9707ad76d08e31d5dbbf] Author: Daniel Kristjansson <danielk@…> Date: Sun Apr 8 16:10:57 2012 -0400

Fixes #10490. Don't return from safe_read() early on stopreads if we haven't read any bytes, this looks like an eof to higher levels of code.

[Kenni Lund [kenni a kelu dot dk]]

Unfortunately still not resolved, as confirmed by stichnot, Seeker´ and myself on IRC. I'm attaching a fresh log file from "mythfrontend -v playback,file".

[Kenni Lund [kenni a kelu dot dk]]

mythtvfrontend -v playback,file from the 9th of April

[danielk]

Potential fix for oldfile

[danielk]

commit [39695b2e9e34d7b5bbb18e056bcd4bb9c9238f0c] Author: Daniel Kristjansson <danielk@…> Date: Mon Apr 9 09:43:00 2012 -0400

Revert "Fixes #10490. Don't return from safe_read() early on stopreads if we haven't read any bytes, this looks like an eof to higher levels of code."

I misread a report from Jim Stichnot, it was oldfile and not stopreads causing problems.

This reverts commit [393295ccfb455a8f76cf9707ad76d08e31d5dbbf].

[Jim Stichnoth <jstichnoth@…>]

In 2531893d539ceb7158033a5862e9fbd51e01da1d/mythtv:

Error: Processor CommitTicketReference failed

GIT backend not available

[Scott <scott.harris0509@…>]

I should report that my Live TV transitions have been near flawless (a nano second video blip and a ~1 second audio drop) as of 2 updates ago. 500 times better than they were even under 0.24.

[warpme@…]

I have one Q: Isn't success of 2531893 masked by 1f5962a ?. I remember 1f5962a was workaround (and indeed 0.25 liveTV segments works OK with 1f5962a alone). I see current master has 2531893, but 1f5962a isn't reverted. Assuming 2531893 properly solves #10490 - shouldn't 1f5962a be reverted ? Thx. If I want to back port 2531893 to 0.25-fixes, should I also revert 1f5962a ?

[Jim Stichnoth <jstichnoth@…>]

In b7484dfdc5fccb2d171c1e024e9d67f10a745e2a/mythtv:

Error: Processor CommitTicketReference failed

GIT backend not available

[Jim Stichnoth <jstichnoth@…>]

In 0349883596549a8c76632fdfdf61920514ee65ae/mythtv:

Error: Processor CommitTicketReference failed

GIT backend not available

[Jim Stichnoth <jstichnoth@…>]

In 7c7852f4d71e54276c8dfa66a589314c5061fd0d/mythtv:

Error: Processor CommitTicketReference failed

GIT backend not available

[Jim Stichnoth <jstichnoth@…>]

In 2e56c2563a75ec2c3c97996de838119f0ea6de6a/mythtv:

Error: Processor CommitTicketReference failed

GIT backend not available

[Jim Stichnoth <jstichnoth@…>]

In 0ecb1d96fc0429a8b9d68ace58097d421be803b3/mythtv:

Error: Processor CommitTicketReference failed

GIT backend not available

[Jim Stichnoth <jstichnoth@…>]

In 3564049d049fd1238ee513712928ada9215ce0d0/mythtv:

Error: Processor CommitTicketReference failed

GIT backend not available

[Jim Stichnoth <jstichnoth@…>]

In 20c814a96f0b3c3d0a6e6038e4229bb75b8e82e2/mythtv:

Error: Processor CommitTicketReference failed

GIT backend not available

[Jim Stichnoth <jstichnoth@…>]

In 46062bfe07bcd7d98e36cb95c118d098e3764795/mythtv:

Error: Processor CommitTicketReference failed

GIT backend not available

[Jim Stichnoth]

After a long roundabout search, the answer is that the problem arose from a race condition between switching ringbuffer files on the backend and the frontend using the LiveTVChain status to signal the EOF optimization on the backend. The net effect of all the changes and reversions is to remove the call to SetTimeout?() in RingBuffer::run(), plus adding more logging.

[Mario Limonciello <Mario_Limonciello@…>]

In 47bed8ed5e6ee58876df6b04cda84a853b257f48/packaging:

Error: Processor CommitTicketReference failed

GIT backend not available

[zorglups.mailing@…]

My Zotac ION (VDPAU) is finally playing HD fine since yesterday night !!!!!! Thanks a lot for this fix !!!

[pieter@…]

Hi,

I still get this at transition:

May 22 17:52:48 media mythfrontend[2379]: N CoreContext? mythplayer.cpp:2079 (PrebufferEnoughFrames?) Player(4): Waited 102ms for video buffers AADAADALAALADA May 22 17:52:48 media mythfrontend[2379]: N CoreContext? mythplayer.cpp:2079 (PrebufferEnoughFrames?) Player(4): Waited 207ms for video buffers AADAADALAALADA May 22 17:52:48 media mythfrontend[2379]: N CoreContext? mythplayer.cpp:2079 (PrebufferEnoughFrames?) Player(4): Waited 308ms for video buffers AADAADALAALADA May 22 17:52:48 media mythfrontend[2379]: N CoreContext? mythplayer.cpp:2079 (PrebufferEnoughFrames?) Player(4): Waited 413ms for video buffers AADAADALAALADA May 22 17:52:48 media mythfrontend[2379]: N CoreContext? mythplayer.cpp:2079 (PrebufferEnoughFrames?) Player(4): Waited 517ms for video buffers AADAADALAALADA May 22 17:52:48 media mythfrontend[2379]: N CoreContext? mythplayer.cpp:2079 (PrebufferEnoughFrames?) Player(4): Waited 623ms for video buffers AADAADALAALADA May 22 18:00:03 media mythfrontend[2379]: N CoreContext? avformatdecoder.cpp:752 (SetEof?) AFD: Resetting byte context eof (livetv 1 was eof 0) May 22 18:00:07 media mythfrontend[2379]: E Decoder ringbuffer.cpp:259 (Reset) RingBuf?(/var/lib/mythtv/livetv/2035_20120522180000.mpg): RingBuffer::Reset() nonzero readpos. toAdjust: 1 readpos: -2703800696 readAdjust: 4635015544 May 22 18:00:07 media mythfrontend[2379]: N Decoder avformatdecoder.cpp:752 (SetEof?) AFD: Resetting byte context eof (livetv 1 was eof 0) May 22 18:00:07 media mythfrontend[2379]: I Decoder mythdbcon.cpp:395 (PurgeIdleConnections?) New DB connection, total: 4 May 22 18:00:07 media mythfrontend[2379]: E Decoder avformatdecoder.cpp:4213 (ProcessAudioPacket?) AFD: Unknown audio decoding error

Thanks,

Pieter