Build: [NanoPi NEO2] armbianmonitor -m reports incorrect CPU usage

[sanderjo]

On my NanoPi NEO2 (with 4 cores), it seems armbianmonitor -m reports incorrect CPU usage. For example, when I start make -j2 to fully load two CPU cores (which top and htop show indeed happens), armbianmonitor tells the CPU load is only 3% (not 50%):

Time      CPU n/a    load %cpu %sys %usr %nice %io %irq   CPU
20:33:18:   ---     0.64   3%   0%   2%   0%   0%   0% 31.4°C

Running top continuously shows a CPU load around 50%, which is correct: 2 cores of the 4 cores fully utilized.
To show what happens, I put an extra line into armbianmonitor to print the CPU load according to top.

Result:

sander@nanopineo2:~$ ./armbianmonitor-sj  -m
Stop monitoring using [ctrl]-[c]
Time      CPU n/a    load %cpu %sys %usr %nice %io %irq   CPU
20:50:18:   ---     0.90   5%   0%   4%   0%   0%   0% 27.5°C
%Cpu(s):  1,1 us,  1,1 sy,  0,0 ni, 97,7 id,  0,0 wa,  0,0 hi,  0,0 si,  0,0 st

20:50:24:   ---     0.92   5%   0%   4%   0%   0%   0% 28.5°C
%Cpu(s): 26,4 us,  1,1 sy,  0,0 ni, 72,4 id,  0,0 wa,  0,0 hi,  0,0 si,  0,0 st

20:50:29:   ---     1.00   5%   0%   4%   0%   0%   0% 31.9°C
%Cpu(s): 50,6 us,  1,1 sy,  0,0 ni, 48,3 id,  0,0 wa,  0,0 hi,  0,0 si,  0,0 st

20:50:35:   ---     1.08   5%   0%   4%   0%   0%   0% 32.8°C
%Cpu(s): 43,0 us, 10,5 sy,  0,0 ni, 46,5 id,  0,0 wa,  0,0 hi,  0,0 si,  0,0 st

20:50:41:   ---     1.16   6%   0%   5%   0%   0%   0% 32.1°C
%Cpu(s): 48,9 us,  3,3 sy,  0,0 ni, 46,7 id,  0,0 wa,  0,0 hi,  1,1 si,  0,0 st

20:50:47:   ---     1.22   6%   0%   5%   0%   0%   0% 32.6°C
%Cpu(s): 49,4 us,  2,3 sy,  0,0 ni, 48,3 id,  0,0 wa,  0,0 hi,  0,0 si,  0,0 st

20:50:52:   ---     1.29   6%   0%   5%   0%   0%   0% 32.7°C
%Cpu(s): 51,1 us,  1,1 sy,  0,0 ni, 47,7 id,  0,0 wa,  0,0 hi,  0,0 si,  0,0 st

20:50:58:   ---     1.34   6%   0%   5%   0%   0%   0% 29.3°C
%Cpu(s):  0,0 us,  0,0 sy,  0,0 ni,100,0 id,  0,0 wa,  0,0 hi,  0,0 si,  0,0 st

20:51:04:   ---     1.14   6%   0%   5%   0%   0%   0% 27.9°C
%Cpu(s):  2,3 us,  0,0 sy,  0,0 ni, 97,7 id,  0,0 wa,  0,0 hi,  0,0 si,  0,0 st

20:51:09:   ---     1.05   6%   0%   5%   0%   0%   0% 27.6°C
%Cpu(s):  1,1 us,  1,1 sy,  0,0 ni, 97,7 id,  0,0 wa,  0,0 hi,  0,0 si,  0,0 st

20:51:15:   ---     0.96   6%   0%   5%   0%   0%   0% 27.5°C
%Cpu(s):  0,0 us,  1,2 sy,  0,0 ni, 98,8 id,  0,0 wa,  0,0 hi,  0,0 si,  0,0 st

So the us CPU usage in the line "%Cpu(s)" starts low, goes up to 50% as soon as I start the "make -j2", and goes to 0% again after stopping the make process. That's good.
The armbianmonitor CPU load stays at 6% ...which is not correct.

The line I used to get the correct CPU load is

top -bn2 -d0,2 | grep "%Cpu(s)" | tail -1

A plain top -bn1 | grep "%Cpu(s)" was not working: on the first run, top does now show a correct CPU load. Maybe a diff not working because the initial value was not filled out (correctly).

... and could that also be the cause of the problem with armbianmonitor...?

[ThomasKaiser]

The problem is parsing of /proc/stat with different kernels. I added this at a time when working with various sunxi legacy kernels but it seems it needs different parsing with more recent kernel versions.

Since Armbian includes sysstat package by default a workaround is to run iostat 5 in parallel.

Please feel free to develop another parsing function that works with mainline kernel so we can add a switch based on kernel version to let armbianmonitor display correct cpustats with all kernels.

By looking at the numbers reported I would believe it's just multiplying with 1000 instead of 100. Please test with iostat in parallel and report your findings :)

[sanderjo]

Intermediate feedback:

I tried with iostat, and it seems to show the same behaviour as top, so "reported numbers on first occurence not correct".

Example: While make -j1 is already running (so CPU load at 25%), the first report op iostat is not correct (0.53%), and the following reports are correct (25%):

sander@nanopineo2:~$ iostat 1
Linux 4.11.10-sun50iw2 (nanopineo2)     08/07/2017      _aarch64_       (4 CPU)

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
           0.53    0.00    0.54    0.87    0.00   98.05

Device:            tps    kB_read/s    kB_wrtn/s    kB_read    kB_wrtn
mmcblk0           5.98       330.54         5.58   21061197     355536

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
          24.94    0.00    0.50    0.00    0.00   74.56

