mythfrontend "Ignoring livetv eof in decoder loop" message at end of LiveTV show then consumes all swap and crashes

[ut_crom@…]

LiveTV freezes at end of show, then mythfrontend consumes all swap and crashes. Looking at the log, the following messages are displayed right before mythfrontend begins to consume all of the swap:

2006-03-04 11:29:59.782 reads allowed (98305 32768) 2006-03-04 11:30:00.111 AFD: positionMap[ 107 ] == 50079846. 2006-03-04 11:30:00.228 LiveTVChain(live-mythtv-2006-03-04T11:22:34): ReloadAll?(): Added new recording 2006-03-04 11:30:00.228 Resyncing position map. posmapStarted = 0 livetv(1) watchingRec(0) 2006-03-04 11:30:00.230 Position map filled from DB to: 93 2006-03-04 11:30:00.230 SyncPositionMap? watchingrecording, from DB: 93 entries 2006-03-04 11:30:00.230 SyncPositionMap? watchingrecording no entries from encoder, try DB 2006-03-04 11:30:00.232 Position map filled from DB to: 93 2006-03-04 11:30:00.232 SyncPositionMap? watchingrecording total: 93 entries 'video_output' mean = '33358.09', std. dev. = '5030.23', fps = '29.98' 2006-03-04 11:30:00.742 LiveTVChain(live-mythtv-2006-03-04T11:22:34): SwitchTo?(3) 2006-03-04 11:30:00.742 LiveTVChain(live-mythtv-2006-03-04T11:22:34): Entry@3: '1005_20060304113000' 2006-03-04 11:30:00.755 NVP: IsReallyNearEnd?() br(1048KB) fps(29) sz(0KB) vfl(10) frh(0) ne:1 2006-03-04 11:30:00.755 SwitchToProgram?(void) 2006-03-04 11:30:00.774 RingBuf?(/media/video/mythtv/1005_20060304112905.mpg): OpenFile?(myth://127.0.0.1:6543/1005_20060304113000.mpg, 10) 2006-03-04 11:30:00.774 Ignoring livetv eof in decoder loop 2006-03-04 11:30:00.774 Ignoring livetv eof in decoder loop 2006-03-04 11:30:00.774 Ignoring livetv eof in decoder loop 2006-03-04 11:30:00.774 Ignoring livetv eof in decoder loop 2006-03-04 11:30:00.774 Ignoring livetv eof in decoder loop 2006-03-04 11:30:00.774 Ignoring livetv eof in decoder loop 2006-03-04 11:30:00.774 Ignoring livetv eof in decoder loop 2006-03-04 11:30:00.774 Ignoring livetv eof in decoder loop 2006-03-04 11:30:00.774 Ignoring livetv eof in decoder loop 2006-03-04 11:30:00.774 Ignoring livetv eof in decoder loop 2006-03-04 11:30:00.775 Ignoring livetv eof in decoder loop 2006-03-04 11:30:00.775 Ignoring livetv eof in decoder loop

... (hundreds of these lines)

2006-03-04 11:30:01.018 Ignoring livetv eof in decoder loop 2006-03-04 11:30:01.020 NVP: prebuffering pause 2006-03-04 11:30:01.020 NVP: Waiting for prebuffer.. 0 AAAAAAAAAAAAAAAAAAAAAAAAAAAaAuL 2006-03-04 11:30:01.018 Ignoring livetv eof in decoder loop

...

2006-03-04 11:30:01.022 Ignoring livetv eof in decoder loop 2006-03-04 11:30:01.022 WriteAudio?: buffer underrun 2006-03-04 11:30:01.022 Ignoring livetv eof in decoder loop

...

Pressing the Esc button during this makes mythfrontend go back to normal, but it usually happens again when the current LiveTV show ends.

There are some other buffering messages a minute or so before LiveTV freezes. I will attach the log which contains the full details.

I am currently running Gentoo with mythtv 0.19_p9163. Please let me know if you need additional information about my system configuration.

Thank you.

[ut_crom@…]

part 1

[ut_crom@…]

part 2

[anonymous]

part 3

[ut_crom@…]

Additional observations. When I start LiveTV, the mythfrontend log shows normal operation:

2006-03-04 14:56:33.560 Using audio as timebase 2006-03-04 14:56:33.560 Video timing method: USleep with busy wait 2006-03-04 14:56:33.560 Refresh rate: 16666, frame interval: 33366 2006-03-04 14:56:35.966 AFD: positionMap[ 6 ] == 3330086. 2006-03-04 14:56:36.466 AFD: positionMap[ 7 ] == 3813414. 'video_output' mean = '33386.46', std. dev. = '4210.91', fps = '29.95' 2006-03-04 14:56:36.967 AFD: positionMap[ 8 ] == 4284454. 2006-03-04 14:56:37.467 AFD: positionMap[ 9 ] == 4773926. 2006-03-04 14:56:37.967 AFD: positionMap[ 10 ] == 5255206. 2006-03-04 14:56:38.470 AFD: positionMap[ 11 ] == 5599270. 2006-03-04 14:56:38.970 AFD: positionMap[ 12 ] == 6021158. 2006-03-04 14:56:39.470 AFD: positionMap[ 13 ] == 6440998. 2006-03-04 14:56:39.970 AFD: positionMap[ 14 ] == 6864934. 'video_output' mean = '33356.56', std. dev. = '1647.91', fps = '29.98' 2006-03-04 14:56:40.470 AFD: positionMap[ 15 ] == 7311398. 2006-03-04 14:56:40.970 AFD: positionMap[ 16 ] == 7778342. 2006-03-04 14:56:41.471 AFD: positionMap[ 17 ] == 8232998. 2006-03-04 14:56:41.973 AFD: positionMap[ 18 ] == 8724518. 2006-03-04 14:56:42.473 AFD: positionMap[ 19 ] == 9267238. 2006-03-04 14:56:42.973 AFD: positionMap[ 20 ] == 9746470. 2006-03-04 14:56:43.473 AFD: positionMap[ 21 ] == 10231846. 'video_output' mean = '33358.87', std. dev. = '1514.06', fps = '29.98' 2006-03-04 14:56:43.974 AFD: positionMap[ 22 ] == 10704934. 2006-03-04 14:56:44.474 AFD: positionMap[ 23 ] == 11325478.

... etc

However, when changing the channel, the following "rebuffering" output is produced in the mythfrontend log:

2006-03-04 14:57:07.203 reads allowed (149569 32768) 2006-03-04 14:57:07.214 AFD: HandleGopStart?: gopset not set, syncing positionMap 2006-03-04 14:57:07.214 Resyncing position map. posmapStarted = 1 livetv(1) watchingRec(1) 2006-03-04 14:57:07.219 Filling position map from 2 to 1 2006-03-04 14:57:07.227 Position map filled from Encoder to: 1 2006-03-04 14:57:07.227 SyncPositionMap? watchingrecording total: 1 entries 2006-03-04 14:57:07.227 AFD: HandleGopStart?: Initial key frame distance: 15. 'video_output' mean = '37939.83', std. dev. = '44485.65', fps = '26.36' 2006-03-04 14:57:07.724 AFD: positionMap[ 1 ] == 1185894. 2006-03-04 14:57:07.779 rebuffering (24641 32768) 2006-03-04 14:57:07.907 reads allowed (155713 32768) 2006-03-04 14:57:08.239 AFD: positionMap[ 2 ] == 1728614. 2006-03-04 14:57:08.290 rebuffering (28737 32768) 2006-03-04 14:57:08.483 reads allowed (159809 32768) 2006-03-04 14:57:08.813 AFD: positionMap[ 3 ] == 2199654. 2006-03-04 14:57:08.866 rebuffering (2113 32768) 2006-03-04 14:57:09.059 reads allowed (133185 32768) 2006-03-04 14:57:09.122 rebuffering (20545 32768) 2006-03-04 14:57:09.379 reads allowed (151617 32768) 2006-03-04 14:57:09.379 AFD: positionMap[ 4 ] == 2650214. 2006-03-04 14:57:09.442 rebuffering (28737 32768) 2006-03-04 14:57:09.698 reads allowed (159809 32768) 2006-03-04 14:57:09.763 AFD: positionMap[ 5 ] == 3176550. 2006-03-04 14:57:10.082 rebuffering (30785 32768) 2006-03-04 14:57:10.338 reads allowed (161857 32768) 2006-03-04 14:57:10.356 AFD: positionMap[ 6 ] == 3584102. 2006-03-04 14:57:10.658 rebuffering (10305 32768) 'video_output' mean = '33865.91', std. dev. = '5800.84', fps = '29.53' 2006-03-04 14:57:10.914 reads allowed (141377 32768) 2006-03-04 14:57:10.918 AFD: positionMap[ 7 ] == 4034662. 2006-03-04 14:57:11.258 AFD: positionMap[ 8 ] == 4470886. 2006-03-04 14:57:11.298 rebuffering (30785 32768) 2006-03-04 14:57:11.491 reads allowed (161857 32768) 2006-03-04 14:57:11.819 AFD: positionMap[ 9 ] == 4925542. 2006-03-04 14:57:12.130 rebuffering (20545 32768) 2006-03-04 14:57:12.450 buffering (20545 32768 0) 2006-03-04 14:57:12.576 NVP: prebuffering pause 2006-03-04 14:57:12.576 NVP: Waiting for prebuffer.. 0 uAAAAAAAAAAAAAAaAALAAAAAAAAAAAA 2006-03-04 14:57:12.706 reads allowed (151617 32768) 2006-03-04 14:57:12.710 AFD: positionMap[ 10 ] == 5382246. 2006-03-04 14:57:12.718 NVP: Waiting for prebuffer.. 1 UUUAAUAAAAAAAAAAAAUALLAAAAAAAAA 2006-03-04 14:57:12.770 rebuffering (26689 32768) 2006-03-04 14:57:12.858 NVP: Waiting for prebuffer.. 2 UUUAUUAAUAAAAAAAAAUAUuAALAAAAAA 2006-03-04 14:57:12.998 NVP: Waiting for prebuffer.. 3 UUUAUUAAUAAAAAAAAAUAUuAALAAAAAA 2006-03-04 14:57:13.026 reads allowed (157761 32768) 2006-03-04 14:57:13.044 AFD: positionMap[ 11 ] == 5744742. 2006-03-04 14:57:13.361 AFD: positionMap[ 12 ] == 6017126. 2006-03-04 14:57:13.410 rebuffering (24641 32768) 2006-03-04 14:57:13.602 reads allowed (155713 32768) 2006-03-04 14:57:13.666 rebuffering (28737 32768) 2006-03-04 14:57:13.922 reads allowed (159809 32768) 2006-03-04 14:57:13.928 AFD: positionMap[ 13 ] == 6469734. 2006-03-04 14:57:14.328 AFD: positionMap[ 14 ] == 6920294. 'video_output' mean = '37744.01', std. dev. = '45427.00', fps = '26.49' 2006-03-04 14:57:14.691 rebuffering (26689 32768) 2006-03-04 14:57:14.882 reads allowed (157761 32768) 2006-03-04 14:57:14.891 AFD: positionMap[ 15 ] == 7325798. 2006-03-04 14:57:15.288 AFD: positionMap[ 16 ] == 7739494.

...

I noticed that this "rebuffering" occurs only when changing the channel and that LiveTV is 2 seconds behind the broadcast instead if the normal 5 seconds. When I press the rewind button and then the fast forward button again, the buffer changes from 2 seconds to the normal 5 seconds. I also noticed that after i rewind and fast forward, the log produces the normal output intead of the output with the "rebuffering" messages.

When a program ends during the time when the "rebuffering" messages occur, then mythfrontend starts to display the "Ignoring livetv eof in decoder loop", LiveTV freezes, mythfrontend consumes all of the swap and eventually crashes.

When a progam ends and there is no "rebuffering" messages, then operation of mythfrontend continues normally without freezing LiveTV, consuming swap or crashing.

I'll attach the full log of my observations.

[ut_crom@…]

prebuffering log

[foobum@…]

I'm seeing the same thing..

Gentoo on x86_64, r9665 of fixes branch. I'll attach logs later today.

[foobum@…]

Some more details and a snipped -v playback frontend log file that demonstrates the problem..

The input used is a pvr350 (ivtv-0.4.0 (same happens with 0.4.4)). The file that it opens (via OpenFile?())just before the 'eof in decoder loop' spam exists and is of non-zero size.

This seems to happen on pretty much every program change :(.

[foobum@…]

Attached patch fixes it for me although I doubt it's the proper way to solve the problem..

[Isaac Richards]

Yup, attached patch isn't correct, and will result in non-smooth program transitions (for the majority of people that this doesn't happen to). I'd suggest looking at why it still thinks there's an EOF at that point in time. Additional logs won't help - more information on what is actually going on is required.

[Isaac Richards]

Closing as 'worksforme', requested additional information > 1 month ago. Please reopen if new info is ever available.