Pausing: video and audio stop about 2 s apart

[laz]

I'd mentioned this in the thread about skipping and it may or may not be connected.

Pressing pause during playback of a recording always seems to take about 2 s to actually stop playback. About half of the time, the video freezes instantly but the audio carries on for a couple of seconds before stopping.

If I then unpause, both video and audio start but the video runs speeded up for a second or so, presumably to catch up with the audio that stopped about 2 s in front when it paused. I thought it was doing this every time but not when I've looked a bit more closely.

Before an earlier update from git, I was seeing things like:
23:18:01.831696 [debug]  2015 Player - Switch state from 1 to 2
23:18:01.833666 [debug]  2015 Video - enter pause
{snip}
23:18:04.007473 [debug]  2015 Video - CommandFinished waited too long 31dc40 0 2
23:18:04.008880 [debug]  2015 Audio -  pause aud_rend idle ChangeComponentState
23:18:04.010742 [notice] 2015 Video - eventHandler 31dc40 0 0 2 0
23:18:04.012784 [debug]  2015 Player - UNLOCKING
23:18:04.013961 [debug]  2015 Audio - OMX_EmptyThisBuffer 5 failed 80001018 2

About a 3 s gap after entering pause before the CommandFinished timeout from the video and also an error from OMX_EmptyThisBuffer from the audio.

Trying this again now (after the git update today to remove some deadlocks) I see the same behaviour but I can't see the same errors in the debug output!

VVideoRec::drawBarClocks seems to be called about 18 times on pausing: is that correct? It just seems to be redrawing the same thing.

Laz

[MartenR]

It is probably the Command Finished waited too long, because it has a 2 second timeout.
Unfortunetely the interesting logs are inbetween enter pause and waited too long, where you have snipped out the log.
(So please post more details!)

Marten

[laz]

The chunks of log I posted were coped from the other thread on the skipping problems (about the 5th post or so), i.e. from before the latest changes in git.

Since then, I think I've seen the "waited too long" messages but I've only outputted debug logs to a console rather than to a file so far (I'm trying to keep a small child out of trouble at the same time!).

However, a few more observations that may help until I can save some debug output this evening. If I play back a recording and skip at some point, if I pause several minutes later, I get the delay as described and when the progress bar and times are eventually shown, they show the position from the previous skip rather than the correct current position.

It looks like it fails to retrieve the real current position when going into pause and uses the previous value from the skip. If I press OK (during normal playback), the correct position is shown immediately.

When I unpause, the progress bar and time jump ahead instantly to the correct position.

So is the timeout when it is trying to get the current position when going into pause? It seems odd that it works straight away at other times!

It definitely feels like a very timing-dependent problem. I'm running this over an ssh session so that the debug output also streams across the network, rather than running it locally on the console, and so that may also affect the timing! (Both vdr server and raspberry pi are plugged into the same 100 MBit switch so it should be fairly quick.)

The joys of multi-threading...

Laz

[laz]

I've attached a couple of logs that I've just saved to (hopefully) help track down the 2 s delay I see when pausing. This is with latest git.

Descriptions of file vomp_pause.log:
I started up vompclient, played a recording from the beginning. Left it to play for a minute or two.

I pressed pause: both video and audio carried on for ca. 2 s then they both stop and the progress bar appears showing a time of 0:00:04 (the time when the initial OSD timed out).

I pressed play and the time flashed something briefly before jumping to 0:01:37, audio starts normally and the video played rapidly for ca. 1 s (I think: see below). Then I exited vompclient.


Descriptions of file vomp_OK_pause.log:
The same as above but I pressed OK at 0:01:10 and then waited for a minute or so before pressing pause. This time after the 2 s delay, the progress bar showed 0:01:14 (the time when I pressed OK + 4 s OSD timeout).

I pressed play and the time briefly flashed 0:01:14 (I think) and then changed to 0:02:26.


Sometimes the video stops instantly and the audio carries on, whereas other times they both stop together after the 2 s delay. Whichever happens, after unpausing, the video is initially rapid, as it tries to resync. I think the rapid-video sequence after unpausing is longer when the video stops before the audio. (Not easy to test!)

My current thoughts are that the current position is unobtainable on pausing and after a timeout, the previously stored value is used. I may have a go at disable showing the progress bar on pausing to see if that is where the problem lies.

Laz

[davep]

In omxplayer, pausing is handled by setting the replay speed to zero - audio and video freeze instantly and continue as normal when the pause is deselected. I presume the same solution would not work on Vomp?

[MartenR]

@davep
The way pausing is handled has historical reasons, so if there is a better way, I will look into this.
Can you point me to the corresponding lines in omxplayer git?

Marten

[davep]

The processing of the pause command is in omxplayer.cpp around line 659

Code Select Expand


      case 'p':
        m_Pause = !m_Pause;
        if(m_Pause)
        {
          SetSpeed(OMX_PLAYSPEED_PAUSE);
          m_av_clock->OMXPause();
        }
        else
        {
          SetSpeed(OMX_PLAYSPEED_NORMAL);
          m_av_clock->OMXResume();
        }
        break;

However when I look into the code more deeply there is rather more happening than simply setting the speed to zero, so it may not be possible to use the same idea.
.

[MartenR]

@davep
Thanks for the suggestion.
Works like a charm (hopefully).
Now in git.

Marten

[laz]

Typical! I spend ages working out what was causing the delay and it gets fixed by a totally different method!



Still, it's nice to know your way around a bit of code (and I'm not convinced I could have fixed what I was looking at!).

A quick test and it seems to be working perfectly, i.e. pausing and unpausing as expected.

Keep up the good work!

Cheers,

Laz

EDIT: Sometimes there is a very brief loss of audio 2 s after playback is resumed. Is this be the timeout in VideoOMX::CommandFinished again? I've not looked in the debug output yet...

[MartenR]

EDIT: Sometimes there is a very brief loss of audio 2 s after playback is resumed. Is this be the timeout in VideoOMX::CommandFinished again? I've not looked in the debug output yet...

No this sounds, as if one buffer is lost, I maybe add later some code, that may prevent this. (2s is also the period of buffered audio in omx).

Marten

[laz]

No this sounds, as if one buffer is lost, I maybe add later some code, that may prevent this. (2s is also the period of buffered audio in omx).

Marten

It isn't that noticeable, really. I'm estimating the audio drop-outs to be about half a second or less (occurring about 2 s after unpausing). Having said that, it's less intrusive than a glitch caused by an error in the DVB stream!



Cheers,

Laz

[MartenR]

Try the new git, may be it helps, if not I do not know what is happening.

Marten

[laz]

Hmmm...a quick test of a new build and it still seems to do the audio drop-out (at least for me).

I wouldn't worry too much about this one: it's only a slight cosmetic thing! I'll try to do a bit more in-depth testing and debugging later on.

Bizarrely, I don't think it does it every time but that could just be it happening coincidentally with a quiet part of the soundtrack!

Laz

[MartenR]

Hmmm...a quick test of a new build and it still seems to do the audio drop-out (at least for me).

I did not test it. So I have no idea what causes this, since the problem is minor I will not investigate it further now.

Marten