Performance issue. 5 mn to boot, each time.

dk31 · January 14, 2019, 11:50am

Hello all,

I’m still facing a strong performance issue, as described in https://volumio.org/forum/installing-the-touch-display-plugin-t6032-50.html

To summarize, very frequently, when volumio is booting, is takes a very long time to come up and become usable through the touch screen or the WebIU. It can be more than one hour… not really usable.

Problem was present yesterday night, everything was blocked. Instead of hard rebooting, I decided to let the system go on. And this morning, it was still on, and usable, but i don’t know how long it was “looping” on kswapd0…

I thought it was linked to the installation of the touch display plugin, but I’m not so sure now.

Maybe it’s only a coincidence, but today, I decided to erase the albumart cache. From what I understand, each time a CD is played, a jpg file is fetched from the CD folder (on a NAS for me), and stored in the /data/albumart/folder/… following then the NAS folder structure. These is also a “web” subdirectory which allows to store images from internet.

So erasing this cache from the webIU empties these folders. It looks like, just rebooting after that, the boot time was very short, and the system came up rapidly. I was able to load a CD, saw the album art coming after a while, and checked that this file was now present alone in the cache. So far so good…

Maybe my performance issue is lying around there? But, next reboot was again quite long (4 mns to have the webUI usable).

If I issue a “ps -aux” on the “node” process, I see:

volumio@volumio:/data$ ps -aux | grep node
volumio    963 12.5 14.8 281112 147760 ?       Ssl  12:02   5:05 /usr/local/bin/node /volumio/index.js
volumio   1130  0.0  1.4  72636 14904 ?        Sl   12:02   0:00 /bin/node /volumio/app/plugins/miscellanea/albumart/serverStartup.js 3001 /data/albumart
volumio   1146  0.0  2.1  82960 21772 ?        Sl   12:02   0:01 /bin/node /volumio/app/plugins/miscellanea/albumart/serverStartup.js 3001 /data/albumart
volumio   1147  0.0  2.1  82456 21252 ?        Sl   12:02   0:01 /bin/node /volumio/app/plugins/miscellanea/albumart/serverStartup.js 3001 /data/albumart
volumio   1152  0.0  2.1  82452 21168 ?        Sl   12:02   0:01 /bin/node /volumio/app/plugins/miscellanea/albumart/serverStartup.js 3001 /data/albumart

So RSS column shows different figures, but the “time” column is very low (0:01).

Does this look normal to anybody who knows volumio?

Any help appreciated

dk31 · January 14, 2019, 12:19pm

A way to get more information: display the CPU/memory usage of process “node” while booting.

I will store this information in a file to check this on a more stable way.

What I see now after my last reboot, is that the process “node” has taken more than 5 mn of CPU time before the system is ready to be used:

ps -aux | grep /volumio/index.js
volumio    944 62.7 14.7 283092 146884 ?       Ssl  13:07   5:03 /usr/local/bin/node /volumio/index.js

This looks very much to me… Is this normal?

dk31 · January 14, 2019, 3:00pm

More inputs. Pb arose again on last reboot, almost 2 hours to be ready to play music!

The result in volumio log is below, I inserted a blank line manually to show the two lines between which the system was blocked:

volumio@volumio:~$ tail -f /var/log/volumio.log 
2019-01-14T12:55:17.613Z - info: MyVolumio status changed
2019-01-14T12:55:19.495Z - info: CoreCommandRouter::volumioGetBrowseSources
2019-01-14T12:55:19.501Z - info: CoreCommandRouter::volumioGetState
2019-01-14T12:55:19.504Z - info: CoreStateMachine::getState
2019-01-14T12:55:19.505Z - info: CorePlayQueue::getTrack 0
2019-01-14T12:55:19.553Z - info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings
2019-01-14T12:55:19.572Z - info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard
2019-01-14T12:55:19.575Z - info: CoreCommandRouter::executeOnPlugin: system , getShowWizard
2019-01-14T12:55:19.609Z - info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom
2019-01-14T12:55:19.612Z - info: Listing playlists
2019-01-14T12:55:42.456Z - info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion
2019-01-14T12:55:42.458Z - info: CoreCommandRouter::executeOnPlugin: system , getConfigParam

2019-01-14T14:43:29.349Z - info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus
2019-01-14T14:43:29.364Z - info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus
2019-01-14T14:43:29.365Z - info: CoreCommandRouter::volumioGetBrowseSources
2019-01-14T14:43:29.367Z - info: CoreCommandRouter::volumioGetState
2019-01-14T14:43:29.367Z - info: CoreStateMachine::getState
2019-01-14T14:43:29.367Z - info: CorePlayQueue::getTrack 0
2019-01-14T14:43:29.555Z - info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom
2019-01-14T14:43:29.556Z - info: Listing playlists
2019-01-14T14:43:29.557Z - info: CoreCommandRouter::volumioGetQueue
2019-01-14T14:43:29.557Z - info: CoreStateMachine::getQueue
2019-01-14T14:43:29.557Z - info: CorePlayQueue::getQueue

I took almost 2 hours (from 12:55:42.458 to 14:43:29.349) to the system to come up.

