Skip to content

User setPlaybackParameters() is overwritten by live adjusment #10882

Closed
Closed
User setPlaybackParameters() is overwritten by live adjusment#10882
Assignees
tonihei
Labels
bug

Description

@stevemayhew
stevemayhew
opened on Dec 22, 2022

ExoPlayer Version

2.18.2

Devices that reproduce the issue

Evolution Digital eStream 4k (https://evolutiondigital.com/estream-4k/) (probably many others)

Easiest to reproduce if device is running AC-3 audio with off-board decode.

Devices that do not reproduce the issue

No response

Reproducible in the demo app?

Yes

Reproduction steps

Pretty difficult, working on a ExoPlayer unit test case (not sure it is even possible)

The steps are to repeatedly tune to a live channel, while speed adjustment is progress, then:

  1. Disable the audio
  2. Set the speed to > 1.0. (eg 8x)

Expected result

Media plays at 2.0x (or whatever the setting was).

Actual result

Playback reverts immediately to 1.0 (with adjustment +/- 3% default).

The branch x-live-speed-overwrites-user-logging has the logging shown in the description below. Here's the sequence that causes the bug with my analysis:

  1. DO_SOME_WORK — sees renderer clock is 1.0, does live speed adjustment, sets speed to 1.03
12-21 14:34:41.564  7303  7343 I ExoPlayerImplInternal: updatePlaybackPositions() changing speed - 
		old: PlaybackParameters(speed=1.00, pitch=1.00) 
		new speed: 1.03 
		MediaClock: DefaultMediaClock isUsingStandaloneClock: false standaloneClockIsStarted: true 
		      rendererClock: PlaybackParameters(speed=1.00, pitch=1.00) 
		      standaloneClock: PlaybackParameters(speed=1.00, pitch=1.00)

12-21 14:34:41.564  7303  7343 I ExoPlayerImplInternal: handlePlaybackParameters()  updatePlaybackInfo:false acknowledgeCommand:false 
        currentPlaybackSpeed: 1.03 currentParameters: PlaybackParameters(speed=1.00, pitch=1.00) playbackParameters: PlaybackParameters(speed=1.00, pitch=1.00)

2a. DO_SOME_WORK — Renderer reports speed 1.0 (ignore 1.03 setting), and this queues a MSG_PLAYBACK_PARAMETERS_CHANGED_INTERNAL, and resets standalone clock to 1.0

12-21 14:34:41.580  7303  7343 I DefaultMediaClock: syncClocks() mismatch - renderer: PlaybackParameters(speed=1.00, pitch=1.00) standalone: PlaybackParameters(speed=1.03, pitch=1.00)

2b. In same DO_SOME_WORK message, live speed again sees speed is 1.0 (from 2a), and again trys to set it to 1.03

12-21 14:34:41.581  7303  7343 I ExoPlayerImplInternal: updatePlaybackPositions() changing speed - 
		old: PlaybackParameters(speed=1.00, pitch=1.00) 
		new speed: 1.03 
		MediaClock: DefaultMediaClock isUsingStandaloneClock: false standaloneClockIsStarted: true 
			rendererClock: PlaybackParameters(speed=1.00, pitch=1.00) 
			standaloneClock: PlaybackParameters(speed=1.00, pitch=1.00)
12-21 14:34:41.581  7303  7343 I ExoPlayerImplInternal: handlePlaybackParameters()  updatePlaybackInfo:false acknowledgeCommand:false 
		currentPlaybackSpeed: 1.03 currentParameters: PlaybackParameters(speed=1.00, pitch=1.00) playbackParameters: PlaybackParameters(speed=1.00, pitch=1.00)

  1. MSG_TRACK_SELECTION_INVALIDATED — disable audio renderer, this messages does the following:

    • update tracks, then calls updatePlaybackPositions(), which does a syncClocks(), again clocks don't match so queues MSG_PLAYBACK_PARAMETERS_CHANGED_INTERNAL
    • disables audio renderer, so standalone clock is now master, standalone clock has 1.03 and renderer vetoed it (so it has 1.0)
12-21 14:34:41.592  7303  7343 D ExoPlayerImplInternal: handleMessage() - msg: 10 playbackInfo.playbackParametersPlaybackParameters(speed=1.00, pitch=1.00)
  1. MSG_SET_PLAYBACK_PARAMETERS — handle the user requested speed.

12-21 14:34:41.655  7303  7343 D ExoPlayerImplInternal: handleMessage() - msg: 4 playbackInfo.playbackParametersPlaybackParameters(speed=1.00, pitch=1.00)
12-21 14:34:41.655  7303  7343 I ExoPlayerImplInternal: setPlaybackParametersInternal() - parameters: PlaybackParameters(speed=8.00, pitch=1.00) 
		MediaClock: DefaultMediaClock isUsingStandaloneClock: true standaloneClockIsStarted: true 
			rendererClock: none 
			standaloneClock: PlaybackParameters(speed=1.03, pitch=1.00)
12-21 14:34:41.655  7303  7343 I ExoPlayerImplInternal: handlePlaybackParameters()  updatePlaybackInfo:true acknowledgeCommand:true 
		currentPlaybackSpeed: 8.0 currentParameters: PlaybackParameters(speed=1.00, pitch=1.00) playbackParameters: PlaybackParameters(speed=8.00, pitch=1.00)
  1. Then the MSG_PLAYBACK_PARAMETERS_CHANGED_INTERNAL, queued in step 3 (track selection) overwrites the 8x speed back to 1.0
12-21 14:34:41.657  7303  7343 D ExoPlayerImplInternal: handleMessage() - msg: 16 playbackInfo.playbackParametersPlaybackParameters(speed=8.00, pitch=1.00)
12-21 14:34:41.657  7303  7343 I ExoPlayerImplInternal: MSG_PLAYBACK_PARAMETERS_CHANGED_INTERNAL updatedParameters : PlaybackParameters(speed=1.00, pitch=1.00) 
		EPII.playbackParameters: PlaybackParameters(speed=8.00, pitch=1.00) 
       	MediaClock: DefaultMediaClock isUsingStandaloneClock: true standaloneClockIsStarted: true 
           	rendererClock: none 
           	standaloneClock: PlaybackParameters(speed=8.00, pitch=1.00)

12-21 14:34:41.657  7303  7343 I ExoPlayerImplInternal: handlePlaybackParameters()  updatePlaybackInfo:true acknowledgeCommand:false 
		currentPlaybackSpeed: 1.0 currentParameters: PlaybackParameters(speed=8.00, pitch=1.00) playbackParameters: PlaybackParameters(speed=1.00, pitch=1.00)
  1. Lastly, again main loop sees renderer clock is 1.0, does live speed adjustment, sets speed to 1.03
12-21 14:34:41.658  7303  7343 I ExoPlayerImplInternal: updatePlaybackPositions() changing speed - 
	old: PlaybackParameters(speed=8.00, pitch=1.00) 
	new speed: 1.03 
	MediaClock: DefaultMediaClock isUsingStandaloneClock: true standaloneClockIsStarted: true 
		rendererClock: none 
		standaloneClock: PlaybackParameters(speed=8.00, pitch=1.00)
12-21 14:34:41.658  7303  7343 I ExoPlayerImplInternal: handlePlaybackParameters()  updatePlaybackInfo:false acknowledgeCommand:false 
		currentPlaybackSpeed: 1.03 currentParameters: PlaybackParameters(speed=1.00, pitch=1.00) playbackParameters: PlaybackParameters(speed=1.00, pitch=1.00)

Media

I'll send a live URL.

Bug Report

Activity

  1. stevemayhew
    added
    bug
    needs triage
    on Dec 22, 2022

  2. stevemayhew commented on Dec 22, 2022

    @stevemayhew
    stevemayhew
    on Dec 22, 2022
    ContributorAuthor

    PS, this bug is related to #10865 as the fact the renderer does not parrot the speed setting causes repeated MSG_PLAYBACK_PARAMETERS_CHANGED_INTERNAL events.

  3. tonihei
    self-assigned this
    on Jan 5, 2023

  4. tonihei commented on Jan 5, 2023

    @tonihei
    tonihei
    on Jan 5, 2023
    Collaborator

    If this is the same device/setup as #10865, doesn't this imply that no speed adjustment is possible (neither automatic for live adjustment nor manual)? If so, the speed is correctly reset to 1.0 presumably.

  5. tonihei
    added
    need more info
    and removed
    needs triage
    on Jan 5, 2023

  6. google-oss-bot commented on Jan 25, 2023

    @google-oss-bot
    google-oss-bot
    on Jan 25, 2023
    Collaborator

    Hey @stevemayhew. We need more information to resolve this issue but there hasn't been an update in 14 weekdays. I'm marking the issue as stale and if there are no new updates in the next 7 days I will close it automatically.

    If you have more information that will help us get to the bottom of this, just add a comment!

  7. google-oss-bot
    added
    stale
    on Jan 25, 2023

  8. stevemayhew commented on Jan 25, 2023

    @stevemayhew
    stevemayhew
    on Jan 25, 2023
    ContributorAuthor

    If this is the same device/setup as #10865, doesn't this imply that no speed adjustment is possible (neither automatic for live adjustment nor manual)? If so, the speed is correctly reset to 1.0 presumably.

    @tonihei Sorry for my late reply to this. The issues are different, it is a bit confusing, I'll get to that.

    1. Let AudioSink indicate if playback speed changes are supported to avoid unnecessary live speed adjustments #10865 - An enhancement, avoids switching speed between live adj attempt and "normal" speed. There will always be cases this is not possible (Pass-Thru AC-3 for example)
    2. User setPlaybackParameters() is overwritten by live adjusment #10882 - this issue, user speed setting is overwritten, this is a bug

    It just turns out that having an audio track that does not support speed adjustment is the easiest way to trigger this issue, that is the only real relation.

    This issue occurs because two sequences of ExoPlayer internal messages on the playback thread can result in the player overwriting the user speed setting request. The pull request #10883 explains it a little better (I hope), the core sequence is:

    1. User thread does a request to set speed to non 1.0x, message is queued to player internal
    2. Live adjustment reads current speed as 1.0x and makes and adjustment to != 1.0x
    3. Message executes to set speed from user request (MSG_SET_PLAYBACK_PARAMETERS)
    4. Msg executes with speed back from renderer (MSG_PLAYBACK_PARAMETERS_CHANGED_INTERNAL) overrides user speed setting

    As I remember, when we discussed this, the design was only the renderer/audio track would retain this internal speed setting. I agree with you, this is the correct way to treat the internal playback speed.

    Thanks for having a look, this is definitely a complicated flow.

  9. google-oss-bot
    added
    needs triage
    and removed
    stale
    need more info
    on Jan 25, 2023

  10. stevemayhew commented on Jan 25, 2023

    @stevemayhew
    stevemayhew
    on Jan 25, 2023
    ContributorAuthor

    PS, we think the LivePlaybackSpeedControl is a key feature for hospitality live playback use cases, happy to work on expanding it to more audio sink's

  11. 19 remaining items

  12. tonihei
    added
    need more info
    and removed
    needs triage
    on Feb 20, 2023

  13. stevemayhew commented on Feb 21, 2023

    @stevemayhew
    stevemayhew
    on Feb 21, 2023
    ContributorAuthor

    Ah, thanks @tonihei excellent enumeration of the 4 cases. So, I think what is happening is an unexpected consequence of case 1 or case 2.

    I put some numbers on the sequence in the original bug description, you can see the logging associated with the in the description that shows the sequence of messages in the branch. Again, the Application Thread

    1. disables audio renderer (MSG_TRACK_SELECTION_INVALIDATED)
    2. set play when ready true (MSG_SET_PLAY_WHEN_READY)
    3. sets speed != 1.0, e.g. 8.0 (MSG_SET_PLAYBACK_PARAMETERS)

    You can see the sequences in 2b. and 3. in the updated main bug description setup the errant MSG_PLAYBACK_PARAMETERS_CHANGED_INTERNAL. The fact that the change from this callback is queued to the player handler message queue sets up the possibility of state changes that invalidate the message.

    I'm very clear why my pull request is invalid, Just to riff on some ideas for MSG_PLAYBACK_PARAMETERS_CHANGED_INTERNAL , this is obviously a very complicated sequence:

    1. handling of the MSG_PLAYBACK_PARAMETERS_CHANGED_INTERNAL in step 5 when the renderer clock is no longer active seems wrong.
    2. Why not handle the PlaybackParametersListener.onPlaybackParametersChanged() synchronously (that eliminates all possible sequencing errors)
    3. Avoid attempting to live adjust speed when MSG_PLAYBACK_PARAMETERS_CHANGED_INTERNAL is pending (seems a bit like a hack, adding more conditions to the already complex check:
       // Adjust live playback speed to new position.
    if (playbackInfo.playWhenReady
        && playbackInfo.playbackState == Player.STATE_READY
        && shouldUseLivePlaybackSpeedControl(playbackInfo.timeline, playbackInfo.periodId)
        && playbackInfo.playbackParameters.speed == 1f)

    Again, thanks for your patience on this use case.

    It is on my plate to proposing a proper API for ROLE_TRICK_PLAY track usage (I'm thinking of a PlaybackParameters.setTrickplayMode(boolean)). Hopefully that can bring these use cases more front and center.

  14. google-oss-bot
    added
    needs triage
    and removed
    need more info
    on Feb 21, 2023

  15. tonihei commented on Feb 24, 2023

    @tonihei
    tonihei
    on Feb 24, 2023
    Collaborator

    Ah! Thanks for the updated logs. I can see the problem now, which only happens if we switch from renderer to stand-alone clock while MSG_PLAYBACK_PARAMETERS_CHANGED_INTERNAL is still pending. The pending change back to 1.0 is stale at this point because it refers to the renderer clock, whereas the stand-alone clock is of course perfectly happy to play any speed. Let me think about this a bit to see what we can do.

    this is obviously a very complicated sequence

    I agree. The main complication is that setting a speed on the renderer clock is not checked immediately for support, but only slightly later when it's actually applied. That's why we blindly assume it works and then use the additional MSG_PLAYBACK_PARAMETERS_CHANGED_INTERNAL callback to signal when something changed.

    1. handling of the MSG_PLAYBACK_PARAMETERS_CHANGED_INTERNAL in step 5 when the renderer clock is no longer active seems wrong.

    Yes, see beginning of my reply where I came to the same conclusion. This event must not be handled, not triggered, or handled before the switch to the stand-alone clock.

    1. Why not handle the PlaybackParametersListener.onPlaybackParametersChanged() synchronously (that eliminates all possible sequencing errors)

    Might be a possibility, but needs to be checked carefully. We always send incoming tasks as a new message (even on the same thread) to ensure the order of event execution is always the same as the order in which the events are triggered. This is more of a general rule that avoids that we even have to think about re-entrance scenarios.

    Avoid attempting to live adjust speed when MSG_PLAYBACK_PARAMETERS_CHANGED_INTERNAL is pending (seems a bit like a hack, adding more conditions to the already complex check:

    Sounds wrong, yes. It would make more sense to implement go/exoghi/10865 to avoid setting the speed at all if it's not supported.

    It is on my plate to proposing a proper API for ROLE_TRICK_PLAY track usage (I'm thinking of a PlaybackParameters.setTrickplayMode(boolean))

    Not really part of this bug, but I'm curious why you'd want to put it in there? The PlaybackParameters are really more of AudioOutputConfigurationParameters at the moment and trick-play doesn't seem to fit logically. If it's just about having an API to configure the player to change it's internal behavior for trick-play, then we probably need a separate ExoPlayer for this.

  16. tonihei commented on Feb 24, 2023

    @tonihei
    tonihei
    on Feb 24, 2023
    Collaborator

    I'll will upload a fix for this (with a test case). The solution I went for is to remove pending internal speed updates when a new speed is set. This makes sense because any newly set speed makes the previous pending message stale.

  17. tonihei
    removed
    needs triage
    on Feb 24, 2023

  18. stevemayhew commented on Feb 25, 2023

    @stevemayhew
    stevemayhew
    on Feb 25, 2023 via email
    ContributorAuthor
  19. tonihei
    added 4 commits that reference this issue on Mar 1, 2023

    Fix some playback parameter signalling problems.

    e79b47c

    Fix some playback parameter signalling problems.

    d363977

    Fix some playback parameter signalling problems.

    f690ebd

    Fix some playback parameter signalling problems.

    3e7eece
  20. tonihei
    closed this as completedon Apr 4, 2023
  21. google
    locked and limited conversation to collaborators on Jun 4, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

Labels

bug

Type

No type

Projects

No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions