Opened 14 years ago

Closed 14 years ago

#754 closed defect (fixed)

PVR-350: LiveTV freezes when show ends and new show begins.

Reported by: anonymous Owned by: danielk
Priority: minor Milestone: 0.19
Component: mythtv Version: head
Severity: medium Keywords:
Cc: Ticket locked: no

Description

Using svn version 8001 from after Live TV changes were made, LiveTV freezes when a show ends and a new one is about to begin. Frontend is still responsive. Exiting LiveTV and entering back in corrects the problem temporarily.

System Info:
Combined frontend/backend
Fedora Core3, kernel 2.6.11-1.27
PVR-350 ivtv driver version 0.3.7c
Pentium4 2.0Ghz, 512mb ram

Log Output from mythfrontend -v record,playback,channel,jobqueue

Using the PVR-350 decoder/TV-out
2005-12-04 11:23:15.696 TV: StartPlayer?(): took 949 ms to start player.
2005-12-04 11:23:15.696 TV: Changing from None to WatchingLiveTV
2005-12-04 11:23:15.712 NVP: ClearAfterSeek?()
2005-12-04 11:23:15.734 Realtime priority would require SUID as root.
2005-12-04 11:23:15.886 keyframedist changed to 15
2005-12-04 11:30:01.138 LiveTVChain::ReloadAll?()
2005-12-04 11:30:01.450 LiveTVChain::SwitchToNext?(up)
2005-12-04 11:30:01.451 LiveTVChain::SwitchTo?(1)
2005-12-04 11:30:01.451 LiveTVChain: Entry@1: '1252_20051204113000'
2005-12-04 11:30:01.503 RingBuf?(/video/recordings/1252_20051204112312.mpg): OpenFile?(myth://127.0.0.1:6543/1252_20051204113000.mpg, 4)
2005-12-04 11:30:01.519 Invalid file handle when opening /video/recordings/1252_20051204113000.mpg. 4 retries remaining. 2005-12-04 11:30:02.021 Resyncing position map. posmapStarted = 0 livetv(1) watchingRec(1)
2005-12-04 11:30:02.024 SyncPositionMap? watchingrecording, from DB: 0 entries
2005-12-04 11:30:02.030 PosMapFromEnc?: Warning, tried to fetch PositionMap? from Encoder but encoder returned framesWritten == 0
2005-12-04 11:30:02.032 SyncPositionMap? watchingrecording no entries from encoder, try DB
2005-12-04 11:30:02.033 Position map filled from DB to: 1
2005-12-04 11:30:02.033 SyncPositionMap? watchingrecording total: 1 entries
2005-12-04 11:30:02.033 SyncPositionMap?, new totframes: 15, new length: 0, posMap size: 1
2005-12-04 11:30:02.075 LiveTVChain::SwitchToNext?(up)
2005-12-04 11:30:02.076 LiveTVChain::SwitchToNext?(up)
2005-12-04 11:30:02.076 LiveTVChain::SwitchToNext?(up)
2005-12-04 11:30:02.076 LiveTVChain::SwitchToNext?(up)
2005-12-04 11:30:02.076 LiveTVChain::SwitchToNext?(up)
same output continues until LiveTv? is exited.

Backend Log from same period:

2005-12-04 11:23:10.800 TVRec(1): Changing from None to WatchingLiveTV 252
2005-12-04 11:23:11.933 ret_pid(5263) child(5263) status(0x0)
2005-12-04 11:23:11.936 External Tuning program exited with no error
2005-12-04 11:30:01.558 TVRec(1): RingBufferChanged?()
2005-12-04 11:30:01.855 Finished recording Maggie and the Ferocious Beast "Just a Little Off the Top; Little Pig Lost; The Cecil Bunions Detective Agency": channel 1252
0: start_time: 0.036 duration: 36.619
1: start_time: 0.030 duration: 36.590
stream: start_time: 0.334 duration: 406.940 bitrate=5211 kb/s
2005-12-04 11:30:01.947 AFD: Opened codec 0x8148920, id(MPEG2VIDEO) type(Video)
2005-12-04 11:30:02.058 AFD: Opened codec 0x8151d20, id(MP2) type(Audio)
2005-12-04 11:30:22.002 Reschedule requested for id 0.
2005-12-04 11:30:22.035 Reschedule requested for id 0.
2005-12-04 11:30:22.235 Scheduled 1 items in 0.2 = 0.05 match + 0.17 place
2005-12-04 11:33:00.413 TVRec(1): Changing from WatchingLiveTV to None
2005-12-04 11:33:00.706 Finished recording Oobi: channel 1252

Attachments (2)

mythbackend.debug.svn8482 (6.7 KB) - added by jasonmollman@… 14 years ago.
svn 8482 backend log
mythfrontend.debug.svn8482 (8.4 KB) - added by jasonmollman@… 14 years ago.
svn 8482 frontend log

Download all attachments as: .zip

Change History (33)

comment:1 Changed 14 years ago by anonymous

That svn version should be 8101, not 8001.

comment:2 Changed 14 years ago by anonymous

Dupe of #726?

comment:3 Changed 14 years ago by anonymous

It may be. I don't have any scheduled recordings though. This occurs with almost every program change.

comment:4 Changed 14 years ago by Isaac Richards

Does this only happen if you use the pvr-350's decoder?

comment:5 Changed 14 years ago by Adam Egger

This also always happens with DVB here. Details: Debian sid Kernel 2.6.14 DVB-t Germany / b2c2_flexcop_pci

I'll retest it with today's svn when I get back home.

comment:6 Changed 14 years ago by jasonmollman@…

I'm the original poster.

I've only used the 350's decoder. I'll also try with a newer svn.

comment:7 Changed 14 years ago by jasonmollman@…

Problem still occurs in svn 8187.

Mythfrontend log with -v all,nodatabase,noaudio

2005-12-08 11:30:01.584 LiveTVChain::ReloadAll?()
2005-12-08 11:30:01.760 LiveTVChain::SwitchToNext?(up)
2005-12-08 11:30:01.760 LiveTVChain::SwitchTo?(1)
2005-12-08 11:30:01.760 LiveTVChain: Entry@1: '1252_20051208113000'
2005-12-08 11:30:01.828 write -> 12 33 MESSAGE[]:[]RECORDING_LIST_CHANGE
2005-12-08 11:30:01.878 read <- 12 2 OK
2005-12-08 11:30:01.881 write -> 12 33 MESSAGE[]:[]RECORDING_LIST_CHANGE
2005-12-08 11:30:01.903 read <- 14 51 BACKEND_MESSAGE[]:[]RECORDING_LIST_CHANGE[]:[]empty
2005-12-08 11:30:01.909 read <- 12 2 OK
2005-12-08 11:30:01.921 read <- 14 51
BACKEND_MESSAGE[]:[]RECORDING_LIST_CHANGE[]:[]empty
2005-12-08 11:30:01.944 RingBuf?(/video/recordings/1252_20051208111111.mpg): OpenFile?(myth://127.0.0.1:6543/1252_20051208113000.mpg, 4)
2005-12-08 11:30:01.945 Resyncing position map. posmapStarted = 0 livetv(1) watchingRec(1)
2005-12-08 11:30:01.947 SyncPositionMap? watchingrecording, from DB: 0 entries
2005-12-08 11:30:01.947 write -> 15 39 QUERY_RECORDER 1[]:[]GET_FRAMES_WRITTEN
2005-12-08 11:30:01.987 read <- 15 7 0[]:[]0
2005-12-08 11:30:01.988 PosMapFromEnc?: Warning, tried to fetch PositionMap? from Encoder but encoder returned framesWritten == 0
2005-12-08 11:30:01.988 SyncPositionMap? watchingrecording no entries from encoder, try DB
2005-12-08 11:30:01.990 Position map filled from DB to: 1
2005-12-08 11:30:01.990 SyncPositionMap? watchingrecording total: 1 entries
2005-12-08 11:30:01.990 SyncPositionMap?, new totframes: 15, new length: 0, posMap size: 1
2005-12-08 11:30:02.048 LiveTVChain::SwitchToNext?(up)
2005-12-08 11:30:02.049 LiveTVChain::SwitchToNext?(up)
2005-12-08 11:30:02.049 LiveTVChain::SwitchToNext?(up)
2005-12-08 11:30:02.049 LiveTVChain::SwitchToNext?(up)
Output continues until LiveTV is exited.

Mythbackend log with -v all,nodatabase,noaudio

2005-12-08 11:30:00.602 TVRec(1): SwitchLiveTVRingBuffer(discont 0, set_rec 1)
2005-12-08 11:30:00.608 TVRec(1): GetProgramRingBufferForLiveTV()
2005-12-08 11:30:00.962 TVRec(1): StartedRecording?(0x8163fe0) fn(/video/recordings/1252_20051208113000.mpg)
2005-12-08 11:30:00.969 write -> 14 51 BACKEND_MESSAGE[]:[]RECORDING_LIST_CHANGE[]:[]empty
2005-12-08 11:30:01.082 Preview: 'myth://127.0.0.1:6543/1252_20051208111111.mpg' is not local,replacing with '/video/recordings/1252_20051208111111.mpg', which is local.
2005-12-08 11:30:01.109 Chain: Appended@1 '1252_20051208113000'
2005-12-08 11:30:01.114 write -> 14 87 BACKEND_MESSAGE[]:[]LIVETV_CHAIN UPDATE live-pvr.home.net-2005-12...
2005-12-08 11:30:01.110 RingBuf?(/video/recordings/1252_20051208111111.mpg): OpenFile?(/video/recordings/1252_20051208111111.mpg, 0)
2005-12-08 11:30:01.193 TVRec(1): SetFlags?(RingBufferReset?,) -> FrontendReady?,RunMainLoop?,AskAllowRecording?,RecorderRunning?,RingBufferRese? t,
2005-12-08 11:30:01.395 RecBase?(/dev/video0): SetRingBuffer?(0x8174d90) '/video/recordings/1252_20051208113000.mpg'
2005-12-08 11:30:01.400 TVRec(1): RingBufferChanged?()
2005-12-08 11:30:01.555 Chain: Updated endtime for '1252_20051208111111' to 20051208113001
2005-12-08 11:30:01.568 write -> 14 87 BACKEND_MESSAGE[]:[]LIVETV_CHAIN UPDATE live-pvr.home.net-2005-12...
2005-12-08 11:30:01.570 Finished recording Maggie and the Ferocious Beast "Ride 'Em Cowboy; Right Next Door; Hamilton's Sailboat": channel 1252
0: start_time: 0.036 duration: 101.528
1: start_time: 0.030 duration: 101.509
stream: start_time: 0.334 duration: 1128.160 bitrate=5197 kb/s
2005-12-08 11:30:01.628 AFD: Stream #0, has id 0x480 codec id MPEG2VIDEO, type Video at 0x0x8172300
2005-12-08 11:30:01.669 detectInterlace(Detect Scan, Detect Scan, 29.97, 480) ->Interlaced Scan
2005-12-08 11:30:01.672 Interlaced: Interlaced Scan video_height: 480 fps: 29.97
2005-12-08 11:30:01.675 AFD: Looking for decoder for MPEG2VIDEO
2005-12-08 11:30:01.677 AFD: Opened codec 0x81485f0, id(MPEG2VIDEO) type(Video)
2005-12-08 11:30:01.679 AFD: Stream #1, has id 0x448 codec id MP2, type Audio at 0x0x8149ba0
2005-12-08 11:30:01.681 AFD: Looking for decoder for MP2
2005-12-08 11:30:01.704 AFD: Opened codec 0x8149c60, id(MP2) type(Audio)
2005-12-08 11:30:01.706 RingBuf:CalcReadAheadThresh(6384 KB) -> threshhold(250 KB) readblocksize(125 KB)
2005-12-08 11:30:01.708 Resyncing position map. posmapStarted = 0 livetv(0) watchingRec(0)
2005-12-08 11:30:01.825 Position map filled from DB to: 2256
2005-12-08 11:30:01.833 SyncPositionMap? prerecorded, from DB: 2256 entries
2005-12-08 11:30:01.836 SyncPositionMap?, new totframes: 33840, new length: 1129, posMap size: 2256
Input #0, mpeg, from '/video/recordings/1252_20051208111111.mpg':
Duration: 00:18:48.1, start: 0.333856, bitrate: 5197 kb/s
Stream #0.0[0x1e0], 1/90000, 29.97 fps: Video: mpeg2video, yuv420p, 480x480, 1001/30000, 6000 kb/s
Stream #0.1[0x1c0], 1/90000: Audio: mp2, 48000 Hz, stereo, 384 kb/s
2005-12-08 11:30:01.835 read <- 13 33 MESSAGE[]:[]RECORDING_LIST_CHANGE
2005-12-08 11:30:01.875 write -> 13 2 OK
2005-12-08 11:30:01.873 AFD: Position map found
2005-12-08 11:30:01.886 AFD: Successfully opened decoder for file: "/video/recordings/1252_20051208111111.mpg". novideo(0)
2005-12-08 11:30:01.881 write -> 14 51 BACKEND_MESSAGE[]:[]RECORDING_LIST_CHANGE[]:[]empty
2005-12-08 11:30:01.897 read <- 13 33 MESSAGE[]:[]RECORDING_LIST_CHANGE
2005-12-08 11:30:01.906 write -> 13 2 OK
2005-12-08 11:30:01.906 VideoOutputNull?()
2005-12-08 11:30:01.911 write -> 14 51 BACKEND_MESSAGE[]:[]RECORDING_LIST_CHANGE[]:[]empty
2005-12-08 11:30:01.929 Image size. dispxoff 0, dispyoff: 0, dispwoff: 0, disphoff: 0
2005-12-08 11:30:01.931 Image size. imgx 0, imgy: 0, imgw: 480, imgh: 480 2005-12-08 11:30:01.935 Created data @0xb0ab7008->0xb0b0b60a
2005-12-08 11:30:01.938 Created data @0xb0a62008->0xb0ab660a
2005-12-08 11:30:01.941 Created data @0xb0a0d008->0xb0a6160a
2005-12-08 11:30:01.944 Created data @0xb09b8008->0xb0a0c60a
2005-12-08 11:30:01.951 Created data @0xb0963008->0xb09b760a
2005-12-08 11:30:01.954 Created data @0xb090e008->0xb096260a
2005-12-08 11:30:01.957 Created data @0xac953008->0xac9a760a
2005-12-08 11:30:01.965 Created data @0xac8fe008->0xac95260a
2005-12-08 11:30:01.969 Created data @0xac8a9008->0xac8fd60a
2005-12-08 11:30:01.972 Created data @0xac854008->0xac8a860a
2005-12-08 11:30:01.976 Created data @0xac7ff008->0xac85360a
2005-12-08 11:30:01.979 Created data @0xac7aa008->0xac7fe60a
2005-12-08 11:30:01.955 read <- 15 39 QUERY_RECORDER 1[]:[]GET_FRAMES_WRITTEN
2005-12-08 11:30:01.983 write -> 15 7 0[]:[]0
2005-12-08 11:30:01.982 Created data @0xac755008->0xac7a960a
2005-12-08 11:30:01.999 Created data @0xac700008->0xac75460a
2005-12-08 11:30:02.001 Created data @0xac6ab008->0xac6ff60a
2005-12-08 11:30:02.005 Created data @0xac656008->0xac6aa60a
2005-12-08 11:30:02.009 Created data @0xac601008->0xac65560a
2005-12-08 11:30:02.013 Created data @0xac5ac008->0xac60060a
2005-12-08 11:30:02.017 Created data @0xac557008->0xac5ab60a
2005-12-08 11:30:02.021 Created data @0xac502008->0xac55660a
2005-12-08 11:30:02.025 Created data @0xac4ad008->0xac50160a
2005-12-08 11:30:02.029 Created data @0xac458008->0xac4ac60a
2005-12-08 11:30:02.032 Created data @0xac403008->0xac45760a
2005-12-08 11:30:02.036 Created data @0xac3ae008->0xac40260a
2005-12-08 11:30:02.040 Created data @0xac359008->0xac3ad60a
2005-12-08 11:30:02.043 Created data @0xac304008->0xac35860a
2005-12-08 11:30:02.047 Created data @0xac2af008->0xac30360a
2005-12-08 11:30:02.081 Created data @0xac25a008->0xac2ae60a
2005-12-08 11:30:02.376 Created data @0xac205008->0xac25960a
2005-12-08 11:30:04.245 Created data @0xac1b0008->0xac20460a
2005-12-08 11:30:04.248 Created data @0xac15b008->0xac1af60a
2005-12-08 11:30:04.250 Created data @0xac106008->0xac15a60a
2005-12-08 11:30:04.253 Image size. dispxoff 0, dispyoff: 0, dispwoff: 0, disphoff: 0
2005-12-08 11:30:04.256 Image size. imgx 0, imgy: 0, imgw: 480, imgh: 480
2005-12-08 11:30:04.280 NVP: ClearAfterSeek?()
2005-12-08 11:30:04.282 NVP: SetCommBreakIter? @ framesPlayed = 0
2005-12-08 11:30:04.284 NVP: new commBreakIter = 3014772 @ frame 137446228083
2005-12-08 11:30:04.450 AFD: DoFastForward?(2516, do flush)
2005-12-08 11:30:04.476 DecorderBase::DoFastForward?(2516, do flush)
2005-12-08 11:30:04.479 AFD: SeekReset?(0, do flush)
2005-12-08 11:30:04.482 AFD: SeekReset?() flushing
2005-12-08 11:30:04.484 VideoBuffers::DiscardFrames?(): AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAL
2005-12-08 11:30:04.486 VideoBuffers::DiscardFrames?(): AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA -- done()
2005-12-08 11:30:04.488 NVP: ClearAfterSeek?()
2005-12-08 11:30:04.490 NVP: SetCommBreakIter? @ framesPlayed = 2506
2005-12-08 11:30:04.492 NVP: new commBreakIter = 3014772 @ frame 137446228083
2005-12-08 11:30:04.566 ~VideoOutputNull?()
2005-12-08 11:30:26.170 JobQueue? currently set at 1 job(s) max and to run new jobs from 00:00 to 23:59
2005-12-08 11:30:26.222 JobQueue::GetJobsInQueue?: findJobs search bitmask 4, found 2 total jobs
2005-12-08 11:30:26.225 JobQueue::GetJobsInQueue?: Ignore 'Flag Commercials' Job for 1031 @ 20051205212800 in Finished state.
2005-12-08 11:30:26.229 JobQueue::GetJobsInQueue?: Ignore 'Flag Commercials' Job for 1252 @ 20051207092000 in Finished state.
2005-12-08 11:30:35.996 AutoExpire?: Adding Programs to 'Do Not Expire' List

comment:8 Changed 14 years ago by Adam Egger

Current SVN (r8189) doesn't crash anymore. LiveTV just stops for 2-3 seconds when a new show begins on my AMD64-3000+. It's the first time I don't see any crashes on a "show change" in LiveTV. Is it the correct behavior or is it possible to shorten the break?

comment:9 Changed 14 years ago by Isaac Richards

Can you try without the pvr-350 decoder, please (pvr-350 in xv mode, or different display on the same machine, if possible)? As far as I'm aware, you're the first to try using one with the new live-tv code..

comment:10 Changed 14 years ago by jasonmollman@…

I'll try to put the 350 in XV mode tomorrow and report the results.

comment:11 Changed 14 years ago by jasonmollman@…

Using XV for playback does not appear to cause the freezes in LiveTV. I let LiveTv? run through about 4 show transitions on the same channel and didn't get any freezes. Putting the frontend back to using the 350's decoder resulted in a freeze on 1 show transition.

comment:12 Changed 14 years ago by Isaac Richards

Summary: LiveTV: SVN 8001 LiveTV freezes when show ends and new show begins.PVR-350: LiveTV freezes when show ends and new show begins.

comment:13 Changed 14 years ago by jasonmollman@…

Below is some more debug on this item from a newer svn, 8323 I believe. I don't know if it helps narrow down this issue any further.

Mythfrontend -v all,nodatabase,noaudio

2005-12-21 19:57:35.753 Image size. dispxoff 0, dispyoff: 0, dispwoff: 1, dispho ff: 1
2005-12-21 19:57:35.753 Image size. imgx 0, imgy: 0, imgw: 720, imgh: 480
2005-12-21 19:57:39.178 Image size. dispxoff 0, dispyoff: 0, dispwoff: 1, dispho ff: 1
2005-12-21 19:57:39.178 Image size. imgx 0, imgy: 0, imgw: 720, imgh: 480
2005-12-21 19:58:01.269 Image size. dispxoff 0, dispyoff: 0, dispwoff: 1, dispho ff: 1
2005-12-21 19:58:01.269 Image size. imgx 0, imgy: 0, imgw: 720, imgh: 480
2005-12-21 19:58:01.659 Image size. dispxoff 0, dispyoff: 0, dispwoff: 1, dispho ff: 1
2005-12-21 19:58:01.661 Image size. imgx 0, imgy: 0, imgw: 720, imgh: 480
2005-12-21 20:00:00.910 read <- 14 51 BACKEND_MESSAGE[]:[]RECORDING_LIST_C HANGE[]:[]empty
2005-12-21 20:00:01.235 read <- 14 87 BACKEND_MESSAGE[]:[]LIVETV_CHAIN UPD ATE live-pvr.home.net-2005-12...
2005-12-21 20:00:01.235 LiveTVChain::ReloadAll?()
2005-12-21 20:00:01.667 LiveTVChain::SwitchToNext?(up)
2005-12-21 20:00:01.667 LiveTVChain::SwitchTo?(1)
2005-12-21 20:00:01.667 LiveTVChain: Entry@1: '1002_20051221200000'
2005-12-21 20:00:01.683 write -> 12 33 MESSAGE[]:[]RECORDING_LIST_CHANGE
2005-12-21 20:00:01.929 read <- 12 2 OK
2005-12-21 20:00:01.932 write -> 12 33 MESSAGE[]:[]RECORDING_LIST_CHANGE
2005-12-21 20:00:02.021 read <- 14 87 BACKEND_MESSAGE[]:[]LIVETV_CHAIN UPD ATE live-pvr.home.net-2005-12...
2005-12-21 20:00:02.021 LiveTVChain::ReloadAll?()
2005-12-21 20:00:02.030 LiveTVChain::SwitchToNext?(up)
2005-12-21 20:00:02.030 LiveTVChain::SwitchTo?(1)
2005-12-21 20:00:02.030 LiveTVChain: Entry@1: '1002_20051221200000'
2005-12-21 20:00:02.041 read <- 14 51 BACKEND_MESSAGE[]:[]RECORDING_LIST_C HANGE[]:[]empty
2005-12-21 20:00:02.086 read <- 12 2 OK
2005-12-21 20:00:02.108 read <- 14 51 BACKEND_MESSAGE[]:[]RECORDING_LIST_C HANGE[]:[]empty
2005-12-21 20:00:02.145 RingBuf?(/video/recordings/1002_20051221195643.mpg): Open File(myth://127.0.0.1:6543/1002_20051221200000.mpg, 10)
2005-12-21 20:00:02.145 Resyncing position map. posmapStarted = 0 livetv(1) watc hingRec(1)
2005-12-21 20:00:02.148 Position map filled from DB to: 1
2005-12-21 20:00:02.148 SyncPositionMap? watchingrecording, from DB: 1 entries
2005-12-21 20:00:02.148 write -> 15 39 QUERY_RECORDER 1[]:[]GET_FRAMES_WRIT TEN
2005-12-21 20:00:02.309 read <- 15 7 0[]:[]0
2005-12-21 20:00:02.309 PosMapFromEnc?: Warning, tried to fetch PositionMap? from Encoder but encoder returned framesWritten == 0
2005-12-21 20:00:02.309 SyncPositionMap? watchingrecording no entries from encode r, try DB
2005-12-21 20:00:02.312 Position map filled from DB to: 1
2005-12-21 20:00:02.312 SyncPositionMap? watchingrecording total: 1 entries
2005-12-21 20:00:02.312 SyncPositionMap?, new totframes: 15, new length: 0, posMa p size: 1
2005-12-21 20:00:02.389 LiveTVChain::SwitchToNext?(up)
2005-12-21 20:00:02.390 LiveTVChain::SwitchToNext?(up)
2005-12-21 20:00:02.390 LiveTVChain::SwitchToNext?(up)

Mythbackend -v all,nodatabase,noaudio

2005-12-21 19:57:03.973 JobQueue? currently set at 1 job(s) max and to run new jobs from 00:00 to 23:59
2005-12-21 19:57:04.036 JobQueue::GetJobsInQueue?: findJobs search bitmask 4, found 0 total jobs
2005-12-21 19:57:13.881 AutoExpire?: Adding Programs to 'Do Not Expire' List
2005-12-21 19:57:13.896 1002 @ Wed Dec 21 19:56:43 2005 in use by player on pvr.home.net
2005-12-21 19:57:13.898 1002 @ Wed Dec 21 19:56:43 2005 in use by recorder on pvr.home.net
2005-12-21 19:58:04.042 JobQueue? currently set at 1 job(s) max and to run new jobs from 00:00 to 23:59
2005-12-21 19:58:04.098 JobQueue::GetJobsInQueue?: findJobs search bitmask 4, found 0 total jobs
2005-12-21 19:58:13. 941 AutoExpire?: Adding Programs to 'Do Not Expire' List
2005-12-21 19:58:13.945 1002 @ Wed Dec 21 19:56:43 2005 in use by player on pvr.home.net
2005-12-21 19:58:13.948 1002 @ Wed Dec 21 19:56:43 2005 in use by recorder on pvr.home.net
2005-12-21 19:58:13.951 AutoExpire?: ExpireLiveTV(10000)
2005-12-21 19:58:13.989 AutoExpire?: SendDeleteMessages?. Nothing to expire.
2005-12-21 19:59:04.103 JobQueue? currently set at 1 job(s) max and to run new jobs from 00:00 to 23:59
2005-12-21 19:59:04.183 JobQueue::GetJobsInQueue?: findJobs search bitmask 4, found 0 total jobs
2005-12-21 19:59:14.034 AutoExpire?: Adding Programs to 'Do Not Expire' List
2005-12-21 19:59:14.039 1002 @ Wed Dec 21 19:56:43 2005 in use by player on pvr.home.net
2005-12-21 19:59:14.041 1002 @ Wed Dec 21 19:56:43 2005 in use by recorder on pvr.home.net
2005-12-21 20:00:00.327 TVRec(1): SwitchLiveTVRingBuffer(discont 0, set_rec 1)
2005-12-21 20:00:00.348 TVRec(1): GetProgramRingBufferForLiveTV()
2005-12-21 20:00:00.868 TVRec(1): StartedRecording?(0x8134cb0) fn(/video/recordings/1002_20051221200000.mpg) 2005-12-21 20:00:00.876 write -> 14 51 BACKEND_MESSAGE[]:[]RECORDING_LIST_CHANGE[]:[]empty
2005-12-21 20:00:01.065 Preview: 'myth://127.0.0.1:6543/1002_20051221195643.mpg' is not local,replacing with '/video/recordings/1002_20051221195643.mpg', which is local.
2005-12-21 20:00:01.102 RingBuf?(/video/recordings/1002_20051221195643.mpg): OpenFile?(/video/recordings/1002_20051221195643.mpg, 0)
2005-12-21 20:00:01.107 Chain: Appended@1 '1002_20051221200000'
2005-12-21 20:00:01.154 write -> 14 87 BACKEND_MESSAGE[]:[]LIVETV_CHAIN UPDATE live-pvr.home.net-2005-12...
2005-12-21 20:00:01.245 TVRec(1): SetFlags?(RingBufferReset?,) -> FrontendReady?,RunMainLoop?,AskAllowRecordin? g,RecorderRunning?,RingBufferReset?,
2005-12-21 20:00:01.351 RecBase?(/dev/video0): SetRingBuffer?(0x8160690) '/video/recordings/1002_20051221200000.mpg'
2005-12-21 20:00:01.393 TVRec(1): RingBufferChanged?()
2005-12-21 20:00:01.681 Chain: Updated endtime for '1002_20051221195643' to 20051221200001
2005-12-21 20:00:01.699 Finished recording Wheel of Fortune "Tis the Season": channel 1002
2005-12-21 20:00:01.691 read <- 13 33 MESSAGE[]:[]RECORDING_LIST_CHANGE
2005-12-21 20:00:01.823 write -> 13 2 OK
2005-12-21 20:00:01.933 write -> 14 87 BACKEND_MESSAGE[]:[]LIVETV_CHAIN UPDATE live-pvr.home.net-2005-12...
2005-12-21 20:00:02.005 write -> 14 51 BACKEND_MESSAGE[]:[]RECORDING_LIST_CHANGE[]:[]empty
2005-12-21 20:00:02.041 read <- 13 33 MESSAGE[]:[]RECORDING_LIST_CHANGE
2005-12-21 20:00:02.059 write -> 13 2 OK
2005-12-21 20:00:02.087 write -> 14 51 BACKEND_MESSAGE[]:[]RECORDING_LIST_CHANGE[]:[]empty
0: start_time: 0.036 duration: 17.652
1: start_time: 0.030 duration: 17.623
stream: start_time: 0.334 duration: 196.196 bitrate=5245 kb/s
2005-12-21 20:00:02.156 read <- 15 39 QUERY_RECORDER 1[]:[]GET_FRAMES_WRITTEN
2005-12-21 20:00:02.129 AFD: Stream #0, has id 0x480 codec id MPEG2VIDEO, type Video at 0x0x8162490
2005-12-21 20:00:02.302 write -> 15 7 0[]:[]0
2005-12-21 20:00:02.306 detectInterlace(Detect Scan, Detect Scan, 29.97, 480) ->Interlaced Scan
2005-12-21 20:00:02.316 Interlaced: Interlaced Scan video_height: 480 fps: 29.97
2005-12-21 20:00:02.318 AFD: Looking for decoder for MPEG2VIDEO
2005-12-21 20:00:02.321 AFD: Opened codec 0x8147710, id(MPEG2VIDEO) type(Video)
2005-12-21 20:00:02.339 AFD: Stream #1, has id 0x448 codec id MP2, type Audio at 0x0x814bc60
2005-12-21 20:00:02.342 AFD: Looking for decoder for MP2
2005-12-21 20:00:02.374 AFD: Opened codec 0x8147c50, id(MP2) type(Audio)
2005-12-21 20:00:02.377 AFD: Audio Track #1 is A/V stream #1 and has 2 channels in the Unknown language(0).
2005-12-21 20:00:02.380 RingBuf:CalcReadAheadThresh(6384 KB) -> threshhold(250 KB) readblocksize(125 KB)
2005-12-21 20:00:02.383 AFD: Selected track 1: Unknown MP2 2ch (A/V Stream #1)
2005-12-21 20:00:02.386 AFD: Initializing audio parms from audio track #1
2005-12-21 20:00:02.389 AFD: Audio format changed
from id(NONE) -1Hz -1ch 0bps ; id(NONE) -1Hz -1ch 0bps
to id( MP2) 48000Hz 2ch 16bps ; id( MP2) 48000Hz 2ch 16bps
2005-12-21 20:00:02.424 Resyncing position map. posmapStarted = 0 livetv(0) watchingRec(0)
2005-12-21 20:00:04.202 JobQueue? currently set at 1 job(s) max and to run new jobs from 00:00 to 23:59
2005-12-21 20:00:04.433 Position map filled from DB to: 394
2005-12-21 20:00:04.447 JobQueue::GetJobsInQueue?: findJobs search bitmask 4, found 0 total jobs
2005-12-21 20:00:04.448 SyncPositionMap? prerecorded, from DB: 394 entries
2005-12-21 20:00:04.451 SyncPositionMap?, new totframes: 5910, new length: 197, posMap size: 394
Input #0, mpeg, from '/video/recordings/1002_20051221195643.mpg':
Duration: 00:03:16.1, start: 0.333856, bitrate: 5245 kb/s
Stream #0.0[0x1e0], 1/90000, 29.97 fps: Video: mpeg2video, yuv420p, 720x480, 1001/30000, 6000 kb/s
Stream #0.1[0x1c0], 1/90000: Audio: mp2, 48000 Hz, stereo, 384 kb/s
2005-12-21 20:00:04.534 AFD: Position map found
2005-12-21 20:00:04.536 AFD: Successfully opened decoder for file: "/video/recordings/1002_20051221195643.mpg". novideo(0)
2005-12-21 20:00:04.578 VideoOutputNull?()
2005-12-21 20:00:04.594 Image size. dispxoff 0, dispyoff: 0, dispwoff: 0, disphoff: 0
2005-12-21 20:00:04.596 Image size. imgx 0, imgy: 0, imgw: 720, imgh: 480
2005-12-21 20:00:04.599 Created data @0xabf20138->0xabf9ea3a
2005-12-21 20:00:04.622 Created data @0xac1149a0->0xac1932a2
2005-12-21 20:00:04.625 Created data @0xac273008->0xac2f190a
2005-12-21 20:00:04.630 Created data @0xac081008->0xac0ff90a
2005-12-21 20:00:04.633 Created data @0xac002008->0xac08090a
2005-12-21 20:00:04.638 Created data @0xabe81008->0xabeff90a
2005-12-21 20:00:04.642 Created data @0xabe02008->0xabe8090a
2005-12-21 20:00:04.646 Created data @0xabd83008->0xabe0190a
2005-12-21 20:00:04.650 Created data @0xabd04008->0xabd8290a
2005-12-21 20:00:04.654 Created data @0xabc85008->0xabd0390a
2005-12-21 20:00:04.658 Created data @0xabc06008->0xabc8490a
2005-12-21 20:00:04.683 Created data @0xabb87008->0xabc0590a
2005-12-21 20:00:04.687 Created data @0xabb08008->0xabb8690a
2005-12-21 20:00:04.691 Created data @0xaba89008->0xabb0790a
2005-12-21 20:00:04.695 Created data @0xaba0a008->0xaba8890a
2005-12-21 20:00:04.699 Created data @0xab98b008->0xaba0990a
2005-12-21 20:00:04.703 Created data @0xab90c008->0xab98a90a
2005-12-21 20:00:04.707 Created data @0xab88d008->0xab90b90a
2005-12-21 20:00:04.711 Created data @0xab80e008->0xab88c90a
2005-12-21 20:00:04.715 Created data @0xab78f008->0xab80d90a
2005-12-21 20:00:04.720 Created data @0xab710008->0xab78e90a
2005-12-21 20:00:04.745 Created data @0xab691008->0xab70f90a
2005-12-21 20:00:04.749 Created data @0xab612008->0xab69090a
2005-12-21 20:00:04.753 Created data @0xab593008->0xab61190a
2005-12-21 20:00:04.757 Created data @0xab514008->0xab59290a
2005-12-21 20:00:04.761 Created data @0xab495008->0xab51390a
2005-12-21 20:00:04.765 Created data @0xab416008->0xab49490a
2005-12-21 20:00:04.770 Created data @0xab397008->0xab41590a
2005-12-21 20:00:04.781 Created data @0xab318008->0xab39690a
2005-12-21 20:00:04.789 Created data @0xab299008->0xab31790a
2005-12-21 20:00:04.812 Created data @0xab21a008->0xab29890a
2005-12-21 20:00:04.818 Created data @0xab19b008->0xab21990a
2005-12-21 20:00:04.821 Image size. dispxoff 0, dispyoff: 0, dispwoff: 0, disphoff: 0
2005-12-21 20:00:04.824 Image size. imgx 0, imgy: 0, imgw: 720, imgh: 480
2005-12-21 20:00:04.840 NVP: ClearAfterSeek?()
2005-12-21 20:00:04.863 NVP: SetCommBreakIter? @ framesPlayed = 0
2005-12-21 20:00:04.865 NVP: new commBreakIter = 3014772 @ frame 7274611
2005-12-21 20:00:04.977 AFD: DoFastForward?(2516, do flush)
2005-12-21 20:00:04.998 DecorderBase::DoFastForward?(2516, do flush)
2005-12-21 20:00:05.070 AFD: SeekReset?(0, do flush)
2005-12-21 20:00:05.074 AFD: SeekReset?() flushing
2005-12-21 20:00:05.080 VideoBuffers::DiscardFrames?(): AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAL
2005-12-21 20:00:05.088 VideoBuffers::DiscardFrames?(): AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA -- done()
2005-12-21 20:00:05.095 NVP: ClearAfterSeek?()
2005-12-21 20:00:05.100 NVP: SetCommBreakIter? @ framesPlayed = 2506
2005-12-21 20:00:05.102 NVP: new commBreakIter = 3014772 @ frame 7274611
2005-12-21 20:00:05.294 ~VideoOutputNull?()
2005-12-21 20:00:14.074 AutoExpire?: Adding Programs to 'Do Not Expire' List
2005-12-21 20:00:14.095 1002 @ Wed Dec 21 20:00:00 2005 in use by player on pvr.home.net
2005-12-21 20:00:14.098 1002 @ Wed Dec 21 20:00:00 2005 in use by recorder on pvr.home.net
2005-12-21 20:00:14.100 AutoExpire?: ExpireLiveTV(10000)
2005-12-21 20:00:14.139 AutoExpire?: SendDeleteMessages?. Nothing to expire.
2005-12-21 20:00:14.144 AutoExpire?: ExpireLiveTV(10001)
2005-12-21 20:00:14.163 AutoExpire?: SendDeleteMessages?. Nothing to expire.
2005-12-21 20:00:14.219 read <- 15 32 QUERY_RECORDER 1[]:[]STOP_LIVETV
2005-12-21 20:00:14.235 AutoExpire?: Checking episode count for each recording profile using max episodes
2005-12-21 20:00:14.244 TVRec(1): Changing from WatchingLiveTV to None
2005-12-21 20:00:14.248 TVRec(1): ClearFlags?(FrontendReady?,CancelNextRecording?,) -> RunMainLoop?,AskAllowRecording?,RecorderRunning?,RingBufferReset?,
2005-12-21 20:00:14.251 TVRec(1): SetFlags?(AskAllowRecording?,) -> RunMainLoop?,AskAllowRecording?,RecorderRunning?,RingBufferReset?,
2005-12-21 20:00:14.254 TVRec(1): Request: Program(no) channel() input() flags(KillRec?,KillRingBuffer?,)
2005-12-21 20:00:14.439 TVRec(1): ClearFlags?(RecorderRunning?,) -> RunMainLoop?,AskAllowRecording?,RingBufferReset?,
2005-12-21 20:00:14.499 Chain: Updated endtime for '1002_20051221200000' to 20051221200014
2005-12-21 20:00:14.659 Finished recording George Lopez "A Clear and Presentless Danger": channel 1002
2005-12-21 20:00:14.665 TVRec(1): ClearFlags?(RecorderRunning?,) -> RunMainLoop?,AskAllowRecording?,RingBufferReset?,
2005-12-21 20:00:14.668 TVRec(1): Tearing down RingBuffer?
2005-12-21 20:00:14.692 TVRec(1): ClearFlags?(PENDINGACTIONS,) -> RunMainLoop?,AskAllowRecording?,RingBufferReset?,
2005-12-21 20:00:14.694 write -> 15 2 ok

comment:14 Changed 14 years ago by danielk

Milestone: 0.19
Owner: changed from Isaac Richards to danielk
Status: newassigned
Version: head

I will be checking this and avformatdecoder ringbuffer switching tomorrow.

comment:15 Changed 14 years ago by jasonmollman@…

I tested for this issue again in 8468. After just a brief 1-show-transition test, I was not able to reproduce this problem. I'll test further on 1/2/06.

comment:16 Changed 14 years ago by jasonmollman@…

Well, the good news is that the pvr-350 didn't freeze on show transitions anymore using svn 8468. The bad news is that after a couple of shows, the frontend got stuck in a loop playing the same show over and over again. Also, the frontend and the system became unresponsive requiring a cold restart.

comment:17 Changed 14 years ago by danielk

So the transition problem happens because the PVR-350 doesn't start playing until it's internal buffer has a good deal of data, but in LiveTV there simply isn't that much data in the file at the ringbuffer switch so the decoder hits the EOF and gives up.

I'm haven't looked at why the UI becomes unresponsive, but I've seen it a couple times.

comment:18 Changed 14 years ago by Mark de Jong <dejongm@…>

I experience the problem of Mythfrontend freezing between shows as well. Currently happens on both my pvr-250 and Divco Fusion5 Gold. Currently I'm running SVN 8474.

comment:19 Changed 14 years ago by anonymous

Mark, this is unrelated to any issues you may have with XVideo output. This ticket is for a PVR-350 only problem.

Jason, I've discovered a freeze culprit. OpenFile?() sometimes fails to find an IvtvDecoder? it can use so it returns an AvFormatDecoder? instead. If this happened at startup things would be ok, we'd just use the PVR-350's XVideo output support with VideoOutputXv?. But when this happens after we have a VideoOutputIVTV running it gets stuck as soon as the AvFormatDecoder? asks for a decoding buffer, because VideoOutputIVTV has none to spare...

I don't know if this is your freeze culprit, but if you attach the 'mythfrontend -v playback' log to the ticket, from an instance of this, I could check.

Please use the 'Attach File' button on this page, don't cut and paste fragments of the log into the ticket's text.

comment:20 Changed 14 years ago by danielk

(In [8478]) References #754.

This fixes three problems:

1/ If timestretch is enabled in LiveTV, Play(1.0f,...) gets called repeatedly. The change is to only call it when the play_speed is greater than one. This was preventing PVR-350 output from pausing the ringbuffer on ringbuffer switches.

2/ We didn't check if OpenFile?() failed in JumpToProgram?(), causing a SEGFAULT when it failed but we tried to use the non-existent decoder anyway.

3/ If we are already using VideoOutputIvtv? and IvtvDecoder? can't decode the ringbuffer presented to it in OpenFile?() then fail, don't try to use an AvFormatDecoder? which will doesn't work with VideoOutputIvtv?.

Also, this adds some documentation.

comment:21 Changed 14 years ago by danielk

Resolution: fixed
Status: assignedclosed

(In [8479]) Fixes #754.

This does not make smooth transitions ringbuffer transitions smooth, but it does prevent us from getting stuck in some infinte loops.

There are two major problems:

  • IvtvDecoder::GetFramesPlayed?() doesn't return a positive value until we have actually played some frames, and this doesn't happen until the ivtv decoding buffers has a lot of data in it. If the recording has just started this can be a problem as SeekReset? was attempting to fill this buffer entirely. In this commit we just try to put some data in the buffer, which avoids hitting the end-of-file.
  • IvtvDecoder::CanHandle?() tried to access the PVR-350 video output device when testing whether it can handle decoding a stream. This causes problems during the ringbuffer switch.. So I broke off the device testing into a CheckDevice?() function, which always returns true once the device has passed the tests once.

I also made VideoOutput::GetFramesPlayed?() virtual so that the Ivtv implementation would not be hidden then the object is treated as VideoOutput?* rather than a VideoOutputIvtv?*

Plus a few cosmetic changes in IvtvDecoder? and some more VERBOSE macros in videooutputIvtv.

Changed 14 years ago by jasonmollman@…

Attachment: mythbackend.debug.svn8482 added

svn 8482 backend log

Changed 14 years ago by jasonmollman@…

Attachment: mythfrontend.debug.svn8482 added

svn 8482 frontend log

comment:22 Changed 14 years ago by jasonmollman@…

Resolution: fixed
Status: closedreopened

Daniel,

I'm still getting transition freezes as of svn 8482. Attached are the front and backend logs using -v playback.

Jason

comment:23 Changed 14 years ago by jasonmollman@…

A quick follow up to my last comment. I've let this run for most of the day and I have only seen the transition freeze in the one instance mentioned above, so its pretty intermittent at this point.

comment:24 Changed 14 years ago by danielk

Jason, that doesn't look like a ringbuffer switch abort. I don't know what happened, but at first blush it doesn't appear to be the same problem. There are no reported timeouts, missing buffers, decoders, etc.

It almost looks as if playback was manually aborted on the frontend. Perhaps LIRC on the fritz?

comment:25 Changed 14 years ago by jasonmollman@…

It could have been. I'll let it go for another couple of days to evaluate further. Feel free to keep this closed and if it acts up again I'll post another comment.

comment:26 Changed 14 years ago by danielk

Resolution: fixed
Status: reopenedclosed

This appears to be fixed.

I did an 8 hour test with ringbuffer changes every 10 seconds. In one instance it took 34 seconds to do the switch, but it never completely failed to make the switch.

comment:27 Changed 14 years ago by jasonmollman@…

Daniel,

I agree. No problems since the single incident. I also changed my pvr-350's firmware back to the "recommended" firmware. The LIRC lockups and complete system freezes have stopped. I had also seen some single frame injection problems where a past frame was getting injected into current live tv playback. Reverting firmware fixed that too.

Great work. Thanks.

comment:28 Changed 14 years ago by jasonmollman@…

Of course I say that, then the system wont exit in live tv again. Oh well. Seperate issue.

comment:29 Changed 14 years ago by johan@…

Resolution: fixed
Status: closedreopened

I'm still experiencing freezes at the end of shows here on Australian DVB-T with the Happauge NOVA-T.

In previous SVNs (after LiveTV rewrite) it would freeze for some time at the end of shows (changing recording files?) and then continue stuttering into the next show.

Now it freezes for a number of seconds at the end of a show and continues fine into the next show.

I'm a little busy at the moment, but if you need logs let me know, just thought I'd mention I'm getting the same issue.

I'm reopening the ticket, please forgive me if this is unrelated.

comment:30 Changed 14 years ago by johan@…

Sorry forgot to mention I'm using SVN 8513.

comment:31 Changed 14 years ago by danielk

Resolution: fixed
Status: reopenedclosed

Johan, you need to open a seperate ticket for your problem with logs, this problem was very specific to PVR-350 decoding. You're probably using the AvFormatDecoder?, unless you have transcoded your recordings into a different format.

Note: See TracTickets for help on using tickets.