LiveTV fails when frontend timesout before backend starts writing

[nooneimprt4nt@…]

As per Daniel's request, I'm opening a new ticket, pasting text from #804 When changing channels (DVB-S) during LiveTV it often takes more than 4 tries for the frontend to see the file the backend is creating (this may be due to having a 98% full EXT3 drive). When this happens, the frontend needs to be restarted to be functional again. As a temporary solution, I have changed the default retries in RingBuffer::OpenFile?() to 20, which works every time. I don't know whether this issue is DVB related or not.

2005-12-13 22:12:37.003 Invalid file handle when opening /var/lib/mythtv/1110_20051213221236.mpg.  4 retries remaining.
2005-12-13 22:12:37.505 Invalid file handle when opening /var/lib/mythtv/1110_20051213221236.mpg.  3 retries remaining.
2005-12-13 22:12:37.580 NVP: Prebuffer wait timed out 10 times.
2005-12-13 22:12:38.007 Invalid file handle when opening /var/lib/mythtv/1110_20051213221236.mpg.  2 retries remaining.
2005-12-13 22:12:38.400 NVP: Prebuffer wait timed out 10 times.
2005-12-13 22:12:38.512 Invalid file handle when opening /var/lib/mythtv/1110_20051213221236.mpg.  1 retries remaining.
2005-12-13 22:12:39.013 Invalid file handle when opening /var/lib/mythtv/1110_20051213221236.mpg.  0 retries remaining.
2005-12-13 22:12:39.224 NVP: Prebuffer wait timed out 10 times.
2005-12-13 22:12:39.518 RingBuf(/var/lib/mythtv/1110_20051213221236.mpg) Error: File I/O problem in 'safe_read()'
    eno: Bad file descriptor (9)
2005-12-13 22:12:39.580 RingBuf(/var/lib/mythtv/1110_20051213221236.mpg) Error: File I/O problem in 'safe_read()'
    eno: Bad file descriptor (9)
2005-12-13 22:12:39.642 RingBuf(/var/lib/mythtv/1110_20051213221236.mpg) Error: File I/O problem in 'safe_read()'
    eno: Bad file descriptor (9)
2005-12-13 22:12:39.644 RingBuf(/var/lib/mythtv/1110_20051213221236.mpg) Error: File I/O problem in 'safe_read()'
    eno: Bad file descriptor (9)
2005-12-13 22:12:39.706 RingBuf(/var/lib/mythtv/1110_20051213221236.mpg) Error: File I/O problem in 'safe_read()'
    eno: Bad file descriptor (9)
2005-12-13 22:12:39.768 RingBuf(/var/lib/mythtv/1110_20051213221236.mpg) Error: File I/O problem in 'safe_read()'
    eno: Bad file descriptor (9)
2005-12-13 22:12:40.044 NVP: Prebuffer wait timed out 10 times.
2005-12-13 22:12:40.864 NVP: Prebuffer wait timed out 10 times.
2005-12-13 22:12:41.685 NVP: Prebuffer wait timed out 10 times.
2005-12-13 22:12:42.507 NVP: Prebuffer wait timed out 10 times.
2005-12-13 22:12:43.327 NVP: Prebuffer wait timed out 10 times.
...

Daniel said:

nooneimprt4nt, I believe you are experiencing a different problem; we don't wait for the recorder to begin writing data before setting the ringbuffer ready flag, so if it takes longer than the timeout on the ringbuffer reads, things go badly. You should open a seperate ticket on that problem.

[danielk]

As nooneimprt4nt said, I think this is due to to us setting the ringbuffer ready flag right away after we create the ringbuffer, instead of waiting until there is a little bit of data. Since the DTV recorders (by default) wait until they see a keyframe before writing any data it can take up to 700 ms for them to start writing data after the ringbuffer reset, even with a fully within spec transmitter.

[danielk]

(In [8286]) Fixes #813.

• Delays the ringbuffer ready flag in one instance.
• Delays RingBuffer? switch if more than 256000 bytes remain in the RingBuffer?; even if there are less than three valid video frames.
• Increases RingBuffer? retries on RingBuffer? switches to approximately 5 seconds.

The RingBuffer? switch threshold of 256000 should really be keyed to the bitrate, but I'm not sure exactly what it should be. This is just double the value used then 3 valid video frames remain. This change is needed so we don't switch prematurely when using XvMC, or when playing back on a marginal system with XVideo (i.e. a 1080i stream on a debug build, running on a P4-2800).

[nooneimprt4nt@…]

This isn't fixed 100% for me. For instance, if I disable the hw_decoder on my card (so I can play with HD content), this same problem comes back:

2005-12-17 16:34:00.024 TV: Changing from None to WatchingLiveTV
2005-12-17 16:34:00.056 Realtime priority would require SUID as root.
2005-12-17 16:34:00.187 Video timing method: USleep with busy wait
[mpeg1video @ 0xb74f8270]ac-tex damaged at 34 0
[mpeg1video @ 0xb74f8270]Warning MVs not available
2005-12-17 16:34:00.459 Invalid file handle when opening /var/lib/mythtv/1111_20051217163358.mpg.  20 retries remaining.
2005-12-17 16:34:00.961 Invalid file handle when opening /var/lib/mythtv/1111_20051217163358.mpg.  19 retries remaining.
...
2005-12-17 16:34:09.996 Invalid file handle when opening /var/lib/mythtv/1111_20051217163358.mpg.  1 retries remaining.
2005-12-17 16:34:10.026 NVP: Prebuffer wait timed out 10 times.
2005-12-17 16:34:10.498 Invalid file handle when opening /var/lib/mythtv/1111_20051217163358.mpg.  0 retries remaining.
2005-12-17 16:34:10.846 NVP: Prebuffer wait timed out 10 times.
2005-12-17 16:34:11.001 RingBuf(/var/lib/mythtv/1111_20051217163358.mpg) Error: Invalid file descriptor in 'safe_read()'
2005-12-17 16:34:11.003 RingBuf(/var/lib/mythtv/1111_20051217163358.mpg) Error: Invalid file descriptor in 'safe_read()'

Note that I had the retry limit set to 20 here. If I set it to 40, I seem to get a lock every time.

[danielk]

nooneimprt4nt, can you attach a backend log with '-v record,channel,siparser' along with the frontend log with '-v playback' for this problem. I think there is something wrong with the recorder or signal monitor if it is taking this long to get video.

[nooneimprt4nt@…]

backend log

[nooneimprt4nt@…]

frontend

[nooneimprt4nt@…]

I included the frontend and bacckend logs. I had to edit them some as they were quite large, and it took several channel changes to trigger the issue (I shouldn't have removed anything you need to see though). Also, it is much more difficult to trigger while logging

[danielk]

Can you repeat with the latest svn? But, please don't edit the logs; it makes it harder for me to read them if I don't see things I'm expecting.

I just checked in a change that should prevent all that detailed descriptor information from being printed out, so the backend log should be much smaller now.

[nooneimprt4nt@…]

new backend

[nooneimprt4nt@…]

new frontend

[nooneimprt4nt@…]

Ok, I've added 2 new logs (I don't have permissions to delete the old ones for some reason) Anyhow, i was able to create the problem as soon as the backend came up, though you'll have to sift through the commercial-detector messages which kicked in on an old recording while I was switching into LiveTV

[danielk]

The streams are encrypted, see my message in mythtv-dev. The signal monitor needs to be extended to wait for decryption, until then just use your hack of increasing the OpenFile? timeout.