Opened 14 years ago

Closed 14 years ago

#684 closed defect (fixed)

LiveTV: "Waited too long for ringbuffer pause" on program change

Reported by: Oscar Carlsson Owned by: Isaac Richards
Priority: major Milestone: 0.19
Component: mythtv Version: head
Severity: medium Keywords:
Cc: Ticket locked: no

Description

When viewing LiveTV and there's a program change (at 13:35), the frontend times out waiting for data.

Frontend:

2005-11-20 13:35:00.040 Resyncing position map. posmapStarted = 0 livetv(1) watchingRec(0)
2005-11-20 13:35:00.087 Position map filled from DB to: 191
2005-11-20 13:35:00.087 SyncPositionMap watchingrecording, from DB: 191 entries
2005-11-20 13:35:00.088 SyncPositionMap watchingrecording no entries from encoder, try DB
2005-11-20 13:35:00.108 Position map filled from DB to: 192
2005-11-20 13:35:00.109 SyncPositionMap watchingrecording total: 192 entries
2005-11-20 13:35:01.162 NVP: prebuffering pause
2005-11-20 13:35:01.162 waiting for prebuffer... 0
2005-11-20 13:35:01.325 waiting for prebuffer... 1
2005-11-20 13:35:01.488 waiting for prebuffer... 2
2005-11-20 13:35:01.651 waiting for prebuffer... 3
2005-11-20 13:35:01.814 waiting for prebuffer... 4
2005-11-20 13:35:01.976 waiting for prebuffer... 5
2005-11-20 13:35:02.139 waiting for prebuffer... 6
2005-11-20 13:35:02.302 waiting for prebuffer... 7
2005-11-20 13:35:02.465 waiting for prebuffer... 8
2005-11-20 13:35:02.628 waiting for prebuffer... 9
2005-11-20 13:35:02.792 waiting for prebuffer... 10
2005-11-20 13:35:02.954 Prebuffer wait timed out 10 times.
2005-11-20 13:35:02.954 waiting for prebuffer... 0
2005-11-20 13:35:03.117 waiting for prebuffer... 1
2005-11-20 13:35:03.280 waiting for prebuffer... 2
2005-11-20 13:35:03.443 waiting for prebuffer... 3
2005-11-20 13:35:03.606 waiting for prebuffer... 4
2005-11-20 13:35:03.689 LiveTVChain::SwitchToNext(up)
2005-11-20 13:35:03.689 LiveTVChain::SwitchTo(1)
2005-11-20 13:35:03.690 LiveTVChain: Entry@1: '6_20051120133500'
2005-11-20 13:35:03.769 waiting for prebuffer... 5
2005-11-20 13:35:03.932 waiting for prebuffer... 6
2005-11-20 13:35:04.095 waiting for prebuffer... 7
2005-11-20 13:35:04.258 waiting for prebuffer... 8
2005-11-20 13:35:04.421 waiting for prebuffer... 9
2005-11-20 13:35:04.523 RingBuf(myth://192.168.1.20:6543/6_20051120133328.mpg): Waited 4 seconds for data to become available, waiting again...
2005-11-20 13:35:04.584 waiting for prebuffer... 10
2005-11-20 13:35:04.747 Prebuffer wait timed out 10 times.

This is repeated a couple of times, then theres this:

2005-11-20 13:35:32.543 RingBuf(myth://192.168.1.20:6543/6_20051120133328.mpg): Waited 14 seconds for data to become available, aborting
2005-11-20 13:35:32.628 waiting for prebuffer... 6
2005-11-20 13:35:32.791 waiting for prebuffer... 7
2005-11-20 13:35:32.954 waiting for prebuffer... 8
2005-11-20 13:35:33.117 waiting for prebuffer... 9
2005-11-20 13:35:33.280 waiting for prebuffer... 10
2005-11-20 13:35:33.443 Prebuffer wait timed out 10 times.
2005-11-20 13:35:33.443 waiting for prebuffer... 0
2005-11-20 13:35:33.580 RingBuf(myth://192.168.1.20:6543/6_20051120133328.mpg): Waited too long for ringbuffer pause..
2005-11-20 13:35:33.606 waiting for prebuffer... 1
2005-11-20 13:35:33.769 waiting for prebuffer... 2
2005-11-20 13:35:33.932 waiting for prebuffer... 3
2005-11-20 13:35:34.094 waiting for prebuffer... 4
2005-11-20 13:35:34.257 waiting for prebuffer... 5
2005-11-20 13:35:34.420 waiting for prebuffer... 6
2005-11-20 13:35:34.583 waiting for prebuffer... 7
2005-11-20 13:35:34.585 RingBuf(myth://192.168.1.20:6543/6_20051120133328.mpg): Waited too long for ringbuffer pause..
2005-11-20 13:35:34.747 waiting for prebuffer... 8
2005-11-20 13:35:34.909 waiting for prebuffer... 9
2005-11-20 13:35:35.072 waiting for prebuffer... 10
2005-11-20 13:35:35.235 Prebuffer wait timed out 10 times.
2005-11-20 13:35:35.236 waiting for prebuffer... 0
2005-11-20 13:35:35.398 waiting for prebuffer... 1
2005-11-20 13:35:35.561 waiting for prebuffer... 2
2005-11-20 13:35:35.588 RingBuf(myth://192.168.1.20:6543/6_20051120133328.mpg): Waited too long for ringbuffer pause..
2005-11-20 13:35:35.719 RingBuf(myth://192.168.1.20:6543/6_20051120133328.mpg): OpenFile(myth://192.168.1.20:6543/6_20051120133500.mpg, 4)
2005-11-20 13:35:35.725 waiting for prebuffer... 3
[mpeg2video @ 0xb76f4270]00 motion_type at 9 6
[mpeg2video @ 0xb76f4270]Warning MVs not available
2005-11-20 13:35:35.888 VideoOutputXv: dtor
2005-11-20 13:35:35.888 VideoBuffers::DiscardFrames(): AAAAAAAAAAAAAAAAAAAUUULAAAAAAAA
2005-11-20 13:35:35.889 VideoBuffers::DiscardFrames(): AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA -- done()

The backend at the same time:

2005-11-20 13:35:00.672 TVRec(2): SwitchLiveTVRingBuffer(discont 0)
2005-11-20 13:35:00.672 TVRec(2): GetProgramRingBufferForLiveTV()
2005-11-20 13:35:00.834 TVRec(2): StartedRecording(0x818ff90) fn(/var/video/6_20051120133500.mpg)
[New Thread -1343415376 (LWP 24109)]
[New Thread -1390425168 (LWP 24110)]
[New Thread -1351808080 (LWP 24111)]
2005-11-20 13:35:00.874 Chain: Appended@2 '6_20051120133500'
2005-11-20 13:35:00.875 TVRec(2): SetFlags(RingBufferReset,) -> FrontendReady,RunMainLoop,AskAllowRecording,RecorderRunning,RingBufferReset,
2005-11-20 13:35:00.905 PreviewGen, Error: Run() file not local: 'myth://192.168.1.20:6543/6_20051120133328.mpg'
[Thread -1351808080 (LWP 24111) exited]
2005-11-20 13:35:00.986 RecBase(/dev/video1): SetRingBuffer(0x81947e0)
2005-11-20 13:35:00.987 TVRec(2): RingBufferChanged()
[Thread -1382032464 (LWP 24098) exited]
[Thread -1373639760 (LWP 24097) exited]
2005-11-20 13:35:01.026 Finished recording Lyckochansen: channel 6
2005-11-20 13:35:01.034 scheduler: Last message repeated 1 times
2005-11-20 13:35:01.047 scheduler: Finished recording
2005-11-20 13:35:36.614 MainServer::HandleAnnounce Playback
2005-11-20 13:35:36.614 adding: laban as a client (events: 0)
2005-11-20 13:35:36.622 MainServer::HandleAnnounce FileTransfer
2005-11-20 13:35:36.622 adding: laban as a remote file transfer
2005-11-20 13:35:36.630 Local file path: /var/video/6_20051120133500.mpg
2005-11-20 13:35:36.630 RingBuf(/var/video/6_20051120133500.mpg): OpenFile(/var/video/6_20051120133500.mpg, 6)
2005-11-20 13:35:44.173 AutoExpire::UpdateDontExpireSet: Adding chanid 8 @ Sun Nov 20 12:30:01 2005 to DON'T Expire List
2005-11-20 13:35:44.173 AutoExpire::UpdateDontExpireSet: Adding chanid 6 @ Sun Nov 20 13:35:00 2005 to DON'T Expire List
2005-11-20 13:35:44.174 AutoExpire::UpdateDontExpireSet: Adding chanid 6 @ Sun Nov 20 13:35:00 2005 to DON'T Expire List
2005-11-20 13:36:44.193 AutoExpire::UpdateDontExpireSet: Adding chanid 8 @ Sun Nov 20 12:30:01 2005 to DON'T Expire List
2005-11-20 13:36:44.193 AutoExpire::UpdateDontExpireSet: Adding chanid 6 @ Sun Nov 20 13:35:00 2005 to DON'T Expire List
2005-11-20 13:36:44.194 AutoExpire::UpdateDontExpireSet: Adding chanid 6 @ Sun Nov 20 13:35:00 2005 to DON'T Expire List
2005-11-20 13:36:44.217 AutoExpire::FillDBOrdered: Adding chanid 6 @ Sun Nov 20 13:33:28 2005 to expire list
2005-11-20 13:36:44.218 AutoExpiring: Lyckochansen Sun Nov 20 12:50:00 2005 62 MBytes
2005-11-20 13:36:44.218 After unlink we will have 14034 MB free.
[New Thread -1373639760 (LWP 24112)]
2005-11-20 13:36:44.372 Reschedule requested for id 0.
2005-11-20 13:36:45.594 Scheduled 60 items in 1.2 = 0.00 match + 1.22 place
2005-11-20 13:36:45.670 scheduler: Scheduled items
2005-11-20 13:36:47.406 About to unlink/delete file: /var/video/6_20051120133328.mpg
2005-11-20 13:36:53.872 Reschedule requested for id 0.

Let me know if you need more info or can't reproduce it.

At revision 7943.

Change History (2)

comment:1 Changed 14 years ago by anonymous

Some additional backend log output from before the log above:

2005-11-20 13:34:25.127 Created data @0xab8c4008->0xab95be0a
2005-11-20 13:34:25.128 Image size. dispxoff 0, dispyoff: 0, dispwoff: 0, disphoff: 0
2005-11-20 13:34:25.128 Image size. imgx 22, imgy: 6, imgw: 677, imgh: 564
2005-11-20 13:34:25.201 AFD: DoFastForward(611, do flush)
2005-11-20 13:34:25.202 DecorderBase::DoFastForward(611, do flush)
2005-11-20 13:34:25.213 AFD: SeekReset(0, do flush)
2005-11-20 13:34:25.214 AFD: SeekReset() flushing
2005-11-20 13:34:25.217 VideoBuffers::DiscardFrames(): AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAL
2005-11-20 13:34:25.223 VideoBuffers::DiscardFrames(): AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA -- done()
2005-11-20 13:34:25.302 ~VideoOutputNull()
[Thread -1343415376 (LWP 24100) exited]
2005-11-20 13:34:44.111 AutoExpire::UpdateDontExpireSet: Adding chanid 8 @ Sun Nov 20 12:30:01 2005 to DON'T Expire List
2005-11-20 13:34:44.112 AutoExpire::UpdateDontExpireSet: Adding chanid 6 @ Sun Nov 20 13:33:28 2005 to DON'T Expire List
2005-11-20 13:34:44.112 AutoExpire::UpdateDontExpireSet: Adding chanid 6 @ Sun Nov 20 13:33:28 2005 to DON'T Expire List
2005-11-20 13:34:44.145 AutoExpire::FillDBOrdered: Adding chanid 8 @ Sun Nov 20 13:32:37 2005 to expire list
2005-11-20 13:34:44.146 AutoExpiring: Ride With Funkmaster Flex Sun Nov 20 13:30:00 2005 33 MBytes
2005-11-20 13:34:44.151 autoexpire: Expiring Program
2005-11-20 13:34:44.151 After unlink we will have 14053 MB free.
[New Thread -1343415376 (LWP 24108)]
2005-11-20 13:34:44.350 Reschedule requested for id 0.
2005-11-20 13:34:45.947 Scheduled 60 items in 1.6 = 0.00 match + 1.60 place
2005-11-20 13:34:45.966 scheduler: Scheduled items
2005-11-20 13:34:47.442 About to unlink/delete file: /var/video/8_20051120133237.mpg
2005-11-20 13:34:53.739 Reschedule requested for id 0.
[Thread -1343415376 (LWP 24108) exited]
2005-11-20 13:34:54.657 Scheduled 60 items in 0.9 = 0.00 match + 0.92 place
2005-11-20 13:35:00.672 TVRec(2): SwitchLiveTVRingBuffer(discont 0)
2005-11-20 13:35:00.672 TVRec(2): GetProgramRingBufferForLiveTV()
2005-11-20 13:35:00.834 TVRec(2): StartedRecording(0x818ff90) fn(/var/video/6_20051120133500.mpg)

comment:2 Changed 14 years ago by Isaac Richards

Resolution: fixed
Status: newclosed

(In [7958]) Fix some bugs that could cause live-tv to get stuck. Should fix #684.

Note: See TracTickets for help on using tickets.