Device:            tps    kB_read/s    kB_wrtn/s    kB_read    kB_wrtn
mmcblk0           2.00        12.00         0.00         12          0

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
          20.05    0.00    2.76    1.00    0.00   76.19

Device:            tps    kB_read/s    kB_wrtn/s    kB_read    kB_wrtn
mmcblk0          21.00      1684.00         0.00       1684          0

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
          21.05    0.00    4.51    0.25    0.00   74.19

Device:            tps    kB_read/s    kB_wrtn/s    kB_read    kB_wrtn
mmcblk0          11.00       176.00       408.00        176        408

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
          24.06    0.00    1.00    0.00    0.00   74.94

Device:            tps    kB_read/s    kB_wrtn/s    kB_read    kB_wrtn
mmcblk0           2.00        20.00         0.00         20          0

So the same as with top: first report is incorrect:

sander@nanopineo2:~$ top -bn5  | grep "%Cpu(s)"
%Cpu(s):  0.5 us,  0.5 sy,  0.0 ni, 98.0 id,  0.9 wa,  0.0 hi,  0.0 si,  0.0 st
%Cpu(s): 24.8 us,  0.3 sy,  0.0 ni, 74.8 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
%Cpu(s): 22.7 us,  2.5 sy,  0.0 ni, 74.8 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
%Cpu(s): 24.4 us,  0.7 sy,  0.0 ni, 74.9 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
%Cpu(s): 24.7 us,  0.5 sy,  0.0 ni, 74.8 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st

[sanderjo]

Further intermediate feedback:

With some python code lines, based on the armbianmonitor code, I was able to produce correct stats based on /proc/stat in about the same way as armbianmonitor does. So:

• /proc/stat is correct
• I now better understand the method used in armbianmonitor
• The "100" used in armbianmonitor and my python code is thus correct. It should not be 1000 or so. It is the factor to get from fraction to percentage. It does NOT have to with USER_HZ (1/100ths of a second on most architectures, or sysconf(_SC_CLK_TCK).

I'll dive deeper to find the bug in armbianmonitor

[ThomasKaiser]

I tried with iostat, and it seems to show the same behaviour as top, so "reported numbers on first occurence not correct"

As expected: first numbers spitten out are 'average values since last boot', following values are what happened in between interval.

[ThomasKaiser]

@sanderjo after merging recent PR https://github.com/armbian/build/commit/494c3811b86189d4d789083b6dad92fc1e11864f can you please give it a try and report back?

[ThomasKaiser]

Just to be sure: wget https://raw.githubusercontent.com/armbian/build/494c3811b86189d4d789083b6dad92fc1e11864f/packages/bsp/common/usr/bin/armbianmonitor

[sanderjo]

Yes, that works beautifully! With make -j2 in another terminal, the new armbianmonitor nicely goes to 50% CPU usage.

Thank you.

sander@nanopineo2:~$ wget blabla
sander@nanopineo2:~$ chmod +x armbianmonitor 
sander@nanopineo2:~$ ./armbianmonitor -m
Stop monitoring using [ctrl]-[c]
Time      CPU n/a    load %cpu %sys %usr %nice %io %irq   CPU

16:25:11:   ---      0.93   0%   0%   0%   0%   0%   0% 41.3°C
16:25:16:   ---      0.86   0%   0%   0%   0%   0%   0% 41.2°C
16:25:21:   ---      0.79   2%   0%   1%   0%   0%   0% 41.8°C
16:25:26:   ---      0.88  33%   3%  30%   0%   0%   0% 45.3°C
16:25:31:   ---      0.97  50%   1%  48%   0%   0%   0% 46.4°C
16:25:36:   ---      1.06  50%   3%  47%   0%   0%   0% 47.2°C
16:25:42:   ---      1.13  50%   1%  48%   0%   0%   0% 47.4°C
16:25:47:   ---      1.20  50%   0%  49%   0%   0%   0% 46.9°C
16:25:52:   ---      1.10  17%   1%  16%   0%   0%   0% 42.9°C
16:25:57:   ---      1.02   0%   0%   0%   0%   0%   0% 42.0°C
16:26:02:   ---      0.93   0%   0%   0%   0%   0%   0% 41.7°C
16:26:07:   ---      0.86   0%   0%   0%   0%   0%   0% 41.3°C
16:26:12:   ---      0.79   0%   0%   0%   0%   0%   0% 41.3°C
sander@nanopineo2:~$ 

[ThomasKaiser]

Thank you

We all need to thank @jaskcon :)

[jaskcon]

I have a tendency to code bash with my fingers crossed, so I'm happy to see the happy results ;)
I hope the NetworkMonitorMode addition is a) considered somewhat useful b) accurate, and c) *.sbc compatible.
./j

[ThomasKaiser]

@jaskcon thank you for the new function too though I'm not that sure whether the NetworkMonitorMode is really useful just since the whole idea behind armbianmonitor was to enable users to provide useful data for us (devs and admins/supporters in the forum, eg. diagnosing slow SD cards by high %iowait percentage, something that now works everywhere thanks to you! 👍 ).

Network monitoring is IMO something special, experts already have their tools and I doubt there's a use case to troubleshoot remote network problems. But since it's working and takes also care about predictable network interface names it's merged now. Thank you! But maybe starting a quick discussion in Armbian development forum prior to next PR would be a good idea :)

[jaskcon]

That all makes perfect sense, Thanks Thomas. I work in network development, so network details are always important to me, even when they're not relevant (hahaha). I'll start the discussion and see where it leads and thanks again for the information and advice - much appreciated.
Regards,
./j