This happened between the two following lines:
info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
and
info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus

Difficult for me to know if this is due to the global memory load of the system, or to what volumio does between these two steps.

If I look at CPU usage:

 ps -aux | grep node             
volumio    941  8.2 14.9 279512 148944 ?       Ssl  13:55   9:36 /usr/local/bin/node /volumio/index.js
volumio   1138  0.0  0.6  72636  6476 ?        Sl   13:55   0:00 /bin/node /volumio/app/plugins/miscellanea/albumart/serverStartup.js 3001 /data/albumart
volumio   1144  0.0  1.2  82440 12628 ?        Sl   13:55   0:01 /bin/node /volumio/app/plugins/miscellanea/albumart/serverStartup.js 3001 /data/albumart
volumio   1145  0.0  1.2  82964 12552 ?        Sl   13:55   0:01 /bin/node /volumio/app/plugins/miscellanea/albumart/serverStartup.js 3001 /data/albumart
volumio   1150  0.0  1.2  82440 12496 ?        Sl   13:55   0:01 /bin/node /volumio/app/plugins/miscellanea/albumart/serverStartup.js 3001 /data/albumart

It looks like CPU usage of processes related to albumart remains very low, so probably nothing to do with albumart management in tihs performance issue.

The “main” node process took 9:36 mns of CPU usage, over almost 2 hours during which the system was not usable…

What is wrong here? If somebody could help me, I would appreciate.

dk31 · January 14, 2019, 4:38pm

I changed the title, I am convinced that the problem does not come from albumart management.

volumio · January 14, 2019, 4:45pm

Can you send us a log?
What plugins did you install?
SD Card?
Power supply?

If you’re using a touchscreen, this might impact performances quite a lot if you don’t use 2 separate power supplies (1 for the pi and one for the touchscreen) since PI3B+ needs lots of current, and if it gets undervoltage warnings it will throttle a lot

dk31 · January 14, 2019, 5:11pm

Hi,

Thanks for the reply.

In the right order:

Here is a log file (last boot):

