radio channels: mythfrontend hang (endless loop) when exiting 'LiveTV' and delays on switching channels

[Stephan Suerken <absurd@…>]

Hi!

When entering 'LiveTV' on a preselected (DVB-S) audio-only channel, exiting 'LiveTV' consistently ends in an endless loop, hanging mythfrontend.

Note that when entering 'LiveTV' and then switching the channel to some audio-only channel, exiting 'LiveTV' suprisingly will work. I however always notice a huge delay (~10s) when switching from an audio-only to some other channel.

For the switching delay, the relevant code is in a loop in MythPlayer::PauseDecoder() and MythPlayer::UnpauseDecoder(); this has a 'max tries protector', so this eventually works.

For the hang, the relevant code is in a loop in MythPlayer::SetDecoder(); this one has no 'max tries protector', so it hangs mythfrontend (audio is happily playing on).

So afaiu, maybe PauseDecoder() can't actually pause (but this is ignored after some delay), and then later SetDecoder() can't get a lock, and that is not ignored (?).

Fwiw1, this is how I can reproduce this, always, on 29-fixes (ed4356116a), several frontend installations, various hardware (backend using DVB-S/Astra):

1. start mythfrontend, enter 'LiveTV'.
2. Switch to an audio-only (radio) channel.
3. Leave and re-enter 'LiveTV' (will now play that preselected radio channel).
4. Leave 'LiveTV' (Esc) => HANG. mythfrontend can only be killed to fix this.

Fwiw2, on hang, the log repeated forever is

2017-10-18 15:51:42.714971 I  Player(0): Waited 10ms for decoder lock

and strace shows the attempts on locking forever

futex(0x557461a1ec38, FUTEX_WAIT_PRIVATE, 3, {tv_sec=0, tv_nsec=10000000}) = -1 ETIMEDOUT (Connection timed out)

Fwiw3 ;), this not a new problem, I remember having similar problems at least with 0.28.

Thx!

S

[Stephan Suerken <absurd@…>]

Hi,

some additional notes:

• In the mean time, I have updated to 29-fixes (83b32140f0) -- no changes.
• The "hang" is actually not necessarily forever - at least on one occasion, it took ~30 Minutes until it finally got a lock and exited to the menu.
• A workaround is to pause ("p") first, then exit ("ESC").

I really hope someone can produce this too, and shed some light on it ;).

Thx!

S

[absurd34]

Hi,

still the same behavior with version 30.0.

Hth,

S

[Peter Bennett]

