openHABian slow, averaging high CPU-usage

Setup, Configuration and Use Runtime
,
1

Is there a way to find out, which specific tasks consume CPU-power?
Since a few days or weeks (?) I notice sometimes very slow behaviour of my openHABian (RPI 3, 1.3 openHABian, 2.1 stable). I suspect some configuration, which causes some CPU-Needs…

Specifically if I save some files (.rules or .items, …) it sometimes takes up to 3min to process the new configuration. Usually I get a direct Response in the logs “Refreshing model XY”, but now if I save a file, it could take some minutes until the refreshing is done. It also has some unwanted side effects for Actions I’d like to have, especially if using the http-binding, this also will be postponed.

So I’d like to see which process Needs CPU, top only gives my something like this:
ok, I see the JAVA and Python runtimes need much time. I assume, JAVA is openHAB an Python is a script I use to read out my heating Controller.

[19:28:50] openhabian@openHABianPi:~$ top
top - 19:45:02 up  6:50,  1 user,  load average: 0,31, 0,65, 0,72
Tasks: 126 total,   1 running, 125 sleeping,   0 stopped,   0 zombie
%Cpu(s): 41,3 us,  3,0 sy,  0,0 ni, 55,7 id,  0,0 wa,  0,0 hi,  0,1 si,  0,0 st
KiB Mem:    994236 total,   530528 used,   463708 free,    38388 buffers
KiB Swap:   102396 total,        0 used,   102396 free.   165472 cached Mem

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
19813 openhab   20   0  504536 270012  28328 S 161,3 27,2  63:49.96 java
 7480 openhab+  20   0   24728   8660   5268 S   7,6  0,9   0:00.23 python
 6504 openhab+  20   0    5708   2560   2124 R   0,7  0,3   0:07.77 top
  139 root      20   0   10232   3120   2860 S   0,3  0,3   0:02.52 systemd-journal
  407 root      20   0   32140   2692   2324 S   0,3  0,3   0:00.53 rsyslogd
  701 openhab   20   0  125080  31464  17684 S   0,3  3,2   0:41.33 node
 6912 root      20   0       0      0      0 S   0,3  0,0   0:00.05 kworker/2:2
 7473 root      20   0    6444   2284   1980 S   0,3  0,2   0:00.01 cron
    1 root      20   0    5544   3972   2736 S   0,0  0,4   0:04.06 systemd
    2 root      20   0       0      0      0 S   0,0  0,0   0:00.02 kthreadd
    3 root      20   0       0      0      0 S   0,0  0,0   0:04.95 ksoftirqd/0
    5 root       0 -20       0      0      0 S   0,0  0,0   0:00.00 kworker/0:0H
    7 root      20   0       0      0      0 S   0,0  0,0   0:28.21 rcu_sched
    8 root      20   0       0      0      0 S   0,0  0,0   0:01.83 rcu_bh
    9 root      rt   0       0      0      0 S   0,0  0,0   0:00.31 migration/0
   10 root       0 -20       0      0      0 S   0,0  0,0   0:00.00 lru-add-drain
   11 root      20   0       0      0      0 S   0,0  0,0   0:00.00 cpuhp/0
   12 root      20   0       0      0      0 S   0,0  0,0   0:00.00 cpuhp/1
   13 root      rt   0       0      0      0 S   0,0  0,0   0:00.26 migration/1
   14 root      20   0       0      0      0 S   0,0  0,0   0:00.24 ksoftirqd/1
   16 root       0 -20       0      0      0 S   0,0  0,0   0:00.00 kworker/1:0H
   17 root      20   0       0      0      0 S   0,0  0,0   0:00.00 cpuhp/2
   18 root      rt   0       0      0      0 S   0,0  0,0   0:00.19 migration/2
   19 root      20   0       0      0      0 S   0,0  0,0   0:01.08 ksoftirqd/2
   21 root       0 -20       0      0      0 S   0,0  0,0   0:00.00 kworker/2:0H
   22 root      20   0       0      0      0 S   0,0  0,0   0:00.00 cpuhp/3
   23 root      rt   0       0      0      0 S   0,0  0,0   0:00.25 migration/3
   24 root      20   0       0      0      0 S   0,0  0,0   0:00.30 ksoftirqd/3
   26 root       0 -20       0      0      0 S   0,0  0,0   0:00.00 kworker/3:0H
   27 root      20   0       0      0      0 S   0,0  0,0   0:00.00 kdevtmpfs
   28 root       0 -20       0      0      0 S   0,0  0,0   0:00.00 netns
   29 root      20   0       0      0      0 S   0,0  0,0   0:00.04 khungtaskd
   30 root      20   0       0      0      0 S   0,0  0,0   0:00.00 oom_reaper
   31 root       0 -20       0      0      0 S   0,0  0,0   0:00.00 writeback
   32 root      20   0       0      0      0 S   0,0  0,0   0:00.00 kcompactd0
   33 root       0 -20       0      0      0 S   0,0  0,0   0:00.00 crypto
   34 root       0 -20       0      0      0 S   0,0  0,0   0:00.00 bioset
   35 root       0 -20       0      0      0 S   0,0  0,0   0:00.00 kblockd
   36 root       0 -20       0      0      0 S   0,0  0,0   0:00.00 watchdogd
   38 root       0 -20       0      0      0 S   0,0  0,0   0:00.00 rpciod
   39 root       0 -20       0      0      0 S   0,0  0,0   0:00.00 xprtiod
   40 root      20   0       0      0      0 S   0,0  0,0   0:00.00 kswapd0
   41 root       0 -20       0      0      0 S   0,0  0,0   0:00.00 vmstat
   42 root       0 -20       0      0      0 S   0,0  0,0   0:00.00 nfsiod
   52 root       0 -20       0      0      0 S   0,0  0,0   0:00.00 kthrotld
   53 root       0 -20       0      0      0 S   0,0  0,0   0:00.00 bioset
   54 root       0 -20       0      0      0 S   0,0  0,0   0:00.00 bioset
   55 root       0 -20       0      0      0 S   0,0  0,0   0:00.00 bioset
   56 root       0 -20       0      0      0 S   0,0  0,0   0:00.00 bioset
   57 root       0 -20       0      0      0 S   0,0  0,0   0:00.00 bioset
   58 root       0 -20       0      0      0 S   0,0  0,0   0:00.00 bioset
   59 root       0 -20       0      0      0 S   0,0  0,0   0:00.00 bioset
   60 root       0 -20       0      0      0 S   0,0  0,0   0:00.00 bioset
   61 root       0 -20       0      0      0 S   0,0  0,0   0:00.00 bioset
   62 root       0 -20       0      0      0 S   0,0  0,0   0:00.00 bioset
