mikebrady / shairport-sync

AirPlay and AirPlay 2 audio player
Other
7.32k stars 574 forks source link

use_precision_timing causes playback to fail on raspberry pi #1430

Closed ben-willmore closed 2 years ago

ben-willmore commented 2 years ago

I noticed a new issue with use_precision_timing. In normal use, playback very occasionally fails randomly, producing glitched sound (a repetitive pulse of noise) that doesn't recover. Although the steps to reproduce require Apple Music, this does happen using other sources, and I think it results from rapidly starting and stopping the stream to the speaker.

I can reproduce this reliably on two machines as follows:

When the sound resumes, it will be glitched (100% reliability for me).

I can't reproduce this using Spotify as the source (perhaps because it fades the music out rather than actually stopping and starting the stream). I also can't reproduce it with use_precision_timing set to off.

This is reminiscent of #1158 (which is why it occurred to me to check the precision timing setting) but it is not the same, and that issue was fixed before 3.3.9.

Here is an example error log:

...
Feb 10 15:02:05 pi-music shairport-sync:          0.000043855 "player.c:1020" flush request: flush done.
Feb 10 15:02:05 pi-music shairport-sync:          0.000067708 "player.c:1029" flush request: request dropped.
Feb 10 15:02:05 pi-music shairport-sync:          0.003649682 "player.c:1110" first_packet_time set for frame 2647874760.
Feb 10 15:02:06 pi-music shairport-sync:          1.505709241 "player.c:1175" Change in estimated first_packet_time:   0.0795 milliseconds.
Feb 10 15:02:06 pi-music shairport-sync:          0.087218891 "player.c:2349" Large positive sync error: 32125.
Feb 10 15:02:06 pi-music shairport-sync:          0.000125260 "player.c:989" flush request: flush frame 2647911109 active -- buffer contains 65824 frames, from 2647879336 to 2647945159
Feb 10 15:02:06 pi-music shairport-sync:          0.000042396 "player.c:1020" flush request: flush done.
Feb 10 15:02:06 pi-music shairport-sync:          0.000069218 "player.c:1029" flush request: request dropped.
Feb 10 15:02:06 pi-music shairport-sync:          0.002287237 "player.c:1110" first_packet_time set for frame 2647945160.
Feb 10 15:02:08 pi-music shairport-sync:          1.506630593 "player.c:1175" Change in estimated first_packet_time:   0.2315 milliseconds.
Feb 10 15:02:08 pi-music shairport-sync:          0.087234880 "player.c:2349" Large positive sync error: 32084.
Feb 10 15:02:08 pi-music shairport-sync:          0.000130208 "player.c:989" flush request: flush frame 2647981468 active -- buffer contains 65824 frames, from 2647949736 to 2648015559
Feb 10 15:02:08 pi-music shairport-sync:          0.000044323 "player.c:1020" flush request: flush done.
Feb 10 15:02:08 pi-music shairport-sync:          0.000069531 "player.c:1029" flush request: request dropped.
...
mikebrady commented 2 years ago

Many thanks for the report, which I’ll check out.

mikebrady commented 2 years ago

I noticed a new issue with use_precision_timing. In normal use, playback very occasionally fails randomly, producing glitched sound (a repetitive pulse of noise) that doesn't recover. Although the steps to reproduce require Apple Music, this does happen using other sources, and I think it results from rapidly starting and stopping the stream to the speaker.

I can reproduce this reliably on two machines as follows:

  • Press play in Apple Music and wait for music to start
  • Press play/pause 6 times quickly (i.e. end on play rather than pause)

When the sound resumes, it will be glitched (100% reliability for me).

Thanks again for this report.

When you press play/pause repeatedly, do you wait each time for the music to resume before pausing it again? In other words, is it:

  1. play, \, pause, play, \, pause... or

or

  1. play, \, pause, play, pause, play, pause...

Also, what output device are you using, please?

ben-willmore commented 2 years ago

For the glitches reported above, I was just hitting play/pause as fast as I could, not waiting for the music to resume. My output device is a hifiberry-compatible ALSA device (configured as 'hw:0').

Today, I can reproduce the glitch (100% reliability across 5+ attempts, including rebooting the pi, and trying different tracks from Apple Music) simply by pressing play, waiting for the music to start then clicking on the timeline to jump to another point in the track. Here is a sample verbosity 3 log output.

log.txt

With precision timing OFF, I still can't reproduce the glitch by either method (even with 20 start/stops in quick succession).

mikebrady commented 2 years ago

Very interesting, thanks!

ben-willmore commented 2 years ago

(I didn't mention that this is with airplay 1; I didn't know there is now airplay 2 support, which is cool)

mikebrady commented 2 years ago

Thanks Ben!

mikebrady commented 2 years ago

Hi Ben, over at #1427, it seems that a bug in the RPi handling of USB audio might be to blame. Could that be relevant in your situation?

[Update] Actually, scratch that -- you're using a non USB audio device...

[Update 2] It might still be worth trying anyway… 🤔

ben-willmore commented 2 years ago

Sorry for the delay. With a lot more testing, this glitch is more stochastic than I saw in the original report above. Some days, it happens reliably, some days it doesn't, so I suspect that gnarly details of network conditions are relevant (which probably makes this very hard to debug).

Given the stochasticity, it's tricky to give a completely clear picture but here goes:

With Airplay 1, and use_precision_timing off, I have been running happily for months without noticing a glitch. I can occasionally reproduce the periodic sound glitch by aggressively start/stopping or scrubbing in Apple Music. The glitch sometimes recovers spontaneously.

With Airplay 1 and use_precision_timing on, the above glitch sometimes happens in normal use of Apple Music.

With Airplay 2, I occasionally get silent play (like #1427) when play "restarts" in Apple Music; more likely to happen with aggressive start/stopping/scrubbing; usually recovers if you skip to next track. I don't see any convincing effect of use_precision_timing.

My impression is that both glitches are more common if audio_backend_buffer_desired_length_in_seconds is long (1 second or more).

ben-willmore commented 2 years ago

Sorry, i forgot the whole point of the message above, which was that there is no clear effect of disable_standby_mode on either Airplay 1 or 2.

mikebrady commented 2 years ago

Hi Ben. Thanks for this very comprehensive and thorough analysis. The problem could indeed be associated with differing network conditions. It could also be associated with unusual or unforeseen interactions between different threads. (These two possibilities might, of course, be connected.)

You note that long values of audio_backend_buffer_desired_length_in_seconds may make the issue more likely to occur -- I'll play around with that idea and see if I can get any further.

The disable_standby_mode setting would be expected to have an effect if there was some problem closing and opening the alsa driver. This seems to have been the case with #1427 with a (possibly) faulty USB driver to blame. If there isn't a problem with closing and opening the alsa device -- as seems to be the case with the use of the hifiberry I2S driver -- the disable_standby_mode setting wouldn't be expected to have an effect, as your testing indeed suggests.

Thanks again.

github-actions[bot] commented 2 years ago

This issue has been inactive for 45 days so will be closed 7 days from now. To prevent this, please remove the "stale" label or post a comment.