Sysadm causes extremely high CPU load


#1

Hi,
I’m kind of using TrueOS and FreeBSD simultaniously. I like the sysadm tool under TrueOS and as I saw sysadm hitting the ports, i was intrigued to test it under FreeBSD (I’m running 12-CURRENT).
Package install went fine and all started up without problems. If i click on “Service Manager” or “User Manager”, sysadm takes over all of my 4 CPU-Cores and produces ~ 200% WCPU. I thought, perhaps it will stop after a while, but after ~10 minutes i killed it because it still did not lower cpu rate.

Any hints?


#2

I’ve had the same thing, I’m on unstable. It stops all desktop configuration and control panel sub windows from opening. A couple of times it caught up on its own but most times i have to logout to stop it.


#3

what version of SysAdm

pkg info | grep sysadm
sysadm-201703122208 SysAdm API server
sysadm-client-201703122208 SysAdm Qt5 Client


#4

Exactly the same as yours


#5

no idea whats going on :frowning:


#6

Nor me but I guess it’ll come out in the wash! I would hopefully expect it to get fixed in near future releases.


#7

“My kingdom for a truss”

ps aux | grep sysadm-client, take note of the PID. Then
truss -o sysadm.txt -p PID from previous command

That will get the syscalls that are happening, which may lead to a clue as to what is spinning.
If you do ps aux | grep sysadm you should see both sysadm-binary and sysadm-client ; this is good. They communicate over a socket on localhost the listening socket is on 127.0.0.1:12150 (netstat -an | grep 12150). If the socket does not exist (created by sysadm-binary) maybe the client side is not handling the error gracefully.
rc-status | grep sysadm to make sure it’s started. If not, rc-service sysadm start and see if the CPU usage goes down.

Does the high cpu only happen on a few things or just in general with sysadm-client?


#8

Thanks, I’ll try that next time it happens.

It has happened about 1 in 5 times I use settings and I see no pattern - it would just not launch something e.g. mouse settings from desktop settings, and I have only had the CPU use up on my desktop today so I didn’t see what was happening before. Sometimes after I closed desktop settings 3 or 4 mouse settings windows would appear so I assume it had cured itself.


#9

Seeing this as well, and can confirm.


#10

@mer
ps aux |grep sysadm only shows sysadm-client running, no sysadm-binary.
your netstat command says closed.
rc-status shows sysadm is started (bsdstats is the only one crashed but restarted ok)
Restarting sysadm said * Failed to stop SysAdm Server (WebSocket) [ !! ]
Restarting again worked and appcafe came up


#11

That is good info. Two places to attack: double check sysadm-client behavior on trying to open the socket and why did sysadm-binary fail to start.


#12

This is how it is right now (behaving) and I tried running both manually to see what happened, I’ll do the same again when it goes wrong and we can compare the 2…

[robert@trueos] /usr/home/robert# ps aux |grep sysadm
root 2648 0.0 0.3 116096 14412 - Ss 20:02 0:00.35 /usr/local/bin/sysadm-binary
robert 2814 0.0 0.9 305348 37056 - SN 20:03 0:00.67 /usr/local/bin/sysadm-client
root 20009 0.0 0.1 14952 2364 0 S+ 20:46 0:00.00 grep sysadm
[robert@trueos] /usr/home/robert# sysadm-binary
[robert@trueos] /usr/home/robert# sysadm-client
qt.network.ssl: QSslSocket: cannot resolve SSL_CTX_set1_groups
Loading Settings From: “/usr/home/robert/.config/SysAdm/sysadm-client.ini”

  • Encrypted SSL Cert Bundle: "/usr/home/robert/.config/SysAdm/sysadm_ssl.pfx12"
    Initial Style: "air"
    Open WebSocket: URL: "wss://127.0.0.1:12150"
    Update Menu false
    Update Menu: “” Has Core: false
    Done Updating menu
    Connection Authorized: “127.0.0.1”
    ^C
    [robert@trueos] /usr/home/robert#

