After AudioTrack.pause(), getCurrentPosition() continues to progress

[jpearl]

I have a requirement that I know the exact position of playback after the content has been "paused" - aka after setPlayWhenReady(false).

I have tested this both with ExoPlayer1 and ExoPlayer2, but I have more logs and data for v1, so the data throughout is for v1, although the same exact behavior reproduces under v2.

My current scenario is that with exo playing, I call setPlayWhenReady(false). I need to know exactly when playback has actually been paused, and what the position of the player is at that point. So I implement an ExoPlayer.Listener that listens for onPlayWhenReadyCommitted() and checks if what was committed was a playWhenRead=true or false.

If I detect that playWhenReady = false was committed, I then query getCurrentPosition() on ExoPlayer. My assumption has been that at this point, playback has actually stopped, and getCurrentPosition() will return to me the position at which playback had stopped.

However, it looks like this is not the case. Even though playWhenReady had been committed and pause() had been called on the AudioTrack, the next pumping of doSomeWork() by ExoPlayer will result in picking up a new position from the underlying AudioTrack - the AudioTrack that had previously been paused.

From looking at logs and the behavior, it looks like AudioTrack requires one doSomeWork() iteration after calling pause() for it to report back the position that it had last flushed out from its buffers and has actually paused at. However, since this does require at least one additional doSomeWork() call AFTER playWhenReadyCommitted, this means there's no ExoPlayer API that exposes to the application when playback has actually paused and what the position is at that time.