2019-01-14T16:15:16.511Z - info: -------------------------------------------
2019-01-14T16:15:16.516Z - info: -----            Volumio2              ----
2019-01-14T16:15:16.518Z - info: -------------------------------------------
2019-01-14T16:15:16.519Z - info: -----          System startup          ----
2019-01-14T16:15:16.520Z - info: -------------------------------------------
2019-01-14T16:15:16.767Z - info: Plugin folders cleanup
2019-01-14T16:15:16.768Z - info: Scanning into folder /volumio/app/plugins/
2019-01-14T16:15:16.769Z - info: Scanning category audio_interface
2019-01-14T16:15:16.770Z - info: Scanning category miscellanea
2019-01-14T16:15:16.772Z - info: Scanning category music_service
2019-01-14T16:15:16.773Z - info: Scanning category plugins.json
2019-01-14T16:15:16.773Z - info: Scanning category system_controller
2019-01-14T16:15:16.775Z - info: Scanning category user_interface
2019-01-14T16:15:16.775Z - info: Scanning into folder /data/plugins/
2019-01-14T16:15:16.776Z - info: Plugin folders cleanup completed
2019-01-14T16:15:16.778Z - info: -------------------------------------------
2019-01-14T16:15:16.778Z - info: -----      Core plugins startup        ----
2019-01-14T16:15:16.779Z - info: -------------------------------------------
2019-01-14T16:15:16.780Z - info: Loading plugins from folder /volumio/app/plugins/
2019-01-14T16:15:16.784Z - info: Adding plugin upnp to MyMusic Plugins
2019-01-14T16:15:16.786Z - info: Adding plugin airplay_emulation to MyMusic Plugins
2019-01-14T16:15:16.788Z - info: Adding plugin upnp_browser to MyMusic Plugins
2019-01-14T16:15:16.791Z - info: Loading plugins from folder /data/plugins/
2019-01-14T16:15:16.795Z - info: Loading plugin "system"...
2019-01-14T16:15:16.861Z - info: Loading plugin "appearance"...
2019-01-14T16:15:18.504Z - info: Loading plugin "network"...
2019-01-14T16:15:19.119Z - info: Loading plugin "services"...
2019-01-14T16:15:19.125Z - info: Loading plugin "alsa_controller"...
2019-01-14T16:15:19.253Z - info: Loading plugin "wizard"...
2019-01-14T16:15:19.277Z - info: Loading plugin "volumio_command_line_client"...
2019-01-14T16:15:19.289Z - info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
2019-01-14T16:15:19.290Z - info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
2019-01-14T16:15:19.290Z - info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
2019-01-14T16:15:19.291Z - info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
2019-01-14T16:15:19.323Z - info: Plugin upnp is not enabled
2019-01-14T16:15:19.324Z - info: Loading plugin "my_music"...
2019-01-14T16:15:19.343Z - info: Loading plugin "mpd"...
2019-01-14T16:15:19.864Z - info: Plugin upnp_browser is not enabled
2019-01-14T16:15:19.865Z - info: Loading plugin "networkfs"...
2019-01-14T16:15:19.921Z - info: CoreCommandRouter::executeOnPlugin: system , registerCallback
2019-01-14T16:15:19.922Z - info: Loading plugin "alarm-clock"...
2019-01-14T16:15:20.288Z - info: Plugin airplay_emulation is not enabled
2019-01-14T16:15:20.289Z - info: Loading plugin "last_100"...
2019-01-14T16:15:20.297Z - info: Loading plugin "webradio"...
2019-01-14T16:15:21.285Z - info: Loading plugin "i2s_dacs"...
2019-01-14T16:15:21.308Z - info: I2S DAC not set, start Auto-detection
2019-01-14T16:15:21.329Z - info: Loading plugin "volumiodiscovery"...
2019-01-14T16:15:21.420Z - info: Applying required configuration parameters for plugin volumiodiscovery
2019-01-14T16:15:21.461Z - info: CoreCommandRouter::executeOnPlugin: system , registerCallback
2019-01-14T16:15:21.462Z - info: Loading plugin "albumart"...
2019-01-14T16:15:21.514Z - info: Plugin example_plugin is not enabled
2019-01-14T16:15:21.517Z - info: Loading plugin "updater_comm"...
2019-01-14T16:15:21.691Z - info: Plugin mpdemulation is not enabled
2019-01-14T16:15:21.694Z - info: Loading plugin "rest_api"...
2019-01-14T16:15:21.712Z - info: Loading plugin "websocket"...
2019-01-14T16:15:21.746Z - info: ___________ START PLUGINS ___________
2019-01-14T16:15:21.752Z - info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
2019-01-14T16:15:21.754Z - info: [1547482521753] CoreMusicLibrary::Adding element Last_100
2019-01-14T16:15:21.762Z - info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
2019-01-14T16:15:21.763Z - info: [1547482521763] CoreMusicLibrary::Adding element Webradio
2019-01-14T16:15:21.765Z - info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion
2019-01-14T16:15:21.769Z - info: -------------------------------------------
2019-01-14T16:15:21.770Z - info: -----    MyVolumio plugins startup     ----
2019-01-14T16:15:21.770Z - info: -------------------------------------------
2019-01-14T16:15:21.772Z - info: Loading plugins from folder /myvolumio/plugins
2019-01-14T16:15:21.801Z - info: Loading plugins from folder /data/myvolumio/plugins
2019-01-14T16:15:21.803Z - info: Loading plugin "my_volumio"...
2019-01-14T16:15:22.507Z - info: Loading plugin "streaming_services"...
2019-01-14T16:15:22.957Z - info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
2019-01-14T16:15:22.958Z - info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
2019-01-14T16:15:22.995Z - info: Streaming services startup
2019-01-14T16:15:23.026Z - info: Loading i18n strings for locale en
2019-01-14T16:15:23.075Z - info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
2019-01-14T16:15:23.094Z - info: CoreCommandRouter::initPlayerControls
2019-01-14T16:15:23.116Z - info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
2019-01-14T16:15:23.117Z - info: CoreCommandRouter::executeOnPlugin: alsa_controller , getAlsaCards
2019-01-14T16:15:23.194Z - info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
2019-01-14T16:15:23.194Z - info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
2019-01-14T16:15:23.195Z - info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
2019-01-14T16:15:23.195Z - info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
2019-01-14T16:15:23.196Z - info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
2019-01-14T16:15:23.208Z - info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
2019-01-14T16:15:23.213Z - info: BOOT COMPLETED
2019-01-14T16:15:23.214Z - info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
2019-01-14T16:15:23.215Z - info: CoreCommandRouter::Close All Modals sent
2019-01-14T16:15:23.217Z - info: CoreCommandRouter::Close All Modals sent
2019-01-14T16:15:23.352Z - info: CoreStateMachine::resetVolumioState
2019-01-14T16:15:23.353Z - info: CoreStateMachine::getcurrentVolume
2019-01-14T16:15:23.354Z - info: CoreCommandRouter::volumioRetrievevolume
2019-01-14T16:15:23.372Z - info: CoreStateMachine::updateTrackBlock
2019-01-14T16:15:23.373Z - info: CorePlayQueue::getTrackBlock
2019-01-14T16:15:23.592Z - info: Setting Device type: Raspberry PI
2019-01-14T16:15:23.614Z - info: MPD running with PID623 ,establishing connection
2019-01-14T16:15:23.745Z - info: VolumeController:: Volume=49 Mute =false
2019-01-14T16:15:23.747Z - info: CoreStateMachine::pushState
2019-01-14T16:15:23.756Z - info: CoreStateMachine::getState
2019-01-14T16:15:23.757Z - info: CorePlayQueue::getTrack 0
2019-01-14T16:15:23.759Z - info: CoreCommandRouter::volumioPushState
2019-01-14T16:15:23.759Z - info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
2019-01-14T16:15:23.768Z - info: Volumio called home
2019-01-14T16:15:23.821Z - info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
2019-01-14T16:15:23.847Z - info: 
2019-01-14T16:15:23.856Z - info:  message= [50@0] {} No such directory, stack=Error:  [50@0] {} No such directory
    at MpdClient.receive (/volumio/app/plugins/music_service/mpd/lib/mpd.js:63:14)
    at Socket.<anonymous> (/volumio/app/plugins/music_service/mpd/lib/mpd.js:43:10)
    at emitOne (events.js:116:13)
    at Socket.emit (events.js:211:7)
    at addChunk (_stream_readable.js:263:12)
    at readableAddChunk (_stream_readable.js:246:13)
    at Socket.Readable.push (_stream_readable.js:208:10)
    at Pipe.onread (net.js:607:20)
