Hello,
I am stuck on a performance issue when booting volumio. The problem was already described in this post:
https://forum.volumio.org/performance-issue-boot-each-time-t11561.html
but I will make a short descrption again.
First, I “solved” (not really solved, let’s say I found a workaround) the issue by using a USB HDD… But now, I have changed several things in my network (wifi router, NAS, etc…) so I was hoping I could get better results, but, no, very same situation.
So, I’m trying back to attach my music library through Wifi. The library is large (more than 2TB of flac files).
When attaching the library (i.e creating the mount point in Volumio interface), everything goes well, then it takes a long time (around 3 hrs) to build the library in volumio. I can see mpd running and some activity on the NAS. At the end, the mpd library i created, it is 4MB large:
volumio@volumio-test:~$ ls -l /var/lib/mpd/
total 4328
drwxr-xr-x 2 root root 71 May 5 16:38 music
drwxrwxrwx 2 mpd audio 3 Dec 12 2014 playlists
-rwxrwxrwx 1 root root 4426535 May 12 11:34 tag_cacheAfter a while, I can access to music files, listen to music. So far so good.
The problem arises when I boot again the RPI. I can see a volumio process which takes 100% of CPU during more than 4 minutes, which is a long time… While this process is running, I cannot access to the music lbrary.
See the first line below: 4.44 mn of CPU time taken by “/usr/local/bin/node /volumio/index.js”
volumio@volumio-test:~$ ps -aux | grep node
volumio 902 22.4 17.1 307364 170692 ? Ssl 13:39 4:44 /usr/local/bin/node /volumio/index.js
volumio 997 0.0 1.0 72636 9976 ? Sl 13:39 0:00 /bin/node /volumio/app/plugins/miscellanea/albumart/serverStartup.js 3001 /data/albumart
volumio 1003 0.1 1.8 115644 18016 ? Sl 13:39 0:01 /bin/node /volumio/app/plugins/miscellanea/albumart/serverStartup.js 3001 /data/albumart
volumio 1004 0.1 1.8 115232 18100 ? Sl 13:39 0:01 /bin/node /volumio/app/plugins/miscellanea/albumart/serverStartup.js 3001 /data/albumart
volumio 1009 0.1 1.8 115132 18096 ? Sl 13:39 0:01 /bin/node /volumio/app/plugins/miscellanea/albumart/serverStartup.js 3001 /data/albumart
volumio 2391 0.0 0.1 4160 1384 pts/1 S+ 14:00 0:00 grep node
This problem, described in my earlier post, is still present. I have downloaded a fresh version of volumio (2.773)
The cpu load is taken here, starting at 14:07:05:
May 12 14:06:47 volumio-test volumio-streaming-daemon[1149]: ############################
May 12 14:06:47 volumio-test volumio-streaming-daemon[1149]: # Volumio Streaming Daemon #
May 12 14:06:47 volumio-test volumio-streaming-daemon[1149]: # Running on port 7777 #
May 12 14:06:47 volumio-test volumio-streaming-daemon[1149]: ############################
May 12 14:06:47 volumio-test volumio-streaming-daemon[1149]: Environment: production
May 12 14:06:48 volumio-test volumio-remote-updater[598]: [2020-05-12 14:06:48] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.5.1" /socket.io/?EIO=4&transport=websocket&t=1589292406 101
May 12 14:06:52 volumio-test volumio-streaming-daemon[1149]: Environment: production
May 12 14:06:54 volumio-test volumio[991]: info: Fetching Streaming Services browse cache
May 12 14:07:01 volumio-test volumio[991]: info: CoreCommandRouter::volumioRemoveToBrowseSourcesQOBUZ
May 12 14:07:01 volumio-test volumio[991]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
May 12 14:07:01 volumio-test volumio[991]: info: CoreCommandRouter::volumioRemoveToBrowseSourcesTIDAL
May 12 14:07:01 volumio-test volumio[991]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
May 12 14:07:05 volumio-test volumio[991]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion
May 12 14:07:05 volumio-test volumio[991]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
May 12 14:11:23 volumio-test nmbd[857]: [2020/05/12 14:11:23.971192, 0] ../source3/nmbd/nmbd_namequery.c:109(query_name_response)
May 12 14:11:23 volumio-test nmbd[857]: query_name_response: Multiple (2) responses received for a query on subnet 192.168.0.23 for name WORKGROUP<1d>.
May 12 14:11:23 volumio-test nmbd[857]: This response was from IP 192.168.0.21, reporting an IP address of 192.168.0.21.
May 12 14:13:52 volumio-test sshd[1303]: Accepted password for volumio from 192.168.0.35 port 59904 ssh2
May 12 14:13:52 volumio-test sshd[1303]: pam_unix(sshd:session): session opened for user volumio by (uid=0)
May 12 14:13:53 volumio-test systemd[1]: Starting user-1000.slice.
May 12 14:13:53 volumio-test systemd[1]: Created slice user-1000.slice.
May 12 14:13:53 volumio-test systemd[1]: Starting User Manager for UID 1000...
May 12 14:13:53 volumio-test systemd-logind[617]: New session c1 of user volumio.
May 12 14:13:53 volumio-test systemd[1]: Starting Session c1 of user volumio.
May 12 14:13:53 volumio-test systemd[1]: Started Session c1 of user volumio.
May 12 14:13:53 volumio-test systemd[1309]: pam_unix(systemd-user:session): session opened for user volumio by (uid=0)
May 12 14:13:53 volumio-test systemd[1309]: Starting Paths.
May 12 14:13:53 volumio-test systemd[1309]: Reached target Paths.
May 12 14:13:53 volumio-test systemd[1309]: Starting Timers.
May 12 14:13:53 volumio-test systemd[1309]: Reached target Timers.
May 12 14:13:53 volumio-test systemd[1309]: Starting Sockets.
May 12 14:13:53 volumio-test systemd[1309]: Reached target Sockets.
May 12 14:13:53 volumio-test systemd[1309]: Starting Basic System.
May 12 14:13:53 volumio-test systemd[1309]: Reached target Basic System.
May 12 14:13:53 volumio-test systemd[1309]: Starting Default.
May 12 14:13:53 volumio-test systemd[1309]: Reached target Default.
May 12 14:13:53 volumio-test systemd[1309]: Startup finished in 61ms.
May 12 14:13:53 volumio-test systemd[1]: Started User Manager for UID 1000.
May 12 14:13:53 volumio-test sshd[1303]: lastlog_openseek: Couldn't stat /var/log/lastlog: No such file or directory
May 12 14:13:53 volumio-test sshd[1303]: lastlog_openseek: Couldn't stat /var/log/lastlog: No such file or directory
May 12 14:15:39 volumio-test volumio[991]: info: CoreCommandRouter::executeOnPlugin: mpd , handleBrowseUri
May 12 14:15:39 volumio-test volumio[991]: info: CURURI: music-library/NAS/RPI4/Chanson
We can see that, in the log, more that 4 minutes are passed in “getConfigParam”, without any additionnal information.
I have even tried to boot without the network and replug it afterwards, same result, the same "node’ process takes 4,40 mn, which makes me say that it is not related to any network performance, but only internal use of resources.
I have made several tests: the bigger the database , the longer the waiting time. But the mpd database was created at the beginning, it is not created at each boot, and is not modified as long as I don’t change anything in the library.
Now the questions:
-
why does the problem disappear with an attached USB HDD, although the mpd music lbrary is strictly the same? With the USB HDD, the “node.jd” takes only a bucket od seconds
-
does this “getConfigParam” function do something different between Networked and USB music library?
-
is there any way to increase the log level and see on the log what happens during these 4 mns?
For me, it would be a great improvment to use my NAS instead of an external HDD.
Any help appreciated. Thanks i advance.