Skip to content

Avoid unnecessary cast state updates#13770

Merged
balloob merged 5 commits intohome-assistant:devfrom
dersger:cast-update-pos
Apr 14, 2018
Merged

Avoid unnecessary cast state updates#13770
balloob merged 5 commits intohome-assistant:devfrom
dersger:cast-update-pos

Conversation

@dersger
Copy link
Copy Markdown
Contributor

@dersger dersger commented Apr 8, 2018

Description:

Got a lot of state entries in the recorder database due to cast updates every 11 seconds or so.

Change it so that some state entries are skipped when position hasn't changed.

Checklist:

  • The code change is tested and works locally.
  • Local tests pass with tox. Your PR cannot be merged unless tests pass

If the code does not interact with devices:

  • Tests have been added to verify that the new code works.

@balloob
Copy link
Copy Markdown
Member

balloob commented Apr 9, 2018

I am confused. I was already under the impression that we did not update the state of an entity if the position remains the same / can be calculated because player state hasn't changed 🤔

CC @OttoWinter

@dersger
Copy link
Copy Markdown
Contributor Author

dersger commented Apr 9, 2018

The component was recently changed to be polling. I believe it's a result of that.

But your comment made me think. Maybe we instead should have some generic handling of this in MediaPlayerDevice.state_attributes()?

@balloob
Copy link
Copy Markdown
Member

balloob commented Apr 9, 2018

It's difficult to make this generic as every media player has a different way of getting data. Cast is push, VLC is polling etc.

@dersger
Copy link
Copy Markdown
Contributor Author

dersger commented Apr 9, 2018

But inside MediaPlayerDevice.state_attributes() it doesn't matter if it's push or poll. What I mean is that the code there could get the old state from self.hass.states, compare it to the new state_attr from the component, and then modify the return value to keep the old position and update time in cases where an update would be unnecessary. It would then fix this type of problem for all media players.

But maybe it's a bit unconventional to change the state attributes inside MediaPlayerDevice.state_attributes().

@OttoWinter
Copy link
Copy Markdown
Member