2019-01-14T16:15:23.925Z - info: CoreStateMachine::setRepeat null single undefined
2019-01-14T16:15:23.925Z - info: CoreStateMachine::pushState
2019-01-14T16:15:23.926Z - info: CoreStateMachine::getState
2019-01-14T16:15:23.927Z - info: CorePlayQueue::getTrack 0
2019-01-14T16:15:23.927Z - info: CoreCommandRouter::volumioPushState
2019-01-14T16:15:23.928Z - info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
2019-01-14T16:15:23.931Z - info: CoreStateMachine::setRandom null
2019-01-14T16:15:23.932Z - info: CoreStateMachine::pushState
2019-01-14T16:15:23.933Z - info: CoreStateMachine::getState
2019-01-14T16:15:23.933Z - info: CorePlayQueue::getTrack 0
2019-01-14T16:15:23.934Z - info: CoreCommandRouter::volumioPushState
2019-01-14T16:15:23.934Z - info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
2019-01-14T16:15:24.072Z - info: mDNS: Found device Volumio
2019-01-14T16:15:24.285Z - info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable
2019-01-14T16:15:24.311Z - info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect
2019-01-14T16:15:24.519Z - info: 
---------------------------- Client requests Volume 50
2019-01-14T16:15:24.523Z - info: VolumeController::SetAlsaVolume50
2019-01-14T16:15:24.538Z - info: CoreStateMachine::pushState
2019-01-14T16:15:24.539Z - info: CoreStateMachine::getState
2019-01-14T16:15:24.539Z - info: CorePlayQueue::getTrack 0
2019-01-14T16:15:24.539Z - info: CoreCommandRouter::volumioPushState
2019-01-14T16:15:24.540Z - info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
2019-01-14T16:15:24.617Z - info: Setting volume on startup at 50
2019-01-14T16:15:24.871Z - info: CoreCommandRouter::volumioGetState
2019-01-14T16:15:24.873Z - info: CoreStateMachine::getState
2019-01-14T16:15:24.874Z - info: CorePlayQueue::getTrack 0
2019-01-14T16:15:24.964Z - info: MYVOLUMIO SUCCESSFULLY LOGGED IN
2019-01-14T16:15:24.967Z - info: MYVOLUMIO: Adding device
2019-01-14T16:15:24.969Z - info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
2019-01-14T16:15:24.971Z - info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
2019-01-14T16:15:24.971Z - info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
2019-01-14T16:15:25.311Z - info: CoreCommandRouter::volumioGetBrowseSources
2019-01-14T16:15:25.329Z - info: CoreCommandRouter::volumioGetState
2019-01-14T16:15:25.330Z - info: CoreStateMachine::getState
2019-01-14T16:15:25.330Z - info: CorePlayQueue::getTrack 0
2019-01-14T16:15:25.404Z - info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom
2019-01-14T16:15:25.412Z - info: Listing playlists
2019-01-14T16:15:25.424Z - info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus
2019-01-14T16:15:25.995Z - info: Updating MyVolumio device info
2019-01-14T16:15:25.998Z - info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
2019-01-14T16:15:25.999Z - info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
2019-01-14T16:15:26.002Z - info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
2019-01-14T16:15:26.108Z - info: MyVolumio status changed
2019-01-14T16:15:26.137Z - info: Stoppping Tunnel 1
2019-01-14T16:15:26.226Z - info: Remote SSH Stopped
2019-01-14T16:15:26.950Z - info: MyVolumio status changed
2019-01-14T16:15:29.045Z - info: CoreCommandRouter::volumioGetBrowseSources
2019-01-14T16:15:29.048Z - info: CoreCommandRouter::volumioGetState
2019-01-14T16:15:29.049Z - info: CoreStateMachine::getState
2019-01-14T16:15:29.050Z - info: CorePlayQueue::getTrack 0
2019-01-14T16:15:29.085Z - info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings
2019-01-14T16:15:29.090Z - info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard
2019-01-14T16:15:29.093Z - info: CoreCommandRouter::executeOnPlugin: system , getShowWizard
2019-01-14T16:15:29.117Z - info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom
2019-01-14T16:15:29.119Z - info: Listing playlists
2019-01-14T16:15:52.278Z - info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion
2019-01-14T16:15:52.281Z - info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
2019-01-14T16:24:53.678Z - info: CoreCommandRouter::volumioGetBrowseSources
2019-01-14T16:24:53.928Z - info: CoreCommandRouter::volumioGetState
2019-01-14T16:24:53.929Z - info: CoreStateMachine::getState
2019-01-14T16:24:53.929Z - info: CorePlayQueue::getTrack 0
2019-01-14T16:24:54.153Z - info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings
2019-01-14T16:24:54.154Z - info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard
2019-01-14T16:24:54.155Z - info: CoreCommandRouter::executeOnPlugin: system , getShowWizard
2019-01-14T16:24:54.201Z - info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom
2019-01-14T16:24:54.203Z - info: Listing playlists