#13

This is what is running when it won’t start:

[robert@trueos] /usr/home/robert# ps aux | grep sysadm
robert 2634 100.0 0.9 311748 37452 - RN 20:11 1:45.78 /usr/local/bin/sysadm-client
robert 35033 64.7 0.9 250084 36720 - R 21:49 0:09.42 /usr/local/bin/sysadm-client -localhost
root 35087 0.0 0.1 14952 2372 0 S+ 21:49 0:00.00 grep sysadm
[robert@trueos] /usr/home/robert#

I killed 2634 and ran sysadm-binary and it didn’t return to a shell like yesterday but ps aux on another terminal showed it running and even with the locked shell, sysadm started ok. But when I stopped -binary with Ctrl-c, the same failing situation arose. I tried starting sysadm-binary from the start menu and it didn’t turn up in ps. I’m not sure what this tells you other than killing sysadm-client doesn’t get sysadm-binary working, and in the failing situation, when run from a shell, -binary works but won’t go into complete/ go to background.

Sysadm.txt from -binary when running without end in a console

clock_gettime(4,{ 7129.117480457 })		 = 0 (0x0)
clock_gettime(4,{ 7129.117775473 })		 = 0 (0x0)
poll({ 3/POLLIN 6/POLLIN 12/POLLIN },3,16883)	 = 0 (0x0)
clock_gettime(4,{ 7146.002502847 })		 = 0 (0x0)
clock_gettime(4,{ 7146.002603141 })		 = 0 (0x0)
clock_gettime(4,{ 7146.002814066 })		 = 0 (0x0)
poll({ 3/POLLIN 6/POLLIN 12/POLLIN },3,37998)	 = 1 (0x1)
ioctl(12,FIONREAD,0xffffd074)			 = 0 (0x0)
read(12,"\^W\^C\^C\0cR\M-s\M^?\M-R\240O"...,104) = 104 (0x68)
write(4,"\^A",1)				 = 1 (0x1)
poll({ 3/POLLIN 6/POLLIN 12/POLLIN },3,0)	 = 1 (0x1)
clock_gettime(4,{ 7176.029389347 })		 = 0 (0x0)
__sysctl(0x7fffffffd410,0x2,0x7fffffffd440,0x7fffffffd408,0x0,0x0) = 0 (0x0)
write(4,"\^A",1)				 = 1 (0x1)
write(4,"\^A",1)				 = 1 (0x1)
write(4,"\^A",1)				 = 1 (0x1)
clock_gettime(4,{ 7176.030737309 })		 = 0 (0x0)
poll({ 3/POLLIN 6/POLLIN 12/POLLIN },3,0)	 = 1 (0x1)
read(3,"\^A\^A\^A\^A",16)			 = 4 (0x4)
clock_gettime(4,{ 7176.031014165 })		 = 0 (0x0)
write(4,"\^A",1)				 = 1 (0x1)
write(12,"\^W\^C\^C\0\M^B\M-7\a\M-{\^F\M-h"...,135) = 135 (0x87)
write(4,"\^A",1)				 = 1 (0x1)
clock_gettime(4,{ 7176.032094769 })		 = 0 (0x0)
poll({ 3/POLLIN 6/POLLIN 12/POLLIN },3,7968)	 = 1 (0x1)
read(3,"\^A\^A",16)				 = 2 (0x2)
clock_gettime(4,{ 7176.032385593 })		 = 0 (0x0)
clock_gettime(4,{ 7176.032454877 })		 = 0 (0x0)
poll({ 3/POLLIN 6/POLLIN 12/POLLIN },3,7968)	 = 1 (0x1)
read(3,0x7fffffffe240,16)			 ERR#35 'Resource temporarily unavailable'
clock_gettime(4,{ 7176.049432209 })		 = 0 (0x0)
ioctl(12,FIONREAD,0xffffd074)			 = 0 (0x0)
read(12,"\^W\^C\^C\0\\\M-^,\^N\M-|\^VT\a"...,97) = 97 (0x61)
write(4,"\^A",1)				 = 1 (0x1)
clock_gettime(4,{ 7176.050469790 })		 = 0 (0x0)
poll({ 3/POLLIN 6/POLLIN 12/POLLIN },3,0)	 = 1 (0x1)
clock_gettime(4,{ 7176.050932427 })		 = 0 (0x0)
clock_gettime(4,{ 7176.051136368 })		 = 0 (0x0)
mmap(0x7fffdf7fa000,2101248,PROT_READ|PROT_WRITE,MAP_STACK,-1,0x0) = 140736943071232 (0x7fffdf7fa000)
mprotect(0x7fffdf7fa000,4096,PROT_NONE)		 = 0 (0x0)
thr_new(0x7fffffffd778,0x68)			 = 0 (0x0)
<new thread 101161>
mmap(0x0,4096,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_ANON,-1,0x0) = 34368065536 (0x8007f1000)
clock_gettime(4,{ 7176.052048232 })		 = 0 (0x0)
poll({ 3/POLLIN 6/POLLIN 12/POLLIN },3,7948)	 = 1 (0x1)
read(3,"\^A",16)				 = 1 (0x1)
clock_gettime(4,{ 7176.052398004 })		 = 0 (0x0)
clock_gettime(4,{ 7176.052491872 })		 = 0 (0x0)
pipe2(0x8078263c0,O_CLOEXEC)			 = 0 (0x0)
fcntl(13,F_GETFL,)				 = 2 (0x2)
fcntl(13,F_SETFL,O_RDWR|O_NONBLOCK)		 = 0 (0x0)
fcntl(15,F_GETFL,)				 = 2 (0x2)
fcntl(15,F_SETFL,O_RDWR|O_NONBLOCK)		 = 0 (0x0)
write(15,"\^A",1)				 = 1 (0x1)
gettimeofday({ 1489875056.753195 },0x0)		 = 0 (0x0)
gettimeofday({ 1489875056.753315 },0x0)		 = 0 (0x0)
gettimeofday({ 1489875056.753440 },0x0)		 = 0 (0x0)
stat("/usr/local/sbin/beadm",{ mode=-r-xr-xr-x ,inode=71857,size=29112,blksize=29184 }) = 0 (0x0)
stat("/usr/local/bin/lpreserver",{ mode=-rwxr-xr-x ,inode=87188,size=23198,blksize=23552 }) = 0 (0x0)
stat("/usr/local/bin/iocage",0x7fffdf9fa6e8)	 ERR#2 'No such file or directory'
stat("/usr/local/sbin/iohyve",0x7fffdf9fa6e8)	 ERR#2 'No such file or directory'
stat("/sbin/zfs",{ mode=-r-xr-xr-x ,inode=5353,size=101392,blksize=101888 }) = 0 (0x0)
stat("/sbin/zpool",{ mode=-r-xr-xr-x ,inode=5355,size=100200,blksize=100352 }) = 0 (0x0)
stat("/usr/local/sbin/pkg",{ mode=-rwxr-xr-x ,inode=25252,size=183752,blksize=131072 }) = 0 (0x0)
stat("/usr/local/bin/pc-updatemanager",{ mode=-rwxr-xr-x ,inode=166933,size=64188,blksize=64512 }) = 0 (0x0)
stat("/usr/sbin/moused",{ mode=-r-xr-xr-x ,inode=10389,size=40672,blksize=40960 }) = 0 (0x0)
stat("/usr/sbin/powerd",{ mode=-r-xr-xr-x ,inode=10011,size=15304,blksize=15360 }) = 0 (0x0)
write(4,"\^A",1)				 = 1 (0x1)
poll({ 3/POLLIN 6/POLLIN 12/POLLIN },3,7948)	 = 1 (0x1)
read(3,"\^A",16)				 = 1 (0x1)
clock_gettime(4,{ 7176.055407939 })		 = 0 (0x0)
write(4,"\^A",1)				 = 1 (0x1)
write(4,"\^A",1)				 = 1 (0x1)
clock_gettime(4,{ 7176.055935670 })		 = 0 (0x0)
write(4,"\^A",1)				 = 1 (0x1)
clock_gettime(4,{ 7176.056383779 })		 = 0 (0x0)
poll({ 3/POLLIN 6/POLLIN 12/POLLIN },3,0)	 = 1 (0x1)
read(3,"\^A\^A\^A",16)				 = 3 (0x3)
clock_gettime(4,{ 7176.056749196 })		 = 0 (0x0)
write(4,"\^A",1)				 = 1 (0x1)
write(12,"\^W\^C\^C\^B.\a\M-e\M-5\^F\M-I-i"...,563) = 563 (0x233)
write(4,"\^A",1)				 = 1 (0x1)
clock_gettime(4,{ 7176.057349842 })		 = 0 (0x0)
poll({ 3/POLLIN 6/POLLIN 12/POLLIN },3,7943)	 = 1 (0x1)
read(3,"\^A\^A",16)				 = 2 (0x2)
clock_gettime(4,{ 7176.057598482 })		 = 0 (0x0)
clock_gettime(4,{ 7176.057671677 })		 = 0 (0x0)
poll({ 3/POLLIN 6/POLLIN 12/POLLIN },3,7943)	 = 0 (0x0)
read(3,0x7fffffffe240,16)			 ERR#35 'Resource temporarily unavailable'
clock_gettime(4,{ 7184.002487939 })		 = 0 (0x0)
clock_gettime(4,{ 7184.003439194 })		 = 0 (0x0)
clock_gettime(4,{ 7184.003642576 })		 = 0 (0x0)

