Corruption of recordings seems to be linked to system events

[jpilk]

New recordings from DVB-T with EIT have packets out of order at times that seem to be related to scheduling or perhaps other system events. When processed by Project-X this causes drops of individual GOPs from files that otherwise play well.

​http://lists.mythtv.org/pipermail/mythtv-users/2019-December/401922.html

2019-12-25 19:28:39.871170 I  Reschedule requested for MATCH 0 1 1 2019-12-25T19:35:00Z EITScanner
2019-12-25 19:28:40.020122 I  Scheduled 81 items in 0.1 = 0.01 match + 0.01 check + 0.03 place
2019-12-25 19:29:42.925171 N  AutoExpire: CalcParams(): Max required Free Space: 10.0 GB w/freq: 7 min
2019-12-25 19:33:32.003281 I  Reschedule requested for MATCH 0 1 1 2019-12-25T21:45:00Z EITScanner
2019-12-25 19:33:32.157194 I  Scheduled 81 items in 0.1 = 0.01 match + 0.01 check + 0.03 place
2019-12-25 19:34:00.200212 I  TVRec[1]: Changing from RecordingOnly to None
2019-12-25 19:34:00.359770 N  Finished Recording: Container: MPEG2-TS Video Codec: none (0x0 A/R: 0 25fps) Audio Codec: mp2
2019-12-25 19:34:00.366041 E  MainServer: PREVIEW_SUCCESS but no receivers.
2019-12-25 19:34:00.366372 I  Finished recording Words and Music: channel 10703
2019-12-25 19:34:00.366462 I  Updating status for "Words and Music" on cardid [1] (Recording => Recorded)
2019-12-25 19:34:00.388458 I  Reschedule requested for CHECK -3 26848 0 UpdateRecStatus2 | Words and Music |  | Texts and music on the theme of swans, with readers Anthony Calf and Louise Jameson. Including Yeats, Rilke and Tennyson, plus Saint-Saens, Villa-Lobos, Tchaikovsky and Sibelius. | fp.bbc.co.uk/b/3yoauw
2019-12-25 19:34:00.551320 I  Scheduled 80 items in 0.1 = 0.03 match + 0.00 check + 0.03 place
2019-12-25 19:34:04.585055 I  MainServer: MainServer::ANN Monitor
2019-12-25 19:34:04.585074 I  MainServer: adding: hpbox(2353dd0) as a client (events: 0)
2019-12-25 19:34:04.586852 I  MainServer: MainServer::ANN Monitor
2019-12-25 19:34:04.586874 I  MainServer: adding: hpbox(28d7470) as a client (events: 1)
2019-12-25 19:34:14.297881 I  Monitor sock(2353dd0) 'hpbox' disconnected
2019-12-25 19:34:14.300736 I  Monitor sock(28d7470) 'hpbox' disconnected
2019-12-25 19:36:42.932107 N  AutoExpire: CalcParams(): Max required Free Space: 10.0 GB w/freq: 14 min
2019-12-25 19:50:42.939335 N  AutoExpire: CalcParams(): Max required Free Space: 10.0 GB w/freq: 14 min
2019-12-25 19:58:00.000997 I  Reschedule requested for PLACE PrepareToRecord
2019-12-25 19:58:00.131761 I  Scheduled 80 items in 0.0 = 0.00 match + 0.00 check + 0.03 place
============
Extract from cutting log of recording with scheduled starttime 201912251900

