"Add to favorites" action is very slow

[tanathos]

Hi,
I'm running Lyrion Music Server on a Raspberry Pi 3, these are the server specs:
Version: 9.0.1 - 1736238071 @ Thu Jan 9 17:13:58 UTC 2025
Hostname: pCP
Server IP Address: 192.168.1.20
Operating system: piCore - EN - utf8
Platform Architecture: armv7l-linux
Perl Version: 5.36.0 - arm-linux-gnueabihf-thread-multi-64int
Audio::Scan: 1.09
IO::Socket::SSL: 2.083
Database Version: DBD::SQLite 1.58 (sqlite 3.22.0)

And this the Library status:
Total genres: 189
Total artists: 914
Total releases: 1738
Total tracks: 17511
Total duration: 61 days 13:06:54
Last scan: 31/01/2025 14:55:00

When I click to the "Add to favorites" action link, I've to wait each time around 27-30 seconds before receiving the confirmation message that the song is added to the favorites.

During this time I can ear the NAS (which host my library) reading heavily, and I cannot perform any other action on the playback. E.g. I cannot pause or skip to next track, until the confirmation message is received.

Seems weird to me, as it should be a fairly simple operation...
Thanks!

[michaelherger]

Saving a favourite should indeed not take long. Can you check your browser's console to see how long the request would take from the frontend's point of view?

Also the favourite should not be stored on the NAS, unless you've decided to have a special set up where LMS would store its data on the NAS instead of the pCP itself. Could it be your NAS would go to sleep and would have to spin up the disks before the favourite could be confirmed? Would you see the same slowness for local media files or remote content (radio station)?

[tanathos]

