High cpu load at playback

[derron7]

Hello, for some time (probably since the update to 8.2.0) I have had problems with a high CPU load at all times during playback. You could think that the server is mining cryptos ;)

I use LMS in a Debian 9 container with an Intel NUC I5. Usually it should not be challenged. Several Squeezeboxes and piCorePlayers are connected. It doesn't matter which player I choose.

Were there any changes to the playback in the last update(s)?

Are there logging features to help you/me find the problem?

[michaelherger]

What process is using the CPU? Are you using Spotty? There's currently an issue with Spotty where using it in Connect mode would cause high CPU load.

[derron7]

It's the squeezeboxserver process. I don't use Spotty. My active plugins are only:

1. Datum und Zeit (v.10)
2. Presets bearbeiten (v1.0)
3. Radio (v1.0)
4. Volltextsuche (v1.0.0)
5. Wiedergabeliste speichern (v1.0)
6. AirPlay bridge (v0.4.62.3)
7. YouTube (v0.143.0)

//edit: I disabled all plugins for testing with the same result.

[mherger]

What kind of content are you playing? Is transcoding involved? What endpoint are you using?

[derron7]

It's a radio stream without transcoding. But that seams to be the right direction. Because everything is fine with an mp3 stream. But if I try AAC, then the higher load begins:

1. MP3@192kb/s CBR: 0.3% CPU load
2. AAC@128kb/s CBR (48.0 kHz): 43%-90% CPU load URL: http://opml.radiotime.com/Tune.ashx?id=s120806&formats=aac,ogg,mp3&partnerId=16&serial=0a7fe3e99e667cee128097c248b756b1 final URL: http://d121.rndfnk.com/ard/dlf/03/aac/192/stream.aac?aggregator=tunein&sid=21HPCAVucvKlxgQfRUm5SaHI296&token=z4Qzk0vuBk3U9GlD9ydHIDlH1JgVndlpbY-TeQYmXVk&tvf=a12-A4r7uRZkMTIxLnJuZGZuay5jb20

If I switch to the mp3-stream, immediatly I get <1% load. If I press Pause/Off nothing changes for a long time (means high CPU load).

[michaelherger]

Ok, I can confirm high load. But it's more like 45% on a Pi4. I'll look into this. Or maybe @philippe44 has a great idea (cough, cough)? 😀

[michaelherger]

Can you confirm you're using "Proxied Streaming" (Settings/Player/Audio), and that the load would go away if you used "Direct Streaming" instead?

[derron7]

I can confirm that "Direct Streaming" results in <1% CPU load.

[mherger]

@philippe44 - I mentioned you because I thought this could be due to some of the new streaming handling. But I'm seeing the same behaviour with 7.9, and no problem with other AAC streams. So nothing you changed. This must be some oddity with this particular stream.

[philippe44]

For AAC inside a MP4, LMS does the frame management and that takes some CPU, but I'm surprised it would be 45% of a pi4. Can you put source logging to info and try on a real SB?

[mherger]

I'm seeing the same behaviour with a Touch. Still around 50% CPU load on a 2020 Intel MacBook Pro!

The frame management you mentioned didn't exist in 7.9 yet, did it?

[philippe44]

No, unwrapping AAC and putting them in ADTS is new, (can't remember if I added that in 8.0 or after)

[philippe44]

That stream does the same on MP3, so it's not related to AAC [edit]: sorry, I'll take that back but it's an issue with pipeline when there is transcoding

[michaelherger]

I think we can agree that this is a very special problem specific to this track? @derron7 - do you see similar behaviour with other streams?

[philippe44]

I've made a fair bit of analysis and it's really strange. It is only this server, when LMS proxies the stream. It is not linked to aac or mp3 format. It is not that the server is sending a ton of small responses (TCP packets) to the GET causing ton of sysreads. As far as LMS is concerned, it receives a normal flow of 2~8kB packets (in sysread) but it seems that something in the underlying layers of CPAN is consuming the CPU. I thought at some point of an issue with icy-metadata interval, but it's fine. I have no idea what that server does that is so specific.

[derron7]

Oh, the crypto miner is hidden in the CPAN module! ;)

I have the same behaviour in another stream:

http://avw.mdr.de/streams/284340-0_aac_high.m3u (This stream url comes directly from the radio station)

I wouldn't really care about if the CPU/Case Fan would not be that loud.