You can see that between 16:15 and 16:24, the system was waiting for more memory. So this boot was 9mn long…

Hint: once everything is started and playing, I have no problem at all (no clicks, no sound interrupt, etc…)

There is an error/warning in the log file, always present. I issued another thred for this https://volumio.org/forum/error-volumio-log-t11554.html.

You can see this error in the log at 16:15:23.856.

Don’t know if this is related to my current problem.

I installed only the touch screen plugin. And also a little tool called “iftop”, which does nothing if not launched (light network monitor).
the SDcard is a standard Class10 16GB card
I have one power supply for the RPI (ifi audio 5V 2,5A), and a separate one for the screen and the Objective DAC (ifi audio 1A). Since I use these 2 supplies, I don’t see any undervoltage warning, as it was the case when I had only one.

I also saw a thread concenring background images and memory usage, so I kept only one image. No impact.

Thanks for your help

dk31 · January 14, 2019, 5:14pm

More:

Result of df, if this can help

volumio@volumio:~$ df
Filesystem                            Size  Used Avail Use% Mounted on
/dev/mmcblk0p2                        2.4G  671M  1.6G  31% /imgpart
/dev/loop0                            296M  296M     0 100% /static
overlay                                14G  816M   12G   7% /
devtmpfs                              497M     0  497M   0% /dev
tmpfs                                 509M   40M  470M   8% /dev/shm
tmpfs                                 509M  4.8M  505M   1% /run
tmpfs                                 5.3M  4.1k  5.3M   1% /run/lock
tmpfs                                 509M     0  509M   0% /sys/fs/cgroup
tmpfs                                 509M   21k  509M   1% /tmp
tmpfs                                 509M     0  509M   0% /var/spool/cups
tmpfs                                  21M   95k   21M   1% /var/log
tmpfs                                 509M     0  509M   0% /var/spool/cups/tmp
/dev/mmcblk0p1                         63M   39M   25M  61% /boot
tmpfs                                 102M     0  102M   0% /run/user/1000
192.168.0.21:/media/music/Music/flac  3.0T  1.7T  1.2T  60% /mnt/NAS/RPI1

dk31 · January 15, 2019, 10:00am

Additionnal information: the “time gap” in the log appears always after the same line, ie

“CoreCommandRouter::executeOnPlugin: system , getConfigParam”

For example, yesterday night (I insert mannualy a blank line to show where it is):

2019-01-14T22:30:30.599Z - info: -------------------------------------------
2019-01-14T22:30:30.603Z - info: -----            Volumio2              ----
2019-01-14T22:30:30.603Z - info: -------------------------------------------
2019-01-14T22:30:30.603Z - info: -----          System startup          ----
2019-01-14T22:30:30.604Z - info: -------------------------------------------
2019-01-14T22:30:30.872Z - info: Plugin folders cleanup
2019-01-14T22:30:30.873Z - info: Scanning into folder /volumio/app/plugins/
2019-01-14T22:30:30.874Z - info: Scanning category audio_interface
.....
2019-01-14T22:30:43.395Z - info: CoreCommandRouter::executeOnPlugin: system , getShowWizard
2019-01-14T22:30:43.417Z - info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom
2019-01-14T22:30:43.418Z - info: Listing playlists
2019-01-14T22:31:06.079Z - info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion
2019-01-14T22:31:06.081Z - info: CoreCommandRouter::executeOnPlugin: system , getConfigParam

2019-01-14T23:05:32.990Z - info: CoreCommandRouter::volumioGetBrowseSources
2019-01-14T23:05:32.994Z - info: CoreCommandRouter::volumioGetState
2019-01-14T23:05:32.994Z - info: CoreStateMachine::getState

We can see that the system took less than one minute to reach this step (22:30:30.599 => 22:31:06.081) and after that, It took more than half an hour to get ready to play music (34 mn), without producing any log in the meantime.

Any way to increase the log level to have more information during this gap?

Also, this is the last occurence of this line in the log, it appears several times. Is it normal?

volumio@volumio:$ grep "CoreCommandRouter::executeOnPlugin: system , getConfigParam" /var/log/volumio.log 
2019-01-14T22:30:37.252Z - info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
2019-01-14T22:30:37.254Z - info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
2019-01-14T22:30:37.487Z - info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
2019-01-14T22:30:38.061Z - info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
2019-01-14T22:30:40.599Z - info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
2019-01-14T22:30:40.600Z - info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
2019-01-14T22:30:40.601Z - info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
2019-01-14T22:30:41.608Z - info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
2019-01-14T22:30:41.609Z - info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
2019-01-14T22:30:41.610Z - info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
2019-01-14T22:31:06.081Z - info: CoreCommandRouter::executeOnPlugin: system , getConfigParam

dk31 · January 15, 2019, 2:51pm

More logs witth journactl forthe same period, but no so much information

