Sat May 13, 2023 4:30 pm
Serviio on TrueNAS 13.2 is Slow to Index Files
Hello All,
I have deleted the jail and recreated the jail and a Serviio 2.3 installation from the ports Collection at least a dozen times.
Each time, I am unable to get Serviio to fully index my music library without failure.
The failure exhibits itself as just about making the TrueNAS server unusable.
Everything in the TrueNAS GUI is very slow.
Ten seconds to show the Dashboard. Ninety seconds to show the jails dialog.
Samba is completely hosed. It takes windows thirty minutes to change to another directory that is Samba shared from the server.
It takes minutes to get a jail shell in order to do "service serviio stop -f". The -f is required or Serviio cannot be stopped.
Once serviio is stopped, all returns to normal. Note that the jail is still running.
Running top from the jail shell while serviio is running shows: (note that it takes minutes to get to that jail shell to run top)
last pid: 24533; load averages: 0.83, 0.79, 0.75 up 0+10:53:17 10:59:22
11 processes: 1 running, 10 sleeping
CPU: 0.1% user, 0.0% nice, 6.0% system, 0.0% interrupt, 93.9% idle
Mem: 814M Active, 2058M Inact, 14G Wired, 14G Free
ARC: 3060M Total, 1657M MFU, 875M MRU, 2228K Anon, 67M Header, 458M Other
2148M Compressed, 3286M Uncompressed, 1.53:1 Ratio
Swap: 8192M Total, 8192M Free
PID USERNAME THR PRI NICE SIZE RES STATE C TIME WCPU COMMAND
24121 dlna 117 52 0 2180M 518M uwait 1 0:59 11.82% java
24508 eewiz 1 20 0 14M 3592K CPU0 0 0:00 0.01% top
24487 eewiz 1 20 0 21M 10M select 1 0:00 0.00% sshd
24463 root 1 23 0 21M 9756K select 2 0:01 0.00% sshd
24490 eewiz 1 20 0 13M 3428K wait 0 0:01 0.00% sh
24112 root 1 20 0 13M 2512K nanslp 3 0:00 0.00% cron
24046 root 1 20 0 13M 2740K select 1 0:00 0.00% syslogd
24108 root 1 20 0 21M 9344K select 3 0:00 0.00% sshd
23849 root 1 52 0 13M 2624K select 2 0:00 0.00% dhclient
23852 root 1 4 0 13M 2696K select 3 0:00 0.00% dhclient
23927 _dhcp 1 24 0 13M 2744K select 0 0:00 0.00% dhclient
The TrueNAS Dashboard shows CPU peaks up to about 10%. The server is not at all busy.
The first time, I tried to index the entire music folder. This caused the slow down failure as described above.
Many more times, I tried breaking the job into smaller pieces.
I started with folders likes ones containing 100 or 1000 or 4000 files.
I can do three or six or nine of these subfolders but eventually the failure happens.
I tried a 40,000 file folder first and it indexed O.K.
Then it fails on the 100 or the 4000 file folder which has been indexed O.K. on a previous install.
After a dozen tries, it has broken on most folders. Any one of those folders has worked multiple times and then failed somewhere along the way.
It doesn't matter what order I use to index the subfolders. I can't get through all of them without the failure.
This dozenth time I decided to try again at the top level.
I erased the jail again, installed from ports again, and tried again to index from the top level music folder.
I could tell from the slow down that Serviio failed immediately and proceeded to slow the server to a snail's pace.
I waited about half an hour and saw the first New File Bubble appear.
Serviio manages to index one new file about every minute.
In the last hour since the first New File Bubble appeared, Serviio has managed to index only 72 files.
Also notice the JAVA usage in the top display above.
It was al least half an hour before top was executed.
It can be seen that JAVA used only 59 seconds of processing time during that half hour that it took for that first New File Bubble to appear.
About one hour later top shows:
last pid: 25218; load averages: 0.34, 0.56, 0.61 up 0+11:47:34 11:53:39
11 processes: 1 running, 10 sleeping
CPU: 0.1% user, 0.0% nice, 10.0% system, 0.0% interrupt, 90.0% idle
Mem: 822M Active, 2088M Inact, 10G Wired, 18G Free
ARC: 3075M Total, 1665M MFU, 880M MRU, 2526K Anon, 67M Header, 459M Other
2162M Compressed, 3310M Uncompressed, 1.53:1 Ratio
Swap: 8192M Total, 8192M Free
PID USERNAME THR PRI NICE SIZE RES STATE C TIME WCPU COMMAND
24121 dlna 118 52 0 2208M 543M uwait 1 3:38 1.94% java
24508 eewiz 1 20 0 14M 3640K CPU0 0 0:01 0.02% top
24487 eewiz 1 20 0 21M 10M select 3 0:00 0.00% sshd
24112 root 1 20 0 13M 2512K nanslp 1 0:01 0.00% cron
24463 root 1 23 0 21M 9756K select 2 0:01 0.00% sshd
24490 eewiz 1 20 0 13M 3428K wait 0 0:01 0.00% sh
24046 root 1 20 0 13M 2740K select 0 0:00 0.00% syslogd
24108 root 1 20 0 21M 9344K select 3 0:00 0.00% sshd
23849 root 1 52 0 13M 2624K select 2 0:00 0.00% dhclient
23852 root 1 4 0 13M 2696K select 3 0:00 0.00% dhclient
23927 _dhcp 1 24 0 13M 2744K select 0 0:00 0.00% dhclient
In 1.5 hours, JAVA has managed to use only 3 minutes 38 seconds of processing time.
It also takes several minutes to get the TrueNAS shell to come up.
Running top from there says:
last pid: 25381; load averages: 2.12, 1.11, 0.82 up 0+11:58:01 12:04:06
79 processes: 1 running, 78 sleeping
CPU: 0.0% user, 0.0% nice, 8.2% system, 0.0% interrupt, 91.8% idle
Mem: 822M Active, 2092M Inact, 10G Wired, 18G Free
ARC: 3079M Total, 1672M MFU, 878M MRU, 1571K Anon, 67M Header, 460M Other
2165M Compressed, 3316M Uncompressed, 1.53:1 Ratio
Swap: 8192M Total, 8192M Free
PID USERNAME THR PRI NICE SIZE RES STATE C TIME WCPU COMMAND
24121 lildeb 118 52 0 2208M 544M uwait 1 4:12 22.19% java
383 root 30 20 0 416M 303M kqread 1 4:49 0.57% python3.
2869 lildeb 120 52 0 2176M 431M uwait 1 4:06 0.11% java
25369 root 1 20 0 14M 4296K CPU0 0 0:00 0.03% top
24508 urbackup 1 20 0 14M 3692K select 1 0:01 0.02% top
1661 root 11 20 0 163M 99M nanslp 0 5:03 0.01% collectd
1457 uucp 1 20 0 13M 2872K select 0 0:04 0.01% usbhid-u
1652 www 1 20 0 36M 9136K kqread 3 0:01 0.01% nginx
1554 root 8 20 0 59M 14M select 0 0:43 0.01% rrdcache
1525 ntpd 1 20 0 21M 7132K select 2 0:01 0.00% ntpd
1715 root 1 20 0 45M 23M kqread 2 0:02 0.00% nmbd
24487 urbackup 1 20 0 21M 10M select 3 0:00 0.00% sshd
1634 root 1 20 0 13M 2812K nanslp 3 0:03 0.00% cron
24046 root 1 20 0 13M 2740K select 0 0:00 0.00% syslogd
1459 uucp 1 20 0 45M 2752K select 1 0:01 0.00% upsd
I don't see any red flags in this "ROOT" top display.
I do noticed that the "ROOT" JAVA user is "lildeb" which is a user on the TrueNAS server, but "lildeb" should have nothing to do with JAVA running on the "ROOT".
Doing this in the "ROOT" shell:
root@plum[~]# java -version
Says:
zsh: command not found: java
Doing this in the jail shell:
eewiz@musicj:~ $ java -version
Says:
openjdk version "1.8.0_372"
OpenJDK Runtime Environment (build 1.8.0_372-b07)
OpenJDK 64-Bit Server VM (build 25.372-b07, mixed mode)
I need some help to fix this issue.
I don't know where to look or what to test to try to resolve this issue.
Please help.
Thank You
I have deleted the jail and recreated the jail and a Serviio 2.3 installation from the ports Collection at least a dozen times.
Each time, I am unable to get Serviio to fully index my music library without failure.
The failure exhibits itself as just about making the TrueNAS server unusable.
Everything in the TrueNAS GUI is very slow.
Ten seconds to show the Dashboard. Ninety seconds to show the jails dialog.
Samba is completely hosed. It takes windows thirty minutes to change to another directory that is Samba shared from the server.
It takes minutes to get a jail shell in order to do "service serviio stop -f". The -f is required or Serviio cannot be stopped.
Once serviio is stopped, all returns to normal. Note that the jail is still running.
Running top from the jail shell while serviio is running shows: (note that it takes minutes to get to that jail shell to run top)
last pid: 24533; load averages: 0.83, 0.79, 0.75 up 0+10:53:17 10:59:22
11 processes: 1 running, 10 sleeping
CPU: 0.1% user, 0.0% nice, 6.0% system, 0.0% interrupt, 93.9% idle
Mem: 814M Active, 2058M Inact, 14G Wired, 14G Free
ARC: 3060M Total, 1657M MFU, 875M MRU, 2228K Anon, 67M Header, 458M Other
2148M Compressed, 3286M Uncompressed, 1.53:1 Ratio
Swap: 8192M Total, 8192M Free
PID USERNAME THR PRI NICE SIZE RES STATE C TIME WCPU COMMAND
24121 dlna 117 52 0 2180M 518M uwait 1 0:59 11.82% java
24508 eewiz 1 20 0 14M 3592K CPU0 0 0:00 0.01% top
24487 eewiz 1 20 0 21M 10M select 1 0:00 0.00% sshd
24463 root 1 23 0 21M 9756K select 2 0:01 0.00% sshd
24490 eewiz 1 20 0 13M 3428K wait 0 0:01 0.00% sh
24112 root 1 20 0 13M 2512K nanslp 3 0:00 0.00% cron
24046 root 1 20 0 13M 2740K select 1 0:00 0.00% syslogd
24108 root 1 20 0 21M 9344K select 3 0:00 0.00% sshd
23849 root 1 52 0 13M 2624K select 2 0:00 0.00% dhclient
23852 root 1 4 0 13M 2696K select 3 0:00 0.00% dhclient
23927 _dhcp 1 24 0 13M 2744K select 0 0:00 0.00% dhclient
The TrueNAS Dashboard shows CPU peaks up to about 10%. The server is not at all busy.
The first time, I tried to index the entire music folder. This caused the slow down failure as described above.
Many more times, I tried breaking the job into smaller pieces.
I started with folders likes ones containing 100 or 1000 or 4000 files.
I can do three or six or nine of these subfolders but eventually the failure happens.
I tried a 40,000 file folder first and it indexed O.K.
Then it fails on the 100 or the 4000 file folder which has been indexed O.K. on a previous install.
After a dozen tries, it has broken on most folders. Any one of those folders has worked multiple times and then failed somewhere along the way.
It doesn't matter what order I use to index the subfolders. I can't get through all of them without the failure.
This dozenth time I decided to try again at the top level.
I erased the jail again, installed from ports again, and tried again to index from the top level music folder.
I could tell from the slow down that Serviio failed immediately and proceeded to slow the server to a snail's pace.
I waited about half an hour and saw the first New File Bubble appear.
Serviio manages to index one new file about every minute.
In the last hour since the first New File Bubble appeared, Serviio has managed to index only 72 files.
Also notice the JAVA usage in the top display above.
It was al least half an hour before top was executed.
It can be seen that JAVA used only 59 seconds of processing time during that half hour that it took for that first New File Bubble to appear.
About one hour later top shows:
last pid: 25218; load averages: 0.34, 0.56, 0.61 up 0+11:47:34 11:53:39
11 processes: 1 running, 10 sleeping
CPU: 0.1% user, 0.0% nice, 10.0% system, 0.0% interrupt, 90.0% idle
Mem: 822M Active, 2088M Inact, 10G Wired, 18G Free
ARC: 3075M Total, 1665M MFU, 880M MRU, 2526K Anon, 67M Header, 459M Other
2162M Compressed, 3310M Uncompressed, 1.53:1 Ratio
Swap: 8192M Total, 8192M Free
PID USERNAME THR PRI NICE SIZE RES STATE C TIME WCPU COMMAND
24121 dlna 118 52 0 2208M 543M uwait 1 3:38 1.94% java
24508 eewiz 1 20 0 14M 3640K CPU0 0 0:01 0.02% top
24487 eewiz 1 20 0 21M 10M select 3 0:00 0.00% sshd
24112 root 1 20 0 13M 2512K nanslp 1 0:01 0.00% cron
24463 root 1 23 0 21M 9756K select 2 0:01 0.00% sshd
24490 eewiz 1 20 0 13M 3428K wait 0 0:01 0.00% sh
24046 root 1 20 0 13M 2740K select 0 0:00 0.00% syslogd
24108 root 1 20 0 21M 9344K select 3 0:00 0.00% sshd
23849 root 1 52 0 13M 2624K select 2 0:00 0.00% dhclient
23852 root 1 4 0 13M 2696K select 3 0:00 0.00% dhclient
23927 _dhcp 1 24 0 13M 2744K select 0 0:00 0.00% dhclient
In 1.5 hours, JAVA has managed to use only 3 minutes 38 seconds of processing time.
It also takes several minutes to get the TrueNAS shell to come up.
Running top from there says:
last pid: 25381; load averages: 2.12, 1.11, 0.82 up 0+11:58:01 12:04:06
79 processes: 1 running, 78 sleeping
CPU: 0.0% user, 0.0% nice, 8.2% system, 0.0% interrupt, 91.8% idle
Mem: 822M Active, 2092M Inact, 10G Wired, 18G Free
ARC: 3079M Total, 1672M MFU, 878M MRU, 1571K Anon, 67M Header, 460M Other
2165M Compressed, 3316M Uncompressed, 1.53:1 Ratio
Swap: 8192M Total, 8192M Free
PID USERNAME THR PRI NICE SIZE RES STATE C TIME WCPU COMMAND
24121 lildeb 118 52 0 2208M 544M uwait 1 4:12 22.19% java
383 root 30 20 0 416M 303M kqread 1 4:49 0.57% python3.
2869 lildeb 120 52 0 2176M 431M uwait 1 4:06 0.11% java
25369 root 1 20 0 14M 4296K CPU0 0 0:00 0.03% top
24508 urbackup 1 20 0 14M 3692K select 1 0:01 0.02% top
1661 root 11 20 0 163M 99M nanslp 0 5:03 0.01% collectd
1457 uucp 1 20 0 13M 2872K select 0 0:04 0.01% usbhid-u
1652 www 1 20 0 36M 9136K kqread 3 0:01 0.01% nginx
1554 root 8 20 0 59M 14M select 0 0:43 0.01% rrdcache
1525 ntpd 1 20 0 21M 7132K select 2 0:01 0.00% ntpd
1715 root 1 20 0 45M 23M kqread 2 0:02 0.00% nmbd
24487 urbackup 1 20 0 21M 10M select 3 0:00 0.00% sshd
1634 root 1 20 0 13M 2812K nanslp 3 0:03 0.00% cron
24046 root 1 20 0 13M 2740K select 0 0:00 0.00% syslogd
1459 uucp 1 20 0 45M 2752K select 1 0:01 0.00% upsd
I don't see any red flags in this "ROOT" top display.
I do noticed that the "ROOT" JAVA user is "lildeb" which is a user on the TrueNAS server, but "lildeb" should have nothing to do with JAVA running on the "ROOT".
Doing this in the "ROOT" shell:
root@plum[~]# java -version
Says:
zsh: command not found: java
Doing this in the jail shell:
eewiz@musicj:~ $ java -version
Says:
openjdk version "1.8.0_372"
OpenJDK Runtime Environment (build 1.8.0_372-b07)
OpenJDK 64-Bit Server VM (build 25.372-b07, mixed mode)
I need some help to fix this issue.
I don't know where to look or what to test to try to resolve this issue.
Please help.
Thank You