Unfortunately I cannot help since I receive no DVB radio in the USA (or if I do I don't know about it!). This ticket is not assigned so will likely not get any attention. You may get help if you find a MythTV developer who has access to DVB radio and is willing to look at it. That probably means you need a developer in Europe. Alternatively you could develop a patch yourself and submit it here for consideration.

[Klaas de Waal]

I can reproduce this on today's master.

The steps are:

• In main menu, select "Watch TV"
• It now plays either an audio or a TV channel
• Change to another audio channel
• Press Esc

Now the never-ending stream of error messages appears:

2019-05-05 12:23:49.695885 I  Player(0): Waited 10ms for decoder lock
2019-05-05 12:23:49.706023 I  Player(0): Waited 10ms for decoder lock
2019-05-05 12:23:49.716184 I  Player(0): Waited 10ms for decoder lock

When "Watch TV" starts in an audio channel, it is possible to Esc back to the menu and select "Watch TV" again, any number of times without problems. It looks like the problem is triggered by the change to another channel.

It does not make any difference if the channel change is done via the program guide or via the arrow keys (up or down) followed by Enter.

It looks like it already goes wrong immediately after the channel change; although the channel does play the sound is initially stuttering and, more important, the following messages appear:

2019-05-05 12:33:01.043431 N  Player(0): Waited 105ms for video buffers AAAAAAAAAAAAAAAAAAAAUUUUUUUUUUUP
2019-05-05 12:33:02.044140 N  Player(0): Waited 105ms for video buffers AAAAAAAAAUUUUUUUUUUUAAAAAAAAAAAP
2019-05-05 12:33:03.111735 N  Player(0): Waited 105ms for video buffers UUUUUUUUUUUAAAAAAAAAAAAAAAAAAAAP

These messages are not present when the first audio channel is played. So after the channel change a TV channel, with video, is expected and that is clearly wrong.

[Klaas de Waal]

The problem can be reproduced with a signal from Astra 1 satellite, "GFD Service", with playback started from the guide. No channel up/down needed.

The sequence, in mythfrontend:

• Select Program Guide
• Select program "GFD Service"
• Select "Watch this channel"

Then on the console after a short while the same messages appear:

...
2019-05-09 10:13:12.524080 W  Player(0): Waited 100ms for decoder to pause
2019-05-09 10:13:12.624296 W  Player(0): Waited 100ms for decoder to pause
2019-05-09 10:13:12.724465 W  Player(0): Waited 100ms for decoder to pause
2019-05-09 10:13:17.830105 E  Player(0): Failed to stop decoder loop.
2019-05-09 10:13:17.840290 I  Player(0): Waited 10ms for decoder lock
2019-05-09 10:13:17.850442 I  Player(0): Waited 10ms for decoder lock
...

Channel info as logged by a mythtv-setup scan:

qpsk:12031500:GFD Service::133:133:3501:4=4:dvb 73501:cnt(pnum:1,channum:382)

[Klaas de Waal]

I've been looking into this but Live TV is a complicated piece of code and I have not found a quick fix. This definitely needs more eyeballs than just mine.

Below are my notes on the various issues.

1. Startup delay of about 20 seconds for audio channel

Sequence:

• Select menu Program Guide
• Select radio channel
• Enter gives popup menu
• Select "Watch this channel" (done here on 22:08:06)

It takes now more than 20 seconds

2019-05-28 22:08:15.350882 W  RingBuf(/mnt/ava/recordings/10101_20190528200808.ts): Taking too long to be allowed to read..
2019-05-28 22:08:21.529038 W  RingBuf(/mnt/ava/recordings/10101_20190528200808.ts): Taking too long to be allowed to read..

Playing starts at 22:08:27, 21 seconds after the start.

As I understand it, the Live TV code sets up a ringbuffer and it expects a stream with a rate of 8000kbit/second:

2019-05-28 22:08:08.106298 I  RingBuf(/mnt/ava/recordings/10101_20190528200806.ts): CalcReadAheadThresh(8000 Kb)
                         -> threshhold(3584 KB) min read(320 KB) blk size(128 KB)

It waits until it has read at least 320kByte before it starts to play. This corresponds to about 20 seconds of music.

The way forward is to make the expected bitrate and the associated buffer sizes dependent on the type of stream that is going to be received. This information is not yet present in the database but it can be when ticket #8774 is implemented.

2. Endless loop/hang on "jump forward" in live audio

It is not necessary to switch to another audio channel to get into the "endless loop/hang" state from which no recovery is possible. A "jump forward" (right arrow) which is in my setup about 45 second has the same effect.

If you start audio then it starts to play after 20 seconds. The "Info" (press "i" key) bar shows that the audio is then about 20 seconds delayed, which is consistent. A "jump forward" tries to make this gap as close as possible. The state is now the same as when a channel switch has been made.

This is consistent; when a channel switch is made the audio starts to play quite soon, albeit with stuttering; it does NOT wait for 20 seconds/320kB now but it plays immediately.

3. What goes wrong (tentative analysis)

Crucial is the call to "decoder->GetFrame?" in mythplayer.cpp:3876

    if (ffrew_skip == 1 || decodeOneFrame)
        ret = decoder->GetFrame(decodetype);

When the system is working OK then this function is called for every video frame, about every 40 milliseconds. It goes wrong when this function does never return. That is what happens after an audio "jump forward" or channel change. When the decoder->GetFrame? does not return then the code surrounding it, which tries to kill the decoder when e.g. Escape is pressed, is never executed anymore. This is essentially the "endless loop/hang" condition.

It did confuse me for a while that there are actually video frames processed when playing an audio-only channel. Apparently, what happens is that it is detected somewhere that there is no video and hence dummy video frames are generated so that the existing TV (video + audio) playback mechanism can be used also for audio-only channels. It looks as if the generation of the dummy video frames is halted when there is not enough data in the ringbuffer. If you pause (press "p") for while and then continue again there is enough data in the ringbuffer, the decode->getFrame() gets video frames again and everything works OK. However, if you do not pause then the ringbuffer will never fill again, because the audio playback consumes data as fast as it is received.

4. Playback of data-only channel

Live playback of the "GDS Service" channel, as noted by me in comment:6, results in the same "endless loop/hang" condition. Here also the decoder->getFrame() function does never return.

In this case however it is somehow logical, as the "GDS Service" channel does contain only data (software download etc) and no video or audio.

It is most likely a bug that this channel is in the channel list when only TV or TV+Audio channels are selected in the channel scan. To be investigated.

When playing back a recording of "GDS Service" the recording is read to the end and no error is given.

It does make sense to give an error message when trying to play back a data-only channel, either live or recorded. For this it would be useful to have information about the channel in the database, as is the subject of ticket #8774.

Note that it can make sense to record data-only channels, one might be interested in the data for other purposes than playback.

[Klaas de Waal]

The problems described in this ticket are still present in today's master. I will not be able to fix this in a reasonable time frame, hence this ticket is now "New" again to allow any developer to pick this up.

[Klaas de Waal]

Tested the "Live Radio" (Live TV with a DVB radio channel) with today's master.

The status is:

• The 20 second wait time before the audio starts is still present
• No endless lock anymore, the frontend stays responsive but it may take some time
• Channel up/down gives stuttering audio; pausing the playback for a few seconds and then resume fixes this for this channel while it is playing
• Stuttering comes from synchronization with video (which is the "dummy" video generated by mythtv itself)

Log file of the frontend is attached.

[Klaas de Waal]

"Live Radio" (Live TV with DVB radio channel) with channel up/down and pause/play.

[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