[mythtv] Debugging DeviceReadBuffer.cpp

Thu Jun 6 05:22:19 UTC 2013

HI!

On 31.05.2013 19:52, Daniel Thor Kristjansson wrote:
> From the looks of the patch you don't print anything for
> the (ret > 0) case. It will be fairly rare for 2.5 seconds
> to elapse with no data coming from the device. You generally
> need to unplug the aerial to get to those cases.

I have now removed POLLPRI, because it does not do anything anyway and
added more debug messages, please see attached patch.

Now I got more information in the log, please see it attached.

What's interesting is:

When the problem starts, I get this:
2013-06-06 04:00:20.521543 W  DevRdB(/dev/dvb/adapter3/frontend0):
polls[0].revents: 0
2013-06-06 04:00:20.521564 W  DevRdB(/dev/dvb/adapter3/frontend0):
polls[1].revents: 0
2013-06-06 04:00:20.521573 W  DevRdB(/dev/dvb/adapter3/frontend0): Poll
ret: 0
2013-06-06 04:00:20.521582 W  DevRdB(/dev/dvb/adapter3/frontend0): Poll
error: 11

revents is 0, ret is 0 and errno is 11.

11 means EAGAIN and basically that's what Myth does, even without
specifically handling EAGAIN (because revents is 0). It stays in the
loop and tries again.

But then it changes to:
2013-06-06 04:00:30.283545 W  DevRdB(/dev/dvb/adapter3/frontend0):
polls[0].revents: 8
2013-06-06 04:00:30.283554 W  DevRdB(/dev/dvb/adapter3/frontend0):
polls[1].revents: 0
2013-06-06 04:00:30.283558 W  DevRdB(/dev/dvb/adapter3/frontend0): Poll
ret: 1
2013-06-06 04:00:30.283562 W  DevRdB(/dev/dvb/adapter3/frontend0): Poll
error: 11

errno is still 11, but ret is 1 now, which normally means poll() was
successful.

But Myth does not react to this and stays in the loop, because revents
is apparently not POLLIN, but 8, which means POLLERR.

And so the loop runs until the scheduled end of the recording. During
this time, mythbackend uses high CPU.

This looks like maybe the driver does not act as it should. Since this
happens only on 2 multiplexes, I guess I have a reception issue every
now and then (most of the time works perfectly).

My question is:
Does Myth react as intended by the devs? Myth 0.23 would have reacted
different, I guess from looking at the source. It would have treated ret
= 1 always as "data" and exited the method.

If this is as intended, can I change anything in Myth to handle this
situation different/better, meaning implement a workaround for the
driver bug?

I can't reach the driver maintainer...

Thanks!

Regards,
Thomas
-------------- next part --------------
A non-text attachment was scrubbed...
Name: mythtv_poll.patch
Type: text/x-patch
Size: 3822 bytes
Desc: not available
URL: <http://www.mythtv.org/pipermail/mythtv-dev/attachments/20130606/10a34f08/attachment.bin>
-------------- next part --------------
2013-06-06 03:59:58.564930 I  EITHelper: Added 1 events
2013-06-06 04:00:20.521543 W  DevRdB(/dev/dvb/adapter3/frontend0): polls[0].revents: 0
2013-06-06 04:00:20.521564 W  DevRdB(/dev/dvb/adapter3/frontend0): polls[1].revents: 0
2013-06-06 04:00:20.521573 W  DevRdB(/dev/dvb/adapter3/frontend0): Poll ret: 0
2013-06-06 04:00:20.521582 W  DevRdB(/dev/dvb/adapter3/frontend0): Poll error: 11
2013-06-06 04:00:20.521607 W  DevRdB(/dev/dvb/adapter3/frontend0): Poll loop restart, 2501 ms
2013-06-06 04:00:23.023561 W  DevRdB(/dev/dvb/adapter3/frontend0): polls[0].revents: 0
2013-06-06 04:00:23.023577 W  DevRdB(/dev/dvb/adapter3/frontend0): polls[1].revents: 0
2013-06-06 04:00:23.023586 W  DevRdB(/dev/dvb/adapter3/frontend0): Poll ret: 0
2013-06-06 04:00:23.023595 W  DevRdB(/dev/dvb/adapter3/frontend0): Poll error: 11
2013-06-06 04:00:23.023614 W  DevRdB(/dev/dvb/adapter3/frontend0): Poll loop restart, 5003 ms
2013-06-06 04:00:25.523890 W  DevRdB(/dev/dvb/adapter3/frontend0): polls[0].revents: 0
2013-06-06 04:00:25.523906 W  DevRdB(/dev/dvb/adapter3/frontend0): polls[1].revents: 0
2013-06-06 04:00:25.523916 W  DevRdB(/dev/dvb/adapter3/frontend0): Poll ret: 0
2013-06-06 04:00:25.523924 W  DevRdB(/dev/dvb/adapter3/frontend0): Poll error: 11
2013-06-06 04:00:25.523943 W  DevRdB(/dev/dvb/adapter3/frontend0): Poll loop restart, 7503 ms
2013-06-06 04:00:28.026505 W  DevRdB(/dev/dvb/adapter3/frontend0): polls[0].revents: 0
2013-06-06 04:00:28.026522 W  DevRdB(/dev/dvb/adapter3/frontend0): polls[1].revents: 0
2013-06-06 04:00:28.026530 W  DevRdB(/dev/dvb/adapter3/frontend0): Poll ret: 0
2013-06-06 04:00:28.026538 W  DevRdB(/dev/dvb/adapter3/frontend0): Poll error: 11
2013-06-06 04:00:28.026556 W  DevRdB(/dev/dvb/adapter3/frontend0): Poll loop restart, 10006 ms
2013-06-06 04:00:30.283545 W  DevRdB(/dev/dvb/adapter3/frontend0): polls[0].revents: 8
2013-06-06 04:00:30.283554 W  DevRdB(/dev/dvb/adapter3/frontend0): polls[1].revents: 0
2013-06-06 04:00:30.283558 W  DevRdB(/dev/dvb/adapter3/frontend0): Poll ret: 1
2013-06-06 04:00:30.283562 W  DevRdB(/dev/dvb/adapter3/frontend0): Poll error: 11
2013-06-06 04:00:30.283569 W  DevRdB(/dev/dvb/adapter3/frontend0): Poll loop restart, 12263 ms
2013-06-06 04:00:31.348200 W  DevRdB(/dev/dvb/adapter3/frontend0): polls[0].revents: 8
2013-06-06 04:00:31.348210 W  DevRdB(/dev/dvb/adapter3/frontend0): polls[1].revents: 0
2013-06-06 04:00:31.348214 W  DevRdB(/dev/dvb/adapter3/frontend0): Poll ret: 1
2013-06-06 04:00:31.348219 W  DevRdB(/dev/dvb/adapter3/frontend0): Poll error: 11
2013-06-06 04:00:31.348229 W  DevRdB(/dev/dvb/adapter3/frontend0): Poll loop restart, 13328 ms
2013-06-06 04:00:32.340080 W  DevRdB(/dev/dvb/adapter3/frontend0): polls[0].revents: 8
2013-06-06 04:00:32.340089 W  DevRdB(/dev/dvb/adapter3/frontend0): polls[1].revents: 0
2013-06-06 04:00:32.340093 W  DevRdB(/dev/dvb/adapter3/frontend0): Poll ret: 1
2013-06-06 04:00:32.340097 W  DevRdB(/dev/dvb/adapter3/frontend0): Poll error: 11
2013-06-06 04:00:32.340104 W  DevRdB(/dev/dvb/adapter3/frontend0): Poll loop restart, 14320 ms
2013-06-06 04:00:33.759034 W  DevRdB(/dev/dvb/adapter3/frontend0): polls[0].revents: 8
2013-06-06 04:00:33.759042 W  DevRdB(/dev/dvb/adapter3/frontend0): polls[1].revents: 0
2013-06-06 04:00:33.759046 W  DevRdB(/dev/dvb/adapter3/frontend0): Poll ret: 1
2013-06-06 04:00:33.759050 W  DevRdB(/dev/dvb/adapter3/frontend0): Poll error: 11
2013-06-06 04:00:33.759057 W  DevRdB(/dev/dvb/adapter3/frontend0): Poll loop restart, 15739 ms

[...]

2013-06-06 07:00:02.771461 I  MainServer::ANN Monitor
2013-06-06 07:00:02.771487 I  adding: linux as a client (events: 1)
2013-06-06 07:00:02.780211 I  MainServer::ANN Monitor
2013-06-06 07:00:02.780217 I  adding: linux as a client (events: 0)
2013-06-06 07:00:02.780380 I  MainServer::ANN Monitor
2013-06-06 07:00:02.780386 I  adding: linux as a client (events: 1)
2013-06-06 07:00:04.098124 I  Reschedule interrupted, will retry
2013-06-06 07:00:04.098171 I  Reschedule requested for CHECK -3 3413 0 UpdateRecStatus2 | 345 (SportHD 2) | 2013-06-06 00:00:00 |  | 
2013-06-06 07:00:04.098745 I  Reschedule requested for PLACE Interrupted
2013-06-06 07:00:05.151718 I  Scheduled 667 items in 0.8 = 0.00 match + 0.00 check + 0.82 place