I didn't configure anything special about Favourites, so I guess they're working with the default configuration (BTW, couldn't find anything to configure in settings... where should I look?).

I would exclude that my NAS is going to sleep, this is happening while the tracks are playing, and the NAS is up and running, answering any other action instantly (skip track, library search, etc...).

I did one "Add to Favourite" now, for a file served by the NAS, these are the relevant information from devtools:

Headers:

Payload:

Response:

Timing:

As you can see this one took 33 seconds...

Then I tried with a Radio station, and it took 29 seconds:

Headers:

Payload:

Timing:

Any idea?
Thanks for looking into it!

[michaelherger]

Where is your data stored (settings, cache)? On the SD card?

Please check the server.log from Settings/Advanced/Logging to see whether there's any information in there. You might want to increase the log level for plugin.favorites to DEBUG.

[tanathos]

So, these are all the logs that are generated when I add to favorites:

[25-02-08 20:50:20.8408] Slim::Plugin::Favorites::OpmlFavorites::findUrl (387) No match for file:///mnt/Music/Agalloch/Ashes%20Against%20the%20Grain/05%20-%20Not%20Unlike%20The%20Waves.mp3
[25-02-08 20:50:20.8558] Slim::Plugin::Favorites::Plugin::cliAdd (849) adding entry Not Unlike The Waves file:///mnt/Music/Agalloch/Ashes%20Against%20the%20Grain/05%20-%20Not%20Unlike%20The%20Waves.mp3 at index 
[25-02-08 20:50:20.8829] Slim::Plugin::Favorites::Opml::save (112) OPML saved to file tempfile: /usr/local/slimserver/prefs/ffDs2yL9KS.opml
[25-02-08 20:50:20.8837] Slim::Plugin::Favorites::Opml::save (121) Renamed /usr/local/slimserver/prefs/ffDs2yL9KS.opml to /usr/local/slimserver/prefs/favorites.opml

Please note that the timestamp seems to match the START of the request (when I click add in the browser).

And these are the current folder, on the SD:

[tanathos]

Forgot to mention: also removing an item from favorites has this average latency

[michaelherger]

Did you try this with different browsers?

You could enable debug logging for control.command. But this will be super noisy! Make sure you disable it immediately after the test.

[tanathos]

Yes, I tried with Edge, Chrome and Firefox, same behavior...

This is what I got increasing the logs as you suggested:

[25-02-11 13:54:36.7501] Slim::Control::Request::dump (2335) Request: Query [b8:27:eb:a9:77:8f->favorites exists] from JSONRPC  (Dispatchable)
[25-02-11 13:54:36.7508] Slim::Control::Request::dump (2339)    Param: [_id] = [file:///mnt/Music/Ghost/Prequelle/08%20-%20Witch%20Image.mp3]
[25-02-11 13:54:36.7519] Slim::Control::Request::dump (2335) Request: Query [b8:27:eb:a9:77:8f->favorites exists] from JSONRPC  (Done)
[25-02-11 13:54:36.7524] Slim::Control::Request::dump (2339)    Param: [_id] = [file:///mnt/Music/Ghost/Prequelle/08%20-%20Witch%20Image.mp3]
[25-02-11 13:54:36.7530] Slim::Control::Request::dump (2371)    Result: [exists] = [0]
[25-02-11 13:54:36.7535] Slim::Control::Request::executeDone (1917) 0
[25-02-11 13:54:36.7669] Slim::Control::Request::dump (2335) Request: Command [b8:27:eb:a9:77:8f->favorites add] from JSONRPC  (Dispatchable)
[25-02-11 13:54:36.7674] Slim::Control::Request::dump (2339)    Param: [url] = [file:///mnt/Music/Ghost/Prequelle/08%20-%20Witch%20Image.mp3]
[25-02-11 13:54:36.7677] Slim::Control::Request::dump (2339)    Param: [icon] = [music/4475/cover.png]
[25-02-11 13:54:36.7680] Slim::Control::Request::dump (2339)    Param: [title] = [Witch Image]
[25-02-11 13:55:09.7827] Slim::Control::Request::notifyFromArray (842) (favorites changed)
[25-02-11 13:55:09.7839] Slim::Control::Request::dump (2335) Request: Command [b8:27:eb:a9:77:8f->favorites add] from JSONRPC  (Done)
[25-02-11 13:55:09.7845] Slim::Control::Request::dump (2339)    Param: [url] = [file:///mnt/Music/Ghost/Prequelle/08%20-%20Witch%20Image.mp3]
[25-02-11 13:55:09.7850] Slim::Control::Request::dump (2339)    Param: [icon] = [music/4475/cover.png]
[25-02-11 13:55:09.7854] Slim::Control::Request::dump (2339)    Param: [title] = [Witch Image]
[25-02-11 13:55:09.7858] Slim::Control::Request::dump (2371)    Result: [count] = [1]
[25-02-11 13:55:09.7863] Slim::Control::Request::executeDone (1917) 0
[25-02-11 13:55:09.7891] Slim::Control::Request::notify (2009) Notifying favorites add
[25-02-11 13:55:09.7943] Slim::Control::Request::__autoexecute (2470) __autoexecute()
[25-02-11 13:55:09.7949] Slim::Control::Request::dump (2335) Request: Query [serverstatus] from /4615e3d0/slim/serverstatus|1||4615e3d0|SqueezePlay-jivelite/8.0.0-r214 (armv7l)  (Dispatchable)
[25-02-11 13:55:09.7953] Slim::Control::Request::dump (2339)    Param: [subscribe] = [60]
[25-02-11 13:55:09.7956] Slim::Control::Request::dump (2339)    Param: [_quantity] = [50]
[25-02-11 13:55:09.7959] Slim::Control::Request::dump (2339)    Param: [_index] = [0]
[25-02-11 13:55:09.7986] Slim::Control::Request::dump (2335) Request: Query [works] (Dispatchable)
[25-02-11 13:55:09.7991] Slim::Control::Request::dump (2339)    Param: [tags] = [CC]
[25-02-11 13:55:09.7994] Slim::Control::Request::dump (2339)    Param: [_quantity] = [1]
[25-02-11 13:55:09.7997] Slim::Control::Request::dump (2339)    Param: [_index] = [0]
[25-02-11 13:55:09.8053] Slim::Control::Request::dump (2335) Request: Query [works] (Done)
[25-02-11 13:55:09.8058] Slim::Control::Request::dump (2339)    Param: [tags] = [CC]
[25-02-11 13:55:09.8061] Slim::Control::Request::dump (2339)    Param: [_quantity] = [1]
[25-02-11 13:55:09.8064] Slim::Control::Request::dump (2339)    Param: [_index] = [0]
[25-02-11 13:55:09.8067] Slim::Control::Request::dump (2371)    Result: [count] = [0]
[25-02-11 13:55:09.8070] Slim::Control::Request::executeDone (1917) 0

You can notice that there's a gap of 33 seconds before the log
Request: Command [b8:27:eb:a9:77:8f->favorites add] from JSONRPC (Done)

Also, during this time the music IS playing, but any other UI interactions are freezed... Looks like the webserver is just answering the single request (which is, anyway, weirdly long) and is not taking anything else in.

[michaelherger]

Please enable debug logging for all of plugin.favorites, control.command, and network.jsonrpc. The actual update seems to be done quickly, but somewhere after that it's spending too much time...

[tanathos]

Sure, I'm including only the relevant block here:

[25-02-11 14:51:22.7898] Slim::Web::JSONRPC::handleURI (141) POST data: [{"id":0,"method":"slim.request","params":["b8:27:eb:a9:77:8f",["favorites","exists","file:///mnt/Music/S%C3%B3lstafir/Endless%20Twilight%20of%20Codependent%20Love/08%20-%20Or.mp3"]]}]
[25-02-11 14:51:22.7921] Slim::Web::JSONRPC::handleURI (159) JSON parsed procedure: {
  id => 0,
  method => "slim.request",
  params => [
        "b8:27:eb:a9:77:8f",
        [
          "favorites",
          "exists",
          "file:///mnt/Music/S%C3%B3lstafir/Endless%20Twilight%20of%20Codependent%20Love/08%20-%20Or.mp3",
        ],
      ],
}
[25-02-11 14:51:22.7946] Slim::Web::JSONRPC::requestMethod (399) requestMethod([
  "b8:27:eb:a9:77:8f",
  [
    "favorites",
    "exists",
    "file:///mnt/Music/S%C3%B3lstafir/Endless%20Twilight%20of%20Codependent%20Love/08%20-%20Or.mp3",
  ],
])
[25-02-11 14:51:22.7953] Slim::Web::JSONRPC::requestMethod (425) Parsing command: Found client [b8:27:eb:a9:77:8f]
[25-02-11 14:51:22.7962] Slim::Web::JSONRPC::requestMethod (474) Dispatching...
[25-02-11 14:51:22.7969] Slim::Control::Request::dump (2335) Request: Query [b8:27:eb:a9:77:8f->favorites exists] from JSONRPC  (Dispatchable)
[25-02-11 14:51:22.7975] Slim::Control::Request::dump (2339)    Param: [_id] = [file:///mnt/Music/S%C3%B3lstafir/Endless%20Twilight%20of%20Codependent%20Love/08%20-%20Or.mp3]
[25-02-11 14:51:22.7984] Slim::Plugin::Favorites::OpmlFavorites::findUrl (387) No match for file:///mnt/Music/S%C3%B3lstafir/Endless%20Twilight%20of%20Codependent%20Love/08%20-%20Or.mp3
[25-02-11 14:51:22.7991] Slim::Control::Request::dump (2335) Request: Query [b8:27:eb:a9:77:8f->favorites exists] from JSONRPC  (Done)
[25-02-11 14:51:22.7997] Slim::Control::Request::dump (2339)    Param: [_id] = [file:///mnt/Music/S%C3%B3lstafir/Endless%20Twilight%20of%20Codependent%20Love/08%20-%20Or.mp3]
[25-02-11 14:51:22.8002] Slim::Control::Request::dump (2371)    Result: [exists] = [0]
[25-02-11 14:51:22.8007] Slim::Control::Request::executeDone (1917) 0
[25-02-11 14:51:22.8013] Slim::Web::JSONRPC::requestWrite (526) requestWrite()
[25-02-11 14:51:22.8019] Slim::Web::JSONRPC::generateJSONResponse (369) generateJSONResponse()
[25-02-11 14:51:22.8048] Slim::Web::JSONRPC::writeResponse (300) JSON response: {
  id => 0,
  method => "slim.request",
  params => [
        "b8:27:eb:a9:77:8f",
        [
          "favorites",
          "exists",
          "file:///mnt/Music/S%C3%B3lstafir/Endless%20Twilight%20of%20Codependent%20Love/08%20-%20Or.mp3",
        ],
      ],
  result => { "exists" => 0 },
}
[25-02-11 14:51:22.8055] Slim::Web::JSONRPC::writeResponse (315) JSON raw response: [{"result":{"exists":0},"params":["b8:27:eb:a9:77:8f",["favorites","exists","file:///mnt/Music/S%C3%B3lstafir/Endless%20Twilight%20of%20Codependent%20Love/08%20-%20Or.mp3"]],"id":"0","method":"slim.request"}]
[25-02-11 14:51:22.8066] Slim::Web::JSONRPC::writeResponse (352) Response headers: [
HTTP/1.1 200 OK
Connection: keep-alive
Content-Length: 206
Content-Type: application/json

]
[25-02-11 14:51:22.8136] Slim::Web::JSONRPC::handleURI (75) handleURI(Slim::Web::HTTP::ClientConn=GLOB(0xa6b5a58))
[25-02-11 14:51:22.8142] Slim::Web::JSONRPC::handleURI (141) POST data: [{"id":0,"method":"slim.request","params":["b8:27:eb:a9:77:8f",["favorites","add","url:file:///mnt/Music/S%C3%B3lstafir/Endless%20Twilight%20of%20Codependent%20Love/08%20-%20Or.mp3","title:Or","icon:music/5158/cover.png"]]}]
[25-02-11 14:51:22.8157] Slim::Web::JSONRPC::handleURI (159) JSON parsed procedure: {
  id => 0,
  method => "slim.request",
  params => [
        "b8:27:eb:a9:77:8f",
        [
          "favorites",
          "add",
          "url:file:///mnt/Music/S%C3%B3lstafir/Endless%20Twilight%20of%20Codependent%20Love/08%20-%20Or.mp3",
          "title:Or",
          "icon:music/5158/cover.png",
        ],
      ],
}
[25-02-11 14:51:22.8171] Slim::Web::JSONRPC::requestMethod (399) requestMethod([
  "b8:27:eb:a9:77:8f",
  [
    "favorites",
    "add",
    "url:file:///mnt/Music/S%C3%B3lstafir/Endless%20Twilight%20of%20Codependent%20Love/08%20-%20Or.mp3",
    "title:Or",
    "icon:music/5158/cover.png",
  ],
])
[25-02-11 14:51:22.8175] Slim::Web::JSONRPC::requestMethod (425) Parsing command: Found client [b8:27:eb:a9:77:8f]
[25-02-11 14:51:22.8180] Slim::Web::JSONRPC::requestMethod (474) Dispatching...
[25-02-11 14:51:22.8183] Slim::Control::Request::dump (2335) Request: Command [b8:27:eb:a9:77:8f->favorites add] from JSONRPC  (Dispatchable)
[25-02-11 14:51:22.8185] Slim::Control::Request::dump (2339)    Param: [title] = [Or]
[25-02-11 14:51:22.8188] Slim::Control::Request::dump (2339)    Param: [icon] = [music/5158/cover.png]
[25-02-11 14:51:22.8190] Slim::Control::Request::dump (2339)    Param: [url] = [file:///mnt/Music/S%C3%B3lstafir/Endless%20Twilight%20of%20Codependent%20Love/08%20-%20Or.mp3]
[25-02-11 14:51:22.8195] Slim::Plugin::Favorites::Plugin::cliAdd (849) adding entry Or file:///mnt/Music/S%C3%B3lstafir/Endless%20Twilight%20of%20Codependent%20Love/08%20-%20Or.mp3 at index 
[25-02-11 14:51:22.8437] Slim::Plugin::Favorites::Opml::save (112) OPML saved to file tempfile: /usr/local/slimserver/prefs/z7XYg3aNul.opml
[25-02-11 14:51:22.8445] Slim::Plugin::Favorites::Opml::save (121) Renamed /usr/local/slimserver/prefs/z7XYg3aNul.opml to /usr/local/slimserver/prefs/favorites.opml
[25-02-11 14:51:55.0012] Slim::Control::Request::notifyFromArray (842) (favorites changed)
[25-02-11 14:51:55.0021] Slim::Control::Request::dump (2335) Request: Command [b8:27:eb:a9:77:8f->favorites add] from JSONRPC  (Done)
[25-02-11 14:51:55.0025] Slim::Control::Request::dump (2339)    Param: [title] = [Or]
[25-02-11 14:51:55.0028] Slim::Control::Request::dump (2339)    Param: [icon] = [music/5158/cover.png]
[25-02-11 14:51:55.0031] Slim::Control::Request::dump (2339)    Param: [url] = [file:///mnt/Music/S%C3%B3lstafir/Endless%20Twilight%20of%20Codependent%20Love/08%20-%20Or.mp3]
[25-02-11 14:51:55.0035] Slim::Control::Request::dump (2371)    Result: [count] = [1]
[25-02-11 14:51:55.0038] Slim::Control::Request::executeDone (1917) 0
[25-02-11 14:51:55.0041] Slim::Web::JSONRPC::requestWrite (526) requestWrite()
[25-02-11 14:51:55.0045] Slim::Web::JSONRPC::generateJSONResponse (369) generateJSONResponse()
[25-02-11 14:51:55.0065] Slim::Web::JSONRPC::writeResponse (300) JSON response: {
  id => 0,
  method => "slim.request",
  params => [
        "b8:27:eb:a9:77:8f",
        [
          "favorites",
          "add",
          "url:file:///mnt/Music/S%C3%B3lstafir/Endless%20Twilight%20of%20Codependent%20Love/08%20-%20Or.mp3",
          "title:Or",
          "icon:music/5158/cover.png",
        ],
      ],
  result => { count => 1 },
}
[25-02-11 14:51:55.0069] Slim::Web::JSONRPC::writeResponse (315) JSON raw response: [{"result":{"count":1},"params":["b8:27:eb:a9:77:8f",["favorites","add","url:file:///mnt/Music/S%C3%B3lstafir/Endless%20Twilight%20of%20Codependent%20Love/08%20-%20Or.mp3","title:Or","icon:music/5158/cover.png"]],"id":"0","method":"slim.request"}]
[25-02-11 14:51:55.0077] Slim::Web::JSONRPC::writeResponse (352) Response headers: [
HTTP/1.1 200 OK
Connection: keep-alive
Content-Length: 245
Content-Type: application/json

]
[25-02-11 14:51:55.0088] Slim::Control::Request::notify (2009) Notifying favorites add
[25-02-11 14:51:55.0258] Slim::Web::JSONRPC::handleURI (75) handleURI(Slim::Web::HTTP::ClientConn=GLOB(0xa208d00))
[25-02-11 14:51:55.0263] Slim::Web::JSONRPC::handleURI (141) POST data: [{"id":0,"method":"slim.request","params":["b8:27:eb:a9:77:8f",["status","-",1,"tags:cdegilopqrstuybhz1AABEGIKNPSTV","alarmData:1"]]}]
[25-02-11 14:51:55.0278] Slim::Web::JSONRPC::handleURI (159) JSON parsed procedure: {
  id => 0,
  method => "slim.request",
  params => [
        "b8:27:eb:a9:77:8f",
        [
          "status",
          "-",
          1,
          "tags:cdegilopqrstuybhz1AABEGIKNPSTV",
          "alarmData:1",
        ],
      ],
}
[25-02-11 14:51:55.0293] Slim::Web::JSONRPC::requestMethod (399) requestMethod([
  "b8:27:eb:a9:77:8f",
  [
    "status",
    "-",
    1,
    "tags:cdegilopqrstuybhz1AABEGIKNPSTV",
    "alarmData:1",
  ],
])
[25-02-11 14:51:55.0296] Slim::Web::JSONRPC::requestMethod (425) Parsing command: Found client [b8:27:eb:a9:77:8f]
[25-02-11 14:51:55.0301] Slim::Web::JSONRPC::requestMethod (474) Dispatching...

The gap seems to be between these two actions:

[25-02-11 14:51:22.8445] Slim::Plugin::Favorites::Opml::save (121) Renamed /usr/local/slimserver/prefs/z7XYg3aNul.opml to /usr/local/slimserver/prefs/favorites.opml
[25-02-11 14:51:55.0012] Slim::Control::Request::notifyFromArray (842) (favorites changed)

[michaelherger]

Ok, we're getting closer: once the file has been written the favorites code would indeed re-build its internal data structure. This can include quite a bit of database lookups if you had many favorite albums from your library etc. Would you mind sharing your favorites.opml file (from the prefs or playlists folder)?

https://www.dropbox.com/request/T3RctyzGgNg0oFDubq6a

[tanathos]

Sure, I just sent it!

[michaelherger]

Hmm... I thought this might be a performance issue due to a massive favorites list. But yours seems quite reasonable - and I haven't been able to reproduce the issue on my end. I have a pCP9 on a Pi3B+, connected to a rather low performance DS218j NAS. I created a favorites lists similar to your (mix of tracks and albums, mostly local). Adding through the web UI would take less than a second.

What kind of NAS are you using?

[tanathos]

It's a DS220+, never had any kind of performance issue...

[tanathos]

Additional info: I'm looking at favorites.opml file while performing the add to favorites, and the file itself is written instantly when I click, meaning that all the operations needed to update it are performed fast, but the http request is still hanging for the following ~30 secs.
It must be something that happens after the file is written.

[michaelherger]

Ok, please add one more log item: database.sql=INFO. Now you should see some SQL activity during those ~30s. Is there any one query which would take particularly long?