#14

Looks like it sitting spinning on input from a socket, with a timeout.
This should give someone a good place to start.


#15

I have the same issues with the following version:

pkg info | grep sysadm
sysadm-201704211306 SysAdm API server
sysadm-client-201704211306 SysAdm Qt5 Client


#16

I also noticed sysadm-binary causing high load, but seems to be more related to IO.
it was writing lots of data to its log file which now stands at:

% du -shc /var/log/sysadm*
643M	/var/log/sysadm                (sum of ls -l  gives: 6.2GB)
645M	/var/log/sysadm-server-ws.log  (uncompressed size is 5.7GB)
1.3G	total                          (compressed size)

This whole sysadm log appears to be multiple copies of /var/log/lpreserver/lpreserver.log
with some quotes added. (around 1500 copies using a quick grep/wc -l)

Since the lpreserver does not appear to rotate its log either this is making the problem worse
especially since I have hourly snapshots. (I had been thinking the system freezing for about 5…10min every hour was just the ZFS replication)

So far I have not found any documentation to rotate this log file; so will manually mv and touch new logs (both the sysadm and lpreserver) and check later to see if the new files are used (no programs were restarted or signalled for this test)


After running overnight:
the renamed log: sysadm-server-ws.log.1 has increased i.e. sysadm-binary does not re-open the file.
However lpreserver

Also in the sysadm/websocket dir there are many weekly/daily logs: e.g.

-rw-r–r-- 1 root wheel 51413700 2017-07-26 23:01 events-lifepreserver-2017-07-26.log
-rw-r–r-- 1 root wheel 263674 2017-07-27 09:01 events-lifepreserver-2017-07-27.log

from the above two I can see that rotating lpreserver.log reduced that log by a couple of orders of magnitude.

EDIT: filed as bug at: https://github.com/trueos/trueos-core/issues/1458


#17

try
chmod 755 /usr/local/bin/pc-updatemanager && rc-service sysadm restart


#18