Log Errors: Too slow to keep up for seqno

[RefineryX]

Describe the bug

When callingmedia_player.play_media in Home Assistant, I receive a lot of errors in the HA logs. Although the content plays successfully, I receive the following errors namely [pyatv.protocols.raop.raop] Too slow to keep up for seqno.

This appears to be present only when using a HomePod Mini. It works fine when using streaming to an Apple TV 4K.

Error log

2021-12-14 15:52:39 WARNING (MainThread) [pyatv.protocols.raop.raop] Too slow to keep up for seqno 41400 (0.710385 vs 0.711670 => -0.001284)
2021-12-14 15:52:39 WARNING (MainThread) [pyatv.protocols.raop.raop] Too slow to keep up for seqno 41423 (0.893968 vs 0.894549 => -0.000581)
2021-12-14 15:52:39 WARNING (MainThread) [pyatv.protocols.raop.raop] Too slow to keep up for seqno 41438 (1.013696 vs 1.015742 => -0.002045)
2021-12-14 15:52:40 WARNING (MainThread) [pyatv.protocols.raop.raop] Too slow to keep up for seqno 41517 (1.644263 vs 1.644280 => -0.000017)
2021-12-14 15:52:40 WARNING (MainThread) [pyatv.protocols.raop.raop] Too slow to keep up for seqno 41520 (1.668209 vs 1.669239 => -0.001030)
2021-12-14 15:52:40 WARNING (MainThread) [pyatv.protocols.raop.raop] Too slow to keep up for seqno 41524 (1.700136 vs 1.700676 => -0.000540)
2021-12-14 15:52:40 WARNING (MainThread) [pyatv.protocols.raop.raop] Too slow to keep up for seqno 41526 (1.716100 vs 1.721130 => -0.005031)
2021-12-14 15:52:40 WARNING (MainThread) [pyatv.protocols.raop.raop] Too slow to keep up for seqno 41528 (1.732063 vs 1.733939 => -0.001876)
2021-12-14 15:52:40 WARNING (MainThread) [pyatv.protocols.raop.raop] Too slow to keep up for seqno 41547 (1.883719 vs 1.884249 => -0.000530)
2021-12-14 15:52:40 WARNING (MainThread) [pyatv.protocols.raop.raop] Too slow to keep up for seqno 41549 (1.899683 vs 1.900989 => -0.001307)
2021-12-14 15:52:40 WARNING (MainThread) [pyatv.protocols.raop.raop] Too slow to keep up for seqno 41551 (1.915646 vs 1.920335 => -0.004689)
2021-12-14 15:52:40 WARNING (MainThread) [pyatv.protocols.raop.raop] Too slow to keep up for seqno 41553 (1.931610 vs 1.935224 => -0.003614)
2021-12-14 15:53:15 WARNING (MainThread) [pyatv.protocols.raop.raop] Too slow to keep up for seqno 4655 (0.949841 vs 0.951042 => -0.001201)
2021-12-14 15:53:15 WARNING (MainThread) [pyatv.protocols.raop.raop] Too slow to keep up for seqno 4657 (0.965805 vs 0.969972 => -0.004167)
2021-12-14 15:53:16 WARNING (MainThread) [pyatv.protocols.raop.raop] Too slow to keep up for seqno 4660 (0.989751 vs 0.993307 => -0.003556)
2021-12-14 15:53:16 WARNING (MainThread) [pyatv.protocols.raop.raop] Too slow to keep up for seqno 4663 (1.013696 vs 1.013705 => -0.000009)
2021-12-14 15:53:16 WARNING (MainThread) [pyatv.protocols.raop.raop] Too slow to keep up for seqno 4744 (1.660227 vs 1.661670 => -0.001444)
2021-12-14 15:53:16 WARNING (MainThread) [pyatv.protocols.raop.raop] Too slow to keep up for seqno 4764 (1.819864 vs 1.820720 => -0.000856)
2021-12-14 15:53:16 WARNING (MainThread) [pyatv.protocols.raop.raop] Too slow to keep up for seqno 4768 (1.851791 vs 1.853138 => -0.001346)
2021-12-14 15:53:16 WARNING (MainThread) [pyatv.protocols.raop.raop] Too slow to keep up for seqno 4771 (1.875737 vs 1.878665 => -0.002928)
2021-12-14 15:53:17 WARNING (MainThread) [pyatv.protocols.raop.raop] Too slow to keep up for seqno 4866 (2.634014 vs 2.636700 => -0.002686)

How to reproduce the bug?

1. Call the media_player.play_media service in HA
2. Choose HomePod as the entity
3. Reference an MP3 file for the 'Content ID' and music for 'Content Type'
4. Select 'Call Service'

What is expected behavior?

To be able to call the service, it playing and it does not show errors.

Operating System

Linux

Python

3.9

pyatv

2.1.0

Device

HomePod 15.2

Additional context

NA

[postlund]

It's not an error per se. Packet streaming is somewhat real-time and when pyatv can't keep up the pace and generate new packets in time, then you get that warning. Normally, getting a few of those is not a problem as pyatv will most likely catch up quite quickly (if it's a real problem, then there will be re-transmissions as well). I however don't want to suppress these warnings as they make it obvious if performance is the issue in case someone has problems with streaming. I might be able to accept (I.e. not log) few over a sliding window , just to filter out some noise.

[postlund]

I'm adding a threshold to only start logging these warnings if three packets in a row are late. If that happens there's likely too much stress on the system and streaming will be unstable anyway.

[RefineryX]

Great solution - thank you.

Just to clarify, does this happen because I have a weak processor? (I'm running a Raspberry Pi 4 4gb).

I have a couple of other questions which I am struggling to get answers for. Can I post them here?=

[postlund]

Let's say there are many factors to take into account. I don't think the CPU performance (RPi 4 in your case) is the biggest issue. It's much more likely the CPU load. But it's hard to say. Having a few of these are not a problem though, pyatv will catch up.

If they are related you can post them here, otherwise I prefer if you open new issues. It's easier for me to keep track and close them when done (issues tend to stay open for a long time otherwise).

[RefineryX]

They are somewhat related to the HomePods but do let me know and happy to open a new issue - though they are mainly questions at this stage.

1. Stereo Group: I have a stereo group of two HomePods. They appear as one HomePod when streaming from my phone etc and there will never be an occasion when I will use them individually. Is there a way to group these together when using HA?
2. Volume: One of my HomePods (Kitchen) is often kept at a low volume which means TTS is never heard. Is there a way for HA to remember the current volume, raise the volume to 100%, stream the TTS an then put the volume back to how it was?

[postlund]

1. I don't have any support for grouping devices, no. Supporting that is a big task and I'm not really up for that challenge yet.
2. There's no way of knowing if a HomePod (or other device) is streaming a TTS file or not, so it's tricky to handle that automatically. I see two potential ways. Either write a script that saves the volume somewhere (an input_number or whatever), changes volume, starts TTS and restores volume afterwards. That forces you to use the script though. Another way is to use an automation that triggers when the device starts to play and app_id is com.apple.tvairplayd (active process when AirPlay is used). Then do more or less the same thing: save volume, wait until state is no longer playing and then restore volume again. A bit tricky bit should be possible and will work with the regular TTS service.

[postlund]

Fixed according to my earlier comment by #1540.