[mythtv] Frontend locking/freezing on FF with SD/HD content

Sat Oct 14 00:09:01 UTC 2006

Hi all.

(just to preface this, I sent this message to mythtv-users, I never
received a reply. The last 5 days of being subscribed I got nearly 400
messages about configuration issues, but nothing about this "bug" (if
it's even a bug). If this isn't the list to post this to, please slap me
now. I also sent this message 5 days ago to this list, it was kicked 
back saying it was too big (large log file attached) and is awaiting the 
moderator's approval. I'm tired of having this problem and I want to 
find a fix soon. This message only links to a log file and doesn't 
actually contain it)

I've got MythTV 0.20 setup on Gentoo. Occasionally the front end will
lockup while fast forwarding, generally this occurs when skipping "in to
the future", that is ff'ing into and past the end of the recorded
program. It will also occasionally do this without even going past the
end. This only seems to happen in LiveTV, going into "watch recordings" 
and using FF it never happens.

This is with sticky fast-forward.

This is what mythfrontend continually pukes into the log when it freezes
playback. Sometimes it'll "unfreeze" once we've caught up to wherever in
the future it's FF'd to, if that happens myth won't accept any keyboard
input and must be killed and started again. We're using the "Standard"
mpeg decoder, and a PVR-150MCE card.

2006-10-04 09:55:28.195 WriteAudio: buffer underrun
2006-10-04 09:55:28.676 NVP: Prebuffer wait timed out 10 times.
2006-10-04 09:55:29.008 Waited too long for video out to pause
2006-10-04 09:55:29.646 NVP: Prebuffer wait timed out 10 times.
2006-10-04 09:55:29.766 Waited too long for decoder to pause
2006-10-04 09:55:30.036 Waited too long for video out to pause
2006-10-04 09:55:30.646 NVP: Prebuffer wait timed out 10 times.
2006-10-04 09:55:31.046 Waited too long for video out to pause
2006-10-04 09:55:31.647 NVP: Prebuffer wait timed out 10 times.
2006-10-04 09:55:32.056 Waited too long for video out to pause
2006-10-04 09:55:32.646 NVP: Prebuffer wait timed out 10 times.
2006-10-04 09:55:33.066 Waited too long for video out to pause
2006-10-04 09:55:33.651 NVP: Prebuffer wait timed out 10 times.
2006-10-04 09:55:33.776 Waited too long for decoder to pause
2006-10-04 09:55:34.076 Waited too long for video out to pause
2006-10-04 09:55:34.646 NVP: Prebuffer wait timed out 10 times.
2006-10-04 09:55:35.086 Waited too long for video out to pause
2006-10-04 09:55:35.646 NVP: Prebuffer wait timed out 10 times.
2006-10-04 09:55:36.096 Waited too long for video out to pause
2006-10-04 09:55:36.646 NVP: Prebuffer wait timed out 10 times.
2006-10-04 09:55:37.106 Waited too long for video out to pause
2006-10-04 09:55:37.646 NVP: Prebuffer wait timed out 10 times.
2006-10-04 09:55:37.786 Waited too long for decoder to pause
2006-10-04 09:55:38.116 Waited too long for video out to pause
2006-10-04 09:55:38.646 NVP: Prebuffer wait timed out 10 times.
2006-10-04 09:55:39.126 Waited too long for video out to pause
2006-10-04 09:55:39.646 NVP: Prebuffer wait timed out 10 times.
2006-10-04 09:55:40.136 Waited too long for video out to pause
2006-10-04 09:55:40.646 NVP: Prebuffer wait timed out 10 times.
2006-10-04 09:55:41.146 Waited too long for video out to pause
2006-10-04 09:55:41.646 NVP: Prebuffer wait timed out 10 times.
2006-10-04 09:55:41.796 Waited too long for decoder to pause
2006-10-04 09:55:42.156 Waited too long for video out to pause

Here's some 'mythfrontend -v playback' information, taken with a later
death of the frontend:

2006-10-06 08:30:51.473 LiveTVChain(live-mythtv-2006-10-06T07:07:28):
SwitchTo(3)
2006-10-06 08:30:51.473 LiveTVChain(live-mythtv-2006-10-06T07:07:28):
Entry at 3: '2106_20061006083000'
2006-10-06 08:30:51.503 JumpToProgram(void)
2006-10-06 08:30:51.545
RingBuf(/media/Rcrd.new/2106_20061006080001.mpg):
OpenFile(myth://127.0.0.1:6543/2106_20061006083000.mpg, 12)
2006-10-06 08:30:51.559
RingBuf(/media/Rcrd.new/2106_20061006083000.mpg):
CalcReadAheadThresh(12000 KB)
			 -> threshhold(439 KB) min read(32 KB) blk size(256 KB)
2006-10-06 08:30:51.559 NVP: ClearAfterSeek(1)
2006-10-06 08:30:51.559 VideoOutputXv: ClearAfterSeek()
2006-10-06 08:30:51.559 VideoOutputXv: DiscardFrames(0)
2006-10-06 08:30:51.559 VideoBuffers::DiscardFrames(0):
UUUUUUULUUUUUuUUUUUUUUUUUUUUuUU
2006-10-06 08:30:51.560 VideoBuffers::DiscardFrames(0):
AAAAAAALAAAAAaAAAAAAAAAAAAAAaAA -- done
2006-10-06 08:30:51.560 VideoOutputXv: DiscardFrames() 3:
AAAAAAALAAAAAaAAAAAAAAAAAAAAaAA -- done()
2006-10-06 08:30:51.560 AFD: SeekReset(0, 0, do flush, do discard)
2006-10-06 08:30:51.560 AFD: SeekReset() flushing
2006-10-06 08:30:51.560 VideoOutputXv: DiscardFrames(1)
2006-10-06 08:30:51.560 VideoBuffers::DiscardFrames(1):
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
2006-10-06 08:30:51.560 VideoBuffers::DiscardFrames():
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA -- done()
2006-10-06 08:30:51.560 VideoBuffers::DiscardFrames(1):
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA -- done
2006-10-06 08:30:51.560 VideoOutputXv: DiscardFrames() 3:
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA -- done()
2006-10-06 08:30:51.560 Resyncing position map. posmapStarted = 0
livetv(1) watchingRec(1)
2006-10-06 08:30:51.561 Position map filled from DB to: 86
2006-10-06 08:30:51.562 SyncPositionMap watchingrecording, from DB: 86
entries
2006-10-06 08:30:51.562 Filling position map from 87 to 100
2006-10-06 08:30:51.562 Position map filled from Encoder to: 100
2006-10-06 08:30:51.562 SyncPositionMap watchingrecording total: 100 entries
2006-10-06 08:30:51.562 SyncPositionMap, new totframes: 1500, new
length: 50, posMap size: 100
2006-10-06 08:30:51.563 AFD: DoFastForward(90 (0), don't discard frames)
2006-10-06 08:30:51.563 Dec: DoFastForward(90 (0), don't discard frames)
2006-10-06 08:30:51.563 AFD: SeekReset(90, 0, do flush, don't discard)
2006-10-06 08:30:51.563 AFD: SeekReset() flushing
2006-10-06 08:30:51.563 WriteAudio: buffer underrun
2006-10-06 08:30:51.595 AFD: DoFastForward(50776 (91), don't discard frames)
2006-10-06 08:30:51.595 Dec: DoFastForward(50776 (91), don't discard frames)
2006-10-06 08:30:51.595 Dec: DoFastForward: Not enough info in positionMap,
			we need frame 50776 but highest we have is 1485.
2006-10-06 08:30:51.595 Resyncing position map. posmapStarted = 1
livetv(1) watchingRec(1)
2006-10-06 08:30:51.595 Filling position map from 101 to 100
2006-10-06 08:30:51.595 Position map filled from Encoder to: 100
2006-10-06 08:30:51.595 SyncPositionMap watchingrecording total: 100 entries
2006-10-06 08:30:51.595 Dec: DoFastForward: Still not enough info in
positionMap after sync,
			we need frame 50776 but highest we have is 1485. Will seek frame-by-frame
2006-10-06 08:30:51.597 AFD: HandleGopStart: gopset not set, syncing
positionMap
2006-10-06 08:30:51.597 Resyncing position map. posmapStarted = 1
livetv(1) watchingRec(1)
2006-10-06 08:30:51.597 Filling position map from 101 to 100
2006-10-06 08:30:51.598 Position map filled from Encoder to: 100
2006-10-06 08:30:51.598 SyncPositionMap watchingrecording total: 100 entries
2006-10-06 08:30:51.598 AFD: HandleGopStart: Initial key frame distance: 15.
2006-10-06 08:30:51.622 NVP: Waiting for prebuffer.. 0
AAAAAAAAAAAAAAAAAAAALAAAaAAAAAA
2006-10-06 08:30:52.238 NVP: Waiting for prebuffer.. 1
AAAAAAAAAAAAAAAAAAAALAAAaAAAAAA
2006-10-06 08:30:52.855 NVP: Waiting for prebuffer.. 2
AAAAAAAAAAAAAAAAAAAALAAAaAAAAAA
2006-10-06 08:30:53.471 NVP: Waiting for prebuffer.. 3
AAAAAAAAAAAAAAAAAAAALAAAaAAAAAA
2006-10-06 08:30:54.088 NVP: Waiting for prebuffer.. 4
AAAAAAAAAAAAAAAAAAAALAAAaAAAAAA
2006-10-06 08:30:54.705 NVP: Waiting for prebuffer.. 5
AAAAAAAAAAAAAAAAAAAALAAAaAAAAAA
2006-10-06 08:30:55.321 NVP: Waiting for prebuffer.. 6
AAAAAAAAAAAAAAAAAAAALAAAaAAAAAA
2006-10-06 08:30:55.938 NVP: Waiting for prebuffer.. 7
AAAAAAAAAAAAAAAAAAAALAAAaAAAAAA
2006-10-06 08:30:56.555 NVP: Waiting for prebuffer.. 8
AAAAAAAAAAAAAAAAAAAALAAAaAAAAAA
2006-10-06 08:30:57.171 NVP: Waiting for prebuffer.. 9
AAAAAAAAAAAAAAAAAAAALAAAaAAAAAA
2006-10-06 08:30:57.772 NVP: Prebuffer wait timed out 10 times.
2006-10-06 08:30:57.788 NVP: Waiting for prebuffer.. 0
AAAAAAAAAAAAAAAAAAAALAAAaAAAAAA
2006-10-06 08:30:58.405 NVP: Waiting for prebuffer.. 1
AAAAAAAAAAAAAAAAAAAALAAAaAAAAAA
2006-10-06 08:30:59.021 NVP: Waiting for prebuffer.. 2
AAAAAAAAAAAAAAAAAAAALAAAaAAAAAA
2006-10-06 08:30:59.638 NVP: Waiting for prebuffer.. 3
AAAAAAAAAAAAAAAAAAAALAAAaAAAAAA
2006-10-06 08:31:00.258 NVP: Waiting for prebuffer.. 4
AAAAAAAAAAAAAAAAAAAALAAAaAAAAAA
2006-10-06 08:31:00.871 NVP: Waiting for prebuffer.. 5
AAAAAAAAAAAAAAAAAAAALAAAaAAAAAA
2006-10-06 08:31:01.488 NVP: Waiting for prebuffer.. 6
AAAAAAAAAAAAAAAAAAAALAAAaAAAAAA
2006-10-06 08:31:02.105 NVP: Waiting for prebuffer.. 7
AAAAAAAAAAAAAAAAAAAALAAAaAAAAAA
2006-10-06 08:31:02.722 NVP: Waiting for prebuffer.. 8
AAAAAAAAAAAAAAAAAAAALAAAaAAAAAA
2006-10-06 08:31:03.338 NVP: Waiting for prebuffer.. 9
AAAAAAAAAAAAAAAAAAAALAAAaAAAAAA
2006-10-06 08:31:03.942 NVP: Prebuffer wait timed out 10 times.
2006-10-06 08:31:03.955 NVP: Waiting for prebuffer.. 0
AAAAAAAAAAAAAAAAAAAALAAAaAAAAAA
2006-10-06 08:31:04.572 NVP: Waiting for prebuffer.. 1
AAAAAAAAAAAAAAAAAAAALAAAaAAAAAA
2006-10-06 08:31:05.188 NVP: Waiting for prebuffer.. 2
AAAAAAAAAAAAAAAAAAAALAAAaAAAAAA
2006-10-06 08:31:05.805 NVP: Waiting for prebuffer.. 3
AAAAAAAAAAAAAAAAAAAALAAAaAAAAAA
2006-10-06 08:31:06.422 NVP: Waiting for prebuffer.. 4
AAAAAAAAAAAAAAAAAAAALAAAaAAAAAA
2006-10-06 08:31:07.038 NVP: Waiting for prebuffer.. 5
AAAAAAAAAAAAAAAAAAAALAAAaAAAAAA
2006-10-06 08:31:07.655 NVP: Waiting for prebuffer.. 6
AAAAAAAAAAAAAAAAAAAALAAAaAAAAAA
2006-10-06 08:31:08.272 NVP: Waiting for prebuffer.. 7
AAAAAAAAAAAAAAAAAAAALAAAaAAAAAA
2006-10-06 08:31:08.888 NVP: Waiting for prebuffer.. 8
AAAAAAAAAAAAAAAAAAAALAAAaAAAAAA
2006-10-06 08:31:09.505 NVP: Waiting for prebuffer.. 9
AAAAAAAAAAAAAAAAAAAALAAAaAAAAAA
2006-10-06 08:31:10.112 NVP: Prebuffer wait timed out 10 times.
2006-10-06 08:31:10.122 NVP: Waiting for prebuffer.. 0
AAAAAAAAAAAAAAAAAAAALAAAaAAAAAA
2006-10-06 08:31:10.632 NVP: Play( 30.0, normal 0, unpause audio 1)
2006-10-06 08:31:10.642 NVP: Play( 60.0, normal 0, unpause audio 1)
2006-10-06 08:31:10.739 NVP: Waiting for prebuffer.. 1
AAAAAAAAAAAAAAAAAAAALAAAaAAAAAA
2006-10-06 08:31:11.355 NVP: Waiting for prebuffer.. 2
AAAAAAAAAAAAAAAAAAAALAAAaAAAAAA
2006-10-06 08:31:11.972 NVP: Waiting for prebuffer.. 3
AAAAAAAAAAAAAAAAAAAALAAAaAAAAAA
2006-10-06 08:31:12.589 NVP: Waiting for prebuffer.. 4
AAAAAAAAAAAAAAAAAAAALAAAaAAAAAA
2006-10-06 08:31:13.205 NVP: Waiting for prebuffer.. 5
AAAAAAAAAAAAAAAAAAAALAAAaAAAAAA
2006-10-06 08:31:13.822 NVP: Waiting for prebuffer.. 6
AAAAAAAAAAAAAAAAAAAALAAAaAAAAAA
2006-10-06 08:31:14.439 NVP: Waiting for prebuffer.. 7
AAAAAAAAAAAAAAAAAAAALAAAaAAAAAA
2006-10-06 08:31:15.055 NVP: Waiting for prebuffer.. 8
AAAAAAAAAAAAAAAAAAAALAAAaAAAAAA
2006-10-06 08:31:15.672 NVP: Waiting for prebuffer.. 9
AAAAAAAAAAAAAAAAAAAALAAAaAAAAAA
2006-10-06 08:31:16.281 NVP: Prebuffer wait timed out 10 times.
2006-10-06 08:31:16.289 NVP: Waiting for prebuffer.. 0
AAAAAAAAAAAAAAAAAAAALAAAaAAAAAA
2006-10-06 08:31:16.905 NVP: Waiting for prebuffer.. 1
AAAAAAAAAAAAAAAAAAAALAAAaAAAAAA
2006-10-06 08:31:17.522 NVP: Waiting for prebuffer.. 2
AAAAAAAAAAAAAAAAAAAALAAAaAAAAAA
2006-10-06 08:31:18.139 NVP: Waiting for prebuffer.. 3
AAAAAAAAAAAAAAAAAAAALAAAaAAAAAA
2006-10-06 08:31:18.755 NVP: Waiting for prebuffer.. 4
AAAAAAAAAAAAAAAAAAAALAAAaAAAAAA
2006-10-06 08:31:19.372 NVP: Waiting for prebuffer.. 5
AAAAAAAAAAAAAAAAAAAALAAAaAAAAAA
2006-10-06 08:31:19.989 NVP: Waiting for prebuffer.. 6
AAAAAAAAAAAAAAAAAAAALAAAaAAAAAA
2006-10-06 08:31:20.605 NVP: Waiting for prebuffer.. 7
AAAAAAAAAAAAAAAAAAAALAAAaAAAAAA
2006-10-06 08:31:21.222 NVP: Waiting for prebuffer.. 8
AAAAAAAAAAAAAAAAAAAALAAAaAAAAAA
2006-10-06 08:31:21.839 NVP: Waiting for prebuffer.. 9
AAAAAAAAAAAAAAAAAAAALAAAaAAAAAA
2006-10-06 08:31:22.441 NVP: Prebuffer wait timed out 10 times.
2006-10-06 08:31:22.456 NVP: Waiting for prebuffer.. 0
AAAAAAAAAAAAAAAAAAAALAAAaAAAAAA
2006-10-06 08:31:23.073 NVP: Waiting for prebuffer.. 1
AAAAAAAAAAAAAAAAAAAALAAAaAAAAAA
2006-10-06 08:31:23.689 NVP: Waiting for prebuffer.. 2
AAAAAAAAAAAAAAAAAAAALAAAaAAAAAA
2006-10-06 08:31:24.306 NVP: Waiting for prebuffer.. 3
AAAAAAAAAAAAAAAAAAAALAAAaAAAAAA
2006-10-06 08:31:24.922 NVP: Waiting for prebuffer.. 4
AAAAAAAAAAAAAAAAAAAALAAAaAAAAAA
2006-10-06 08:31:25.539 NVP: Waiting for prebuffer.. 5
AAAAAAAAAAAAAAAAAAAALAAAaAAAAAA
2006-10-06 08:31:26.156 NVP: Waiting for prebuffer.. 6
AAAAAAAAAAAAAAAAAAAALAAAaAAAAAA
2006-10-06 08:31:26.772 NVP: Waiting for prebuffer.. 7
AAAAAAAAAAAAAAAAAAAALAAAaAAAAAA
2006-10-06 08:31:27.389 NVP: Waiting for prebuffer.. 8
AAAAAAAAAAAAAAAAAAAALAAAaAAAAAA
2006-10-06 08:31:28.006 NVP: Waiting for prebuffer.. 9
AAAAAAAAAAAAAAAAAAAALAAAaAAAAAA
2006-10-06 08:31:28.610 NVP: Prebuffer wait timed out 10 times.

It then repeats this until I kill it. Full log can be found here:
http://renders.dittobox.net/Myth_TV/mythfrontend_log_dashveeplayback.txt

Software:
-Gentoo 2006.1
-Linux 2.6.18-gentoo (using built-in DVB drivers for pcHDTV card)
-MythTV: Gentoo-Portage version: media-tv/mythtv-0.20_p11281 (machine is
both a frontend and backend)
-ffmpeg: media-video/ffmpeg-0.4.9_p20060530 <--This could be the
problem, I've tried XvMC and Libmpeg, which don't do this. Libmpeg has
frame deterioration on FF/RW and XvMC is ugly and has pass through problems
-gcc (GCC) 4.1.1 (Gentoo 4.1.1)
-ivtv 0.8, built from sources on ivtv website, since portage doesn't
have it yet
-XFCE 4.2
-LIRC 0.8.0, with lirc_streamzap

Hardware:
-ASUSTeK Computer Inc. K8N4-E Mainboard
-Non-OC'd AMD Athlon(tm) 64 Processor 3200+ Venice, 2.0ghz
-1gb Crucial DDR400 RAM
-Hercules Game Theater XP (Cirrus Logic CS 4614/22/24/30)
-nVidia Corporation NV43 [GeForce 6600 GT] (rev a2) (w/nvidia driver)
-pcHDTV 5500 (Conexant CX23880/1/2/3 PCI Video and Audio Decoder)
-Hauppauge computer works Inc. WinTV PVR 150 (Internext Compression Inc
iTVC16 (CX23416) MPEG-2 Encoder (rev 01))
-250GB Western Digital Caviar 7200rpm SATA150

Thanks for any help, this is starting to get annoying. I just recently
formatted and rebuilt Gentoo on this machine after some upgrades to
support HD playback/recording, and this problem was prevalent even
before the rebuild. It's occurred since the 0.17 version we started with
well over a year and half ago, and has persisted through 0.18, 0.19 and
now 0.20. This rebuild was from the ground up, I saved only our media
and did not use the old database or configurations files (save lircrc
and lirc.conf and my xorg.conf...which has been totally "rewritten")

__
Nathan