[mythtv] Too much EIT activity causing defective recordings

[Stephen Worthington]

On Wed, 1 Aug 2018 13:52:06 +0100, you wrote:

>On 01/08/18 12:49, Michael T. Dean wrote:
>> On 07/31/2018 06:51 PM, John Pilkington wrote:
>>> Hi;  I'm running Master under SL7, recording UK SD DVB-T material via 
>>> one PCI single-tuner device and one twin-tuner usb dongle.
>>>
>>> Bus 001 Device 002: ID 1b80:e409 Afatech IT9137FN Dual DVB-T [KWorld 
>>> UB499-2T]
>>>
>>> Around 9 July my Project-X-based mythDVBcut logs started reporting 
>>> multiple AV sync corrections of up to a second in recordings from the 
>>> usb tuners.  The change occurred after I rescanned my transports 
>>> following the Wimbledon special tennis coverage;  I'm fairly sure I 
>>> made other 'minor' changes in the multirec and EIT configs too.
>>>
>>> Today I realised that the defects were often around 5 minutes apart, 
>>> and EIT scanning seemed a possible culprit.  I have now unchecked the 
>>> boxes for usb open-on-demand and active-EIT-scan, and it looks as if 
>>> the recording defects have largely gone.
>>>
>>> In the past I probably haven't taken as much notice of the EIT 
>>> settings as I should have done, but the recent defects were much worse 
>>> than I had seen before and I think some of the recent code changes 
>>> must have been implicated.
>>>
>>> John P
>>>
>>> Below is a Project-X log resync section from an affected recording. 
>>> This should be just a few lines, with no resync required.
>>>
>>> {{{
>>>
>>> Input File 0:  '/mnt/dat2/RSG3/1004_20180723195800.ts.old' 
>>> (1,149,983,780 bytes)
>>> -> Filetype is TS (generic PES Container)
>>>
>>> <demux log snipped>
>>>
>>> ++> Mpg Audio: PID 0x044E / PesID 0xC0 / SubID 0x00 :
>>> -> check CRC of AC-3 / MPEG-Audio L1,2
>>> -> remove CRC in MPEG-Audio L1,2
>>> -> add frames
>>> -> Audio PTS: first packet 08:48:35.071, last packet 09:48:52.207
>>> -> Video PTS: start 1.GOP 08:48:41.439, end last GOP 09:48:41.999
>>> -> adjusting audio at video-timeline
>>> -> src_audio: MPEG-1, Layer2, 48000Hz, stereo, 192kbps, noCRC @ 
>>> 00:00:00.000
>>> !> 5 frame(s) (120ms) inserted @ 00:02:28.608
>>> !> missing syncword @  6527233, @ 00:04:08.064
>>> !> found syncword @ 6528384
>>> !> 22 frame(s) (528ms) inserted @ 00:04:08.064
>>> !> missing syncword @  6528961, @ 00:04:08.592
>>> !> found syncword @ 6529352
>>> !> missing syncword @  14213193, @ 00:09:27.840
>>> !> found syncword @ 14213560
>>> !> missing syncword @  14214137, @ 00:09:27.864
>>> !> found syncword @ 14214344
>>> !> 4 frame(s) (96ms) inserted @ 00:09:27.864
>>> !> missing syncword @  29606793, @ 00:16:02.448
>>> !> found syncword @ 29607000
>>> !> 1 frame(s) (24ms) inserted @ 00:16:02.448
>>> !> 19 frame(s) (456ms) inserted @ 00:21:21.144
>>> !> missing syncword @  45001753, @ 00:26:40.656
>>> !> found syncword @ 45001960
>>> !> 23 frame(s) (552ms) inserted @ 00:26:40.680
>>> !> missing syncword @  52701353, @ 00:27:54.144
>>> !> found syncword @ 52701536
>>> !> missing syncword @  52702689, @ 00:27:54.192
>>> !> found syncword @ 52703080
>>> !> 20 frame(s) (480ms) inserted @ 00:27:54.192
>>> !> missing syncword @  60403625, @ 00:33:14.592
>>> !> found syncword @ 60404248
>>> !> 17 frame(s) (408ms) inserted @ 00:33:14.616
>>> !> missing syncword @  68103065, @ 00:38:34.344
>>> !> found syncword @ 68103712
>>> !> 17 frame(s) (408ms) inserted @ 00:38:34.344
>>> !> missing syncword @  68120993, @ 00:38:34.752
>>> !> found syncword @ 68121960
>>> !> 2 frame(s) (48ms) inserted @ 00:38:34.752
>>> !> missing syncword @  75797161, @ 00:39:47.760
>>> !> found syncword @ 75797944
>>> !> missing syncword @  83496185, @ 00:45:07.344
>>> !> found syncword @ 83496968
>>> !> 21 frame(s) (504ms) inserted @ 00:45:07.416
>>> !> missing syncword @  83504457, @ 00:45:07.920
>>> !> found syncword @ 83505080
>>> !> missing syncword @  83566137, @ 00:45:09.816
>>> !> found syncword @ 83566920
>>> !> 2 frame(s) (48ms) inserted @ 00:45:09.816
>>> !> 2 frame(s) (48ms) inserted @ 00:45:09.960
>>> audio frames: wri-pre-skip-ins-add 117813-0-0-155-0 @ 00:47:07.512 
>>> done...
>>> ---> new File: '/home/john/MythTmp/tempcut19417.mp2'
>>>
>>> summary of created media files:
>>> .Video (m2v):    70688 Frames    00:47:07.520 
>>> '/home/john/MythTmp/tempcut19417.m2v'
>>> Audio 00 (mp2):    117813 Frames    00:47:07.512    0-0-155-0 
>>> '/home/john/MythTmp/tempcut19417.mp2'
>>> => 775,195,585 bytes written...
>>> -> we have 139 warnings/errors.
>>>
>>> }}}
>> 
>> Could this be due to I/O activity? Have you done an optimize on your 
>> database, recently?  If not, it may just be that MySQL is taking too 
>> much time with I/O when MythTV tries to write your listings data and it 
>> causes problems with MythTV's writing recording data.  Do you have any 
>> warnings or errors in your MythTV backend logs?
>> 
>> Mike
>
>Hi Mike:  I run optimize every few days, so I don't think that's it. 
>But I usually arranged the schedule to record from the usb tuners only 
>when the PCI device was already recording, often from several channels, 
>so usually the system would be fairly busy.  Database sql.gz backups are 
>now 125 MiB and autodelete of old recordings is getting invoked.  40 GB 
>free, 2% of 2.3 GiB reported: 3 partitions on 2 disks.
>
>I haven't seen any obvious signs of distress on the terminal window in 
>which I run the backend, and at present I would prefer to let things 
>roll for a bit rather than going back to do more investigations.

