search

librespot-org / librespot

Open Source Spotify client library
MIT License
4.46k stars 540 forks source link

High CPU usage and stutter for some songs #1254

Open alvaropp opened 4 months ago

alvaropp commented 4 months ago

Hi everyone!

Describe the bug I'm experiencing stutter and 100% CPU usage when playing some particular songs, and every now and then otherwise. I'm running on a Raspberry Pi Zero W Rev 1.1 and listening on a bluetooth speaker. I've basically tried to set the sound quality as low as possible as the RPi Zero doesn't seem to be able to cope with medium/high quality + bluetooth. I'm using Librespot 0.4.2 and running the following command: sudo librespot --name rpi --bitrate 96 --format S16 --ap-port 13561 --dither none --mixer softvol --initial-volume 0 --volume-ctrl log --volume-range 60 --cache /var

It plays music perfectly fine 99.99% of the time, but some particular songs present a lot of stutter and CPU usage skyrockets:

Usual CPU load:

Screenshot 2024-02-22 at 17 12 22

Max CPU load and stutter:

Screenshot 2024-02-22 at 17 10 50

To reproduce There's a couple of songs that I've noticed producing stutter very frequently—I can monitor Spotify from my laptop and see the songs' progress bar jumping around a little:

Log

➜  ~ sudo librespot --name rpi --bitrate 96 --format S16 --ap-port 13561 --dither none --mixer softvol --initial-volume 0 --volume-ctrl log --volume-range 60 --cache /var --verbose
[2024-02-22T16:25:38Z INFO  librespot] librespot 0.4.2 22f8aed (Built on 2022-08-18, Build ID: 8HLByBc0, Profile: release)
[2024-02-22T16:25:38Z TRACE librespot] Command line argument(s):
[2024-02-22T16:25:38Z TRACE librespot]      name "rpi"
[2024-02-22T16:25:38Z TRACE librespot]      bitrate "96"
[2024-02-22T16:25:38Z TRACE librespot]      format "S16"
[2024-02-22T16:25:38Z TRACE librespot]      ap-port "13561"
[2024-02-22T16:25:38Z TRACE librespot]      dither "none"
[2024-02-22T16:25:38Z TRACE librespot]      mixer "softvol"
[2024-02-22T16:25:38Z TRACE librespot]      initial-volume "0"
[2024-02-22T16:25:38Z TRACE librespot]      volume-ctrl "log"
[2024-02-22T16:25:38Z TRACE librespot]      volume-range "60"
[2024-02-22T16:25:38Z TRACE librespot]      cache "/var"
[2024-02-22T16:25:38Z TRACE librespot]      verbose
[2024-02-22T16:25:38Z TRACE librespot] Using cached credentials.
[2024-02-22T16:25:38Z DEBUG librespot_discovery::server] Zeroconf server listening on 0.0.0.0:45121
[2024-02-22T16:25:38Z WARN  librespot_core::apresolve] Ignoring blacklisted access point ap-gue1.spotify.com:443
[2024-02-22T16:25:38Z WARN  librespot_core::apresolve] Ignoring blacklisted access point ap-gew4.spotify.com:80
[2024-02-22T16:25:38Z WARN  librespot_core::apresolve] Failed to resolve Access Point: Unable to resolve any viable access points.
[2024-02-22T16:25:38Z WARN  librespot_core::apresolve] Using fallback "ap.spotify.com:443"
[2024-02-22T16:25:38Z INFO  librespot_core::session] Connecting to AP "ap.spotify.com:443"
[2024-02-22T16:25:38Z INFO  librespot_core::session] Authenticated as "<USER_NAME>" !
[2024-02-22T16:25:38Z DEBUG librespot_core::session] new Session[0]
[2024-02-22T16:25:38Z INFO  librespot_playback::mixer::softmixer] Mixing with softvol and volume control: Log(60.0)
[2024-02-22T16:25:38Z DEBUG librespot_connect::spirc] new Spirc[0]
[2024-02-22T16:25:38Z DEBUG librespot_connect::spirc] <canonical_username: USER_NAME>
[2024-02-22T16:25:38Z DEBUG librespot::component] new MercuryManager
[2024-02-22T16:25:38Z DEBUG librespot_core::session] Session[0] strong=3 weak=2
[2024-02-22T16:25:38Z INFO  librespot_core::session] Country: "GB"
[2024-02-22T16:25:38Z DEBUG librespot_playback::player] new Player[0]
[2024-02-22T16:25:38Z INFO  librespot_playback::audio_backend::rodio] Using Rodio sink with format S16 and cpal host: ALSA
[2024-02-22T16:25:38Z INFO  librespot_playback::audio_backend::rodio] Using audio device: default
[2024-02-22T16:25:38Z DEBUG librespot_core::mercury] subscribed uri=hm://remote/user/<USER_NAME>/ count=0
[2024-02-22T16:25:38Z DEBUG librespot_playback::audio_backend::rodio] Rodio sink was created
[2024-02-22T16:25:38Z DEBUG librespot_playback::player] command=AddEventSender
[2024-02-22T16:25:38Z DEBUG librespot_playback::player] command=VolumeSet(0)
[2024-02-22T16:25:38Z DEBUG librespot_connect::spirc] kMessageTypeNotify "<LAPTOP_NAME>" d5fa1c2d8fdb4a30b0d8edca82dbac15a0effa53 1369639314 1708619138679 kPlayStatusStop
[2024-02-22T16:25:58Z DEBUG librespot_connect::spirc] kMessageTypeNotify "<LAPTOP_NAME>" d5fa1c2d8fdb4a30b0d8edca82dbac15a0effa53 1369659162 1708619158527 kPlayStatusPlay
[2024-02-22T16:25:59Z DEBUG librespot_connect::spirc] kMessageTypeNotify "<LAPTOP_NAME>" d5fa1c2d8fdb4a30b0d8edca82dbac15a0effa53 1369659943 1708619159308 kPlayStatusPlay
[2024-02-22T16:26:00Z DEBUG librespot_connect::spirc] kMessageTypeNotify "<LAPTOP_NAME>" d5fa1c2d8fdb4a30b0d8edca82dbac15a0effa53 1369661007 1708619160372 kPlayStatusPlay
[2024-02-22T16:26:02Z DEBUG librespot_connect::spirc] kMessageTypeNotify "<LAPTOP_NAME>" d5fa1c2d8fdb4a30b0d8edca82dbac15a0effa53 1369663184 1708619162549 kPlayStatusPlay
[2024-02-22T16:26:03Z DEBUG librespot_connect::spirc] kMessageTypeLoad "<LAPTOP_NAME>" d5fa1c2d8fdb4a30b0d8edca82dbac15a0effa53 1369664392 1708619162549 kPlayStatusPlay
[2024-02-22T16:26:03Z DEBUG librespot_connect::spirc] State: context_uri: "spotify:album:09ZGdaL9F1eSqKS8U9sKFt?si=1002dc2f30404d33" index: 4 position_ms: 3559 status: kPlayStatusPlay position_measured_at: 1708619163819 context_description: "" shuffle: false repeat: false playing_from_fallback: true row: 0 playing_track_index: 4 track {gid: "\200\321N\351\351\006J\241\242\224\3301\360\302\330\345"} track {gid: "\2178\300\317p\013J3\245xwj7\3142\""} track {gid: "H\253\n\236\274uL\203\242gI,\024\000\266^"} track {gid: "\035Ac-|\376C\010\272\024\226\365L\275\222\372"} track {gid: "\305[\303\3769\303FO\236\342r\'\026\230L&"} track {gid: ":\263u\227j\374Lg\227\333m\030\375\207\362B"} track {gid: "Q\303\252\252=\206D\257\246\\\273{\365I\264\035"} track {gid: "\316\373\351\004\tEE\026\206\3648\203\023\260\033?"} track {gid: "\345\213\342\321\024\360M{\246~\331\207\006\360G\312"} track {gid: "`@s\343\013\315IT\276E<IY\213\361]"} track {gid: "9\275\237\345l\224E-\203\025\366?.\332\263\027"} track {gid: "\335\357\271\307i\253I\213\227m\360\033t\331p\001"} track {gid: "\232~\375\304j}M\257\246=#T@`lf"} track {gid: "\002\'\264<\212\323M/\263\016\340\026\200\\\312{"} track {gid: "U\323\013%\216\326Nj\216\031\005\200Y~\256\300"} track {gid: "\377\236\375\031=?B\223\256\277\204wC\216\361\346"}
[2024-02-22T16:26:03Z DEBUG librespot_connect::spirc] Frame has 16 tracks
[2024-02-22T16:26:03Z DEBUG librespot_playback::player] command=SetAutoNormaliseAsAlbum(true)
[2024-02-22T16:26:03Z DEBUG librespot_playback::player] command=Load(SpotifyId { id: 262334389395457805104157627534888422438, audio_type: Track }, true, 3559)
[2024-02-22T16:26:03Z TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusPlay]
[2024-02-22T16:26:03Z TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusPlay]
[2024-02-22T16:26:03Z INFO  librespot_playback::player] Loading <Requiem, K. 626: III. Sequentia: c. Rex tremendae (Orch. Süssmayr, Beyer) - Live> with Spotify URI <spotify:track:60pqnhyfkGHQr4wcvD1nhA>
[2024-02-22T16:26:03Z DEBUG librespot_audio::fetch] Downloading file 630a38dd52e4dc70cdfa089b6006f9c62900bbf2
[2024-02-22T16:26:03Z DEBUG librespot::component] new ChannelManager
[2024-02-22T16:26:03Z DEBUG librespot::component] new AudioKeyManager
[2024-02-22T16:26:04Z INFO  librespot_playback::player] <Requiem, K. 626: III. Sequentia: c. Rex tremendae (Orch. Süssmayr, Beyer) - Live> (104506 ms) loaded
[2024-02-22T16:26:04Z TRACE librespot_playback::player] == Starting sink ==
[2024-02-22T16:26:04Z TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusPlay]
[2024-02-22T16:26:04Z TRACE librespot_connect::spirc] ==> kPlayStatusPlay
[2024-02-22T16:26:06Z DEBUG librespot_audio::fetch] File 630a38dd52e4dc70cdfa089b6006f9c62900bbf2 complete, saving to cache
[2024-02-22T16:27:14Z DEBUG librespot_playback::player] command=Preload(SpotifyId { id: 78027029931689442831697607988427092546, audio_type: Track })
[2024-02-22T16:27:14Z DEBUG librespot_playback::player] Preloading track
[2024-02-22T16:27:14Z INFO  librespot_playback::player] Loading <Requiem, K. 626: III. Sequentia: d. Recordare (Orch. Süssmayr, Beyer) - Live> with Spotify URI <spotify:track:1MLzdPny9GBqK7WUZ27irE>
[2024-02-22T16:27:14Z DEBUG librespot_audio::fetch] File 870783ba1f6eee22419914daeb4ab572da8c780b already in cache
[2024-02-22T16:27:14Z INFO  librespot_playback::player] <Requiem, K. 626: III. Sequentia: d. Recordare (Orch. Süssmayr, Beyer) - Live> (304493 ms) loaded
[2024-02-22T16:27:38Z DEBUG librespot_core::session] Session[0] strong=3 weak=4
[2024-02-22T16:27:44Z DEBUG librespot_connect::spirc] At track 6 of 16 <"spotify:album:09ZGdaL9F1eSqKS8U9sKFt?si=1002dc2f30404d33"> update [false]
[2024-02-22T16:27:44Z TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusPlay]
[2024-02-22T16:27:44Z DEBUG librespot_playback::player] command=Load(SpotifyId { id: 78027029931689442831697607988427092546, audio_type: Track }, true, 0)
[2024-02-22T16:27:44Z TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusPlay]
[2024-02-22T16:27:44Z TRACE librespot_connect::spirc] ==> kPlayStatusPlay
[2024-02-22T16:29:38Z DEBUG librespot_core::session] Session[0] strong=3 weak=4

Host (what you are running librespot on):

Additional comments Are there any other settings you can recommend tweaking to reduce CPU usage even more?

roderickvd commented 3 months ago

You can try using Also directly, instead of through Rodio which will consume some extra cycles especially when resampling. Unfortunately we have started waving goodbye to support to the original Zero, which is starting to get underpowered. Older versions should run OK on it.