2

This is normal behavior if you change .rules or .items, to reparse them can take up to some minutes, and is has been like that as long as I can remember. To change .items is particularly bad.
What I believe to have changed in recent times is that if you happen to save a file, reparsing starts and if you save it again before it completed parsing, another parser run will be started when the first one has finished.
So avoid to edit the file directly. Better create a copy and copy it over when you’re finally sure you will not have to change it again.

3

it’s not just for reparsing new files, the system is actually slow on response the whole time… Is there a way to tell which task/thread/… whatever is using the CPU-power?

4

Use top to see it’s the java process. I don’t know of a easy way to look inside but you can be sure it’s the parser / update thread to eat that CPU.

1 Like
5

hmmm… I didn’t change anything the last 10days, still pretty high and I experience some lagging in rules, I didn’t have before… hmmm… :thinking:

[17:35:47] openhabian@openHABianPi:~$ top
top - 17:36:07 up 10 days,  4:41,  1 user,  load average: 0,85, 0,55, 0,50
Tasks: 123 total,   1 running, 122 sleeping,   0 stopped,   0 zombie
%Cpu(s):  7,7 us,  3,7 sy,  0,0 ni, 88,6 id,  0,0 wa,  0,0 hi,  0,0 si,  0,0 st
KiB Mem:    994236 total,   836200 used,   158036 free,    55780 buffers
KiB Swap:   102396 total,        0 used,   102396 free.   363260 cached Mem

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
19813 openhab   20   0  573044 347568  28500 S  24,0 35,0   2539:52 java
 4782 openhab+  20   0    5796   2580   2180 R   4,8  0,3   0:00.24 top
 4794 openhab+  20   0   24728   9268   5820 S   2,4  0,9   0:00.32 python
 4474 openhab+  20   0   11748   3572   2836 S   1,2  0,4   0:00.05 sshd
    1 root      20   0    5544   3972   2736 S   0,0  0,4   0:34.60 systemd
    2 root      20   0       0      0      0 S   0,0  0,0   0:00.69 kthreadd
    3 root      20   0       0      0      0 S   0,0  0,0   2:45.20 ksoftirqd/0
    5 root       0 -20       0      0      0 S   0,0  0,0   0:00.00 kworker/0:0H
    7 root      20   0       0      0      0 S   0,0  0,0  16:10.96 rcu_sched
    8 root      20   0       0      0      0 S   0,0  0,0   1:06.39 rcu_bh
    9 root      rt   0       0      0      0 S   0,0  0,0   0:07.47 migration/0
   10 root       0 -20       0      0      0 S   0,0  0,0   0:00.00 lru-add-drain
   11 root      20   0       0      0      0 S   0,0  0,0   0:00.00 cpuhp/0
   12 root      20   0       0      0      0 S   0,0  0,0   0:00.00 cpuhp/1
   13 root      rt   0       0      0      0 S   0,0  0,0   0:06.07 migration/1
   14 root      20   0       0      0      0 S   0,0  0,0   0:09.95 ksoftirqd/1
   16 root       0 -20       0      0      0 S   0,0  0,0   0:00.00 kworker/1:0H
   17 root      20   0       0      0      0 S   0,0  0,0   0:00.00 cpuhp/2
   18 root      rt   0       0      0      0 S   0,0  0,0   0:06.38 migration/2
   19 root      20   0       0      0      0 S   0,0  0,0   0:36.64 ksoftirqd/2
   21 root       0 -20       0      0      0 S   0,0  0,0   0:00.00 kworker/2:0H
   22 root      20   0       0      0      0 S   0,0  0,0   0:00.00 cpuhp/3
   23 root      rt   0       0      0      0 S   0,0  0,0   0:06.15 migration/3
   24 root      20   0       0      0      0 S   0,0  0,0   0:10.20 ksoftirqd/3
   26 root       0 -20       0      0      0 S   0,0  0,0   0:00.00 kworker/3:0H
   27 root      20   0       0      0      0 S   0,0  0,0   0:00.01 kdevtmpfs
   28 root       0 -20       0      0      0 S   0,0  0,0   0:00.00 netns
   29 root      20   0       0      0      0 S   0,0  0,0   0:01.53 khungtaskd
   30 root      20   0       0      0      0 S   0,0  0,0   0:00.00 oom_reaper
   31 root       0 -20       0      0      0 S   0,0  0,0   0:00.00 writeback
   32 root      20   0       0      0      0 S   0,0  0,0   0:00.00 kcompactd0
   33 root       0 -20       0      0      0 S   0,0  0,0   0:00.00 crypto
   34 root       0 -20       0      0      0 S   0,0  0,0   0:00.00 bioset
   35 root       0 -20       0      0      0 S   0,0  0,0   0:00.00 kblockd
   36 root       0 -20       0      0      0 S   0,0  0,0   0:00.00 watchdogd
   38 root       0 -20       0      0      0 S   0,0  0,0   0:00.00 rpciod
   39 root       0 -20       0      0      0 S   0,0  0,0   0:00.00 xprtiod
   40 root      20   0       0      0      0 S   0,0  0,0   0:00.00 kswapd0
   41 root       0 -20       0      0      0 S   0,0  0,0   0:00.00 vmstat
   42 root       0 -20       0      0      0 S   0,0  0,0   0:00.00 nfsiod
   52 root       0 -20       0      0      0 S   0,0  0,0   0:00.00 kthrotld
   53 root       0 -20       0      0      0 S   0,0  0,0   0:00.00 bioset
   54 root       0 -20       0      0      0 S   0,0  0,0   0:00.00 bioset
   55 root       0 -20       0      0      0 S   0,0  0,0   0:00.00 bioset
   56 root       0 -20       0      0      0 S   0,0  0,0   0:00.00 bioset
   57 root       0 -20       0      0      0 S   0,0  0,0   0:00.00 bioset
   58 root       0 -20       0      0      0 S   0,0  0,0   0:00.00 bioset
   59 root       0 -20       0      0      0 S   0,0  0,0   0:00.00 bioset
   60 root       0 -20       0      0      0 S   0,0  0,0   0:00.00 bioset
   61 root       0 -20       0      0      0 S   0,0  0,0   0:00.00 bioset
   62 root       0 -20       0      0      0 S   0,0  0,0   0:00.00 bioset
   63 root       0 -20       0      0      0 S   0,0  0,0   0:00.00 bioset
   64 root       0 -20       0      0      0 S   0,0  0,0   0:00.00 bioset
   65 root       0 -20       0      0      0 S   0,0  0,0   0:00.00 bioset
   66 root       0 -20       0      0      0 S   0,0  0,0   0:00.00 bioset
6

Anything below 100% ist not a problem.
You’ll see java at 100+% when you experience lagging. It’s because OH is serializing some of the processing, and when it’s busy postprocessing your latest file changes, you’ll have to wait for that to finish before e.g. an UI action is processed.

7

OK… I Keep an eye on it. thanks for your help, Markus.