You might try setting the -v record option on the mythbackend command
line.  That gives more logging of the recording process, and will give
you messages like the following if you are getting any problems
detected with a recording:

root at mypvr:/etc/mythtv# grep -a "overall_score=\"0"
/var/log/mythtv/mythbackend.log.1
Jul 22 20:34:01 mypvr mythbackend: mythbackend[3543]: I TVRecEvent
tv_rec.cpp:863 (FinishedRecording) TVRec[96]:
FinishedRecording(10072_2018-07-22T07:29:00Z) good
recq:<RecordingQuality overall_score="0.991667"
key="10072_2018-07-22T07:29:00Z" countinuity_error_count="11"
packet_count="7494980">#012    <Gap start="2018-07-22T07:46:02Z"
end="2018-07-22T07:46:22Z" duration="19" />#012</RecordingQuality>
Jul 23 20:39:00 mypvr mythbackend: mythbackend[3543]: I TVRecEvent
tv_rec.cpp:863 (FinishedRecording) TVRec[94]:
FinishedRecording(10007_2018-07-23T07:59:00Z) damaged
recq:<RecordingQuality overall_score="0"
key="10007_2018-07-23T07:59:00Z" countinuity_error_count="0"
packet_count="108664">#012    <Gap start="2018-07-23T07:59:30Z"
end="2018-07-23T08:35:00Z" duration="2129" />#012</RecordingQuality>
Jul 25 23:06:01 mypvr mythbackend: mythbackend[3644]: I TVRecEvent
tv_rec.cpp:863 (FinishedRecording) TVRec[92]:
FinishedRecording(10070_2018-07-25T10:14:00Z) damaged
recq:<RecordingQuality overall_score="0"
key="10070_2018-07-25T10:14:00Z" countinuity_error_count="0"
packet_count="194555">#012    <Gap start="2018-07-25T10:15:27Z"
end="2018-07-25T11:05:00Z" duration="2972" />#012</RecordingQuality>

What I see if I have my hard drives too busy is that I get short gaps
in recordings, and get messages like the first one above, where there
is a gap with a short duration, and also continuity errors.  I use a
rule of thumb that two recordings at once is all I want to have on one
hard drive.  Three at once is OK for a short period (during overlaps
between recordings due to pre- and post roll), but if I have three
recordings at once to one drive for the full length of a recording,
there is a good chance I will get gaps.  Four at once and there will
almost always be gaps.  Since you have three tuners with multirec on
each of them, and only two hard drives to record to, then it is likely
that the drives will be overloaded at some point.  And if one of the
recording drives is also the system and database drive, then it is
much more likely to be too busy at some point.  I put my system and
database onto an SSD a couple of years ago and that made a big
difference.  But when I increased my tuners, I also had to add more
hard drives.  I now have 5 x DVB-T2 and 4 x DVB-S2 tuners in use, and
have 7 recording drives.  And I do at times have 14 recordings at
once.  But the gaps I get now are normally caused by rain fade on the
satellite dish, not by overworked hard drives.