Of course we can talk about workarounds for this, like in our onPlayWhenReadyCommitted() callback, waiting for one second, which is the doSomeWork() interval in the playWhenReady = false state. But this has the potential to introduce noticeable application latency to the user if we have to block future user interactions on waiting for this second for the playback position to land on its final value. It also makes the assumption (which may or may not be valid - I don't know the specifics of of AudioTrack work) that we only are required to wait for one doSomeWork pump of AudioTrack, not potentially more than one.

Here are some logs that demonstrate the problem (the logs of SamplePlayer logging the position were added for debugging purposes and are done on a background thread):

09-17 14:01:45.050 14007 14032 I SamplePlayer: pause
09-17 14:01:45.050 14007 14033 I AudioTrack: calling pause
09-17 14:01:45.050 14007 14033 D AudioTrack: currentPositionUs = 45327534
09-17 14:01:45.051 14007 14032 D SamplePlayer: playWhenReadyCommitted
09-17 14:01:45.051 14007 14032 D SamplePlayer: triggerStateCallback for playbackState [4]; playWhenReady [false]
09-17 14:01:45.051 14007 14032 D SamplePlayer: #0: playback paused. at position 45327
09-17 14:01:45.055 14007 14033 D AudioTrack: currentPositionUs = 45327534
09-17 14:01:45.055 14007 14033 D OMX.vendor.aac.decoder-MediaCodecAudioTrackRenderer: processOutputBuffer: positionUs = 45327534 elapsedRealtimeUs = 7269340000 bufferInfo.flags = 0 bufferIndex = 0 shouldSkip = false presentationTimeUs = 45975334
09-17 14:01:45.055 14007 14033 D AudioTrack: handleBuffer : offset = 0 size = 4096 presentationTimeUs = 45975334
09-17 14:01:45.102 14007 14032 D SamplePlayer: #1: playback paused. at position 45327
09-17 14:01:45.153 14007 14032 D SamplePlayer: #2: playback paused. at position 45327
09-17 14:01:45.204 14007 14032 D SamplePlayer: #3: playback paused. at position 45327
09-17 14:01:45.256 14007 14032 D SamplePlayer: #4: playback paused. at position 45327
09-17 14:01:45.307 14007 14032 D SamplePlayer: #5: playback paused. at position 45327
09-17 14:01:45.358 14007 14032 D SamplePlayer: #6: playback paused. at position 45327
09-17 14:01:45.409 14007 14032 D SamplePlayer: #7: playback paused. at position 45327
09-17 14:01:45.460 14007 14032 D SamplePlayer: #8: playback paused. at position 45327
09-17 14:01:45.512 14007 14032 D SamplePlayer: #9: playback paused. at position 45327
09-17 14:01:45.564 14007 14032 D SamplePlayer: #10: playback paused. at position 45327
09-17 14:01:45.615 14007 14032 D SamplePlayer: #11: playback paused. at position 45327
09-17 14:01:45.666 14007 14032 D SamplePlayer: #12: playback paused. at position 45327
09-17 14:01:45.718 14007 14032 D SamplePlayer: #13: playback paused. at position 45327
09-17 14:01:45.769 14007 14032 D SamplePlayer: #14: playback paused. at position 45327
09-17 14:01:45.820 14007 14032 D SamplePlayer: #15: playback paused. at position 45327
09-17 14:01:45.871 14007 14032 D SamplePlayer: #16: playback paused. at position 45327
09-17 14:01:45.924 14007 14032 D SamplePlayer: #17: playback paused. at position 45327
09-17 14:01:45.975 14007 14032 D SamplePlayer: #18: playback paused. at position 45327
09-17 14:01:46.026 14007 14032 D SamplePlayer: #19: playback paused. at position 45327
09-17 14:01:46.056 14007 14033 D AudioTrack: currentPositionUs = 45359530
09-17 14:01:46.057 14007 14033 D OMX.vendor.aac.decoder-MediaCodecAudioTrackRenderer: processOutputBuffer: positionUs = 45359530 elapsedRealtimeUs = 7270342000 bufferInfo.flags = 0 bufferIndex = 0 shouldSkip = false presentationTimeUs = 45975334
09-17 14:01:46.057 14007 14033 D AudioTrack: handleBuffer : offset = 0 size = 4096 presentationTimeUs = 45975334
09-17 14:01:46.058 14007 14033 D OMX.vendor.aac.decoder-MediaCodecAudioTrackRenderer: processOutputBuffer: positionUs = 45359530 elapsedRealtimeUs = 7270342000 bufferInfo.flags = 0 bufferIndex = 1 shouldSkip = false presentationTimeUs = 45998556
09-17 14:01:46.058 14007 14033 D AudioTrack: handleBuffer : offset = 0 size = 4096 presentationTimeUs = 45998556
09-17 14:01:46.077 14007 14032 D SamplePlayer: #20: playback paused. at position 45359
09-17 14:01:46.129 14007 14032 D SamplePlayer: #21: playback paused. at position 45359

I have reproduced this on multiple devices including a Nexus5 running 6.0.1

[ojw28]

It's important to understand what you mean by "exact position". Some people understand this as the exact timestamp of the video frame that's currently displayed, however note that in general positions reported during playback are at a finer granularity than video frame and are based on audio time.

Please could you clarify exactly what your use case is? Thanks.

[jpearl]

Absolutely. For my purposes, I care about the position value reported via ExoPlayer's getCurrentPosition() API.

For (unfortunate) reasons in our application layer dependency, when the user pauses, we have to report up the position that the user paused at. When the user resumes, our application layer dependency (so outside of our control), doesn't tell us strictly to "resume playback", but specifically tells us to "start playback from position X".

So in order to achieve a "resume", we're in essence told to play from the position we reported up after the "pause" (implemented as getCurrentPosition() in onPlayWhenReadyCommitted()).

The behavior above is causing problems on non-seekable content. If we're told to play from position X where X = getCurrentPosition() - 32ms (from the example above), we'll do a strict equality check on the current value of getCurrentPosition(), which will fail, we'll call seekTo(X), and because the content is non-seekable, it resets the position to 0.

In the logs above, the "SamplePlayer"/"at position" logs are logging the value of exo.getCurrentPosition()

Hope this clarifies.

Thanks

[ojw28]

Got it, but note that even if we fixed things to behave in the way you expect, I'm not sure we'd want to guarantee that the seek call wouldn't re-buffer all of the currently buffered media. Why don't you just add a check that omits the call to seekTo if X is within ~100ms or so of the current position?

[jpearl]

Sorry I should have mentioned - yes, we only conditionally call seek(), for the reason you mentioned of any overhead of rebuffering.

And yes, adding a "fudge factor"/threshold in that conditional was the work around we were considering.

in essence, changing:

public void play(ExoPlayer exo, long position) {
    if (exo.getPostition() != position) {
        exo.seeTo(position);
    }
    exo.setPlayWhenReady(true);
}

to:

public void play(ExoPlayer exo, long position) {
    if (Math.abs(exo.getPostition() - position) > SEEKING_THRESHOLD ) {
        exo.seeTo(position);
    }
    exo.setPlayWhenReady(true);
}

[ojw28]

I think you should just go with your fudge/workaround, and longer term try and resolve the constraints that are requiring you to seek instead of resume in the first place. In V2, we don't even have onPlayWhenReadyCommitted (although it's possible that it'll make a comeback).

[peddisri]

This issue happens because Android AOSP AudioTrack's Pause API handles the command asynchronously. It posts a command to pause, and returns before the playback is actually paused. So, between issuing the command and actually pausing, its possible that some amount of audio data (may be couple of frames) are played out. This internally updates the playbackheadposition. So, before and after pause, there can be some slight increment in the current position.

[ojw28]

Closing this as working as intended. The behaviour is only problematic for the original poster due to what sound like unfortunate design decisions. A fudge/workaround is known, and in the medium to long term these decisions can probably be undone ;).