Process with 1% CPU usage causing load average of 1.5

Question

We recently observed a high load average of about 1.5 on our embedded system, even though pretty much all processes are supposedly sleeping (according to htop).

The system in question is a dual-core Cortex-A9 running a realtime Linux kernel (4.14.126) built using buildroot. We are using initramfs for our root filesystem and there is no swap, so there is definitely no disk I/O during normal operation.

After a bit of digging, we found out that the load is caused by a program called swupdate, which provides us with a convenient web interface for software updates (and we would very much like to continue using that).

When i use time to estimate the average cpu-usage of that application (by calculating (user+sys)/real), i get a value of only about 1%, which doesn't make much sense considering the load average of 1.5.

I know that the load average also includes processes in the TASK_UNINTERRUPTIBLE state, which don't contribute to cpu usage. What i don't understand is why any of the threads/processes of that application would ever be in that state.

To further analyze the situation i have captured a kernel trace using lttng, which shows that the only thing swupdate does is this (every 50ms):

and this (every 100ms):

As you can see, there's a little bit of what appears to be socket-based IPC, and a select waiting for something. In the IPC case, one thread appears to be mostly blocking in nanosleep(), while the other is blocking in accept(), neither of which should consume any system resources as far as i'm aware.

FYI: the time base for both screenshots is the same, and the IPC takes approx. 500-600µs in total (which, considering the interval of 50ms, fits quite nicely with the observed 1% CPU usage)

So, what is causing the load here?

Answer 1

Since tasks both in state R and D contribute to the Linux load, you can sample all threads in your system in either of these states. For example:

for x in {1..100} ; do ps -aeos,user,comm,wchan | grep "^[RD]" ; sleep 0.1 ; done | sort | uniq -c | sort -nbr | head -20

Example output below, you'd need to ignore the top line showing your own ps process always active - as it's the one that does all the sampling:

# for x in {1..100} ; do
>   ps -aeos,user,comm,wchan | grep "^[RD]"
>   sleep 0.1
> done | sort | uniq -c | sort -nbr | head -20

    100 R root     ps              -
      3 R oracle   oracle_14047_li -
      2 R root     rcu_sched       rcu_gp_kthread
      2 R root     rcu_sched       -
      2 R root     kworker/1:2-eve -
      2 R oracle   perl            -
      2 R oracle   ora_vktm_lin19c hrtimer_nanosleep
      2 D root     md10_raid10     md_super_wait
      2 D oracle   ora_ckpt_linprd md_write_start
      1 R redis    redis-server    -
      1 R oracle   ora_vktm_linprd hrtimer_nanosleep
      1 R oracle   ora_m001_linprd -
      1 D root     xfsaild/dm-18   rq_qos_wait
      1 D oracle   ora_mz00_lin19c x64_sys_io_destroy
      1 D oracle   ora_lg00_lin19c inode_dio_wait
      1 D oracle   ora_dbrm_lin19c msleep

Unless you're running on an old kernel, you should run this as root as newer kernels mask WCHAN values of other users' processes.

You can go deeper than that (but not with ps), you can sample /proc/PID/syscall and /proc/PID/stack to get system call and kernel stack trace info too. I have written a tool called Linux Process Snapper (psn) for this, so you can do pretty advanced drilldown into such performance issues without having to resort to kernel tracing:

[tanel@linux01 ~]$ sudo psn -G syscall,wchan

Linux Process Snapper v0.18 by Tanel Poder [https://0x.tools]
Sampling /proc/syscall, stat, wchan for 5 seconds... finished.


=== Active Threads ==========================================================================================

 samples | avg_threads | comm             | state                  | syscall         | wchan                 
-------------------------------------------------------------------------------------------------------------
     511 |      255.50 | (kworker/*:*)    | Disk (Uninterruptible) | [kernel_thread] | blkdev_issue_flush 
     506 |      253.00 | (oracle_*_l)     | Disk (Uninterruptible) | pread64         | do_blockdev_direct_IO 
      28 |       14.00 | (oracle_*_l)     | Running (ON CPU)       | [running]       | 0                     
       1 |        0.50 | (collectl)       | Running (ON CPU)       | [running]       | 0                     
       1 |        0.50 | (mysqld)         | Running (ON CPU)       | [running]       | 0                     
       1 |        0.50 | (ora_lgwr_lin*c) | Disk (Uninterruptible) | io_submit       | inode_dio_wait        
       1 |        0.50 | (oracle_*_l)     | Disk (Uninterruptible) | pread64         | 0                     
       1 |        0.50 | (oracle_*_l)     | Running (ON CPU)       | [running]       | SYSC_semtimedop       
       1 |        0.50 | (oracle_*_l)     | Running (ON CPU)       | [running]       | read_events           
       1 |        0.50 | (oracle_*_l)     | Running (ON CPU)       | read            | 0                     
       1 |        0.50 | (oracle_*_l)     | Running (ON CPU)       | semtimedop      | SYSC_semtimedop       

You can go much deeper than that, a relevant blog entry is here:

• Troubleshooting high linux system load with low CPU utilization

Answer 2

CPU usage and load are different metrics. In fact load could be above 1. CPU is the real time used by CPU, so it should be always less then 100% (but on multiple core/CPUs, but you get the idea). Load indicates the load: how many processes are running and waiting to be run.

As you probably know (from discussion in your question), I/O usually is one of such wait, so it increases loads. But you can have also signals/semaphores/locks that could cause waiting, and these may be just caused by one process which it is not doing I/O). E.g. if one process wake up every second, and there are many processes that are waiting for data from such process, you get higher load (equal to the number of process waiting).

You may see pipes as I/O, but mmap and locks... do you classify as IO? They will not show up in bio (block I/O), so you may not see them in many load statistics.

Often the easier way to find out this: block a process and check where it is. Do it many times, and you should hopefully see one function is blocking (and you may find it much often then other functions).

Answer 3

I was having the same issue on an embedded system running on an i.mx28 at roughly 450 MHz.

htop was constantly showing 50% CPU usage, solely caused by one of the swupdate tasks.

When browsing through mongoose_interface.c your 100 ms observation triggered when reading this at the end of start_mongoose():

                mg_mgr_poll(&mgr, 100);

I experimentally changed the 100 to 1000 and after a recompile and restart, the CPU usage went down to around 2% of the swupdate threads as observed in htop.

As said, this has been experimental as the numbers struck me as too much of a coincidence. I have not investigated whether any side effects occur.