[mythtv-commits] Ticket #2335: LiveTV hangs when a recording is finished and a new on starts (no channel change)

MythTV mythtv at cvs.mythtv.org
Tue Jul 24 06:23:44 UTC 2007


#2335: LiveTV hangs when a recording is finished and a new on starts (no channel
change)
-----------------------------------------+----------------------------------
 Reporter:  tino.keitel+mythtv at tikei.de  |        Owner:  ijr     
     Type:  defect                       |       Status:  reopened
 Priority:  minor                        |    Milestone:  unknown 
Component:  mythtv                       |      Version:  head    
 Severity:  medium                       |   Resolution:          
  Mlocked:  0                            |  
-----------------------------------------+----------------------------------

Comment(by anonymous):

 Replying to [comment:58 Shane Shrybman <gnome42 at gmail.com>]:
 > I found a problem that causes the wrong position map to be deleted. Try
 this patch (mythtv_move_ResetForNewFile.diff) and see if it helps.
 >
 > Shane

 Sadly no improvement with this patch using my ivtv source. From the
 backend log it appears the correct ringbuffer file is being requested -
 and the recordings directory certainly contains it (it grows in size until
 I back out of frozen Live TV).

 From the backend log around a program boundary (044000)followed by a
 freeze:

 {{{
 2007-07-24 04:40:00.209 TVRec(4): SwitchLiveTVRingBuffer(discont 0,
 set_rec 1)
 2007-07-24 04:40:00.214 TVRec(4): GetProgramRingBufferForLiveTV()
 2007-07-24 04:40:00.238 Scheduler: FindNextLiveTVDir: next dir is
 '/recordings'
 2007-07-24 04:40:00.373 ProgramInfo: StartedRecording: Recording to
 '/recordings/4021_20070724044000.mpg'
 2007-07-24 04:40:00.491 TVRec(4): StartedRecording(0xa178010)
 fn(/recordings/4021_20070724044000.mpg)
 2007-07-24 04:40:00.572 TVRec(4): FinishedRecording(Watercolours with
 Charles Evans) in recgroup: LiveTV
 2007-07-24 04:40:00.639 Chain: Updated endtime for '4021_20070724041655'
 to 20070724044000
 2007-07-24 04:40:00.662 Finished recording Watercolours with Charles
 Evans: channel 4021
 2007-07-24 04:40:00.683 scheduler: Finished recording: Watercolours with
 Charles Evans: channel 4021
 2007-07-24 04:40:00.685 SG(LiveTV): Unable to find storage group 'LiveTV',
 trying 'Default' group!
 2007-07-24 04:40:00.687 SG(Default): FindRecordingFile: Searching for
 '4021_20070724041655.mpg'
 2007-07-24 04:40:00.688 SG(Default): FindRecordingDir: Checking
 '/recordings'
 2007-07-24 04:40:00.688 SG(Default): FindRecordingFile: Found
 '/recordings/4021_20070724041655.mpg'
 2007-07-24 04:40:00.689 ProgramInfo: GetPlaybackURL: File is local:
 '/recordings/4021_20070724041655.mpg'
 2007-07-24 04:40:00.691 Preview:
 'myth://192.168.1.1:6543/4021_20070724041655.mpg' is not local,
                         replacing with
 '/recordings/4021_20070724041655.mpg', which is local.
 2007-07-24 04:40:00.732 Chain: Appended at 4 '4021_20070724044000'
 [mpeg @ 0x185520]2007-07-24 04:40:01.251 TVRec(4):
 SetFlags(RingBufferReady,) ->
 FrontendReady,RunMainLoop,CancelNextRecording,AskAllowRecor
 ding,RecorderRunning,RingBufferReady,
 2007-07-24 04:40:01.258 TVRec(4): !has_rec(1) !rec_soon(1)
 curRec(0x9f16698) starttm(2007-07-24T04:16:55)
 2007-07-24 04:40:01.262 TVRec(4): Enabling Full LiveTV UI.
 Parser not found for Codec Id: 94210 !
 0: start_time: -9223372036854.775 duration: -9223372036854.775
 1: start_time: -9223372036854.775 duration: -9223372036854.775
 2: start_time: -9223372036854.775 duration: -9223372036854.775
 stream: start_time: -9223372036854.775 duration: -9223372036854.775
 bitrate=6256 kb/s
 0: start_time: 57.467 duration: 125.154
 1: start_time: 3573.291 duration: 124.781
 2: start_time: 57.435 duration: 125.148
 stream: start_time: 638.172 duration: 40451.510 bitrate=173 kb/s
 2007-07-24 04:40:01.335 AFD: Opened codec 0xa25b4c0, id(MPEG2VIDEO)
 type(Video)
 2007-07-24 04:40:01.348 AFD: Opened codec 0x9fa0650, id(MP2) type(Audio)
 2007-07-24 04:40:01.682 RecBase(/dev/video0): SetRingBuffer(0x9f5cc40)
 '/recordings/4021_20070724044000.mpg'
 2007-07-24 04:40:01.686 TVRec(4): RingBufferChanged()
 2007-07-24 04:40:01.691 TVRec(4): FinishedRecording(Watercolours with
 Charles Evans) in recgroup: LiveTV
 2007-07-24 04:40:01.693 Chain: Updated endtime for '4021_20070724041655'
 to 20070724044001
 2007-07-24 04:40:01.729 Finished recording Watercolours with Charles
 Evans: channel 4021
 2007-07-24 04:47:45.732 StopLiveTV(void) curRec: 0x9f16698 pseudoRec: 0
 2007-07-24 04:47:45.746 TVRec(4): Changing from WatchingLiveTV to None
 2007-07-24 04:47:45.747 TVRec(4):
 ClearFlags(FrontendReady,CancelNextRecording,) ->
 RunMainLoop,AskAllowRecording,RecorderRunning,RingBuffer
 Ready,
 2007-07-24 04:47:45.748 TVRec(4): SetFlags(AskAllowRecording,) ->
 RunMainLoop,AskAllowRecording,RecorderRunning,RingBufferReady,
 2007-07-24 04:47:45.748 TVRec(4): Request: Program(no) channel() input()
 flags(KillRec,KillRingBuffer,)
 2007-07-24 04:47:45.788 TVRec(4): ClearFlags(RecorderRunning,) ->
 RunMainLoop,AskAllowRecording,RingBufferReady,
 2007-07-24 04:47:45.821 TVRec(4): FinishedRecording(The Joy of Painting)
 in recgroup: LiveTV
 2007-07-24 04:47:45.822 Chain: Updated endtime for '4021_20070724044000'
 to 20070724044745
 2007-07-24 04:47:45.845 Finished recording The Joy of Painting "A Perfect
 Winter Day": channel 4021
 2007-07-24 04:47:45.851 scheduler: Last message repeated 1 times: Finished
 recording: Watercolours with Charles Evans: channel 4021
 2007-07-24 04:47:45.854 scheduler: Finished recording: The Joy of Painting
 "A Perfect Winter Day": channel 4021
 2007-07-24 04:47:45.858 TVRec(4): ClearFlags(RecorderRunning,) ->
 RunMainLoop,AskAllowRecording,RingBufferReady,
 2007-07-24 04:47:45.860 TVRec(4): Tearing down RingBuffer
 2007-07-24 04:47:45.861 TVRec(4): ClearFlags(PENDINGACTIONS,) ->
 RunMainLoop,AskAllowRecording,RingBufferReady,
 }}}

 From the frontend log


 {{{
 2007-07-24 04:40:00.239 read  <- 20 53
 BACKEND_MESSAGE[]:[]QUERY_NEXT_LIVETV_DIR 4[]:[]empty
 2007-07-24 04:40:00.240 MythEvent: QUERY_NEXT_LIVETV_DIR 4
 2007-07-24 04:40:00.508 read  <- 20 51
 BACKEND_MESSAGE[]:[]RECORDING_LIST_CHANGE[]:[]empty
 2007-07-24 04:40:00.510 MythEvent: RECORDING_LIST_CHANGE
 2007-07-24 04:40:00.630 NVP: 50400 interlaced frames seen.
 2007-07-24 04:40:00.647 read  <- 20 85
 BACKEND_MESSAGE[]:[]LIVETV_CHAIN UPDATE live-homer.home-2007-07-2...
 2007-07-24 04:40:00.647 MythEvent: LIVETV_CHAIN UPDATE live-
 homer.home-2007-07-24T04:06:06
 'video_output' mean = '39960.44', std. dev. = '3163.89', fps = '25.02'
 2007-07-24 04:40:00.805 read  <- 20 85
 BACKEND_MESSAGE[]:[]LIVETV_CHAIN UPDATE live-homer.home-2007-07-2...
 2007-07-24 04:40:00.805 MythEvent: LIVETV_CHAIN UPDATE live-
 homer.home-2007-07-24T04:06:06
 2007-07-24 04:40:00.863 LiveTVChain(live-homer.home-2007-07-24T04:06:06):
 ReloadAll(): Added new recording
 2007-07-24 04:40:00.863 Resyncing position map. posmapStarted = 0
 livetv(1) watchingRec(0)
 2007-07-24 04:40:01.111 Position map filled from DB to: 2888
 2007-07-24 04:40:01.112 SyncPositionMap watchingrecording, from DB: 2888
 entries
 2007-07-24 04:40:01.112 SyncPositionMap watchingrecording no entries from
 encoder, try DB
 2007-07-24 04:40:01.250 Position map filled from DB to: 2891
 2007-07-24 04:40:01.250 SyncPositionMap watchingrecording total: 2891
 entries
 2007-07-24 04:40:01.251 SyncPositionMap, new totframes: 34692, new length:
 1387, posMap size: 2891
 2007-07-24 04:40:01.263 read  <- 20 46
 BACKEND_MESSAGE[]:[]LIVETV_WATCH 4 0[]:[]empty
 2007-07-24 04:40:01.263 MythEvent: LIVETV_WATCH 4 0
 2007-07-24 04:40:01.695 read  <- 20 85
 BACKEND_MESSAGE[]:[]LIVETV_CHAIN UPDATE live-homer.home-2007-07-2...
 2007-07-24 04:40:01.695 MythEvent: LIVETV_CHAIN UPDATE live-
 homer.home-2007-07-24T04:06:06
 2007-07-24 04:40:02.085 LiveTVChain(live-homer.home-2007-07-24T04:06:06):
 SwitchTo(3)
 2007-07-24 04:40:02.085 LiveTVChain(live-homer.home-2007-07-24T04:06:06):
 Entry at 3: '4021_20070724044000'
 2007-07-24 04:40:02.089 NVP: IsReallyNearEnd() br(782KB) fps(24)
 sz(2602KB) vfl(30) frh(83) ne:0
 2007-07-24 04:40:02.105 NVP: IsReallyNearEnd() br(782KB) fps(24)
 sz(2602KB) vfl(30) frh(83) ne:0
 2007-07-24 04:40:02.117 NVP: IsReallyNearEnd() br(782KB) fps(24)
 sz(2569KB) vfl(30) frh(82) ne:0
 2007-07-24 04:40:02.133 NVP: IsReallyNearEnd() br(782KB) fps(24)
 sz(2569KB) vfl(30) frh(82) ne:0
 2007-07-24 04:40:02.162 NVP: IsReallyNearEnd() br(782KB) fps(24)
 sz(2536KB) vfl(30) frh(81) ne:0
 2007-07-24 04:40:02.177 NVP: IsReallyNearEnd() br(782KB) fps(24)
 sz(2536KB) vfl(30) frh(81) ne:0
 2007-07-24 04:40:02.200 NVP: IsReallyNearEnd() br(782KB) fps(24)
 sz(2536KB) vfl(30) frh(81) ne:0
 2007-07-24 04:40:02.213 NVP: IsReallyNearEnd() br(782KB) fps(24)
 sz(2536KB) vfl(30) frh(81) ne:0
 2007-07-24 04:40:02.229 NVP: IsReallyNearEnd() br(782KB) fps(24)
 sz(2536KB) vfl(30) frh(81) ne:0

 etc

 2007-07-24 04:40:05.505 NVP: IsReallyNearEnd() br(782KB) fps(24) sz(472KB)
 vfl(30) frh(15) ne:0
 2007-07-24 04:40:05.530 NVP: IsReallyNearEnd() br(782KB) fps(24) sz(472KB)
 vfl(30) frh(15) ne:0
 2007-07-24 04:40:05.551 NVP: IsReallyNearEnd() br(782KB) fps(24) sz(472KB)
 vfl(30) frh(15) ne:0
 2007-07-24 04:40:05.569 NVP: IsReallyNearEnd() br(782KB) fps(24) sz(439KB)
 vfl(30) frh(14) ne:1
 2007-07-24 04:40:05.569 SwitchToProgram(void)
 2007-07-24 04:40:05.574 write -> 18 33
 MESSAGE[]:[]RECORDING_LIST_CHANGE
 2007-07-24 04:40:05.574 read  <- 18 2       OK
 2007-07-24 04:40:05.575 read  <- 20 51
 BACKEND_MESSAGE[]:[]RECORDING_LIST_CHANGE[]:[]empty
 2007-07-24 04:40:05.575 MythEvent: RECORDING_LIST_CHANGE
 2007-07-24 04:40:05.577 write -> 18 33
 MESSAGE[]:[]RECORDING_LIST_CHANGE
 2007-07-24 04:40:05.582 read  <- 20 51
 BACKEND_MESSAGE[]:[]RECORDING_LIST_CHANGE[]:[]empty
 2007-07-24 04:40:05.582 MythEvent: RECORDING_LIST_CHANGE
 2007-07-24 04:40:05.578 read  <- 18 2       OK
 2007-07-24 04:40:05.586 SG(LiveTV): Unable to find storage group 'LiveTV',
 trying 'Default' group!
 2007-07-24 04:40:05.587 SG(Default): FindRecordingFile: Searching for
 '4021_20070724044000.mpg'
 2007-07-24 04:40:05.587 SG(Default): FindRecordingDir: Checking
 '/recordings'
 2007-07-24 04:40:05.587 SG(Default): FindRecordingFile: Found
 '/recordings/4021_20070724044000.mpg'
 2007-07-24 04:40:05.588 ProgramInfo: GetPlaybackURL: File is local:
 '/recordings/4021_20070724044000.mpg'
 2007-07-24 04:40:05.588 RingBuf(/recordings/4021_20070724041655.mpg):
 OpenFile(/recordings/4021_20070724044000.mpg, 10)
 2007-07-24 04:40:05.588 RingBuf(/recordings/4021_20070724044000.mpg):
 CalcReadAheadThresh(2967649640 KB)
                          -> threshhold(64 KB) min read(0 KB) blk size(32
 KB)
 2007-07-24 04:40:05.588 RingBuf(/recordings/4021_20070724044000.mpg):
 CalcReadAheadThresh(117570023 KB)
                          -> threshhold(64 KB) min read(0 KB) blk size(32
 KB)
 2007-07-24 04:40:05.649 Avg read interval was 184 msec. 64K block size
 2007-07-24 04:40:05.665 Avg read interval was 197 msec. 96K block size
 2007-07-24 04:40:05.684 Avg read interval was 197 msec. 128K block size
 2007-07-24 04:40:05.701 Avg read interval was 197 msec. 160K block size
 2007-07-24 04:40:05.913 Avg read interval was 195 msec. 192K block size
 2007-07-24 04:40:06.333 FileChangedCallback
 2007-07-24 04:40:06.382 Resyncing position map. posmapStarted = 0
 livetv(1) watchingRec(1)
 2007-07-24 04:40:06.383 Position map filled from DB to: 1
 2007-07-24 04:40:06.383 SyncPositionMap watchingrecording, from DB: 1
 entries
 2007-07-24 04:40:06.383 write -> 21 39      QUERY_RECORDER
 4[]:[]GET_FRAMES_WRITTEN
 2007-07-24 04:40:06.384 read  <- 21 8       0[]:[]96
 2007-07-24 04:40:06.384 Filling position map from 2 to 8
 2007-07-24 04:40:06.384 write -> 21 50      QUERY_RECORDER
 4[]:[]FILL_POSITION_MAP[]:[]2[]:[]8
 2007-07-24 04:40:06.385 read  <- 21 203
 0[]:[]2[]:[]0[]:[]602220[]:[]0[]:[]3[]:[]0[]:[]808208[]:[]0[]:[]4...
 2007-07-24 04:40:06.385 Position map filled from Encoder to: 8
 2007-07-24 04:40:06.385 SyncPositionMap watchingrecording total: 8 entries
 2007-07-24 04:40:06.385 SyncPositionMap, new totframes: 96, new length: 3,
 posMap size: 8
 2007-07-24 04:40:07.812 NVP: prebuffering pause
 2007-07-24 04:40:07.812 NVP: Waiting for prebuffer.. 0
 AAAAuAAAAAAAAAAAAaAALAAAAAAAAAA
 2007-07-24 04:40:07.812 WriteAudio: buffer underrun
 2007-07-24 04:40:07.991 NVP: Waiting for prebuffer.. 1
 AAAAuAAAAAAAAAAAAaAALAAAAAAAAAA
 2007-07-24 04:40:08.153 NVP: Waiting for prebuffer.. 2
 AAAAuAAAAAAAAAAAAaAALAAAAAAAAAA
 2007-07-24 04:40:08.336 NVP: Waiting for prebuffer.. 3
 AAAAuAAAAAAAAAAAAaAALAAAAAAAAAA
 2007-07-24 04:40:08.342 RingBuf(/recordings/4021_20070724044000.mpg):
 Waited 1.0 seconds for data to become available...
 2007-07-24 04:40:08.342 Checking to see if there's a new livetv program to
 switch to..
 2007-07-24 04:40:08.498 NVP: Waiting for prebuffer.. 4
 AAAAuAAAAAAAAAAAAaAALAAAAAAAAAA
 2007-07-24 04:40:08.681 NVP: Waiting for prebuffer.. 5
 AAAAuAAAAAAAAAAAAaAALAAAAAAAAAA
 2007-07-24 04:40:08.863 NVP: Waiting for prebuffer.. 6
 AAAAuAAAAAAAAAAAAaAALAAAAAAAAAA
 2007-07-24 04:40:09.026 NVP: Waiting for prebuffer.. 7
 AAAAuAAAAAAAAAAAAaAALAAAAAAAAAA
 2007-07-24 04:40:09.208 NVP: Waiting for prebuffer.. 8
 AAAAuAAAAAAAAAAAAaAALAAAAAAAAAA
 2007-07-24 04:40:09.365 RingBuf(/recordings/4021_20070724044000.mpg):
 Waited 2.0 seconds for data to become available...
 2007-07-24 04:40:09.365 Checking to see if there's a new livetv program to
 switch to..
 2007-07-24 04:40:09.370 NVP: Waiting for prebuffer.. 9
 AAAAuAAAAAAAAAAAAaAALAAAAAAAAAA
 2007-07-24 04:40:09.533 NVP: Prebuffer wait timed out 10 times.
 2007-07-24 04:40:09.533 NVP: Waiting for prebuffer.. 0
 AAAAuAAAAAAAAAAAAaAALAAAAAAAAAA
 2007-07-24 04:40:09.715 NVP: Waiting for prebuffer.. 1
 AAAAuAAAAAAAAAAAAaAALAAAAAAAAAA
 2007-07-24 04:40:09.878 NVP: Waiting for prebuffer.. 2
 AAAAuAAAAAAAAAAAAaAALAAAAAAAAAA
 2007-07-24 04:40:10.063 NVP: Waiting for prebuffer.. 3
 AAAAuAAAAAAAAAAAAaAALAAAAAAAAAA
 2007-07-24 04:40:10.243 NVP: Waiting for prebuffer.. 4
 AAAAuAAAAAAAAAAAAaAALAAAAAAAAAA
 2007-07-24 04:40:10.405 NVP: Waiting for prebuffer.. 5
 AAAAuAAAAAAAAAAAAaAALAAAAAAAAAA
 2007-07-24 04:40:10.588 NVP: Waiting for prebuffer.. 6
 AAAAuAAAAAAAAAAAAaAALAAAAAAAAAA
 2007-07-24 04:40:10.750 NVP: Waiting for prebuffer.. 7
 AAAAuAAAAAAAAAAAAaAALAAAAAAAAAA
 2007-07-24 04:40:10.933 NVP: Waiting for prebuffer.. 8
 AAAAuAAAAAAAAAAAAaAALAAAAAAAAAA
 2007-07-24 04:40:11.115 NVP: Waiting for prebuffer.. 9
 AAAAuAAAAAAAAAAAAaAALAAAAAAAAAA
 2007-07-24 04:40:11.277 NVP: Prebuffer wait timed out 10 times.
 2007-07-24 04:40:11.278 NVP: Waiting for prebuffer.. 0
 AAAAuAAAAAAAAAAAAaAALAAAAAAAAAA
 2007-07-24 04:40:11.413 RingBuf(/recordings/4021_20070724044000.mpg):
 Waited 4.0 seconds for data to become available...
 2007-07-24 04:40:11.413 Checking to see if there's a new livetv program to
 switch to..
 }}}

 The file /recordings/4021_20070724044000.mpg was being recorded normally
 whilst the frontend was frozen.

 The frontend log then continued with the following as things timed out:

 {{{
 2007-07-24 04:40:21.748 NVP: Prebuffer wait timed out 10 times.
 2007-07-24 04:40:21.766 NVP: Waiting for prebuffer.. 0
 AAAAuAAAAAAAAAAAAaAALAAAAAAAAAA
 2007-07-24 04:40:21.929 NVP: Waiting for prebuffer.. 1
 AAAAuAAAAAAAAAAAAaAALAAAAAAAAAA
 2007-07-24 04:40:22.111 NVP: Waiting for prebuffer.. 2
 AAAAuAAAAAAAAAAAAaAALAAAAAAAAAA
 2007-07-24 04:40:22.274 NVP: Waiting for prebuffer.. 3
 AAAAuAAAAAAAAAAAAaAALAAAAAAAAAA
 2007-07-24 04:40:22.456 NVP: Waiting for prebuffer.. 4
 AAAAuAAAAAAAAAAAAaAALAAAAAAAAAA
 2007-07-24 04:40:22.639 NVP: Waiting for prebuffer.. 5
 AAAAuAAAAAAAAAAAAaAALAAAAAAAAAA
 2007-07-24 04:40:22.801 NVP: Waiting for prebuffer.. 6
 AAAAuAAAAAAAAAAAAaAALAAAAAAAAAA
 2007-07-24 04:40:22.984 NVP: Waiting for prebuffer.. 7
 AAAAuAAAAAAAAAAAAaAALAAAAAAAAAA
 2007-07-24 04:40:23.146 NVP: Waiting for prebuffer.. 8
 AAAAuAAAAAAAAAAAAaAALAAAAAAAAAA
 2007-07-24 04:40:23.308 NVP: Waiting for prebuffer.. 9
 AAAAuAAAAAAAAAAAAaAALAAAAAAAAAA
 2007-07-24 04:40:23.444 RingBuf(/recordings/4021_20070724044000.mpg)
 Error: Waited 16 seconds for data, aborting.
 [mpeg2video @ 0x5273a8]ac-tex damaged at 34 34
 [mpeg2video @ 0x5273a8]Warning MVs not available
 2007-07-24 04:40:23.462 Ignoring livetv eof in decoder loop
 2007-07-24 04:40:23.472 NVP: Prebuffer wait timed out 10 times.
 2007-07-24 04:40:23.491 NVP: Waiting for prebuffer.. 0
 AAALUAAAAAAAAAAAAAAAuAAAAAAAAAA
 2007-07-24 04:40:23.512 Avg read interval was 195 msec. 64K block size
 2007-07-24 04:40:23.512 Avg read interval was 196 msec. 96K block size
 2007-07-24 04:40:23.512 Avg read interval was 196 msec. 128K block size
 2007-07-24 04:40:23.513 Avg read interval was 196 msec. 160K block size
 2007-07-24 04:40:23.513 Avg read interval was 196 msec. 192K block size
 2007-07-24 04:40:23.513 Avg read interval was 196 msec. 224K block size
 }}}

 The "Ignoring livetv eof in decoder loop" looks ominous. The log was just
 filling up with this information repeated over and over. Looks like a nice
 quick way of filling a partition!

 Nick

-- 
Ticket URL: <http://svn.mythtv.org/trac/ticket/2335#comment:62>
MythTV <http://svn.mythtv.org/trac>
MythTV


More information about the mythtv-commits mailing list