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...?