[derron7]

https://st03.sslstream.dlf.de/dlf/03/low/aac/stream.aac?aggregator=web AAC 48kbit/s cpu load: 5-25% (switching periodically)

https://st03.sslstream.dlf.de/dlf/03/mid/aac/stream.aac?aggregator=web AAC 96kbit/s cpu load: 20-23% (switching periodically)

https://st03.sslstream.dlf.de/dlf/03/high/aac/stream.aac?aggregator=web AAC 192kbit/s cpu load: 37-57% (switching periodically)

https://st03.sslstream.dlf.de/dlf/03/128/mp3/stream.mp3 MP3 128kb/s cpu load: 21-42% (switching periodically)

I wonder that I also have a high load on the last mp3-Stream. In stream details LMS shows 128kb/s CBR everytime. So there is a transcoding on the fly everytime(?) I don't have installed LAME. Maybe that's for interest for this issue.

[derron7]

Do I have any chance of solving this - maybe via LMS downgrade or CPAN update? DLF (nova) is actually one of my favorite streams that I listen to in the morning.

[derron7]

This is the second time my LMS had 100% cpu load after a while listening to http://live.radioart.com/fFilm_scores.mp3?dlid= Music stopped, then I switched on Network related logging, and after a while I re-opened the stream and afterwards cpu load was fine again. server.log.zip

[mimicko74]

Sames issue on a LMS 8.2.0 on Ubuntu 20.04 (Intel x64) - a high load for some streams, independent of device (Baby or Squeezeplay on RPI). CPAN update did not help.

Tried on 7.9.3 and 8.3.0 with no change of CPU load (CPU load stays at 30-40%) for specific streams and tested it with streams from derron7..

e.g. - High CPU Load https://liveradio.swr.de/tn2d2ac/swr1bw/ : High CPU load. Additional players add ~30% cpu per player. AAC 48khz

No/very low CPU Load http://opml.radiotime.com/Tune.ashx?id=s237962&formats=aac,ogg,mp3&partnerId=16&serial=2526f1ff10eb1bcfab8dfdf373ea94e7 AAC 44,1khz AAC-Extension SBR

High CPU load stops only if another radio station (or something from the local library) is selected.

Could it have something to do with 48khz instead of 44,1khz ?

[philippe44]

I'll try to have a look again but this one seems really complicated to investigate. @mimicko74 just to be sure, you are confirming that the problem is not related to LMS version, correct?

[philippe44]

So... I'm not a TCP expert, but consider the attached screenshot. One is with a working server (RadioParadise) and you'll see that the TCP WindowSize has scaled properly to 40kB where the one with rndfnk.com is stuck at the ridiculous 11 and cannot scale. It might be a problem of the underlying socket layers, but it's not LMS as such.

These server seems to be dysfunctional in term of their TCP handling by having a scaling value of -1. I'll investigate more

[mimicko74]

Hej philippe44, thanks for looking into this.