The cast integration is now "semi-polling" indeed (since #13275, tl;dr in theory, the cast protocol notifies us of all media state changes, but in practice quite a few apps including netflix never send those callbacks out 😕). We're only in polling mode iff an app is active, but yes the issue is definitely caused by this.

So to summarise, the reason this is happening in the first place is because of media_status_position. Normally, states are never updated in the state machine if they're identical to the previous state. This is in order to keep the state machine from being flooded by polling integrations. But the state machine state equal checking code of course doesn't know about media_status_position. If we schedule a new state change it will of course have a new position and therefore also a state that is different from the last one.

I'm not 100% sure how this should be handled. Doing this inside the cast integration just seems quite messy and potentially lots of other polling media_player implementations will just copy the code over. On the other hand, I don't think there's currently a good way component.media_player.__init__ can override the state equality behavior... Another option would potentially be to store the media_started_at = now - media_position, though that would be breaking and definitely would make machine learning a bit more difficult.

@dersger
Copy link
Copy Markdown
Contributor Author

dersger commented Apr 9, 2018

I've been thinking about how to change MediaPlayerDevice.state_attributes() to handle all media players. This is totally untested but can at least show my idea:

    def state_attributes(self):
        """Return the state attributes."""
        if self.state == STATE_OFF:
            return None

        state_attr = {
            attr: getattr(self, attr) for attr
            in ATTR_TO_PROPERTY if getattr(self, attr) is not None
        }

        old_state = self.hass.states.get(self.entity_id)
        if old_state and (self.state == old_state.state and
                          ATTR_MEDIA_POSITION_UPDATED_AT in state_attr and
                          ATTR_MEDIA_POSITION in state_attr and
                          ATTR_MEDIA_POSITION_UPDATED_AT in old_state.attributes and
                          ATTR_MEDIA_POSITION in old_state.attributes):
            if self.state == STATE_PLAYING:
                pos_diff = state_attr[ATTR_MEDIA_POSITION] - old_state.attributes[ATTR_MEDIA_POSITION]
                time_diff = (state_attr[ATTR_MEDIA_POSITION_UPDATED_AT] -
                             old_state.attributes[ATTR_MEDIA_POSITION_UPDATED_AT]).total_seconds()
                if abs(pos_diff - time_diff) < 1.5:
                    state_attr[ATTR_MEDIA_POSITION] = old_state.attributes[ATTR_MEDIA_POSITION]
                    state_attr[ATTR_MEDIA_POSITION_UPDATED_AT] = old_state.attributes[ATTR_MEDIA_POSITION_UPDATED_AT]
            elif state_attr[ATTR_MEDIA_POSITION] == old_state.attributes[ATTR_MEDIA_POSITION]:
                state_attr[ATTR_MEDIA_POSITION_UPDATED_AT] = old_state.attributes[ATTR_MEDIA_POSITION_UPDATED_AT]

        return state_attr

I think both the advantage and disadvantage of that is that the component will be in less control of the attribute updates.

z"""The tests for the Cast Media player platform."""
# pylint: disable=protected-access
import asyncio
import datetime as dt
Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

module level import not at top of file

@@ -1,6 +1,7 @@
"""The tests for the Cast Media player platform."""
z"""The tests for the Cast Media player platform."""
Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

SyntaxError: invalid syntax

entity.new_media_status(media_status)
await hass.async_block_till_done()
assert ATTR_MEDIA_POSITION not in state.attributes
assert ATTR_MEDIA_POSITION_UPDATED_AT not in state.attributes
Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

undefined name 'ATTR_MEDIA_POSITION_UPDATED_AT'

with patch('homeassistant.util.dt.utcnow', return_value=now_plus_20):
entity.new_media_status(media_status)
await hass.async_block_till_done()
assert ATTR_MEDIA_POSITION not in state.attributes
Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

undefined name 'ATTR_MEDIA_POSITION'

await hass.async_block_till_done()
state = hass.states.get('media_player.speaker')
assert state.attributes[ATTR_MEDIA_POSITION] == 30
assert state.attributes[ATTR_MEDIA_POSITION_UPDATED_AT] == now_plus_20
Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

undefined name 'ATTR_MEDIA_POSITION_UPDATED_AT'

entity.new_media_status(media_status)
await hass.async_block_till_done()
state = hass.states.get('media_player.speaker')
assert state.attributes[ATTR_MEDIA_POSITION] == 30
Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

undefined name 'ATTR_MEDIA_POSITION'

await hass.async_block_till_done()
state = hass.states.get('media_player.speaker')
assert state.attributes[ATTR_MEDIA_POSITION] == 25
assert state.attributes[ATTR_MEDIA_POSITION_UPDATED_AT] == now_plus_10
Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

undefined name 'ATTR_MEDIA_POSITION_UPDATED_AT'

entity.new_media_status(media_status)
await hass.async_block_till_done()
state = hass.states.get('media_player.speaker')
assert state.attributes[ATTR_MEDIA_POSITION] == 20
Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

undefined name 'ATTR_MEDIA_POSITION'

await hass.async_block_till_done()
state = hass.states.get('media_player.speaker')
assert state.attributes[ATTR_MEDIA_POSITION] == 10
assert state.attributes[ATTR_MEDIA_POSITION_UPDATED_AT] == now
Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

undefined name 'ATTR_MEDIA_POSITION_UPDATED_AT'

entity.new_media_status(media_status)
await hass.async_block_till_done()
state = hass.states.get('media_player.speaker')
assert state.attributes[ATTR_MEDIA_POSITION] == 10
Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

undefined name 'ATTR_MEDIA_POSITION'

await hass.async_block_till_done()
state = hass.states.get('media_player.speaker')
assert state.attributes[ATTR_MEDIA_POSITION] == 10
assert state.attributes[ATTR_MEDIA_POSITION_UPDATED_AT] == now
Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

undefined name 'ATTR_MEDIA_POSITION_UPDATED_AT'

entity.new_media_status(media_status)
await hass.async_block_till_done()
state = hass.states.get('media_player.speaker')
assert state.attributes[ATTR_MEDIA_POSITION] == 10
Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

undefined name 'ATTR_MEDIA_POSITION'

@balloob
Copy link
Copy Markdown
Member

balloob commented Apr 14, 2018

Thanks for taking the time to fix this! 👍 🐬

@balloob balloob merged commit 80a3220 into home-assistant:dev Apr 14, 2018
@balloob
Copy link
Copy Markdown
Member

balloob commented Apr 20, 2018

So I am still seeing this issue locally.

See here some logs (I removed duplicate attributes and formatted for readability)

As you can see, media_position_updated_at is being increased, but media_duration or position is not.

2018-04-20 15:53:05 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=media_player.living_room,
    old_state=<state media_player.living_room=playing;
        media_duration=186.619,
        media_position=0,
        media_position_updated_at=2018-04-20T15:53:05.219675-04:00
         @ 2018-04-20T15:42:16.049785-04:00>,
    new_state=<state media_player.living_room=playing;
        media_duration=186.619,
        media_position=30.398,
        media_position_updated_at=2018-04-20T15:53:05.589218-04:00
         @ 2018-04-20T15:42:16.049785-04:00>>

2018-04-20 15:53:07 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=media_player.living_room,
    old_state=<state media_player.living_room=playing;
        media_duration=186.619,
        media_position=30.398,
        media_position_updated_at=2018-04-20T15:53:05.589218-04:00
         @ 2018-04-20T15:42:16.049785-04:00>,
    new_state=<state media_player.living_room=playing;
        media_duration=186.619,
        media_position=30.645,
        media_position_updated_at=2018-04-20T15:53:07.589727-04:00
         @ 2018-04-20T15:42:16.049785-04:00>>

2018-04-20 15:53:13 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=media_player.living_room,
    old_state=<state media_player.living_room=playing;
        media_duration=186.619,
        media_position=30.645,
        media_position_updated_at=2018-04-20T15:53:07.589727-04:00
         @ 2018-04-20T15:42:16.049785-04:00>,
    new_state=<state media_player.living_room=playing;
        media_duration=186.619,
        media_position=30.645,
        media_position_updated_at=2018-04-20T15:53:13.089250-04:00
         @ 2018-04-20T15:42:16.049785-04:00>>

2018-04-20 15:53:24 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=media_player.living_room,
    old_state=<state media_player.living_room=playing;
        media_duration=186.619,
        media_position=30.645,
        media_position_updated_at=2018-04-20T15:53:13.089250-04:00
         @ 2018-04-20T15:42:16.049785-04:00>,
    new_state=<state media_player.living_room=playing;
        media_duration=186.619,
        media_position=30.645,
        media_position_updated_at=2018-04-20T15:53:24.171143-04:00
         @ 2018-04-20T15:42:16.049785-04:00>>

2018-04-20 15:53:35 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=media_player.living_room,
    old_state=<state media_player.living_room=playing;
        media_duration=186.619,
        media_position=30.645,
        media_position_updated_at=2018-04-20T15:53:24.171143-04:00
         @ 2018-04-20T15:42:16.049785-04:00>,
    new_state=<state media_player.living_room=playing;
        media_duration=186.619,
        media_position=30.645,
        media_position_updated_at=2018-04-20T15:53:35.089597-04:00
         @ 2018-04-20T15:42:16.049785-04:00>>

@dersger
Copy link
Copy Markdown
Contributor Author

dersger commented Apr 20, 2018

I wrote the code so that it's supposed to update media_position if it doesn't increase as much as the elapsed time between old and new (and accepting a 1 second jitter as equal) in 'playing' state. It looks like that is true for all of the updates.

At 15:53:05 the position jumps 30 seconds in almost no time.
At 15:53:07 the position is almost the same but 2 seconds has elapsed in playing state.
In the others the position is the same but several seconds elapsed in playing state between each.

The later updates wouldn't have been created if the state had been 'paused' instead.
To me it looks like either state or position from the chromecast device is incorrect.

@balloob
Copy link
Copy Markdown
Member

balloob commented Apr 21, 2018

Not sure what's going on. It's also not consistent wrong, only like 80% of the time.

@dersger
Copy link
Copy Markdown
Contributor Author

dersger commented Apr 21, 2018

I did a small code review of https://github.com/balloob/pychromecast/blob/master/pychromecast/controllers/media.py.

I wonder if self.current_time = status_data.get('currentTime', self.current_time) inside MediaStatus.update() instead should be something like

new_current_time = status_data.get('currentTime')
if new_current_time is not None:
	self.current_time = new_current_time
	self.current_time_last_updated = datetime.now(timezone.utc)

Then current_time_last_updated could be used instead of dt_util.utcnow() in cast.py. But I don't really know how different apps behave.

elapsed = now - self.media_status_position_received
do_update = abs(media_status.current_time -
(self.media_status_position +
elapsed.total_seconds())) > 1
Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@dersger That shouldn't be an issue since the MEDIA_STATUS package always contains the currentTime attribute. At least that's the case with all apps I just tested: Spotify, YouTube and Netflix.

However, there's a really weird thing going on: With the packets we receive when we manually poll the media status with GET_STATUS. We don't get the actual currentTime in the track, but the current time from the last callback! So for example, if I pause and play a track at 30 seconds, we will first receive MEDIA_STATUS packages with currentTime = 30 from the callback. But even 30 and 60 seconds later when manually poll the device, currentTime in the packet will still be 30 - even though it should be 60/90 by now.

As there's no information from the cast packages about relative to which timestamp currentTime is measured, I think we can't really solve this problem :( So I'd say maybe remove the half-polling feature again?

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

ugggh. Can we distinguish between polling and non-polling updates?

Copy link
Copy Markdown
Member

@OttoWinter OttoWinter Apr 22, 2018

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

With the current pychromecast library, AFAIK not. We might be able to create two MediaControllers on two different cast socket "channels" (not actually new sockets, just IDs that identify a stream of packets), and use one of them for Push-Updates and the other one for polling updates. But that would probably just end up being a lot of spaghetti code :(

@balloob balloob mentioned this pull request Apr 27, 2018
@home-assistant home-assistant locked and limited conversation to collaborators Jul 26, 2018
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.

Projects

None yet

Development

Successfully merging this pull request may close these issues.

5 participants