[mythtv-users] Recording problems after upgrade to 0.28
Stephen Worthington
stephen_agent at jsw.gen.nz
Tue Jul 26 12:25:28 UTC 2016
MythTV Version : v0.28-45-g6cda212
Mythbackend is running with -v record,dvbcam for extra logging.
I have just upgraded my Mythbuntu 14.04 system from MythTV 0.27 to
0.28, and I have started having problems recording from my DVB-T
tuners. This was not happening with 0.27. There seem to be two
different, but possibly related, problems with tuning.
The first thing I noted was that when I ran LiveTV and tuned to one
particular channel (TV3) on any of my DVB-T tuners, I got two popup
messages about it failing to tune within 3000 ms. That channel has
always taken a very long time to start playing with LiveTV, but
normally did eventually start. It is an HD channel, and probably has
the highest bit rate of any channel available here in New Zealand. It
seems that it has always taken longer than 3000 ms to start, but in
0.27 that did not seem to matter. In 0.28, it looks like that tuning
timeout is now treated differently and the tuning is timing out and
restarting once it hits that limit. When this happens, TV3 never
tunes properly and mythfrontend often locks up hard - it takes a kill
-9 to kill it.
So I went into mythtv-setup and changed all the tuning timeouts for
the DVB-T tuners to 4000 ms. That made TV3 able to be started in
LiveTV, although there were still sometimes timeout messages. But
mythfrontend did not lock up and it normally did start to play.
However, since then all scheduled recordings from TV3 have displayed
in mythfrontend with the yellow colour that indicates a damaged
recording. But as far as I can tell, they have in fact recorded
correctly. There are no messages logged at the end of the recording
saying it was a damaged recording. Messages about damaged recordings
look like this:
Jul 16 21:34:00 mypvr mythbackend: mythbackend[20660]: I TVRecEvent
tv_rec.cpp:835 (FinishedRecording) TVRec[32]:
FinishedRecording(4045_2016-07-16T08:29:00Z) damaged
recq:<RecordingQuality overall_score="0.729167"
key="4045_2016-07-16T08:29:00Z" countinuity_error_count="14"
packet_count="5354956">#012 <Gap start="2016-07-16T09:15:00Z"
end="2016-07-16T09:17:10Z" duration="129" />#012</RecordingQuality>
which is a real damaged recording that happened on one of my DVB-S
tuners for other reasons. Instead, the TV3 recordings have a message
logged at the end like this:
Jul 26 21:34:00 mypvr mythbackend: mythbackend[17043]: I TVRecEvent
tv_rec.cpp:848 (FinishedRecording) TVRec[11]:
FinishedRecording(1003_2016-07-26T08:28:00Z) good
recq:<RecordingQuality overall_score="1"
key="1003_2016-07-26T08:28:00Z" countinuity_error_count="5"
packet_count="25709453" />
The message says that the recording has an overall score of 1
(perfect), but it also says it has 5 continuity errors. This is
exactly like I used to get with 0.27. However, the very next message
logged is this:
Jul 26 21:34:00 mypvr mythbackend: mythbackend[17043]: I TVRecEvent
tv_rec.cpp:899 (FinishedRecording) TVRec[11]:
FinishedRecording(1003_2016-07-26T08:28:00Z) Bad
quality#012#011#011#011title: NCIS: LA#012#011#011#01
1in recgroup: Favourites status: Failing:Recorder Failed not_dummy
finished_now
Which I think is saying that tuning failed for that recording, which
is completely incorrect as the recording seems completely fine on
scanning through it, although I have not watched it yet to be
completely sure. The recording file is the expected size, it starts
and stops at the expected times and when I skip though it in 30 second
chunks, there is no problem discernable with it, as there usually is
with a real damaged recording.
So it looks like some of the logic used to monitor recordings in 0.28
is going wrong, and even though the tuner has tuned in the channel,
something thinks that tuning failed and is reporting that, and marking
the recording as damaged as a result of that. I am guessing that it
is happening as a result of the very long tuning time taken for TV3.
So the next thing I am going to try is setting the tuning timeout to a
much larger value, probably 10,000 ms, and see if that helps.
The TV3 channel is the only one on that mux that I normally record
from, so it may be that the mux is the thing causing the problems,
rather than that particular channel.
But this evening, another tuning problem occurred which is rather
worse. I had two back-to-back programmes fail to record from another
channel on another mux. That channel has never been a problem in the
past. The first of these was "One News at 6pm" starting at 18:00 NZST
and the second was "Seven Sharp" starting at 19:00 NZST, both from the
channel "TV One". As well, another programme on another channel on
the same mux also failed to record. That was "Lift Off" on channel
"Duke" starting at 18:00 NZST. Later recordings from that mux on
other channels did work. As best I can tell, the tuner never actually
managed to tune to the mux when these recordings started. The later
recordings from the same mux started after a gap between recordings on
that mux, so mythbackend started the tuning from the beginning again,
and it succeeded in tuning in the mux. That tuner has occasionally
had a problem in the past, but only because it is a USB tuner and I
had accidentally disturbed its USB cable so it was not working any
more. That is not what happened today.
So can anyone see anything in the logs that might indicate why that
particular tuner failed to tune at 18:00 only, but tuned correctly
later?
Note that I have three DVB-T tuners, with these powerpriority rules in
place so that recordings from the three original NZ muxes are always
done on the same physical tuner, with recordings from the new fourth
mux being scheduled around them on any tuner:
mysql> select * from powerpriority;
+----------------------+-------------+--------------------------------------------------+
| priorityname | recpriority | selectclause |
+----------------------+-------------+--------------------------------------------------+
| TVNZ multiplex | 20 | channel.mplexid=2 and cardid in (1,2,3,4,5) |
| Mediaworks multiplex | 20 | channel.mplexid=3 and cardid in (11,12,13,14,15) |
| Kordia multiplex | 20 | channel.mplexid=4 and cardid in (6,7,8,9,10) |
+----------------------+-------------+--------------------------------------------------+
3 rows in set (0.00 sec)
Those rules were to fix a problem with the scheduler up to 0.27 where
it could manage to assign different physical tuners to the same mux
and then run out of tuners. With the rules in place, the scheduler
always puts recordings for those muxes on the designated physical
tuner and never makes that mistake. I am not sure if that problem has
been fixed in 0.28 - there are some indications in the way it is
scheduling my DVB-S tuners that it may have been fixed and the
scheduler is now making sure that if it already has a tuner recording
a mux, it will assign all other recordings for that mux to the same
tuner. Having those rules does help with debugging these new
problems, however, as it ensures that the later recordings from the
same mux as the recordings that failed did occur on the same physical
tuner, ruling out the likelihood of a tuner having gone bad and caused
the recordings to fail.
I have put full copies of my mythfrontend, mythbackend and
mythtv-setup log files for the last few days in a file on my web
server:
http://www.jsw.gen.nz/mythtv/tuning-problem-logs.tgz
The logs have both 0.27 and 0.28 recordings in them, for comparison,
and cover the upgrade from 0.27 to 0.28. The first run of mythbackend
after the 0.28 upgrade happened at timestamp "Jul 25 00:56:39" in
mythbackend.log.1.
To help interpret the logs, here are the essential bits from my
cardinput table:
mysql> select
cardid,parentid,videodevice,cardtype,defaultinput,tunechan,startchan,displayname,signal_timeout,channel_timeout,dvb_tuning_delay
from capturecard order by cardid;
+--------+----------+-----------------------------------+----------+--------------+----------+-----------+---------------------------+----------------+-----------------+------------------+
| cardid | parentid | videodevice | cardtype | defaultinput | tunechan | startchan | displayname | signal_timeout | channel_timeout | dvb_tuning_delay |
+--------+----------+-----------------------------------+----------+--------------+----------+-----------+---------------------------+----------------+-----------------+------------------+
| 1 | 0 | /dev/dvb/adapter0/frontend0 | DVB | DVBInput | NULL | 1 | DVB-T 1.1 (1) | 1000 | 10000 | 500 |
| 2 | 1 | /dev/dvb/adapter0/frontend0 | DVB | DVBInput | NULL | 1 | DVB-T 1.1 (1) | 1000 | 10000 | 500 |
| 3 | 1 | /dev/dvb/adapter0/frontend0 | DVB | DVBInput | NULL | 1 | DVB-T 1.1 (1) | 1000 | 10000 | 500 |
| 4 | 1 | /dev/dvb/adapter0/frontend0 | DVB | DVBInput | NULL | 1 | DVB-T 1.1 (1) | 1000 | 10000 | 500 |
| 5 | 1 | /dev/dvb/adapter0/frontend0 | DVB | DVBInput | NULL | 1 | DVB-T 1.1 (1) | 1000 | 10000 | 500 |
| 6 | 0 | /dev/dvb/adapter1/frontend0 | DVB | DVBInput | NULL | 17 | DVB-T 2.1 (6) | 1000 | 10000 | 500 |
| 7 | 6 | /dev/dvb/adapter1/frontend0 | DVB | DVBInput | NULL | 17 | DVB-T 2.1 (6) | 1000 | 10000 | 500 |
| 8 | 6 | /dev/dvb/adapter1/frontend0 | DVB | DVBInput | NULL | 17 | DVB-T 2.1 (6) | 1000 | 10000 | 500 |
| 9 | 6 | /dev/dvb/adapter1/frontend0 | DVB | DVBInput | NULL | 17 | DVB-T 2.1 (6) | 1000 | 10000 | 500 |
| 10 | 6 | /dev/dvb/adapter1/frontend0 | DVB | DVBInput | NULL | 17 | DVB-T 2.1 (6) | 1000 | 10000 | 500 |
| 11 | 0 | /dev/dvb/adapter2/frontend0 | DVB | DVBInput | NULL | 3 | DVB-T 3.1 (11) | 1000 | 10000 | 500 |
| 12 | 11 | /dev/dvb/adapter2/frontend0 | DVB | DVBInput | NULL | 3 | DVB-T 3.1 (11) | 1000 | 10000 | 500 |
| 13 | 11 | /dev/dvb/adapter2/frontend0 | DVB | DVBInput | NULL | 3 | DVB-T 3.1 (11) | 1000 | 10000 | 500 |
| 14 | 11 | /dev/dvb/adapter2/frontend0 | DVB | DVBInput | NULL | 3 | DVB-T 3.1 (11) | 1000 | 10000 | 500 |
| 15 | 11 | /dev/dvb/adapter2/frontend0 | DVB | DVBInput | NULL | 3 | DVB-T 3.1 (11) | 1000 | 10000 | 500 |
| 16 | 0 | /dev/video0 | MPEG | S-Video 1 | NULL | 1073 | Composite 1 (16) | 1000 | 12000 | 0 |
| 17 | 0 | /dev/dvb/adapter3/frontend0 | DVB | DVBInput | NULL | 70 | QBox2 DVB-S2.1 (17) | 7000 | 10000 | 500 |
| 18 | 17 | /dev/dvb/adapter3/frontend0 | DVB | DVBInput | NULL | 70 | QBox2 DVB-S2.2 (18) | 7000 | 10000 | 500 |
| 19 | 17 | /dev/dvb/adapter3/frontend0 | DVB | DVBInput | NULL | 70 | QBox2 DVB-S2.3 (19) | 7000 | 10000 | 500 |
| 20 | 17 | /dev/dvb/adapter3/frontend0 | DVB | DVBInput | NULL | 70 | QBox2 DVB-S2.4 (20) | 7000 | 10000 | 500 |
| 21 | 17 | /dev/dvb/adapter3/frontend0 | DVB | DVBInput | NULL | 70 | QBox2 DVB-S2.5 (21) | 7000 | 10000 | 500 |
| 22 | 0 | /dev/dvb/adapter4/frontend0 | DVB | DVBInput | NULL | 91 | TeVii S470.1 (22) | 7000 | 10000 | 500 |
| 23 | 22 | /dev/dvb/adapter4/frontend0 | DVB | DVBInput | NULL | 91 | TeVii S470.2 (23) | 7000 | 10000 | 500 |
| 24 | 22 | /dev/dvb/adapter4/frontend0 | DVB | DVBInput | NULL | 91 | TeVii S470.3 (24) | 7000 | 10000 | 500 |
| 25 | 22 | /dev/dvb/adapter4/frontend0 | DVB | DVBInput | NULL | 91 | TeVii S470.4 (25) | 7000 | 10000 | 500 |
| 26 | 22 | /dev/dvb/adapter4/frontend0 | DVB | DVBInput | NULL | 91 | TeVii S470.4 (26) | 7000 | 10000 | 500 |
| 27 | 0 | /dev/dvb/adapter5/frontend0 | DVB | DVBInput | NULL | 4089 | QBox2 sasc-ng.1 (27) | 7000 | 10000 | 500 |
| 28 | 27 | /dev/dvb/adapter5/frontend0 | DVB | DVBInput | NULL | 4089 | QBox2 sasc-ng.2 (28) | 7000 | 10000 | 500 |
| 29 | 27 | /dev/dvb/adapter5/frontend0 | DVB | DVBInput | NULL | 4089 | QBox2 sasc-ng.3 (29) | 7000 | 10000 | 500 |
| 30 | 27 | /dev/dvb/adapter5/frontend0 | DVB | DVBInput | NULL | 4089 | QBox2 sasc-ng.4 (30) | 7000 | 10000 | 500 |
| 31 | 27 | /dev/dvb/adapter5/frontend0 | DVB | DVBInput | NULL | 4089 | QBox2 sasc-ng.5 (31) | 7000 | 10000 | 500 |
| 32 | 0 | /dev/dvb/adapter6/frontend0 | DVB | DVBInput | NULL | 4074 | TeVii S470 sasc-ng.1 (32) | 7000 | 10000 | 500 |
| 33 | 32 | /dev/dvb/adapter6/frontend0 | DVB | DVBInput | NULL | 4074 | TeVii S470 sasc-ng.2 (33) | 7000 | 10000 | 500 |
| 34 | 32 | /dev/dvb/adapter6/frontend0 | DVB | DVBInput | NULL | 4074 | TeVii S470 sasc-ng.3 (34) | 7000 | 10000 | 500 |
| 35 | 32 | /dev/dvb/adapter6/frontend0 | DVB | DVBInput | NULL | 4074 | TeVii S470 sasc-ng.4 (35) | 7000 | 10000 | 500 |
| 36 | 32 | /dev/dvb/adapter6/frontend0 | DVB | DVBInput | NULL | 4074 | TeVii S470 sasc-ng.5 (36) | 7000 | 10000 | 500 |
| 142 | 0 | http://10.0.2.4:8080/playlist.m3u | FREEBOX | Television | NULL | 5006 | Minisatip | 1000 | 30000 | 0 |
+--------+----------+-----------------------------------+----------+--------------+----------+-----------+---------------------------+----------------+-----------------+------------------+
37 rows in set (0.00 sec)
I need to fix the displayname fields - it looks like the 0.28 upgrade
has changed my custom settings I had for them on the DVB-T tuners.
There seem to be at least two bugs here. Firstly, mythfrontend should
not ever lock up requiring a kill -9.
Second, the way mythbackend goes about doing its tuning seems to have
some problems. If a tuner is not actually tuning, surely at some
point mythbackend should decide that it is not going to succeed in
tuning and it should try to reset the tuner and start again, or
perhaps try another tuner, if possible. What it appears to do at the
moment is that once it has told a tuner to select a particular
frequency for a mux, it will never touch the tuner frequency setting
again until there is a gap in the use of that mux when all the
recordings on it go past the time they are due to stop. So a tuner
that fails to tune correctly for whatever reason will fail to record
all those recordings. If the tuner fails to tune, and no data is
being received from the mux, all those recordings are clearly not
going to work, so it would be much better if mythbackend were to
detect the failure to tune and try again, even if that means that the
start of some recordings will be a little delayed from their scheduled
start times.
Also, is the default 3000 ms value for the DVB-T tuning time possibly
too small? Or is it just that the NZ TV3 channel is doing something
unusual that is causing it to need a longer tuning time?
More information about the mythtv-users
mailing list