[mythtv] LiveTV playback stops at end of shows

Chris Bagwell chris at cnpbagwell.com
Wed Feb 22 03:32:16 UTC 2006


Hi all,

I decided to upgrade my mythbox to Fedora Core 5 Test 3 and latest SVN 
of MythTV.  I'm seeing LiveTV playback stopping at an end of shows; 
similar to other reports.  Lockup rate is about 3 out of 4 show 
transitions. Exiting and reentering LiveTV cures the problem. 

I'm new to SVN so I don't know what version I'm using but I ran "svn 
update" Feb 21st 8:00am.  I'm using ivtv driver and xvmc on via and 
everything runs on 1 box (frontend is local).

Sorry to waste bandwidth but I hope this "mythfrondend -v playback" log 
helps.  I tried to trim out the repeating data and just provide unique.  
I'm not sure what to look for specifically but I'll try to debug further.

Also, I'll be glad to write a ticket but it wasn't obvious to me if my 
problem was unique or a duplicate of the other mentions on the mailing list.

2006-02-21 19:59:59.245 reads allowed (131073 32768)
2006-02-21 19:59:59.312 AFD: positionMap[ 7147 ] == -1960239926.
2006-02-21 19:59:59.814 AFD: positionMap[ 7148 ] == -1959912314.
2006-02-21 19:59:59.890 reads allowed (131073 32768)
'video_output' mean = '33285.05', std. dev. = '6185.58', fps = '30.04'
2006-02-21 20:00:00.315 AFD: positionMap[ 7149 ] == -1959660478.
2006-02-21 20:00:00.811 AFD: positionMap[ 7150 ] == -1959281666.
2006-02-21 20:00:01.243 
LiveTVChain(live-localhost.localdomain-2006-02-21T18:59:50): 
ReloadAll(): Added new recording
2006-02-21 20:00:01.244 Resyncing position map. posmapStarted = 0 
livetv(1) watchingRec(0)
2006-02-21 20:00:01.311 AFD: positionMap[ 7151 ] == -1958855750.
2006-02-21 20:00:01.811 AFD: positionMap[ 7152 ] == -1958464650.
2006-02-21 20:00:02.080 reads allowed (131073 32768)
2006-02-21 20:00:02.238 reads allowed (131073 32768)
2006-02-21 20:00:02.274 reads allowed (131073 32768)
2006-02-21 20:00:02.351 AFD: positionMap[ 7153 ] == -1958126798.
2006-02-21 20:00:02.384 Position map filled from DB to: 7173
2006-02-21 20:00:02.409 SyncPositionMap watchingrecording, from DB: 7173 
entries2006-02-21 20:00:02.430 SyncPositionMap watchingrecording no 
entries from encoder, try DB
2006-02-21 20:00:03.392 Position map filled from DB to: 7186
2006-02-21 20:00:03.406 SyncPositionMap watchingrecording total: 7186 
entries
2006-02-21 20:00:03.460 SyncPositionMap, new totframes: 107790, new 
length: 3596, posMap size: 7186
'video_output' mean = '33464.48', std. dev. = '9854.05', fps = '29.88'
2006-02-21 20:00:05.396 
LiveTVChain(live-localhost.localdomain-2006-02-21T18:59:50): SwitchTo(1)
2006-02-21 20:00:05.397 
LiveTVChain(live-localhost.localdomain-2006-02-21T18:59:50): Entry at 1: 
'1011_20060221200000'
2006-02-21 20:00:05.401 NVP: IsReallyNearEnd() br(798KB) fps(29) 
sz(2287KB) vfl(12) frh(85) ne:0
2006-02-21 20:00:05.424 NVP: IsReallyNearEnd() br(798KB) fps(29) 
sz(2221KB) vfl(12) frh(83) ne:0
[snip repeats of this]
2006-02-21 20:00:05.969 NVP: IsReallyNearEnd() br(798KB) fps(29) 
sz(1894KB) vfl(12) frh(71) ne:0
2006-02-21 20:00:06.058 reads allowed (131073 32768)
2006-02-21 20:00:06.064 NVP: IsReallyNearEnd() br(798KB) fps(29) 
sz(229KB) vfl(10) frh(8) ne:0
[ snip repeats]
2006-02-21 20:00:06.533 NVP: IsReallyNearEnd() br(798KB) fps(29) 
sz(1565KB) vfl(12) frh(58) ne:0
2006-02-21 20:00:06.558 NVP: IsReallyNearEnd() br(798KB) fps(29) 
sz(1532KB) vfl(12) frh(57) ne:0
2006-02-21 20:00:06.656 
LiveTVChain(live-localhost.localdomain-2006-02-21T18:59:50): SwitchTo(1)
2006-02-21 20:00:06.657 
LiveTVChain(live-localhost.localdomain-2006-02-21T18:59:50): Entry at 1: 
'1011_20060221200000'
2006-02-21 20:00:06.662 reads allowed (131073 32768)
2006-02-21 20:00:06.668 NVP: IsReallyNearEnd() br(798KB) fps(29) 
sz(229KB) vfl(10) frh(8) ne:0
2006-02-21 20:00:06.682 NVP: IsReallyNearEnd() br(798KB) fps(29) 
sz(491KB) vfl(11) frh(18) ne:0
[snip repeats]
2006-02-21 20:00:06.843 NVP: IsReallyNearEnd() br(798KB) fps(29) 
sz(1401KB) vfl(13) frh(52) ne:0
'video_output' mean = '33391.51', std. dev. = '6452.18', fps = '29.95'
2006-02-21 20:00:07.108 
LiveTVChain(live-localhost.localdomain-2006-02-21T18:59:50): SwitchTo(1)
2006-02-21 20:00:07.109 
LiveTVChain(live-localhost.localdomain-2006-02-21T18:59:50): Entry at 1: 
'1011_20060221200000'
2006-02-21 20:00:07.114 reads allowed (131073 32768)
2006-02-21 20:00:07.121 NVP: IsReallyNearEnd() br(798KB) fps(29) 
sz(360KB) vfl(5) frh(13) ne:0
[snip repeats]
2006-02-21 20:00:07.228 NVP: IsReallyNearEnd() br(798KB) fps(29) 
sz(1179KB) vfl(9) frh(44) ne:0
2006-02-21 20:00:07.541 NVP: prebuffering pause
2006-02-21 20:00:07.541 NVP: Waiting for prebuffer.. 0 AAAAAAAAdAAALAAA
2006-02-21 20:00:07.568 
LiveTVChain(live-localhost.localdomain-2006-02-21T18:59:50): SwitchTo(1)
2006-02-21 20:00:07.569 
LiveTVChain(live-localhost.localdomain-2006-02-21T18:59:50): Entry at 1: 
'1011_20060221200000'
2006-02-21 20:00:07.574 reads allowed (131073 32768)
2006-02-21 20:00:07.583 NVP: IsReallyNearEnd() br(798KB) fps(29) 
sz(327KB) vfl(0) frh(12) ne:0
[snip repeats]
2006-02-21 20:00:08.015 NVP: IsReallyNearEnd() br(798KB) fps(29) 
sz(646KB) vfl(13) frh(24) ne:0
2006-02-21 20:00:08.021 
LiveTVChain(live-localhost.localdomain-2006-02-21T18:59:50): SwitchTo(1)
2006-02-21 20:00:08.021 
LiveTVChain(live-localhost.localdomain-2006-02-21T18:59:50): Entry at 1: 
'1011_20060221200000'
2006-02-21 20:00:08.029 NVP: IsReallyNearEnd() br(798KB) fps(29) 
sz(646KB) vfl(12) frh(24) ne:0
[snip repeats]
2006-02-21 20:00:08.677 NVP: IsReallyNearEnd() br(798KB) fps(29) 
sz(187KB) vfl(12) frh(7) ne:1
2006-02-21 20:00:08.677 SwitchToProgram(void)
2006-02-21 20:00:08.741 RingBuf(/mnt/store//1011_20060221190001.mpg): 
OpenFile(myth://127.0.0.1:6543/1011_20060221200000.mpg, 10)
2006-02-21 20:00:09.001 FileChangedCallback
2006-02-21 20:00:09.009 Resyncing position map. posmapStarted = 0 
livetv(1) watchingRec(1)
2006-02-21 20:00:09.014 Position map filled from DB to: 11
2006-02-21 20:00:09.014 SyncPositionMap watchingrecording, from DB: 11 
entries
2006-02-21 20:00:09.027 Filling position map from 12 to 13
2006-02-21 20:00:09.034 Position map filled from Encoder to: 13
2006-02-21 20:00:09.035 SyncPositionMap watchingrecording total: 13 entries
2006-02-21 20:00:09.035 SyncPositionMap, new totframes: 195, new length: 
6, posMap size: 13
2006-02-21 20:00:10.045 buffering (1 32768 0)
2006-02-21 20:00:10.088 NVP: prebuffering pause
2006-02-21 20:00:10.089 NVP: Waiting for prebuffer.. 0 AAAdLAAAAAAAAAAA
2006-02-21 20:00:10.237 NVP: Waiting for prebuffer.. 1 AAAdLAAAAAAAAAAA
2006-02-21 20:00:10.365 buffering (1 32768 0)
2006-02-21 20:00:10.387 NVP: Waiting for prebuffer.. 2 AAAdLAAAAAAAAAAA
2006-02-21 20:00:10.539 NVP: Waiting for prebuffer.. 3 AAAdLAAAAAAAAAAA
2006-02-21 20:00:10.685 buffering (1 32768 0)
2006-02-21 20:00:10.687 NVP: Waiting for prebuffer.. 4 AAAdLAAAAAAAAAAA
2006-02-21 20:00:10.705 RingBuf(/mnt/store//1011_20060221200000.mpg): 
Taking too long to be allowed to read..
2006-02-21 20:00:10.837 NVP: Waiting for prebuffer.. 5 AAAdLAAAAAAAAAAA
2006-02-21 20:00:10.987 NVP: Waiting for prebuffer.. 6 AAAdLAAAAAAAAAAA
2006-02-21 20:00:11.009 buffering (1 32768 0)
2006-02-21 20:00:11.136 NVP: Waiting for prebuffer.. 7 AAAdLAAAAAAAAAAA
2006-02-21 20:00:11.286 NVP: Waiting for prebuffer.. 8 AAAdLAAAAAAAAAAA
2006-02-21 20:00:11.330 buffering (1 32768 0)
2006-02-21 20:00:11.436 NVP: Waiting for prebuffer.. 9 AAAdLAAAAAAAAAAA
2006-02-21 20:00:11.577 NVP: Prebuffer wait timed out 10 times.
2006-02-21 20:00:11.586 NVP: Waiting for prebuffer.. 0 AAAdLAAAAAAAAAAA
2006-02-21 20:00:11.649 buffering (1 32768 0)
2006-02-21 20:00:11.709 RingBuf(/mnt/store//1011_20060221200000.mpg): 
Taking too long to be allowed to read..
2006-02-21 20:00:11.736 NVP: Waiting for prebuffer.. 1 AAAdLAAAAAAAAAAA
2006-02-21 20:00:11.886 NVP: Waiting for prebuffer.. 2 AAAdLAAAAAAAAAAA
2006-02-21 20:00:11.969 buffering (1 32768 0)
2006-02-21 20:00:12.036 NVP: Waiting for prebuffer.. 3 AAAdLAAAAAAAAAAA
2006-02-21 20:00:12.185 NVP: Waiting for prebuffer.. 4 AAAdLAAAAAAAAAAA
2006-02-21 20:00:12.289 buffering (1 32768 0)
2006-02-21 20:00:12.335 NVP: Waiting for prebuffer.. 5 AAAdLAAAAAAAAAAA
2006-02-21 20:00:12.485 NVP: Waiting for prebuffer.. 6 AAAdLAAAAAAAAAAA
2006-02-21 20:00:12.609 buffering (1 32768 0)
2006-02-21 20:00:12.635 NVP: Waiting for prebuffer.. 7 AAAdLAAAAAAAAAAA
2006-02-21 20:00:12.713 RingBuf(/mnt/store//1011_20060221200000.mpg): 
Taking too long to be allowed to read..
2006-02-21 20:00:12.715 restarting readhead thread..
2006-02-21 20:00:12.785 NVP: Waiting for prebuffer.. 8 AAAdLAAAAAAAAAAA
2006-02-21 20:00:12.925 buffering (1 32768 0)
[Thread -1272288352 (LWP 8295) exited]
2006-02-21 20:00:12.969 NVP: Waiting for prebuffer.. 9 AAAdLAAAAAAAAAAA
[New Thread -1272288352 (LWP 8569)]
2006-02-21 20:00:13.105 NVP: Prebuffer wait timed out 10 times.
[ snip repeats of NVP: waiting and Prebuffer wait timeout messages... ]
2006-02-21 20:00:22.126 NVP: Prebuffer wait timed out 10 times.
[New Thread -1272288352 (LWP 8574)]
2006-02-21 20:00:22.149 NVP: Waiting for prebuffer.. 0 AAAdLAAAAAAAAAAA
2006-02-21 20:00:22.153 RingBuf(/mnt/store//1011_20060221200000.mpg) 
Error: Took more than 10 seconds to be allowed to read, aborting.
2006-02-21 20:00:22.153 Ignoring livetv eof in decoder loop
2006-02-21 20:00:22.213 Ignoring livetv eof in decoder loop
2006-02-21 20:00:22.215 buffering (1 32768 0)
2006-02-21 20:00:22.216 buffering (1 32768 0)
2006-02-21 20:00:22.216 buffering (1 32768 0)
2006-02-21 20:00:22.219 buffering (1 32768 0)

The "buffering" messages repeat until I exit LiveTV.

Chris



More information about the mythtv-dev mailing list