$ cat mythGOPdrop2.txt | grep -A1 "dropping GOP"
!> dropping GOP# 2271 @ orig.PTS 02:45:08.322 (891749060), errorcode: 24
!> Pics exp/cnt 23/3, inGOP PTS diff. 1920ms, new Timecode 00:35:23.280
--
!> dropping GOP# 3862 @ orig.PTS 03:10:07.682 (1026691460), errorcode: 24
!> Pics exp/cnt 24/19, inGOP PTS diff. 1920ms, new Timecode 01:00:19.680
--
!> dropping GOP# 5720 @ orig.PTS 03:39:11.642 (1183647860), errorcode: 24
!> Pics exp/cnt 27/17, inGOP PTS diff. 1520ms, new Timecode 01:29:20.680
--
!> dropping GOP# 6092 @ orig.PTS 03:45:06.082 (1215547460), errorcode: 24
!> Pics exp/cnt 25/35, inGOP PTS diff. 2880ms, new Timecode 01:35:12.440
--
!> dropping GOP# 7466 @ orig.PTS 04:06:34.882 (1331539460), errorcode: 24
!> Pics exp/cnt 24/8, inGOP PTS diff. 2880ms, new Timecode 01:56:37.320
--
!> dropping GOP# 7805 @ orig.PTS 04:11:56.482 (1360483460), errorcode: 20
!> Pics exp/cnt 12/12, inGOP PTS diff. 3840ms, new Timecode 02:01:55.000
--
!> dropping GOP# 7944 @ orig.PTS 04:14:10.642 (1372557860), errorcode: 24
!> Pics exp/cnt 25/30, inGOP PTS diff. 2400ms, new Timecode 02:04:04.840
--
!> dropping GOP# 7958 @ orig.PTS 04:14:25.762 (1373918660), errorcode: 24
!> Pics exp/cnt 24/23, inGOP PTS diff. 3840ms, new Timecode 02:04:16.480
--
!> dropping GOP# 8070 @ orig.PTS 04:16:15.522 (1383797060), errorcode: 24
!> Pics exp/cnt 23/11, inGOP PTS diff. 960ms, new Timecode 02:06:01.360
--

[Klaas de Waal]

It would be useful to have your exact postprocessing command to see if the problem can be reproduced.

[jpilk]

Hmm. Thanks for offering to try this :-) ​https://www.mythtv.org/wiki/MythDVBcut

A typical command is

ionice -c3 nice ~/MythDVBcut.sh 10002_20191225202800.ts

where the filename identifies a recording known to MythTV. That generates

ionice -c3 java -jar /home/john/projectx_link -name tempcut28735 -id 0xc9,0xca -out /home/john/MythTmp -cut projx28735 10002_20191225202800.ts.old

where the input file has been renamed. Any mpeg2 video ought to work as input if no cutting is to be done. That produces two demuxed files

Video (m2v): 132101 Frames 01:28:04.040 '/home/john/MythTmp/tempcut28735.m2v' Audio 00 (mp2): 220168 Frames 01:28:04.032 0-0-184-0 '/home/john/MythTmp/tempcut28735.mp2'

which are then remuxed. The error messages I quoted are from Project-X during the demux phase.

I build Project-X locally and don't use its GUI. A packaged version would be called differently, and for this test the -cut file ought to be unnecessary.

[Klaas de Waal]

This is a problem that I cannot reproduce with a recent master. There is the "dropping useless B-Frames @ GOP# 0" message once for each file but that is the only error message from ProjectX.

My test setup:

• Created 30 SD/MPEG2 recordings from DVB-C
• All recordings done with the MyGica? USB tuner
• Recording 3 channels of the same multiplex simultaneously
• Passive EIT on the MyGica? USB tuner
• Also a second DVB-C tuner doing active EIT all the time.

N.B. The local DVB-T2 is HEVC/H265 coded only so that cannot be used. It should not matter whether the input is from DVB-T or DVB-C, although one can never be really sure.

To me this problem does not look like a MythTV software bug, more like underpowered hardware, but it is possible that something can be optimized for this.

To figure out what this can be it would be useful to know:

• exact which system events correlate with the missing packets
• does it depend on the tuner (USB or PCEe or network)

[jpilk]

Thank you for looking at this. I have not yet found a good correlation with a particular system event, but the drops do appear to happen most frequently around the time another recording ends. Most recordings are from the BBC SD DVB-T mpeg2 multiplex, using a legacy PCI card

saa7134 0000:07:04.0: DVB: adapter 0 frontend 0 (Philips TDA10046H DVB-T)...

Other tuners on this system are usb 1-3: DVB: adapter 1 frontend 0 (Afatech AF9033 (DVB-T))... and adapter 2 in the same package

System storage is in 3 SGs on 2 spinning disks, ~2500 recordings, ~2200 GiB, and old recordings are being autodeleted. core2duo @ 2.6 Ghz. I guess you're right - it's mainly a system load problem, sometimes combined with an OTA signal that used to be better.