....
Jan 14 23:30:49 volumio dhcpcd[467]: timed out
Jan 14 23:30:49 volumio dhcpcd[467]: exited
Jan 14 23:30:49 volumio ifup[428]: dhcpcd[467]: timed out
Jan 14 23:30:49 volumio ifup[428]: dhcpcd[467]: exited
Jan 14 23:30:49 volumio ifup[428]: Failed to bring up eth0.
Jan 14 23:31:06 volumio volumio[941]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion
Jan 14 23:31:06 volumio volumio[941]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Jan 14 23:31:21 volumio sudo[1287]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0
Jan 14 23:31:21 volumio sudo[1287]: pam_unix(sudo:session): session opened for user root by (uid=0)
Jan 14 23:31:21 volumio sudo[1287]: pam_unix(sudo:session): session closed for user root
Jan 14 23:31:21 volumio sudo[1293]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0
Jan 14 23:31:21 volumio sudo[1293]: pam_unix(sudo:session): session opened for user root by (uid=0)
Jan 14 23:31:21 volumio sudo[1293]: pam_unix(sudo:session): session closed for user root
Jan 14 23:36:44 volumio volumio-remote-updater[575]: [2019-01-14 23:36:20] [disconnect] Disconnect close local:[1008,Pong timeout] remote:[1006]
Jan 14 23:36:51 volumio volumio-remote-updater[575]: [2019-01-14 23:36:48] [connect] Successful connection
Jan 14 23:38:07 volumio volumio-remote-updater[575]: [2019-01-14 23:38:02] [connect] Successful connection
Jan 14 23:39:14 volumio volumio-remote-updater[575]: [2019-01-14 23:39:06] [connect] Successful connection
Jan 14 23:40:10 volumio volumio-remote-updater[575]: [2019-01-14 23:40:00] [connect] Successful connection
Jan 14 23:42:13 volumio volumio-remote-updater[575]: [2019-01-14 23:41:45] [info] Error getting remote endpoint: system:9 (Bad file descriptor)
Jan 14 23:42:31 volumio volumio-remote-updater[575]: [2019-01-14 23:42:15] [info] asio async_shutdown error: system:9 (Bad file descriptor)
Jan 14 23:43:10 volumio volumio-remote-updater[575]: [2019-01-14 23:42:41] [error] handle_connect error: Timer Expired
Jan 14 23:43:25 volumio volumio-remote-updater[575]: [2019-01-14 23:43:16] [connect] Successful connection
Jan 14 23:45:50 volumio volumio-remote-updater[575]: [2019-01-14 23:45:06] [error] handle_connect error: Timer Expired
Jan 14 23:47:14 volumio volumio-remote-updater[575]: [2019-01-14 23:46:47] [error] handle_connect error: Timer Expired
Jan 14 23:47:26 volumio volumio-remote-updater[575]: [2019-01-14 23:47:22] [connect] Successful connection
Jan 14 23:48:54 volumio volumio-remote-updater[575]: [2019-01-14 23:48:37] [info] Error getting remote endpoint: system:9 (Bad file descriptor)
Jan 14 23:49:40 volumio volumio-remote-updater[575]: [2019-01-14 23:49:14] [info] asio async_shutdown error: system:9 (Bad file descriptor)
Jan 14 23:50:11 volumio volumio-remote-updater[575]: [2019-01-14 23:49:44] [error] handle_connect error: Timer Expired
Jan 14 23:50:11 volumio systemd[1]: Starting Cleanup of Temporary Directories...
Jan 14 23:51:26 volumio volumio-remote-updater[575]: [2019-01-14 23:50:48] [info] Error getting remote endpoint: system:9 (Bad file descriptor)
Jan 14 23:52:47 volumio volumio-remote-updater[575]: [2019-01-14 23:51:50] [info] asio async_shutdown error: system:9 (Bad file descriptor)
Jan 14 23:53:30 volumio volumio-remote-updater[575]: [2019-01-14 23:52:47] [error] handle_connect error: Timer Expired
Jan 14 23:54:31 volumio volumio-remote-updater[575]: [2019-01-14 23:54:06] [info] Error getting remote endpoint: system:9 (Bad file descriptor)
Jan 14 23:55:00 volumio volumio-remote-updater[575]: [2019-01-14 23:54:25] [info] asio async_shutdown error: system:9 (Bad file descriptor)
Jan 14 23:55:05 volumio volumio-remote-updater[575]: [2019-01-14 23:54:42] [error] handle_connect error: Timer Expired
Jan 14 23:55:47 volumio volumio-remote-updater[575]: [2019-01-14 23:55:35] [info] Error getting remote endpoint: system:9 (Bad file descriptor)
Jan 14 23:56:04 volumio volumio-remote-updater[575]: [2019-01-14 23:55:47] [info] asio async_shutdown error: system:9 (Bad file descriptor)
Jan 14 23:56:06 volumio volumio-remote-updater[575]: [2019-01-14 23:56:04] [error] handle_connect error: Timer Expired
Jan 14 23:57:25 volumio volumio-remote-updater[575]: [2019-01-14 23:57:05] [info] Error getting remote endpoint: system:9 (Bad file descriptor)
Jan 14 23:57:48 volumio volumio-remote-updater[575]: [2019-01-14 23:57:33] [info] asio async_shutdown error: system:9 (Bad file descriptor)
Jan 14 23:58:24 volumio volumio-remote-updater[575]: [2019-01-14 23:57:55] [error] handle_connect error: Timer Expired
Jan 14 23:58:53 volumio volumio-remote-updater[575]: [2019-01-14 23:58:34] [info] Error getting remote endpoint: system:9 (Bad file descriptor)
Jan 14 23:59:27 volumio volumio-remote-updater[575]: [2019-01-14 23:59:15] [info] asio async_shutdown error: system:9 (Bad file descriptor)
Jan 15 00:00:07 volumio volumio-remote-updater[575]: [2019-01-14 23:59:38] [error] handle_connect error: Timer Expired
Jan 15 00:01:24 volumio volumio-remote-updater[575]: [2019-01-15 00:00:41] [info] Error getting remote endpoint: system:9 (Bad file descriptor)
Jan 15 00:02:17 volumio volumio-remote-updater[575]: [2019-01-15 00:01:56] [info] asio async_shutdown error: system:9 (Bad file descriptor)
Jan 15 00:02:31 volumio systemd[1]: Started Cleanup of Temporary Directories.

