[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