Kernel 6.1.39 -> top -> high wa > 20%

[Npi4]

Describe the bug

Using Kernel 6.1.36 everything is working normal for me.
Using the top-command the wa-Parameter is switching from 0 to X and back to 0.

After upgrading to 6.1.39 the wa-Parameter is not going back to 0.
It always is over 20% (20-25%).

Steps to reproduce the behaviour

1. select top with a kernel like 6.1.36 (is availabel for download).
2. type top and look for the wa-parameter.
3. install 6.1.39
4. type top and look also for the wa-parameter.

Device (s)

Raspberry Pi 4 Mod. B

System

6.1.36:
Raspberry Pi reference 2020-05-27
Generated using pi-gen, https://github.com/RPi-Distro/pi-gen, 30e2dd32ba47cc3bec15ab1413c16a17e5797775, stage4
Apr 25 2023 18:26:03
Copyright (c) 2012 Broadcom
version d7f9c2b4ef7e4a8c0b04374a879ce89d7a948453 (clean) (release) (start)
Linux nextcloudpi.fritz.box 6.1.36-v8+ #1 SMP PREEMPT Fri Jun 30 13:03:56 UTC 2023 aarch64 GNU/Linux

Logs

No response

Additional context

running rpi4 with bookworm

[pelwell]

Not a complete refutation, but at least a counterpoint: I'm running the latest 6.1.39-v8+ (sudo rpi-update d873621) on a Pi 400, and wa (I/O wait) is sitting at 0.0 most of the time. What's more, with a current kernel and delayacct in cmdline.txt you can run sudo iotop to find out which processes are keeping the I/O busy (you'll probably need to sudo apt install iotop first).

Where my system differs from yours is that I'm not running bookworm, it's still on bullseye. The Pi 4 vs Pi 400 distinction should be irrelevant.

[Npi4]

I installed 6.1.39-v8+ again with delayacct in cmdline.txt:

top:
top - 16:22:53 up 53 min, 1 user, load average: 0,03, 0,09, 0,23
Tasks: 179 total, 1 running, 178 sleeping, 0 stopped, 0 zombie
%CPU(s): 0,2 us, 0,5 sy, 0,0 ni, 74,8 id, 24,6 wa, 0,0 hi, 0,0 si, 0,0 st
MiB Spch: 3838,1 total, 1787,5 free, 573,5 used, 1585,8 buff/cache
MiB Swap: 4096,0 total, 4096,0 free, 0,0 used. 3264,6 avail Spch

iostat:
Total DISK READ: 0.00 B/s | Total DISK WRITE: 0.00 B/s
Current DISK READ: 0.00 B/s | Current DISK WRITE: 0.00 B/s
PID PRIO USER DISK READ DISK WRITE SWAPIN IO> COMMAND
14120 be/4 root 0.00 B 0.00 B 0.00 % 0.53 % [kworker/u8:5-events_unbound]
14118 be/4 root 0.00 B 0.00 B 0.00 % 0.20 % [kworker/u8:2-events_unbound]
380 be/3 root 0.00 B 2.25 M 0.00 % 0.08 % [jbd2/sda1-8]
107 be/3 root 0.00 B 72.00 K 0.00 % 0.05 % [jbd2/mmcblk0p2-8]
44050 be/4 mysql 4.02 M 100.00 K 0.00 % 0.05 % mariadbd
15179 be/4 root 0.00 B 0.00 B 0.00 % 0.04 % [kworker/2:2-mm_percpu_wq]
42617 be/4 root 0.00 B 0.00 B 0.00 % 0.01 % [kworker/2:0-events_freezable]

after stopping the mariadb-service:
top:
top - 16:28:21 up 59 min, 1 user, load average: 0,02, 0,05, 0,16
Tasks: 178 total, 1 running, 177 sleeping, 0 stopped, 0 zombie
%CPU(s): 0,2 us, 0,2 sy, 0,0 ni, 99,7 id, 0,0 wa, 0,0 hi, 0,0 si, 0,0 st
MiB Spch: 3838,1 total, 2002,6 free, 358,4 used, 1585,9 buff/cache
MiB Swap: 4096,0 total, 4096,0 free, 0,0 used. 3479,7 avail Spch

restarting mariadb shows again
top - 16:31:28 up 1:02, 1 user, load average: 0,07, 0,06, 0,14
Tasks: 184 total, 1 running, 183 sleeping, 0 stopped, 0 zombie
%CPU(s): 0,2 us, 0,2 sy, 0,0 ni, 74,7 id, 25,0 wa, 0,0 hi, 0,0 si, 0,0 st
MiB Spch: 3838,1 total, 1801,9 free, 559,0 used, 1586,0 buff/cache
MiB Swap: 4096,0 total, 4096,0 free, 0,0 used. 3279,1 avail Spch

restoring to 6.1.36 - rpi-update dc41960
top - 16:39:52 up 5 min, 1 user, load average: 1,06, 1,33, 0,72
Tasks: 177 total, 1 running, 176 sleeping, 0 stopped, 0 zombie
%CPU(s): 0,3 us, 0,4 sy, 0,0 ni, 99,3 id, 0,0 wa, 0,0 hi, 0,0 si, 0,0 st
MiB Spch: 3838,1 total, 2224,5 free, 625,2 used, 1094,4 buff/cache
MiB Swap: 4224,0 total, 4224,0 free, 0,0 used. 3212,9 avail Spch

[pelwell]

Interesting. Would you expect mariadb to have been active at that time (and not just running)?

[Npi4]

I only typed systemctl stop maridb

[pelwell]

No, I wanted to know if mariadb would have had any reason to be busy before you stopped it.

Have you tried any of the kernel versions between 6.1.36 and 6.1.39? You will find the other releases here: https://github.com/raspberrypi/rpi-firmware/commits/master
The hexadecimal numbers on the right of the page are the values you can give to rpi-update to select that release.

[Npi4]

OK. Thank you for your old-version-memo https://github.com/raspberrypi/rpi-firmware/commits/master .
I was looking for a version between 6.1.36 and 6.1.39 but couldn't find it.
Choosing 6.1.38 is working for me now:

top - 05:50:30 up 8 min, 1 user, load average: 0,10, 0,76, 0,56
Tasks: 182 total, 1 running, 181 sleeping, 0 stopped, 0 zombie
%CPU(s): 0,1 us, 0,3 sy, 0,0 ni, 99,6 id, 0,0 wa, 0,0 hi, 0,0 si, 0,0 st
MiB Spch: 3838,2 total, 2151,8 free, 680,3 used, 1110,9 buff/cache
MiB Swap: 4224,0 total, 4224,0 free, 0,0 used. 3158,0 avail Spch

uname -a
Linux nextcloudpi.fritz.box 6.1.38-v8+ #1661 SMP PREEMPT Mon Jul 10 19:39:55 BST 2023 aarch64 GNU/Linux

I always waited some time for the system to really come up, There are no things for mariadb to do except starting and do initial tasks. Then it it's idle vs waiting.

[pelwell]

Installing mariadb-server (and mariadb-client) didn't make any difference here. The server process is running, but perhaps some basic configuration and/or the creation of a database is required.

[pelwell]

The build number of your 6.1.38 kernel (1661) suggests it was installed with rpi-update release 2a89340, and the 6.1.39 kernel is build number 1664. There are two other releases between them that make some significant changes to config settings:

• 33ad824 adds CHECKPOINT_RESTORE and TASK_DELAY_ACCT
• b63c3c7 adds PSI and MPTCP

I'm hoping it was one of those two releases that caused the increased iowait values - can you try them?

[Npi4]

with: kernel: configs: Add CHECKPOINT_RESTORE to 64-bit kernel
rpi-update 331d82458d03cf9e2d43e93be3b6f62dcd2744fe
uname -a
Linux nextcloudpi.fritz.box 6.1.38-v8+ #1662 SMP PREEMPT Fri Jul 14 13:29:18 BST 2023 aarch64 GNU/Linux
top - 13:41:34 up 10 min, 1 user, load average: 0,10, 0,47, 0,48
Tasks: 177 total, 1 running, 176 sleeping, 0 stopped, 0 zombie
%CPU(s): 0,2 us, 0,5 sy, 0,0 ni, 99,4 id, 0,0 wa, 0,0 hi, 0,0 si, 0,0 st
MiB Spch: 3838,2 total, 2201,5 free, 644,4 used, 1096,5 buff/cache
MiB Swap: 4224,0 total, 4224,0 free, 0,0 used. 3193,8 avail Spch

with: kernel: configs: Add PSI, disabled by default
rpi-update b63c3c7de4e3ecfb369ce991e25a7acf450852d1
uname -a
Linux nextcloudpi.fritz.box 6.1.38-v8+ #1663 SMP PREEMPT Mon Jul 17 12:22:57 BST 2023 aarch64 GNU/Linux
top - 13:51:00 up 6 min, 1 user, load average: 0,87, 1,21, 0,68
Tasks: 182 total, 1 running, 181 sleeping, 0 stopped, 0 zombie
%CPU(s): 0,2 us, 0,6 sy, 0,0 ni, 99,3 id, 0,0 wa, 0,0 hi, 0,0 si, 0,0 st
MiB Spch: 3838,1 total, 2215,0 free, 628,0 used, 1100,6 buff/cache
MiB Swap: 4224,0 total, 4224,0 free, 0,0 used. 3210,1 avail Spch

So for now 6.1.38 #1663 is active and working without wa > 20%

[pelwell]

That leaves almost 600 commits that could be responsible for the regression. I'm sure that by eye we can weed out a reasonable number of them because the config settings don't cause them to be built (it would be nice to automate this in some way), but that still leaves a lot.

If I could reproduce the issue it would probably only take around 10 kernel builds to find the culprit, thanks to git bisect, but so far I've not seen the problem here.

[popcornmix]

Where my system differs from yours is that I'm not running bookworm, it's still on bullseye.

I've got an rpi-updated bullseye image here on Pi4.

pi@pi4:~ $ uname -a
Linux pi4 6.1.39-v8+ #1664 SMP PREEMPT Thu Jul 20 15:29:15 BST 2023 aarch64 GNU/Linux
pi@pi4:~ $ cat /etc/os-release 
PRETTY_NAME="Debian GNU/Linux 12 (bookworm)"
NAME="Debian GNU/Linux"
VERSION_ID="12"
VERSION="12 (bookworm)"
VERSION_CODENAME=bookworm
ID=debian
HOME_URL="https://www.debian.org/"
SUPPORT_URL="https://www.debian.org/support"
BUG_REPORT_URL="https://bugs.debian.org/"

I don't see the "wa" issue initially.

top - 14:31:20 up 25 min,  2 users,  load average: 0.00, 0.00, 0.02
Tasks: 152 total,   1 running, 151 sleeping,   0 stopped,   0 zombie
%Cpu(s):  0.0 us, 11.1 sy,  0.0 ni, 88.9 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st 
MiB Mem :   3794.1 total,   3515.1 free,    184.2 used,    161.4 buff/cache     
MiB Swap:    100.0 total,    100.0 free,      0.0 used.   3610.0 avail Mem 

But I do after apt install mariadb-server:

top - 14:36:58 up 30 min,  2 users,  load average: 0.20, 0.32, 0.16
Tasks: 159 total,   1 running, 158 sleeping,   0 stopped,   0 zombie
%Cpu(s):  0.1 us,  0.1 sy,  0.0 ni, 75.0 id, 24.9 wa,  0.0 hi,  0.0 si,  0.0 st 
MiB Mem :   3794.1 total,   2923.6 free,    281.7 used,    665.5 buff/cache     
MiB Swap:    100.0 total,    100.0 free,      0.0 used.   3512.5 avail Mem 

[popcornmix]

Occurs with 6.1.40 and 6.5-rc3. I can confirm it doesn't occur with 6.1.38.

[pelwell]

I'll go through the bisection once I have a working image

[popcornmix]

The top commit of 6.1.39 looked vaguely related to the issue, so I tried reverting it. And the "wa" is gone.

top - 15:53:11 up 7 min,  2 users,  load average: 0.00, 0.19, 0.16
Tasks: 156 total,   1 running, 155 sleeping,   0 stopped,   0 zombie
%Cpu(s):  0.8 us,  0.5 sy,  0.0 ni, 98.7 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st 
MiB Mem :   3794.2 total,   3377.5 free,    265.0 used,    218.4 buff/cache     
MiB Swap:    100.0 total,    100.0 free,      0.0 used.   3529.2 avail Mem 

[pelwell]

Gah - I was just about to start the bisect, having reproduced the issue.

[popcornmix]

Feel free to work out why this occurs.

I suspect it's an accounting issue, rather than a performance issue - I doubt the increased wa time is actually harmful, except by messing up numbers reported.

I seem to recall a similar issue with vchiq with a switch of wait_event_killableor wait_event_interruptible which affected accounting in top (but no real performance change).

[pelwell]

The commit intentionally puts the CPU into a "busy doing I/O" mode while waiting for mumble to prevent it going into deeper sleep states. Unsurprisingly that means the CPU spends longer in I/O mode.

Revert it and wait for upstream to sort it out - I still have PTSD from the vchiq scheduling and signalling nightmares.

[popcornmix]

I've pushed a revert and will push an rpi-update shortly.

[pelwell]

I've sent a message to the upstream devs: https://lore.kernel.org/lkml/CAMEGJJ2RxopfNQ7GNLhr7X9=bHXKo+G5OOe0LUq=+UgLXsv1Xg@mail.gmail.com/

[pelwell]

There is apparently a patch in the works.

[popcornmix]

rpi-update contains the revert. We'll drop the revert if/when the upstream patch mentioned gets accepted.

[popcornmix]

A fix has appeared upstream, so we've dropped the revert. In rpi-update.