LMS unresponsive after saving playlist

[jrfinlay]

LMS becomes unresponsive for several minutes (5-10m) after saving a long playlist after a full wipe and rescan.

The procedure that illustrates the problem is:

1. Create a playlist with 3000 tracks in it.
2. Do a full wipe and rescan of the library. The playlist is rewritten with tmp:// urls
3. After the full wipe and rescan completes, save the playlist to the playlist directory.
4. The playlist is created and contains the tmp:// urls but LMS seems to go into a tight loop using nearly 100% of the CPU.
5. LMS then becomes unresponsive i.e. the browser cannot be updated and all the players eventually stop playing after a delay where I assume the buffers are drained.
6. After 5-10m LMS completes the high compute load operation and becomes responsive and the players resume playing.

[michaelherger]

I can't reproduce this. Are you trying to save while the scan Is still going on? What UI are you using to save the playlist?

[jrfinlay]

I can reproduce this every time using the Default web UI. I wait until after the full wipe and rescan is complete before saving the playlist. Sometimes I have to refresh the browser to get the "save playlist" button to appear at the bottom right of the webpage next to the "clear playlist" button. With short playlists the same high CPU load occurs but for a short enough time that the loss of responsiveness is not noticeable.

[michaelherger]

Could you please provide a copy of your server.log.zip (Settings/Information)?

[jrfinlay]

The server.log was empty when I initiated the full wipe and rescan. All the entries in the server.log were entered during the wipe and rescan. After the wipe and rescan completed, I saved the playlist and the server ran at mostly 100% CPU usage for 6m. All the players stopped playing within a minute of the start of saving the playlist. No additional entries were added to the server.log.

server.log.gz

[jrfinlay]

The same problem with LMS becoming unresponsive occurs if I clear the current playlist and then add the playlist that I saved that contains tmp:// urls. The server log doesn't have any new entries added during the time LMS is unresponsive.

[michaelherger]

There are hundreds or thousands of lines which say "Too many open files". Please restart your LMS or computer and you should be good again.

[jrfinlay]

The many lines that report "Too many open files" are a manifestation of the problem that seems to be driven by LMS. These reports occur while LMS does a full wipe and rescan and first rewrites the long (4000+ tracks) clientplaylist in prefs to use tmp:// urls. These are not caused by any situation external to LMS. I have tested this repeatedly on two different hosts with the exact same playlists after rebooting the systems. I have crudely monitored the file descriptors in /proc and can see that at some point the number of fds blows up for the LMS process and the reports of "Too many open files" accumulate in the server.log.

What changes (if any) can I make to the logging to try and reveal more info about the problem occurrence?

[mherger]

Are those file handles related to the files in the playlist? Eg. are they opened but not closed?

Please try the latest 8.2 nightly. We recently applied a change which was related to LMS keeping files handles open under certain circumstances. And it might explain why I'm not seeing this issue.

[jrfinlay]

The files are opened and file descriptors appear and then the files are closed but at some point it looks like LMS opens the files but can't get access and doesn't close the fd so they build up but eventually all the extra fds are closed. My guess would be something is blocking read access for a thread(?) at some point and then eventually the thread(?) ends and all the open files are closed and the number of open files returns to a normal value of around 40+.

I'm using what looks like the latest nightly build from March 27 - logitechmediaserver_8.2.0~1616822338_amd64.deb.

[mherger]

What kind of system is this running on? You mentioned initially a 3k+ playlist, latest is 4k+. What's the smallest you need to reproduce the issue?

[jrfinlay]

Both systems are xubuntu - one is 16.04 the other 20.04.

I'll have to run some tests to try and find the smallest list the exhibits the problem though smaller lists recover faster and the player buffers are big enough that any playlist that takes less than a minute will not exhibit the problem.

However there may be more than one problem here - it's not clear to me whether the responsiveness is directly related to the problem of opening too many files.

I also have been trying to see if a particular file or album name is triggering the file opening problem - so far no clear indication.

[michaelherger]

What kind of hardware? I tried again with 5000 items in the list. No issue at all. Saved in a fraction of a second (on a MacBook).

[jrfinlay]

I have narrowed it down on my one system to the situation where I have two identical playlists (not synchronized) of 3401 or more tracks that are setup and then a full wipe and rescan is started. The soft limit on the number of open files for LMS is set to 1024.

I have tried various size combination but it seems that both clientplaylists must have more than 3400 tracks in them for the problem to manifest itself. There is still some LMS unresponsiveness when one clientplaylist is less than 3400 tracks and while the clientplaylists are being rewritten but no errors.

As the clientplaylists are being rewritten it seems that files are opened but not closed for some reason until there are 1024 open files when LMS starts throwing errors. On my system that continues for about 16s and then all the extra open files get closed.

[mherger]

I suggest you take this topic to forums.slimdevices.com and add more information about your system (hard- and software). There are users more knowledgeable about Linux than I am. More users who can try to reproduce. Because for me it's just working as expected.

[jrfinlay]

One system is an older dual core amd64 with 4GB RAM; the other newer 8core intel with 16GB RAM. I can reliably see the problem on the slower older system but not reliably on the newer faster system.

The variations in the problem occurring make me feel like this is a race condition problem somewhere in LMS and probably too difficult to track down unless there is a reliable test case.

For me I found that increasing the soft open file limit to 2048 for LMS on the faster system seems to eliminate the problem occurrence so I'm not going to pursue this further.