It occurred to me that wifi probing from another system close to the input cabling might give a similar pattern of timings, but stopping that made no difference. Logs from the Project-X runs still often show no problem, but it is real. I'll see if I can find a 'grep' formula to shed more light.

[jpilk]

I'm still seeing this, although it seems less frequent after I moved EIT scans from my main tuner. Connecting it to a system event has been awkward because the timings in the log are relative to the startpoint selected in the editor, so I tried with none selected. The only bad GOP was at 6m 2s from the start - with a DVB-T multirec overlap of 6m with an earlier recording.

I had wondered if the problem was only apparent via my Projectx postprocessing, but playing the unprocessed file showed a conspicuous glitch at that point, while the normal output plays with a dropout that is often hard to spot. It's not clear yet why other people haven't seen this.

The log for the earlier recording showed no problem.

In this case no frames were added to maintain sync.

v32-Pre-32-1c0b76b

-> cut-in @ GOP# 0 / new vframe 0 / new Timecode 00:00:00.000 (417924)
-> video basics: 704*576 @ 25fps @ 0.7031 (16:9) @ 15000000 bps - vbv 112
-> starting export of video data @ GOP# 0
!> dropping useless B-Frames @ GOP# 0 / new Timecode 00:00:00.000
!> PID 0x0065 -> packet 1010160 @ pos. 189909892 out of sequence (2/1) (shifting counter..) (~00:06:02.360)
!> PID 0x0066 -> packet 1010187 @ pos. 189914968 out of sequence (11/14) (shifting counter..) (~00:06:02.360)
!> PID 0x0065 -> packet 1010220 @ pos. 189921172 out of sequence (4/3) (shifting counter..) (~00:06:02.360)
!> ID 0xC0 (sub 0x0) packet# 3030, big PTS difference: this 149889608, prev. 149641208
!> dropping GOP# 405 @ orig.PTS 00:27:42.325 (149609312), errorcode: 24
!> Pics exp/cnt 25/28, inGOP PTS diff. 3000ms, new Timecode 00:06:02.360
!> PTS difference of 360000 (00:00:04.000) to last exported GOP detected 
!> dropping useless B-Frames @ GOP# 406 / new Timecode 00:06:02.360
packs: 9733803 100% 2406824504


-> adjusting audio at video-timeline
-> src_audio: MPEG-1, Layer2, 48000Hz, stereo, 256kbps, noCRC @ 00:00:00.000
!> missing syncword @  11632897, @ 00:06:02.352
!> found syncword @ 11633848
!> missing syncword @  11634617, @ 00:06:02.352
!> found syncword @ 11635200

[Klaas de Waal]

Could it be that all your corruptions can be related to start and stop of multirec recordings?

[jpilk]

I have suspected that for some time, but this is the first time I've done the extra run without a content-defined timer. Probably the end-of-recording isn't done cleanly.

[jpilk]

I set up two multirec DVB-T recordings on the Fedora 30 box, and playback of the second freezes briefly at 6 m in, when the first ended.

[jpilk]

It looks as if this was happening in 2019 April and maybe earlier (when my channel format was 100?)

[john@HP_Box Logs]$ grep -A1 -m1 "dropping GOP" *1000?_201904* | grep "Timecode 00:0"

[jpilk]

I have been able to provoke these glitches in raw SD multirec recordings on two systems with PCI tuners, but I haven't yet seen them with HD. I'll try 'preferring' USB SD tuners, although these have previously seemed less reliable.

[jpilk]

Hmm. After reassigning input connections and scheduling a few recordings that demanded multirec, I couldn't detect the expected glitches and neither did ProjectX. google's MythTV archaeology found

​https://code.mythtv.org/trac/ticket/3541#comment:9

for the same hardware. In all other respects my cards have appeared to work well, but EIT-related defective recordings that I reported several months ago might perhaps be related.

​http://lists.mythtv.org/pipermail/mythtv-dev/2018-July/076965.html

[Stuart Auchterlonie]

We have moved all bug tracking to github [1]

If you continue to have this issue, please open a new issue at github, referencing this ticket.

[1] - ​https://github.com/MythTV/mythtv/issues