This is the content of the system log for the time interval during which the “node” process takes all CPU, almost all RAM memory, and produces apparently no extra information in logs., to my eyes at least.

Additionnal info: I was able to monitor the network during the same interval, there was no remarkable traffic either, so this is not a network issue.

volumio · January 15, 2019, 5:10pm

Send logs as per here:
volumio.github.io/docs/User_Man … oting.html

Did you by any chance enable embedded albumarts?

dk31 · January 15, 2019, 5:31pm

Thanks. I will send the logs this evening.

Embedded albumarts? As far as I know, no.

I did enable “Web album art” at once, but disabled it after a while and made a reset of the cache, which emptied the directories under /data/albumart.

Is this what you call “embedded album art”?

All my “album arts” are jpg files located with the music, so web album art is not useful for me.

dk31 · January 15, 2019, 5:34pm

Logs are here:

logs.volumio.org/volumio/t7cqgAP.html

dk31 · January 16, 2019, 2:15pm

More than 3 hours booting this morning, and still not there! Not sure, but it seems that things get worst day after day.

dk31 · January 17, 2019, 12:34pm

More hints:

first boot of the day is always very long. Goes into swapping, and takes more than 30 mn,one hour, etc… After unplugging PSU and restarting, boot takes 5 mn, but at least, it does not stay blocked for hours. So, to summarize, first boot of the day is always a problem. Further ones are better.
during these 5 mn, sometimes, I have access to the WebUI (I can navigate through the menus), but I don’t have access to the music (WebRadio or NAS). The system becomes ready only when the “NAS” appears in the music library. This correspond to the end of having the “node” process taking all CPU and RAM.

So I guess that during these long minutes with no trace in the log, the “node” process makes avalaible the music files and library? But why is it so long?

dk31 · January 18, 2019, 4:18pm

Bad news… I have flashed another SD card, to start again from the beginning.

First boot: eveything comes up in a second. The “node” process took 10 s of CPU time. Good.

I go into declaring my database (access through NFS, wired ethernet). Scan starts immediately. The scanning of the database took almost 3 hours. Not surprising, it was the same with the other SD card.

Reboot volumio: back to the same issue. The “node” process took more than five minutes of CPU time before finishing.

I have not installed anything (no plugin, etc), I just configured the path to my music.

Below the result of the “ps -aux” just after the webUI is accessible: 5:49 minutes of CPU Time.

volumio   1022 51.0 16.9 304024 168976 ?       Ssl  15:39   5:49 /usr/local/bin/node /volumio/index.js

Second chance: reboot again. Same result…

Is this database too large for volumio? I had a much bigger one (twice this size) with mpd alone on my previous platfom (an old eeepc 701…) , without any performance issue.

ls -l /var/lib/mpd/
total 41136
drwxr-xr-x 2 root root        71 Dec  6 23:34 music
drwxrwxrwx 2 mpd  audio        3 Dec 12  2014 playlists
-rwxrwxrwx 1 root root  42117562 Jan 18 15:00 tag_cache

File “tag_cache” is 42 MB large.

cat /var/lib/mpd/tag_cache | wc -l
1357860

In the WebUI, “MyMusic” shows me:
5076 Artists
4746 Albums
126859 Songs.
8872 hours of playtime.

Which looks good to me. Is this too much for volumio?

But, from my understanding, this file “tag_cache” is managed by mpd.

Is the “node” process scanning this file at boot time, each time? What for?

Thanks for your help.

dk31 · January 18, 2019, 8:39pm

What I understand from now: I’m not sure I’m facing a bug, but a true performance issue. I don’t know which one I prefer…

the time needed for “/usr/local/bin/node /volumio/index.js” at boot time is closely related to the size of the MPD database. The greater the DB, the longer the needed CPU time. My DB is 42 MB large, it takes 5 mn to “load” it for the “node” process. 5 mn of CPU time, and a lot of RAM memory. So, when memory is missing, this can take hours…
things get worst when the touch screen plugin is active, because more processes are present at boot time (chromium-browser for example). So this extra load is not the best thing that can happen…