Yes, I can confirm that the cpu load is not related to the LMS version. I tried it on 7.9.2 to 8.3.0 with the same result. I tried to change faad to a little script with ffmpeg (from : http://www.siski.de/~carsten/radio-streaming-squeezebox.html#aac , in german) and exchanged the faad in /Bin to another faad binary - no changes.

It could have something to do with the switch of the german radio stations to AAC LC in July - unfortunately it was "ARD" who are responsible for the majority of the german radiostations (NDR, MDR,SWR, BR, etc...),

Input #0, aac, from 'https://liveradio.swr.de/sw890cl/swr1bw/play.aac':
  Metadata:
    icy-br          : 128
    icy-description :
    icy-genre       : Pop Music
    icy-name        : SWR1BW AAC 48
    icy-pub         : 0
    icy-samplerate  : 44100
    icy-url         :
  Duration: N/A, bitrate: 48 kb/s
    Stream #0:0: Audio: aac (LC), 48000 Hz, stereo, fltp, 48 kb/s

[philippe44]

Hi saw the same issue with mp3 files. It seems to me that their server is configure in a way that prevents TCP Window Size to grow from a ridiculous value of 11, so basically we are killing the network stack

[terual]

So... I'm not a TCP expert, but consider the attached screenshot. One is with a working server (RadioParadise) and you'll see that the TCP WindowSize has scaled properly to 40kB where the one with rndfnk.com is stuck at the ridiculous 11 and cannot scale. It might be a problem of the underlying socket layers, but it's not LMS as such.

These server seems to be dysfunctional in term of their TCP handling by having a scaling value of -1. I'll investigate more

Did Wireshark also capture the three-way handshake? See also https://osqa-ask.wireshark.org/questions/10071/window-size-scaling-factor-1-unknown/

[philippe44]

My bad, I had to re-read my "TCP for dummies". So capturing the SYN, Wireshark was able to get the actual WindowSize and we have an actual 45kB window... wrong lead then :confused:

I really don't know what's happening there. All I can say at that point is that the tcpdump capture appears much slower that another same bitrate but low CPU stream.

[terual]

I have timeed slimserver.pl while playing both https://liveradio.swr.de/tn2d2ac/swr1bw/ as well as http://opml.radiotime.com/Tune.ashx?id=s237962&formats=aac,ogg,mp3&partnerId=16&serial=2526f1ff10eb1bcfab8dfdf373ea94e7:

Playing http://opml.radiotime.com/Tune.ashx?id=s237962&formats=aac,ogg,mp3&partnerId=16&serial=2526f1ff10eb1bcfab8dfdf373ea94e7:

$ \time -v ./slimserver.pl
^C  Command being timed: "./slimserver.pl"
    User time (seconds): 2.84
    System time (seconds): 0.31
    Percent of CPU this job got: 4%
    Elapsed (wall clock) time (h:mm:ss or m:ss): 1:17.93
    Average shared text size (kbytes): 0
    Average unshared data size (kbytes): 0
    Average stack size (kbytes): 0
    Average total size (kbytes): 0
    Maximum resident set size (kbytes): 146512
    Average resident set size (kbytes): 0
    Major (requiring I/O) page faults: 2
    Minor (reclaiming a frame) page faults: 84125
    Voluntary context switches: 441
    Involuntary context switches: 1295
    Swaps: 0
    File system inputs: 2872
    File system outputs: 8664
    Socket messages sent: 0
    Socket messages received: 0
    Signals delivered: 0
    Page size (bytes): 4096
    Exit status: 0

Playing https://liveradio.swr.de/tn2d2ac/swr1bw/:

$ \time -v ./slimserver.pl
^C  Command being timed: "./slimserver.pl"
    User time (seconds): 11.93
    System time (seconds): 0.89
    Percent of CPU this job got: 17%
    Elapsed (wall clock) time (h:mm:ss or m:ss): 1:12.12
    Average shared text size (kbytes): 0
    Average unshared data size (kbytes): 0
    Average stack size (kbytes): 0
    Average total size (kbytes): 0
    Maximum resident set size (kbytes): 145572
    Average resident set size (kbytes): 0
    Major (requiring I/O) page faults: 0
    Minor (reclaiming a frame) page faults: 84025
    Voluntary context switches: 446
    Involuntary context switches: 4750
    Swaps: 0
    File system inputs: 304
    File system outputs: 8936
    Socket messages sent: 0
    Socket messages received: 0
    Signals delivered: 0
    Page size (bytes): 4096
    Exit status: 0

Only difference I can see are some differences between the involuntary context switches. Not much to go on.

[terual]

Would profiling using nytprof provide some insights?

[mimicko74]

I wiresharked the streams from my server to a SqueezePlay Client on my windows machine. No 1650 is the switch to SWR1 (the stream with the high cpu load). After the switch of the station the server floods out a lot traffic. Unluckily I am not able to interpret the data any further :(

Additionally here the tail from the server.log with network.http on debug while playing SWR1 radio : [21-12-10 17:01:22.1931] Slim::Web::HTTP::sendStreamingResponse (2425) Streamed 1563 to 192.168.188.69 [21-12-10 17:01:22.1936] Slim::Web::HTTP::sendStreamingResponse (2168) sendStreaming response begun... [21-12-10 17:01:22.1939] Slim::Web::HTTP::sendStreamingResponse (2276) (audio: 5856 bytes) [21-12-10 17:01:22.1942] Slim::Web::HTTP::sendStreamingResponse (2425) Streamed 5856 to 192.168.188.69 [21-12-10 17:01:22.1944] Slim::Web::HTTP::sendStreamingResponse (2168) sendStreaming response begun... [21-12-10 17:01:22.1947] Slim::Web::HTTP::sendStreamingResponse (2299) Nothing to stream, let's wait for 0.4 seconds... [21-12-10 17:01:22.1950] Slim::Web::HTTP::sendStreamingResponse (2412) $httpClient is: Slim::Web::HTTP::ClientConn=GLOB(0x564fbc321548) [21-12-10 17:01:22.1952] Slim::Web::HTTP::sendStreamingResponse (2414) $peeraddr{$httpClient} is: 192.168.188.69 [21-12-10 17:01:22.1953] Slim::Web::HTTP::sendStreamingResponse (2415) Got nothing for streaming data to 192.168.188.69 [21-12-10 17:01:22.5044] Slim::Web::HTTP::sendStreamingResponse (2168) sendStreaming response begun... [21-12-10 17:01:22.5054] Slim::Web::HTTP::sendStreamingResponse (2276) (audio: 3810 bytes) [21-12-10 17:01:22.5061] Slim::Web::HTTP::sendStreamingResponse (2425) Streamed 3810 to 192.168.188.69 [21-12-10 17:01:22.5068] Slim::Web::HTTP::sendStreamingResponse (2168) sendStreaming response begun... [21-12-10 17:01:22.5076] Slim::Web::HTTP::sendStreamingResponse (2299) Nothing to stream, let's wait for 0.4 seconds... [21-12-10 17:01:22.5082] Slim::Web::HTTP::sendStreamingResponse (2412) $httpClient is: Slim::Web::HTTP::ClientConn=GLOB(0x564fbc321548) [21-12-10 17:01:22.5086] Slim::Web::HTTP::sendStreamingResponse (2414) $peeraddr{$httpClient} is: 192.168.188.69 [21-12-10 17:01:22.5090] Slim::Web::HTTP::sendStreamingResponse (2415) Got nothing for streaming data to 192.168.188.69 [21-12-10 17:01:22.8143] Slim::Web::HTTP::sendStreamingResponse (2168) sendStreaming response begun... [21-12-10 17:01:22.8153] Slim::Web::HTTP::sendStreamingResponse (2276) (audio: 1406 bytes) [21-12-10 17:01:22.8159] Slim::Web::HTTP::sendStreamingResponse (2425) Streamed 1406 to 192.168.188.69 [21-12-10 17:01:22.8166] Slim::Web::HTTP::sendStreamingResponse (2168) sendStreaming response begun... [21-12-10 17:01:22.8175] Slim::Web::HTTP::sendStreamingResponse (2299) Nothing to stream, let's wait for 0.4 seconds... [21-12-10 17:01:22.8181] Slim::Web::HTTP::sendStreamingResponse (2412) $httpClient is: Slim::Web::HTTP::ClientConn=GLOB(0x564fbc321548) [21-12-10 17:01:22.8186] Slim::Web::HTTP::sendStreamingResponse (2414) $peeraddr{$httpClient} is: 192.168.188.69 [21-12-10 17:01:22.8192] Slim::Web::HTTP::sendStreamingResponse (2415) Got nothing for streaming data to 192.168.188.69 [21-12-10 17:01:23.1245] Slim::Web::HTTP::sendStreamingResponse (2168) sendStreaming response begun... [21-12-10 17:01:23.4330] Slim::Web::HTTP::sendStreamingResponse (2276) (audio: 5312 bytes) [21-12-10 17:01:23.4334] Slim::Web::HTTP::sendStreamingResponse (2425) Streamed 5312 to 192.168.188.69 [21-12-10 17:01:23.4339] Slim::Web::HTTP::sendStreamingResponse (2168) sendStreaming response begun... [21-12-10 17:01:23.4342] Slim::Web::HTTP::sendStreamingResponse (2276) (audio: 4304 bytes) [21-12-10 17:01:23.4344] Slim::Web::HTTP::sendStreamingResponse (2425) Streamed 4304 to 192.168.188.69 [21-12-10 17:01:23.4348] Slim::Web::HTTP::sendStreamingResponse (2168) sendStreaming response begun... [21-12-10 17:01:23.4351] Slim::Web::HTTP::sendStreamingResponse (2299) Nothing to stream, let's wait for 0.4 seconds... [21-12-10 17:01:23.4354] Slim::Web::HTTP::sendStreamingResponse (2412) $httpClient is: Slim::Web::HTTP::ClientConn=GLOB(0x564fbc321548) [21-12-10 17:01:23.4356] Slim::Web::HTTP::sendStreamingResponse (2414) $peeraddr{$httpClient} is: 192.168.188.69 [21-12-10 17:01:23.4357] Slim::Web::HTTP::sendStreamingResponse (2415) Got nothing for streaming data to 192.168.188.69

[Phil1pp]

I am encountering the same issues with high CPU load. It seems that all German public broadcasting stations recently switched to a new streaming plattform. Now all of them point to rndfnk.com.

https://dispatcher.rndfnk.com/br/br3/live/mp3/mid https://dispatcher.rndfnk.com/hr/hr2/live/mp3/high https://liveradio.swr.de/sw282p3/swr3/play.mp3 https://liveradio.swr.de/sw331ch/swr3/play.aac

@philippe44: It seems only to occur when playing on one of my "squeezelite-esp32". When using squeezelite-x64.exe or Squeezelite-X from the MS store, CPU load of the server remains at 0~1%. However if I enable proxied-streaming for the Windows client, the CPU load will be high as well. On the esp32s the proxied-streaming was already disabled, so I don't understand why it's only causing problems there.

[mherger]

Streams would automatically be proxied if the player didn't support https.

[philippe44]

Yes, this only happens when the stream is being proxied by LMS, which can happen because user wants to, player does not support HTTPS, transcoding is required, or seeking requires special HTTP handling and a few other cases I'm probably forgetting.

In other words, the culprit is in the network layers used by LMS but I have no idea of what is happening - this one if a big mystery for me...

[michaelherger]

Would anybody know of another https stream we could test? All I've tried so far are http only. Decoding encrypted data certainly has some impact. But I believe it shouldn't be that much.

[michaelherger]

Found https://stream.srg-ssr.ch/m/drs3/aacp_96 - which would leave the CPU at 1-2%, whereas rndfnk.com usually are at around 30% on a M1 Mac mini.

[shruggingatlas]

Hello everybody, my name is Alexander Leschinsky, co-founder and managing director of G&L Geißendörfer & Leschinsky GmbH. We are indeed operating the audio distribution platform rndfnk.com. Thanks for reaching out to us. Generally, we are not aware of any issues with CPU load when playing back streams we deliver. We are very curious to see what is causing this with LMS. I have dedicated a Perl engineer to look into these issues starting tomorrow, December 14th. We might come back with questions about LMS to this thread, as we had not been using this software before.

I'd like to list a few test streams here:

1. rndfnk.com, RSAS server, HTTPS, encoder vendor A, MP3: https://mdr-284320-0.sslcast.mdr.de/mdr/284320/0/mp3/high/stream.mp3
2. rndfnk.com, RSAS server, HTTP, encoder vendor A, MP3: http://mdr-284320-0.sslcast.mdr.de/mdr/284320/0/mp3/high/stream.mp3
3. rndfnk.com, RSAS server, HTTPS, encoder vendor A, AAC: https://mdr-284320-0.sslcast.mdr.de/mdr/284320/0/aac/high/stream.aac
4. rndfnk.com, RSAS server, HTTP, encoder vendor A, AAC: http://mdr-284320-0.sslcast.mdr.de/mdr/284320/0/aac/high/stream.aac
5. rndfnk.com, RSAS server, HTTPS, encoder vendor B, MP3: https://st01.sslstream.dlf.de/dlf/01/128/mp3/stream.mp3
6. rndfnk.com, RSAS server, HTTP, encoder vendor B, MP3: http://st01.sslstream.dlf.de/dlf/01/128/mp3/stream.mp3
7. rndfnk.com, RSAS server, HTTPS, encoder vendor B, AAC: https://st01.sslstream.dlf.de/dlf/01/high/aac/stream.aac
8. rndfnk.com, RSAS server, HTTP, encoder vendor B, AAC: http://st01.sslstream.dlf.de/dlf/01/high/aac/stream.aac
9. rndfnk.com, RSAS server, HTTPS, encoder vendor C, MP3: https://dispatcher.rndfnk.com/br/br3/live/mp3/mid
10. rndfnk.com, RSAS server, HTTP, encoder vendor C, MP3: http://dispatcher.rndfnk.com/br/br3/live/mp3/mid
11. rndfnk.com, RSAS server, HTTPS, encoder vendor C, AAC: https://dispatcher.rndfnk.com/br/br3/live/aac/low
12. rndfnk.com, RSAS server, HTTP, encoder vendor C, AAC: http://dispatcher.rndfnk.com/br/br3/live/aac/low
13. addradio.de, AIS server, HTTPS, unknown encoder, MP3: https://radiovest.cast.addradio.de/radiovest/simulcast/high/stream.mp3
14. addradio.de, AIS server, HTTP, unknown encoder, MP3: http://radiovest.cast.addradio.de/radiovest/simulcast/high/stream.mp3
15. addradio.de, AIS server, HTTPS, unknown encoder, AAC: https://fhr-chari-live.cast.addradio.de/fhr/chari/live/aac/48/stream.aac
16. addradio.de, AIS server, HTTP, unknown encoder, AAC: http://fhr-chari-live.cast.addradio.de/fhr/chari/live/aac/48/stream.aac
17. radiomast.io, RSAS server, HTTPS, unknown encoder, MP3: https://streams.radiomast.io/9f9702d0-ac14-48aa-b7cf-909db540365b
18. radiomast.io, RSAS server, HTTP, unknown encoder, MP3: http://streams.radiomast.io/9f9702d0-ac14-48aa-b7cf-909db540365b
19. audiostream.io, AIS server, HTTPS, encoder vendor B, MP3: https://dom.audiostream.io/domradio/1000/mp3/128/domradio
20. audiostream.io, AIS server, HTTP, encoder vendor B, MP3: http://dom.audiostream.io/domradio/1000/mp3/128/domradio

These are not covering all combinations, but still might be helpful to localize the issue.

[shruggingatlas]

It would be helpful to know if the issue can be observed for streams that are using rndfnk.com, but different encoder vendors, like streams 3, 7, and 11.

[Phil1pp]

A quick tests shows that it seems to affect all streams from rndfnk.com with HTTPS. No matter which encoder and for both MP3 and AAC. The same streams with HTTP have no abnormal CPU load on the server.

Also the HTTPS streams from addradio.de and audiostream.io have no issue. However the radiomast.io HTTPS stream has the high load as well.

[shruggingatlas]

@Phil1pp this is really helpful. rndfnk.com and radiomast.io share the same underlying streaming software, RSAS. We will focus our examination tomorrow on RSAS streams with HTTPS, then.

[michaelherger]

Ok, here's my results. First of all: https is NOT the culprit. What @Phil1pp most likely is seeing is that the CPU load in LMS is lower because http can be streamed to the player directly. https on the other hand is proxied through LMS (the players can't do https). If you enabled proxied streaming in Settings/Player/Audio, you'd see the same load in LMS for http vs. https.

Here's what I've found playing rndfnk.m3u.txt (remove .txt from the end to use it as a playlist):

-- https://mdr-284320-0.sslcast.mdr.de/mdr/284320/0/mp3/high/stream.mp3
-- http://mdr-284320-0.sslcast.mdr.de/mdr/284320/0/mp3/high/stream.mp3
-- https://mdr-284320-0.sslcast.mdr.de/mdr/284320/0/aac/high/stream.aac
-- http://mdr-284320-0.sslcast.mdr.de/mdr/284320/0/aac/high/stream.aac
-- https://st01.sslstream.dlf.de/dlf/01/128/mp3/stream.mp3
-- http://st01.sslstream.dlf.de/dlf/01/128/mp3/stream.mp3
--- https://st01.sslstream.dlf.de/dlf/01/high/aac/stream.aac
--- http://st01.sslstream.dlf.de/dlf/01/high/aac/stream.aac
-- https://dispatcher.rndfnk.com/br/br3/live/mp3/mid
-- http://dispatcher.rndfnk.com/br/br3/live/mp3/mid
- https://dispatcher.rndfnk.com/br/br3/live/aac/low
- http://dispatcher.rndfnk.com/br/br3/live/aac/low
+ https://radiovest.cast.addradio.de/radiovest/simulcast/high/stream.mp3
+ http://radiovest.cast.addradio.de/radiovest/simulcast/high/stream.mp3
+ https://fhr-chari-live.cast.addradio.de/fhr/chari/live/aac/48/stream.aac
+ http://fhr-chari-live.cast.addradio.de/fhr/chari/live/aac/48/stream.aac
-- https://streams.radiomast.io/9f9702d0-ac14-48aa-b7cf-909db540365b
-- http://streams.radiomast.io/9f9702d0-ac14-48aa-b7cf-909db540365b
+ https://dom.audiostream.io/domradio/1000/mp3/128/domradio
+ http://dom.audiostream.io/domradio/1000/mp3/128/domradio

Where

• +: 1-2% CPU load
• -: >20%
• --: >30%
• ---: >50%

I ran all testing on a 2020 Intel based MacBook Pro. Those numbers are for the Perl process (LMS) on a single core. I enabled proxied streaming for all playback. As you can see there's no real difference between http and https, but certainly between the different stations.

[philippe44]

That correlates, with much higher cases, what I observed a while ago: this is purely due to LMS proxying the stream. I guess we'd need some profiling but I don't know if it can be done with the size of LMS. Again, they might need to be redone, but I took some extensive wireshark traces being convinced that the issue would at the tcp level and all all showed a correct receive window size and normal length packets. On LMS side we don't seem to receive small packets either. One thing is that I don't seem to have observed a cpu difference on windows.

[michaelherger]

Any findings so far? This situation seems to be leading to LMS hanging at some point. I've seen three or four reports so far about LMS no longer responding where it turns out that these were all German users suffering from this issue. Reports seen for Windows as well as Linux systems (see eg. #714).

[philippe44]

No, I've not been able to find some time and I know it will be a difficult one, looking at what I've already tried. I think I will have to profile the whole slimserver.pl and I don't expect that to be easy. BTW, on a different topic, there is still socket exhaustion in LMS with players that come and go all the time. I thought I fixed it but no.

[marcelfischer]

Just wanted to mention here, that Im also effected by this issue. Using rndfnk stream

[mimicko74]

Merry Christmas!

I have resolved it for my setup by using the http mp3 streams instead of the https versions (I just removed the "s" from the https-URL)

http://liveradio.swr.de/sw282p3/swr1bw/play.mp3 http://d121.rndfnk.com/ard/br/br3/live/mp3/128/stream.mp3

With this, the CPU load gets back to near zero. So it might (in the end) have something to do with https? (specifically with the streams from rndfnk.com?)

I also removed the content of the CPAN folder to the bare minimum and use the up-to-date versions. But this seems to have nothing to do with the CPU load - as the CPU load remains low on all tried versions with a complete CPAN folder (7.9.2 - 8.3.0).

[philippe44]

No I don't think it's HTTPS. I've done some verification earlier which seems to indicate it's purely server dependent. What happens in your example is that likely the stream is sent directly to the player (no proxy) and the issue happens as soon as LMS proxies such streams, regardless of the format or protocol (HTTP/HTTPS).

[philippe44]

I've setup the profiler and I'm getting results. Need a bit more time to read them properly but there is an obvious HUGE difference in term of number of times we call readChunk/sysread (like for 60s of playback, one is called 2000 times the other 130,000 times

[philippe44]

So ... first data says that when it's time to read the ICY metadata, we spend a HUGE amount of time calling readChunk with probably no success. In 60s, readMetadata is called about 70 times but in one case it consumes 16,000,000 cycles and in the other case 12,000 cycles - I'll do some traces now that I know where the issue sits

[philippe44]

The hypothesis is that these radio align their chunks with icy metadata blocks. When offset has been reached to read icy, LMS enters a busy loop to read the one byte that gives the icy length. As it is a radio stream, then that 1st byte will arrive "much" later with the next chunk but LMS cycles on it. I'll verify that

[edit]: This is confirmed, now I can't think of an elegant solution that does require some re-architecturing. The ugly PR for now is to add in Slim::Player::Protocols::HTPP.pm::readMetadata, line 215 (after the else)

Time::HiRes::usleep(100*1000);

It takes care of the issue but it is so ugly...

[philippe44]

I think I have a solution with read "behind" instead of read "ahead" - See https://github.com/Logitech/slimserver/pull/718

[mherger]

This should be fixed in 8.3 via @philippe44's change in #718. Please give it a try.

Thanks a lot, @philippe44!

[derron7]

This fix (v8.3 beta) works for me! CPU load is 0,5-0,8 in average and 3% at maximum with 3 synced Players. Thank you very much @philippe44 and @mherger! Now my music listening has a much better CO2 footprint again!