Cutlist editor hangups, particularly in DVB-T radio recordings

[Jpilk]

• Platform: SL7.9 x86_64 and Fedora 32 x86_64

• MythTV version: Master head mythtv-32.Pre.2528.g36f21e9df5-100.el7.x86_64.rpm of 20210320

• Package version:

• Component:

What steps will reproduce the bug?

Start 'mythfrontend -v file' in a window Start playback of a radio recording Step forward a few times, E for the editor, then M Read the log. This will probably not make the editor hang, but the log will have errors like

E Overlay: Failed to create window osd_status

E XMLParseBase: No theme file /usr/share/mythtv/themes/MythCenter-wide/osd.xml ( the file exists)

E TVMenu: No theme file /home/john/.mythtv/menu_cutlist.xml (or in 2 other locations - I don't see any of them )

How often does it reproduce? Is there a required condition?

What is the expected behaviour?

What do you see instead?

Several attempts to attach the short logfile. This is where it ended up: myth_edit_hang.txt

Additional information

This 'unpredictable' hang in the editor has been lurking for several months but never showed any likely cause in the logs. I saw this only after enabling 'file' verbosity for another reason. The hangs are more noticeable with radio but also affect TV. May be related to #333

[kmdewaal]

The error messages are completely reproducible. Unfortunately they do not show a real problem, they are merely unfortunately phrased and should probable be of type info rather than error. What happens is that mythtv searches for a window, e.g. osd_debug, in a theme file. e.g. osd.xml. This search is done in a number of directories, going from specific to general; in this case from MythCenter-wide, via "default-wide" to "default". The osd_debug window is not found in MythCenter-wide/osd.xml and then the error message E XMLParseBase: No theme file /usr/share/mythtv/themes/MythCenter-wide/osd.xml is given. This message should tell that the window osd_debug is not found in file MythCenter-wide/osd.xml instead of telling that the file does not exist. The osd_debug window is found in default-wide/osd.xml but there is no message given when the window is found. There is definitely room for improvement here but for the issue of "hang in the editor" the messages are a red herring.

FYI, The search path for window definitions in xml files makes it possible to create a theme, e.g. default-wide, that contains only the differences with respect to the basic theme, default. In a similar way, the MythCenter-wide menu contains only the xml files that have been modified for this theme.

About the real subject of this issue, the hang in the editor. This is something I cannot reproduce here, not with TV recordings but also not with DVB radio recordings. This on my laptop running Fedora 33/Wayland/Gnome.

It would be great to have a key sequence that does always reproduce the problem. Also: does the "hang in the editor" last forever or is it e.g. always 20 seconds?

[Jpilk]

Thank you for looking at this, and for your characteristically clear explanation. I spend most of my effort trying to avoid the hangs - but can usually provoke one by pressing E repeatedly to enter and leave edit mode, with a short burst of playback each time. When it happens it lasts for 20 seconds. Sometimes after such a session there is a claim to have reached EOF, and it quits. I'm using software decode and KDE. The Player(n) count rises until the frontend is restarted.

The file here is a DVB-T radio recording, and it has a seektable. For many media files mythcommflag --rebuild will create a new seektable, but that doesn't work for files like this.

myth_edit_hang2.txt

[kmdewaal]

On my system it all works OK, also with the sequence specified.

The following messages:

2021-03-25 11:40:27.562522 W  AOG: Buffer overflow. Clipping samples.
2021-03-25 11:40:30.695890 E  GLVid: Invalid software frame

appear also in my logs. They can probably be considered harmless.

These messages:

2021-03-25 11:40:33.747782 W  Player(8): Waited 100ms for decoder to pause
2021-03-25 11:40:33.847874 W  Player(8): Waited 100ms for decoder to pause

are scary and I have seen them, also on my systems, when investigating trac ticket 13156 (see https://code.mythtv.org/trac/ticket/13156) about playing live DVB audio. This could very well be the same underlying problem.

[Jpilk]

I have been trying the 'original ffmpeg TS demuxer' which was recently restored as an option; the main reason was to look at issue#351, where it un-broke playback of a clip from the Finnish YLE channel. But I no longer get these hangups in the cutlist editor. They come back with the 'Normal' profile and demuxer.

There is also a change in the skip-back responsivity during playback. At present I'm inclined to stick with the rpmfusion ffmpeg setting - which on this quasi-el7 box is version 3.4.8, while mythffmpeg is now 4.3.2. Their configurations differ too.

[kmdewaal]

John, are you saying that this issue is fixed when you select the "Use FFmpeg's original MPEG-TS demuxer" option, as described in #351 ?

[Jpilk]

That seems to be true. I was never able to provoke the 20-second hangup at will, but it would 'just happen' during editing sessions. I have created cutlists for several recordings, both TV and Radio, with that newly-enabled option and the hang has not happened.

[Jpilk]

I'm not aware of any recent changes here, but should perhaps update. I have always been able to define the cut points eventually, but the process is still more inconvenient than it used to be, for both video and audio recordings.

When editing with the 'original MPEG-TS demuxer' I don't get the 20-second hangups, but stepping forward and back during normal playback is not 'clean' and takes a few seconds to settle down. (JYA commented that it was written as a diagnostic tool and is likely to give problems in normal use)

Editing DVB radio doesn't provide visual clues and has to be done by interrupting playback - hitting 'e'. When using the normal demuxer this will often trigger the 20-second hangup. The likelihood of this can be reduced by hitting the back-arrow when the desired cutpoint is reached and hitting 'e' when it comes round again. It helps to have a 'cut to end' defined before trying to define the (earlier) real end.

For radio, edit steps of frames or keyframes have never been reliable, and '-0.5 s' may give +1 or -16 frames. 1 s is a reliable 24 frames. This is a 'feature' and I'm not complaining.

[Jpilk]

I have the new devel/ffmpeg-resync running in Fedora 34, and tried the playback editor on a new DVB_T2 BBC_ONE HD h264 recording, using a 'Normal' profile and with cut-from-start and cut-to-end marks already set.. There are still occasional unexpected 20-second pauses on going from playback to the editor, but now there are new error messages too (GetNextFreeFrame) ; and on resuming playback after the pause, EOF is now reached and playback quits.

The Player(n) number increments until the FE is restarted.

2021-11-01 10:47:16.678585 C mythfrontend version: devel/ffmpeg-resync [v32-Pre-72726d7166] www.mythtv.org 2021-11-01 10:47:16.678589 C Qt version: compile: 5.15.2, runtime: 5.15.2 2021-11-01 10:47:16.678613 I Fedora 34 (Thirty Four) (x86_64)

2021-11-01 10:48:08.860408 I VideoOutput: SetDeinterlacing (Doublerate 1): Single Medium|CPU|DRIVER Double Basic|CPU|DRIVER 2021-11-01 10:48:08.860460 I MythDeint: Deinterlacer change: 1920x1080 YUV420P dr:1 tff:1 -> 1920x1080 YUV420P dr:1 tff:1 2021-11-01 10:48:47.029499 W Player(0): Waited 100ms for decoder to pause 2021-11-01 10:48:47.129591 W Player(0): Waited 100ms for decoder to pause

2021-11-01 10:48:48.931096 W Player(0): Waited 100ms for decoder to pause 2021-11-01 10:48:49.031183 W Player(0): Waited 100ms for decoder to pause 2021-11-01 10:48:49.060196 E GetNextFreeFrame: available:0 used:15 limbo:3 pause:0 displayed:0 decode:2 finished:0 2021-11-01 10:48:49.060204 E GetNextFreeFrame() unable to lock frame 2000 times. Discarding Frames. 2021-11-01 10:48:49.131283 W Player(0): Waited 100ms for decoder to pause 2021-11-01 10:48:49.231376 W Player(0): Waited 100ms for decoder to pause

2021-11-01 10:49:06.846619 W Player(0): Waited 100ms for decoder to pause 2021-11-01 10:49:06.946699 W Player(0): Waited 100ms for decoder to pause 2021-11-01 10:49:06.954286 E AFD: Unknown audio decoding error 2021-11-01 10:49:06.954613 E decoding error End of file (-541478725) 2021-11-01 10:49:06.957531 E decoding error End of file (-541478725) 2021-11-01 10:49:06.975557 W AOG: Buffer overflow. Clipping samples. 2021-11-01 10:49:07.223237 I TV::HandleStateChange(): Attempting to change from WatchingPreRecorded to None 2021-11-01 10:49:07.223298 I ScreenSaverDBus: Screensaver uninhibited via org.freedesktop.ScreenSaver 2021-11-01 10:49:07.223318 I ScreenSaverDBus: Screensaver uninhibited via org.freedesktop.PowerManagement.Inhibit 2021-11-01 10:49:07.223326 I ScreenSaverX11: Uninhibited screensaver 2021-11-01 10:49:07.223480 I Qt: QThread::setPriority: Cannot determine scheduler priority range 2021-11-01 10:49:07.781565 I TV::HandleStateChange(): Changing from WatchingPreRecorded to None 2021-11-01 10:49:07.781592 I TV::StartTV(): Exiting main playback loop. 2021-11-01 10:49:07.783142 N Resuming idle timer 2021-11-01 10:49:07.783164 I Qt: QThread::setPriority: Cannot determine scheduler priority range

[Jpilk]

After processing that left only the video and main audio streams in that recording the editor does not have this problem. :--)

Input #0, mpegts, from '/home/john/SGs/RecsSG3/20101_20211031195800.ts': Duration: 00:58:12.87, start: 1.400000, bitrate: 5172 kb/s Stream #0:0[0x100]: Video: h264 (High), yuv420p(tv, bt709, progressive), 1920x1080 [SAR 1:1 DAR 16:9], 25 fps, 25 tbr, 90k tbn, 50 tbc Stream #0:10x101: Audio: aac_latm (LC), 48000 Hz, 5.1, fltp At least one output file must be specified

[Jpilk]

Still using the same ffmpeg-resync version as above, I find that hangups may happen on entering the editor from playback of an unprocessed mpeg2 video recording too; but again, after processing that leaves only the video and main audio streams, no such hangups occur. With the new ffmpeg, return from a hangup seems less predictable than before.

[Jpilk]

I have the impression that https://github.com/MythTV/mythtv/commit/c5819a0682f3ee19532465ac9d7923d2c3f91975 'Restarting playback with VDPAU after PMT change' may have solved this; I have had only one editor hangup with a raw recording after determined attempts to provoke one. That was with both h264 and mpeg2video using OpenGL Normal with VDPAU acceleration in Fedora 34, and without the new ffmpeg-resync. I'll do more tests later. Thanks!

[Jpilk]

Something else that looks odd. A clip downloaded from iplayer gives me 1280x720p 50 fps .mp4.

After conversion to .ts this plays well both as a video, with no seektable, or as a recording with one.

In both cases "mythfrontend -v playback" typically shows a Std.Dev. around 7 ms: about 1/3 of the frame interval. That implies that the individual values may be scattered almost randomly over a range of 20 ms. Files with 25 fps give much smaller values. Clearly the frame interval value is correctly set for playback but not for the log calculation.

{{{ 2021-12-06 14:35:10.544425 I PlayerFPS: 49.97 Mean: 20013 Std.Dev: 8090 CPUs: 8% 6% 2021-12-06 14:35:11.543464 I PlayerFPS: 50.06 Mean: 19976 Std.Dev: 7093 CPUs: 10% 6% 2021-12-06 14:35:12.543987 I PlayerFPS: 49.98 Mean: 20006 Std.Dev: 7492 CPUs: 11% 7% 2021-12-06 14:35:13.544779 I PlayerFPS: 49.97 Mean: 20011 Std.Dev: 6869 CPUs: 10% 6% 2021-12-06 14:35:14.544840 I PlayerFPS: 50.01 Mean: 19996 Std.Dev: 4018 CPUs: 8% 13% }}}

And for the issue named in the title I'm beginning to think that DoFastForwardSecs in /mythtv/libs/libmythtv/mythplayereditorui.cpp ought to have an upper limit that corresponds to the lower limit applied in DoRewindSecs. There are often EoF reports from the decoder.

Current build info: post 4.4.1 resync {{{ 2021-12-06 15:02:32.186403 C mythfrontend version: HEAD [v32-Pre-e0120c551e] www.mythtv.org 2021-12-06 15:02:32.186407 C Qt version: compile: 5.15.2, runtime: 5.15.2 2021-12-06 15:02:32.186432 I Fedora 34 (Thirty Four) (x86_64) }}}

[Jpilk]

The high values for Std.Dev immediately above are with VDPAU decoding only and not all files show them.

After .mp4 to .ts conversion, mythcommflag --rebuild puts 'keyframes' 192 frames apart. Skip lengths within the editor are often not as expected...

[Jpilk]

While running the ffmpeg-resync branch I noticed that this 'issue' disappears when 'Interactive TV' is enabled at Frontend setup > Video > Playback OSD

That applies in fixes/32 as well. Usually I have had Interactive TV disabled; I don't remember exactly why, but I probably suspected that it might have been the cause of some instability. It's mainly intended for use in Live TV.

With '-v dsmcc' it's clear that a lot happens in dsmcc when stepping in the editor. Also, when playing a recording from the start and entering the editor, the AOG display is absent. It reappears when its 'buffer overflow reset' has been activated, for example by an editor step. Something not initialised?

It seems to me unlikely that DSMCC is directly affecting the operation of the editor, but its activity may somehow reset whatever is causing the hangup