What I don’t get, is that MPD + GMPC alone work like a charm on a database which is twice the one I have now on Volumio (89 MB), as I have today loaded only half of my DB… I’ve been using this for years on a old eeepc 701, I have never seen such a performance issue.

So, what can I do?

I could use a faster SD card. The one I have is a “standard” Class 10 (noname). What about giving a chance to a Kingston or Samsung “pro”. Will it help?
any way to postpone the launch of chromium-browser at boot time? I don’t really need the touch screen display when booting, I would prefer to save CPU and RAM for the node process. Are they launched in /etc/init.d? Any way to insert a pause/timer there?
Would it make sense to split my DB in parts? The global size would be the same, but I could make 5 or 6 different “first level” directories. Would it help?
go back to MPD/GMPC ?

Any other suggestion?

dk31 · January 19, 2019, 12:06pm

Hi,

I have now reduced as much as I can the size of my DB (mostly suppressing symlinks):

volumio@volumio2:~$ ls -l /var/lib/mpd/tag_cache 
-rwxrwxrwx 1 root root 28484728 Jan 19 11:21 /var/lib/mpd/tag_cache
volumio@volumio2:~$ cat /var/lib/mpd/tag_cache | wc -l
915369

Number of lines is slighlty lower, but the size of the file was reduced (43MB => 28 MB), mostly because the pathnames are shorter (the way I declare mount points). So, file is much smaller, and holds 10% less lines.

I can’t do more without suppressing music… which I don’t want.

I have also splitted into 5 mount points, instead of one, but I’m not sure it changes anything concerning performance, but this reduces the size of the tag-cache file, because pathnames are shorter.

I have now 2:51 of CPU time needed for the node process at boot time (instead of 5:10). That’s 30% less. This corresponds more or less to the reduction of the file size.

I have not installed the touchscreen plugin yet… And I have not yet declared the other half of my music library. I fear that this will make the system out of use again…

As far as I understand, the “node” process" makes a scan of the mpd database during each boot. Even if this database has not changed. It seems to me that the CPU time needed for the node process is somewhat proportionnal to the size of the “tag_cache” file… Am I wrong?

Can somebody explain me why it is needed to do so? I understand that, for an update, or a rescan of the DB, this is mandatory, but why is it done at each boot?

I have been using mpd/gmpc for years, and it is clear for me that no rescan is needed if nothing was changed in the music library, the mpd clients have an immediate access to the db, whatever its size.

GMPC displays the same information as Volumio (music libraries, albums, tracks, album art, etc…), but it shows it in a second, and does no make any scan.

In volumio, it seems to me that large music libraries have a direct impact on boot time. Not so nice.

I’m very hapy with the audio features in Volumio, quality of sound, user interface, etc… But performance is another story. Can anything be done to solve this?

dk31 · January 19, 2019, 3:28pm

Situation is now more stable.

With my “reduced” mpd db, node requires now 2:50 before letting other processes do something… After several boots, this time remains the same.

I have installed the touchscreen plugin, and inserted a “sleep 240” at the beginning of /opt/volumiokiosk.sh. This means that the X server and chromium are launched 4 mn after boot, leaving CPU and RAM to “node”. This seem to work for the moment.

I’ll give a chance to a higher speed SD card, I have ordered a “Kingston Sdcg2 32go Micro Sd Sdhc Classe 10 Uhs-i U3 V30”. Let’s see if things are better when it arrives.

The 240 sec waiting time could be adjusted, but I’m wondering how to do that. What could I monitor in order to be sure that the node process has finished its uptdate job? Something in the log?

Of course, if I load the second half of my music library, things will get worst. But for the moment, I can live like that.

It would nevertheless be nice to reduce the load of this “node” process at boot time.

dk31 · January 22, 2019, 3:25pm

I have now attached a USB HD instead of using my NAS. This solves the issue, don’t ask me why…

Even with my “full” mpd db (71MB, 2,6MLines, 216000 Tracks, 13000 hrs of Music):

volumio@volumio:/var/lib/mpd$ ls -l
total 69852
drwxr-xr-x 2 root root        71 Dec  7 00:34 music
drwxrwxrwx 1 mpd  audio     4096 Jan 16 09:31 playlists
-rwxrwxrwx 1 root root  71513293 Jan 17 12:37 tag_cache
volumio@volumio:/var/lib/mpd$ cat ./tag_cache | wc -l
2594913

It just boots now in 30 seconds, most of this time taken by the “mpd” process. The main “node” process takes only 10 or 15 seconds of CPU time. So, there’s something strange when accessing from network, at least for big libraries.

I don’t put “SOLVED” in the title.

pumuckl · October 18, 2020, 12:13pm

Over 1 year after this post, I can only confirm what dk31 writes. At the moment I’m still in the test phase with Virtuoso, but it looks like nobody here has a solution for large music libraries. It is always pointed out that the size is not a problem, but that is not true!
Working with a USB hard drive is counterproductive, as synchronization with the NAS must always be done manually. I am very disappointed at the moment because the product is otherwise very well thought out.