[mythtv] Ticket #3690: Prebuffering pauses with ivtv sinceffmpeg resync

Michael Wisniewski wiz561 at gmail.com
Wed Aug 15 02:05:03 UTC 2007


Hi!  Thanks for your help in trying to diagnose this.  It seems like
it happens mostly when one show ends and the next begins.  For
example, tonight, I was just watching something a few minutes ago.
When 9:00 came, the box paused and kicked me out of live tv and says
"error was encountered while displaying video".   The log file for
this is posted below...

I also have the whole log file if you want it, but it's rather large
(1.5gig, 80 meg gzip'ed).  I'll be more than happy to share it if you
would like it; just let me know and I can post it on my web server.

Thanks again for your help,
Mike


----
/var/log/mythtv$ tail -n100 mythfrontend.log
2007-08-14 20:59:24.468 NVP: 16400 interlaced frames seen.
'video_output' mean = '33363.73', std. dev. = '16193.77', fps = '29.97'
'video_output' mean = '33362.34', std. dev. = '16095.19', fps = '29.97'
'video_output' mean = '33363.37', std. dev. = '16169.61', fps = '29.97'
'video_output' mean = '33360.97', std. dev. = '16215.01', fps = '29.98'
2007-08-14 20:59:37.814 NVP: 16800 interlaced frames seen.
'video_output' mean = '33400.39', std. dev. = '16114.99', fps = '29.94'
'video_output' mean = '33320.54', std. dev. = '16130.51', fps = '30.01'
'video_output' mean = '33363.12', std. dev. = '16178.63', fps = '29.97'
'video_output' mean = '33362.44', std. dev. = '16106.50', fps = '29.97'
2007-08-14 20:59:51.160 NVP: 17200 interlaced frames seen.
'video_output' mean = '33362.43', std. dev. = '16130.22', fps = '29.97'
'video_output' mean = '33361.35', std. dev. = '16047.03', fps = '29.97'
2007-08-14 20:59:57.916 Avg read interval was 192 msec. 320K block size
'video_output' mean = '33362.78', std. dev. = '16059.25', fps = '29.97'
'video_output' mean = '33373.41', std. dev. = '16158.14', fps = '29.96'
2007-08-14 21:00:04.506 NVP: 17600 interlaced frames seen.
'video_output' mean = '33352.88', std. dev. = '16283.28', fps = '29.98'
'video_output' mean = '33362.05', std. dev. = '16063.19', fps = '29.97'
'video_output' mean = '33364.07', std. dev. = '16207.90', fps = '29.97'
'video_output' mean = '33360.91', std. dev. = '16043.36', fps = '29.98'
2007-08-14 21:00:17.830 LiveTVChain(live-chorizo-2007-08-14T20:50:11):
ReloadAll(): Added new recording
2007-08-14 21:00:17.830 Resyncing position map. posmapStarted = 0
livetv(1) watchingRec(0)
2007-08-14 21:00:17.852 NVP: 18000 interlaced frames seen.
'video_output' mean = '33362.57', std. dev. = '16449.92', fps = '29.97'
2007-08-14 21:00:18.366 LiveTVChain(live-chorizo-2007-08-14T20:50:11):
SwitchTo(1)
2007-08-14 21:00:18.366 LiveTVChain(live-chorizo-2007-08-14T20:50:11):
Entry at 1: '2005_20070814210002'
2007-08-14 21:00:18.370 NVP: IsReallyNearEnd() br(798KB) fps(29)
sz(73KB) vfl(30) frh(2) ne:1
2007-08-14 21:00:18.370 SwitchToProgram(void)
2007-08-14 21:00:18.424 Position map filled from DB to: 1113
2007-08-14 21:00:18.424 SyncPositionMap watchingrecording, from DB: 1113 entries
2007-08-14 21:00:18.424 SyncPositionMap watchingrecording no entries
from encoder, try DB
2007-08-14 21:00:18.818 Position map filled from DB to: 1115
2007-08-14 21:00:18.818 SyncPositionMap watchingrecording total: 1115 entries
2007-08-14 21:00:19.104
RingBuf(/data/myth/live/2005_20070814205034.mpg):
OpenFile(/data/myth/live/2005_20070814210002.mpg, 10)
2007-08-14 21:00:19.320 NVP: prebuffering pause
2007-08-14 21:00:19.706 NVP: Waiting for prebuffer.. 0
AAAAAAAAAAAAAAAAALAAAAAAAuAAAAA
2007-08-14 21:00:19.853 NVP: Waiting for prebuffer.. 1
AAAAAAAAAAAAAAAAALAAAAAAAuAAAAA
2007-08-14 21:00:20.003 NVP: Waiting for prebuffer.. 2
AAAAAAAAAAAAAAAAALAAAAAAAuAAAAA
2007-08-14 21:00:20.153 NVP: Waiting for prebuffer.. 3
AAAAAAAAAAAAAAAAALAAAAAAAuAAAAA
2007-08-14 21:00:20.303 NVP: Waiting for prebuffer.. 4
AAAAAAAAAAAAAAAAALAAAAAAAuAAAAA
2007-08-14 21:00:20.454 NVP: Waiting for prebuffer.. 5
AAAAAAAAAAAAAAAAALAAAAAAAuAAAAA
2007-08-14 21:00:20.604 NVP: Waiting for prebuffer.. 6
AAAAAAAAAAAAAAAAALAAAAAAAuAAAAA
2007-08-14 21:00:20.754 NVP: Waiting for prebuffer.. 7
AAAAAAAAAAAAAAAAALAAAAAAAuAAAAA
2007-08-14 21:00:20.904 NVP: Waiting for prebuffer.. 8
AAAAAAAAAAAAAAAAALAAAAAAAuAAAAA
2007-08-14 21:00:21.054 NVP: Waiting for prebuffer.. 9
AAAAAAAAAAAAAAAAALAAAAAAAuAAAAA
2007-08-14 21:00:21.194 NVP: Prebuffer wait timed out 10 times.
2007-08-14 21:00:21.204 NVP: Waiting for prebuffer.. 0
AAAAAAAAAAAAAAAAALAAAAAAAuAAAAA
2007-08-14 21:00:21.354 NVP: Waiting for prebuffer.. 1
AAAAAAAAAAAAAAAAALAAAAAAAuAAAAA
2007-08-14 21:00:21.505 NVP: Waiting for prebuffer.. 2
AAAAAAAAAAAAAAAAALAAAAAAAuAAAAA
2007-08-14 21:00:21.655 NVP: Waiting for prebuffer.. 3
AAAAAAAAAAAAAAAAALAAAAAAAuAAAAA
2007-08-14 21:00:21.805 NVP: Waiting for prebuffer.. 4
AAAAAAAAAAAAAAAAALAAAAAAAuAAAAA
2007-08-14 21:00:21.955 NVP: Waiting for prebuffer.. 5
AAAAAAAAAAAAAAAAALAAAAAAAuAAAAA
2007-08-14 21:00:22.105 NVP: Waiting for prebuffer.. 6
AAAAAAAAAAAAAAAAALAAAAAAAuAAAAA
2007-08-14 21:00:22.270 NVP: Waiting for prebuffer.. 7
AAAAAAAAAAAAAAAAALAAAAAAAuAAAAA
2007-08-14 21:00:22.422 NVP: Waiting for prebuffer.. 8
AAAAAAAAAAAAAAAAALAAAAAAAuAAAAA
2007-08-14 21:00:22.572 NVP: Waiting for prebuffer.. 9
AAAAAAAAAAAAAAAAALAAAAAAAuAAAAA
2007-08-14 21:00:22.710 NVP: Prebuffer wait timed out 10 times.
2007-08-14 21:00:22.722 NVP: Waiting for prebuffer.. 0
AAAAAAAAAAAAAAAAALAAAAAAAuAAAAA
2007-08-14 21:00:22.872 NVP: Waiting for prebuffer.. 1
AAAAAAAAAAAAAAAAALAAAAAAAuAAAAA
2007-08-14 21:00:23.023 NVP: Waiting for prebuffer.. 2
AAAAAAAAAAAAAAAAALAAAAAAAuAAAAA
2007-08-14 21:00:23.173 NVP: Waiting for prebuffer.. 3
AAAAAAAAAAAAAAAAALAAAAAAAuAAAAA
2007-08-14 21:00:23.323 NVP: Waiting for prebuffer.. 4
AAAAAAAAAAAAAAAAALAAAAAAAuAAAAA
2007-08-14 21:00:23.473 NVP: Waiting for prebuffer.. 5
AAAAAAAAAAAAAAAAALAAAAAAAuAAAAA
2007-08-14 21:00:23.623 NVP: Waiting for prebuffer.. 6
AAAAAAAAAAAAAAAAALAAAAAAAuAAAAA
2007-08-14 21:00:23.773 NVP: Waiting for prebuffer.. 7
AAAAAAAAAAAAAAAAALAAAAAAAuAAAAA
2007-08-14 21:00:23.923 NVP: Waiting for prebuffer.. 8
AAAAAAAAAAAAAAAAALAAAAAAAuAAAAA
2007-08-14 21:00:24.074 NVP: Waiting for prebuffer.. 9
AAAAAAAAAAAAAAAAALAAAAAAAuAAAAA
2007-08-14 21:00:24.214 NVP: Prebuffer wait timed out 10 times.
2007-08-14 21:00:24.224 NVP: Waiting for prebuffer.. 0
AAAAAAAAAAAAAAAAALAAAAAAAuAAAAA
2007-08-14 21:00:24.374 NVP: Waiting for prebuffer.. 1
AAAAAAAAAAAAAAAAALAAAAAAAuAAAAA
2007-08-14 21:00:24.524 NVP: Waiting for prebuffer.. 2
AAAAAAAAAAAAAAAAALAAAAAAAuAAAAA
2007-08-14 21:00:24.674 NVP: Waiting for prebuffer.. 3
AAAAAAAAAAAAAAAAALAAAAAAAuAAAAA
2007-08-14 21:00:24.824 NVP: Waiting for prebuffer.. 4
AAAAAAAAAAAAAAAAALAAAAAAAuAAAAA
2007-08-14 21:00:24.974 NVP: Waiting for prebuffer.. 5
AAAAAAAAAAAAAAAAALAAAAAAAuAAAAA
2007-08-14 21:00:25.125 NVP: Waiting for prebuffer.. 6
AAAAAAAAAAAAAAAAALAAAAAAAuAAAAA
2007-08-14 21:00:25.210
RingBuf(/data/myth/live/2005_20070814210002.mpg): Invalid file (fd -1)
when opening '/data/myth/live/2005_20070814210002.mpg'.
2007-08-14 21:00:25.210
RingBuf(/data/myth/live/2005_20070814210002.mpg):
CalcReadAheadThresh(274877907 KB)
                         -> threshhold(64 KB) min read(0 KB) blk size(32 KB)
2007-08-14 21:00:25.210 NVP, Error: SwitchToProgram's OpenFile failed.
2007-08-14 21:00:25.210 NVP, Error: Unknown error, exiting decoder
2007-08-14 21:00:25.210 NVP: Exited decoder loop.
2007-08-14 21:00:25.214 TV: Attempting to change from WatchingLiveTV to None
2007-08-14 21:00:25.214 TV: StopStuff() -- begin
2007-08-14 21:00:25.214 TV: StopStuff(): stopping ring buffer[s]
2007-08-14 21:00:25.214 TV: StopStuff(): stopping player[s] (1/2)
2007-08-14 21:00:25.214 TV: StopStuff(): stopping recorder[s]
2007-08-14 21:00:25.275 VideoOutputXv: dtor
2007-08-14 21:00:25.275 VideoOutputXv: DiscardFrames(1)
2007-08-14 21:00:25.275 VideoBuffers::DiscardFrames(1):
AAAAAAAAAAAAAAAAALAAAAAAAuAAAAA
2007-08-14 21:00:25.275 VideoBuffers::DiscardFrames():
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA -- done()
2007-08-14 21:00:25.276 VideoBuffers::DiscardFrames(1):
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA -- done
2007-08-14 21:00:25.276 VideoOutputXv: DiscardFrames() 3:
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA -- done()
2007-08-14 21:00:25.276 VideoOutputXv: DiscardFrames(1)
2007-08-14 21:00:25.276 VideoBuffers::DiscardFrames(1):
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
2007-08-14 21:00:25.276 VideoBuffers::DiscardFrames():
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA -- done()
2007-08-14 21:00:25.276 VideoBuffers::DiscardFrames(1):
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA -- done
2007-08-14 21:00:25.276 VideoOutputXv: DiscardFrames() 3:
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA -- done()
2007-08-14 21:00:25.277 VideoOutputXv: Closing XVideo port 275
2007-08-14 21:00:30.100 TV: StopStuff(): stopping player[s] (2/2)

----


On 8/14/07, Anduin Withers <awithers at anduin.com> wrote:
> > Alright, I ran through the test and with 13655, it locked up twice.  I
> > have the log file with '-v playback', but I don't want to flood the
> > listserv with it.  Is there a suggested way I can upload this
> > somewhere?
>
> Does it not lock up with 13654? From your last log things seemed to go very
> bad on live TV switch, that isn't the #3690 bug. Can you reproduce your
> issue with recorded programs?
>
> You can feel free to put the log somewhere and post a link to it here and/or
> feel free to e-mail it to me privately.
>
> --
> Anduin Withers
>
> _______________________________________________
> mythtv-dev mailing list
> mythtv-dev at mythtv.org
> http://mythtv.org/cgi-bin/mailman/listinfo/mythtv-dev
>


More information about the mythtv-dev mailing list