2

I have a problem with high load average (~2) on my (personal laptop) computer for a long time now. I am running Arch Linux. If I remember correctly, the problem started with a certain kernel update, initially I thought it was related to this bug. The problem was not solved though, when the bug was fixed. I did not really care as I thought it is still a bug, because the performance did not seem to suffer. What made me curious is that, recently, I had a moment of super low load average (~0) while idling. After a reboot, everything went back to "normal", with high load average. So I started investigating:

 % uptime
 14:31:04 up  2:22,  1 user,  load average: 1.96, 1.98, 1.99

So far nothing new. Then I tried top:

 % top -b -n 1
top - 14:33:52 up  2:25,  1 user,  load average: 2.02, 2.07, 2.02
Tasks: 146 total,   2 running, 144 sleeping,   0 stopped,   0 zombie
%Cpu0  :   2.6/0.9     3[||||                                                    ]
%Cpu1  :   2.7/0.9     4[||||                                                    ]
%Cpu2  :   2.7/1.0     4[||||                                                    ]
%Cpu3  :   2.7/0.8     3[||||                                                    ]
GiB Mem :228125107552256.0/7.712    [
GiB Swap:  0.0/7.904    [                                                    ]

  PID USER  PR  NI    VIRT    RES  %CPU %MEM     TIME+ S COMMAND
    2 root  20   0    0.0m   0.0m   0.0  0.0   0:00.00 S kthreadd
  404 root  20   0    0.0m   0.0m   0.0  0.0   0:01.09 D  `- rtsx_usb_ms_2
 1854 root  20   0    0.0m   0.0m   0.0  0.0   0:06.03 D  `- kworker/0:2

I cut out all the processes and kernel threads except those two. Here we can see already some suspicious kernel threads (state D). And some suspicious Mem value (see edit)...

Looking at CPU:

 % mpstat
Linux 4.13.12-1-ARCH (arch) 30.11.2017  _x86_64_    (4 CPU)

14:36:09     CPU    %usr   %nice    %sys %iowait    %irq   %soft  %steal  %guest  %gnice   %idle
14:36:09     all    2.66    0.00    0.88    1.56    0.00    0.01    0.00    0.00    0.00   94.90
 % sar -u 1 30
Linux 4.13.12-1-ARCH (arch) 30.11.2017  _x86_64_    (4 CPU)

14:37:04    CPU %user     %nice   %system   %iowait    %steal     %idle
14:37:05    all  1.00      0.00      0.75      0.00  0.00     98.25
14:37:06    all  1.76      0.00      0.50      0.00  0.00     97.74
14:37:07    all  1.00      0.00      0.25      0.00  0.00     98.75
14:37:08    all  0.50      0.00      0.50      0.00  0.00     99.00
14:37:09    all  0.50      0.00      0.50      0.25  0.00     98.75
14:37:10    all  0.50      0.00      0.50      6.03  0.00     92.96
14:37:11    all  0.75      0.00      0.50     11.75  0.00     87.00
14:37:12    all  0.50      0.00      0.25      0.00  0.00     99.25
[ . . . ]
14:37:21    all  1.26      0.00      0.76      0.00  0.00     97.98
14:37:22    all  0.75      0.00      0.25      2.26  0.00     96.73
14:37:23    all  0.50      0.00      0.50     16.83  0.00     82.16
14:37:24    all  0.75      0.00      0.50      0.00  0.00     98.74
14:37:25    all  0.50      0.00      0.50      0.00  0.00     98.99
14:37:26    all  0.76      0.00      0.50      7.56  0.00     91.18
14:37:27    all  0.25      0.00      0.51      0.00  0.00     99.24
14:37:28    all  1.00      0.00      0.75      0.25  0.00     98.00
14:37:29    all  0.25      0.00      0.76      0.00  0.00     98.99
14:37:30    all  0.75      0.00      0.50      0.00  0.00     98.74
14:37:31    all  0.75      0.00      0.50      3.27  0.00     95.48
14:37:32    all  0.51      0.00      0.51     13.16  0.00     85.82
14:37:33    all  0.75      0.00      0.50      0.25  0.00     98.49
14:37:34    all  1.26      0.00      0.75      0.00  0.00     97.99
Average:    all  0.71      0.00      0.56      2.06  0.00     96.67

reveals some peaks in I/O wait. The best guess so far. Looking closer:

 % iostat -x 1 30
Linux 4.13.12-1-ARCH (arch) 30.11.2017  _x86_64_    (4 CPU)

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
       2.60    0.00    0.87    1.55    0.00   94.98

Device:     rrqm/s   wrqm/s     r/s     w/s    rkB/s    wkB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
sda       0.93     3.00    3.71    1.94    95.04   102.27    69.91     0.60  106.78   16.56  279.32  14.47   8.17

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
       0.75    0.00    0.75    0.25    0.00   98.25

Device:     rrqm/s   wrqm/s     r/s     w/s    rkB/s    wkB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
sda       0.00     0.00    0.00    1.00     0.00     0.00     0.00     0.01   13.00    0.00   13.00  10.00   1.00

[ . . . ]

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
       0.50    0.00    0.50   17.04    0.00   81.95

Device:     rrqm/s   wrqm/s     r/s     w/s    rkB/s    wkB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
sda       0.00     8.00    0.00    2.00     0.00    40.00    40.00     0.69  346.50    0.00  346.50 346.50  69.30

[ . . . ]

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
       0.25    0.00    0.50    7.29    0.00   91.96

[ . . . ]

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
       1.00    0.00    0.75   16.96    0.00   81.30

Device:     rrqm/s   wrqm/s     r/s     w/s    rkB/s    wkB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
sda       0.00     5.00    0.00    2.00     0.00    28.00    28.00     0.71  357.00    0.00  357.00 356.50  71.30

[ . . . ]

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

Device:     rrqm/s   wrqm/s     r/s     w/s    rkB/s    wkB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
sda       0.00     0.00    0.00    0.00     0.00     0.00     0.00     0.00    0.00    0.00    0.00   0.00   0.00

Looking at processes with uninterruptable sleep:

 % for x in `seq 1 1 10`; do ps -eo state,pid,cmd | grep "^D"; echo "----"; sleep 5; done
D   404 [rtsx_usb_ms_2]
D  1854 [kworker/0:2]
D  2877 [kworker/0:0]
----
D   404 [rtsx_usb_ms_2]
D  1854 [kworker/0:2]
D  2877 [kworker/0:0]
----
D   404 [rtsx_usb_ms_2]
D  1854 [kworker/0:2]
D  2877 [kworker/0:0]
----
D   404 [rtsx_usb_ms_2]
D  2877 [kworker/0:0]
----
D   404 [rtsx_usb_ms_2]
----
D   404 [rtsx_usb_ms_2]
D  1854 [kworker/0:2]
D  2877 [kworker/0:0]
----
D   404 [rtsx_usb_ms_2]
D  2877 [kworker/0:0]
----
D   404 [rtsx_usb_ms_2]
D  2877 [kworker/0:0]
----
D   404 [rtsx_usb_ms_2]
D  1854 [kworker/0:2]
D  2877 [kworker/0:0]
----
D   404 [rtsx_usb_ms_2]
D  3177 [kworker/u32:4]
----

and last thing I did:

 % vmstat 1
procs -----------memory---------- ---swap-- -----io---- -system-- ------cpu-----
 r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa st
 0  1      0 5010040 123612 1220080    0    0    23    25  111  433  3  1 95  2  0
 0  0      0 5006256 123612 1224164    0    0     0    96  186  839  1  1 97  1  0
 1  0      0 5006132 123612 1224164    0    0     0 0  175  714  1  0 99  0  0
 0  0      0 5003156 123612 1224156    0    0     0 0  234 1009  2  1 98  0  0
 0  0      0 5003156 123612 1224156    0    0     0 0  161  680  0  0 99  0  0
 0  1      0 5003156 123616 1224156    0    0     0    60  214  786  1  1 94  5  0
 0  0      0 5003280 123620 1224156    0    0     0 4  226  776  1  0 88 11  0
 1  0      0 5003156 123620 1224156    0    0     0 0  210  733  1  0 99  0  0
 0  0      0 5005388 123620 1224156    0    0     0 0  159  747  1  0 99  0  0
 0  0      0 5005388 123620 1224156    0    0     0 0  233  803  1  0 99  0  0
 0  0      0 5005512 123620 1224156    0    0     0 0  152  670  1  0 99  0  0
 0  0      0 5009664 123620 1220060    0    0     0 0  240  914  1  1 99  0  0
 0  0      0 5009540 123620 1220060    0    0     0 0  237  833  1  1 99  0  0
 0  0      0 5009664 123620 1220060    0    0     0 0  166  999  1  1 99  0  0
 0  1      0 5009664 123620 1220060    0    0     0 4  168  700  1  0 88 11  0
 0  0      0 5009540 123628 1220060    0    0     0    12  207  778  1  1 91  8  0
 0  0      0 5009788 123628 1220064    0    0     0 0  189  717  0  1 99  0  0
 0  0      0 5009664 123628 1220064    0    0     0 0  243 1453  1  1 98  0  0
 0  0      0 5009044 123628 1220576    0    0     0 0  166  708  1  0 99  0  0
 0  0      0 5009168 123628 1220576    0    0     0 0  146  663  1  0 99  0  0
 0  0      0 5009540 123628 1220064    0    0     0 0  175  705  1  1 99  0  0
 0  1      0 5009292 123632 1220128    0    0     0 8  223  908  1  0 99  0  0
^C

Now I still don't know what the problem is, but it looks like it comes from some peak I/O operations. There are some suspicious kernel threads. Any further ideas? What else could I do to investigate?

edit: The Mem value seems strange, but it just occured very recently, a week ago or so, everything seemed to be normal. And

 % free          
              total        used        free      shared  buff/cache   available
Mem:        8086240     1913860     4824764      133880     1347616     6231856
Swap:       8288252           0     8288252

seems to be fine though.

edit2: First results of testing sar monitoring my system (very frequently, intervals of 1 second, but for a short duration, to get the peaks):

Linux 4.13.12-1-ARCH (arch)     01.12.2017  _x86_64_    (4 CPU)

12:36:25        CPU     %user     %nice   %system   %iowait    %steal     %idle
12:36:26        all      0.50      0.00      0.50      0.00      0.00     99.00
12:36:27        all      0.50      0.00      0.50      0.25      0.00     98.74
12:36:28        all      0.50      0.00      0.75      0.00      0.00     98.75
12:36:29        all      0.50      0.00      0.25      7.52      0.00     91.73
12:36:30        all      0.25      0.00      0.75      9.77      0.00     89.22
12:36:31        all      0.25      0.00      0.75      0.00      0.00     98.99
12:36:32        all      1.00      0.00      0.50      0.25      0.00     98.25
12:36:33        all      1.00      0.00      1.00      0.00      0.00     98.00
12:36:34        all      0.25      0.00      0.25      0.25      0.00     99.24
12:36:35        all      0.50      0.25      0.75     33.25      0.00     65.25
12:36:36        all      0.50      0.00      0.75      0.25      0.00     98.50
12:36:37        all      0.75      0.00      0.25      0.00      0.00     99.00
12:36:38        all      0.25      0.00      0.50      0.00      0.00     99.24
12:36:39        all      0.50      0.00      0.50      0.00      0.00     99.00
12:36:40        all      0.50      0.25      0.50     10.75      0.00     88.00
Average:        all      0.52      0.03      0.57      4.16      0.00     94.72

Network (-n) seems to be alright. Looking at devices (-d) reveals:

Linux 4.13.12-1-ARCH (arch)     01.12.2017  _x86_64_    (4 CPU)

12:36:25          DEV       tps  rd_sec/s  wr_sec/s  avgrq-sz  avgqu-sz     await     svctm     %util
12:36:26       dev8-0      0.00      0.00      0.00      0.00      0.00      0.00      0.00      0.00
12:36:26       dev8-1      0.00      0.00      0.00      0.00      0.00      0.00      0.00      0.00
[ . . . ]
12:36:29       dev8-7      0.00      0.00      0.00      0.00      0.00      0.00      0.00      0.00
12:36:30       dev8-0      2.00      0.00     88.00     44.00      0.41    355.00    207.00     41.40
12:36:30       dev8-1      2.00      0.00     88.00     44.00      0.41    355.00    207.00     41.40
12:36:30       dev8-2      0.00      0.00      0.00      0.00      0.00      0.00      0.00      0.00
12:36:30       dev8-3      0.00      0.00      0.00      0.00      0.00      0.00      0.00      0.00
12:36:30       dev8-4      0.00      0.00      0.00      0.00      0.00      0.00      0.00      0.00
12:36:30       dev8-5      0.00      0.00      0.00      0.00      0.00      0.00      0.00      0.00
12:36:30       dev8-6      0.00      0.00      0.00      0.00      0.00      0.00      0.00      0.00
12:36:30       dev8-7      0.00      0.00      0.00      0.00      0.00      0.00      0.00      0.00
12:36:31       dev8-0      0.00      0.00      0.00      0.00      0.00      0.00      0.00      0.00
12:36:31       dev8-1      0.00      0.00      0.00      0.00      0.00      0.00      0.00      0.00
[ . . . ]
12:36:34       dev8-7      0.00      0.00      0.00      0.00      0.00      0.00      0.00      0.00
12:36:35       dev8-0      2.00      0.00     24.00     12.00      0.70    348.50    348.00     69.60
12:36:35       dev8-1      2.00      0.00     24.00     12.00      0.70    348.50    348.00     69.60
12:36:35       dev8-2      0.00      0.00      0.00      0.00      0.00      0.00      0.00      0.00
12:36:35       dev8-3      0.00      0.00      0.00      0.00      0.00      0.00      0.00      0.00
12:36:35       dev8-4      0.00      0.00      0.00      0.00      0.00      0.00      0.00      0.00
12:36:35       dev8-5      0.00      0.00      0.00      0.00      0.00      0.00      0.00      0.00
12:36:35       dev8-6      0.00      0.00      0.00      0.00      0.00      0.00      0.00      0.00
12:36:35       dev8-7      0.00      0.00      0.00      0.00      0.00      0.00      0.00      0.00
12:36:36       dev8-0      0.00      0.00      0.00      0.00      0.00      0.00      0.00      0.00
12:36:36       dev8-1      0.00      0.00      0.00      0.00      0.00      0.00      0.00      0.00
[ . . . ]
12:36:40       dev8-7      0.00      0.00      0.00      0.00      0.00      0.00      0.00      0.00
Average:       dev8-0      0.27      0.00      7.47     28.00      0.12    351.75    455.75     12.15
Average:       dev8-1      0.27      0.00      7.47     28.00      0.12    351.75    455.75     12.15
Average:       dev8-2      0.00      0.00      0.00      0.00      0.00      0.00      0.00      0.00
Average:       dev8-3      0.00      0.00      0.00      0.00      0.00      0.00      0.00      0.00
Average:       dev8-4      0.00      0.00      0.00      0.00      0.00      0.00      0.00      0.00
Average:       dev8-5      0.00      0.00      0.00      0.00      0.00      0.00      0.00      0.00
Average:       dev8-6      0.00      0.00      0.00      0.00      0.00      0.00      0.00      0.00
Average:       dev8-7      0.00      0.00      0.00      0.00      0.00      0.00      0.00      0.00

and -b gives:

Linux 4.13.12-1-ARCH (arch)     01.12.2017  _x86_64_    (4 CPU)

12:36:25          tps      rtps      wtps   bread/s   bwrtn/s
12:36:26         0.00      0.00      0.00      0.00      0.00
12:36:27         0.00      0.00      0.00      0.00      0.00
12:36:28         0.00      0.00      0.00      0.00      0.00
12:36:29         0.00      0.00      0.00      0.00      0.00
12:36:30         2.00      0.00      2.00      0.00     88.00
12:36:31         0.00      0.00      0.00      0.00      0.00
12:36:32         0.00      0.00      0.00      0.00      0.00
12:36:33         0.00      0.00      0.00      0.00      0.00
12:36:34         0.00      0.00      0.00      0.00      0.00
12:36:35         2.00      0.00      2.00      0.00     24.00
12:36:36         0.00      0.00      0.00      0.00      0.00
12:36:37         0.00      0.00      0.00      0.00      0.00
12:36:38         0.00      0.00      0.00      0.00      0.00
12:36:39         0.00      0.00      0.00      0.00      0.00
12:36:40         0.00      0.00      0.00      0.00      0.00
Average:         0.27      0.00      0.27      0.00      7.47

So I assume the issue seems to be related to my hard drive (?). Because the I/O is on partition 1 (my root partition), it should be somewhere outside of /var which has an extra partition. The other partitions are data partitions and not system related.

edit3: Even more data to that specific peak: paging looks fine (from my perspective with limited knowledge)

Linux 4.13.12-1-ARCH (arch)     01.12.2017  _x86_64_    (4 CPU)

12:36:25     pgpgin/s pgpgout/s   fault/s  majflt/s  pgfree/s pgscank/s pgscand/s pgsteal/s    %vmeff
12:36:26         0.00      0.00      0.00      0.00   2233.00      0.00      0.00      0.00      0.00
12:36:27         0.00      0.00      0.00      0.00     88.00      0.00      0.00      0.00      0.00
12:36:28         0.00      0.00    766.00      0.00    185.00      0.00      0.00      0.00      0.00
12:36:29         0.00     40.00      0.00      0.00     47.00      0.00      0.00      0.00      0.00
12:36:30         0.00      4.00      0.00      0.00     45.00      0.00      0.00      0.00      0.00
12:36:31         0.00      0.00      1.00      0.00     46.00      0.00      0.00      0.00      0.00
12:36:32         0.00      0.00      5.00      0.00    560.00      0.00      0.00      0.00      0.00
12:36:33         0.00      0.00      2.00      0.00     85.00      0.00      0.00      0.00      0.00
12:36:34         0.00      0.00      2.00      0.00     47.00      0.00      0.00      0.00      0.00
12:36:35         0.00     12.00      0.00      0.00     44.00      0.00      0.00      0.00      0.00
12:36:36         0.00      0.00      0.00      0.00     47.00      0.00      0.00      0.00      0.00
12:36:37         0.00      0.00      2.00      0.00     45.00      0.00      0.00      0.00      0.00
12:36:38         0.00      0.00      0.00      0.00     47.00      0.00      0.00      0.00      0.00
12:36:39         0.00      0.00      0.00      0.00     77.00      0.00      0.00      0.00      0.00
12:36:40         0.00      8.00      0.00      0.00     47.00      0.00      0.00      0.00      0.00
Average:         0.00      4.27     51.87      0.00    242.87      0.00      0.00      0.00      0.00

It looks like files were created during that peak (-v):

Linux 4.13.12-1-ARCH (arch)     01.12.2017  _x86_64_    (4 CPU)

12:36:25    dentunusd   file-nr  inode-nr    pty-nr
12:36:26       186520      4480    195468         2
[ . . . ]
12:36:34       186520      4480    195468         2
12:36:35       186520      4512    195468         2
[ . . . ]
12:36:40       186520      4512    195468         2
Average:       186520      4493    195468         2

edit4: It looks like some irq's are responsible. Running iotop -o -a (show only processes with i/o and accumulate them, so keep all processes that had i/o since the start of the program) resulted in:

Total DISK READ :       0.00 B/s | Total DISK WRITE :       0.00 B/s
Actual DISK READ:       0.00 B/s | Actual DISK WRITE:       0.00 B/s
  TID  PRIO  USER     DISK READ  DISK WRITE  SWAPIN     IO>    COMMAND     
    7 be/4 root          0.00 B      0.00 B  0.00 % 99.99 % [ksoftirqd/0]
   17 be/4 root          0.00 B      0.00 B  0.00 % 99.99 % [ksoftirqd/1]
   23 be/4 root          0.00 B      0.00 B  0.00 % 99.99 % [ksoftirqd/2]
   29 be/4 root          0.00 B      0.00 B  0.00 % 99.99 % [ksoftirqd/3]
  292 rt/4 root          0.00 B      0.00 B  0.00 % 99.99 % [i915/signal:0]
[ . . . ]

So, is this a thing? How could I continue...?

  • To get a fuller understanding of what is happening, download the sysstat package and then use sar to gather system information over time. The high load average does seem to suggest an issue with the processor having to wait to write to disk. – Raman Sailopal Nov 30 '17 at 15:30
  • @RamanSailopal I tried sar (see edit2), but I don't know why long-term surveillance of the problem might help. Could you explain what info you could get from that? Why this could help? A resource on how to use sar to monitor everything needed to help here? Thanks so far. – nox Nov 30 '17 at 16:27
0

Try htop (enable IO_READ_RATE and IO_WRITE_RATE columns), iotop and inotifywait.

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.