CPU performance governor not effective after initial turbo/throttling

[MichaIng]

Describe the bug
When using the performance governor for CPUfreq scaling in combination with initial_turbo, it does not become effective until e.g. a CPUfreq-related sysfs tunable is read or written to.
The same was observed when the frequency got throttled (but is not throttled actively anymore, verified via vcgencmd get_throttled) due to low voltage, but that is harder to replicate repliably.

To reproduce

1. Apply initial_turbo=20
2. Apply echo performance > /sys/devices/system/cpu/cpufreq/policy0/scaling_governor during the first 20 seconds of boot (while initial turbo is effective).
3. Check vcgencmd measure_clock arm for and beyond the next 20 seconds.

Expected behaviour
After 20 seconds uptime, the performance governor assures max clock rate.

Actual behaviour
Clock rate stays at minimum/idle frequency, until, for some reason one reads or writes any of the sysfs tunables inside /sys/devices/system/cpu/cpufreq/policy0/.

System
Copy and paste the results of the raspinfo command in to this section. Alternatively, copy and paste a pastebin link, or add answers to the following questions:

• Which model of Raspberry Pi? Seen on RPi2 and RPi4, likely all models affected
• Which OS and version (cat /etc/rpi-issue)? Seen on Raspbian Buster and Bullseye
• Which firmware version (vcgencmd version)? Seen on current stable #1327 and current master #1336
• Which kernel version (uname -a)? 5.4.51-v7+ #1327 - 5.4.65-v7+ #1341

Logs

... this is already ~2 minutes after boot
2020-09-16 12:47:43 root@micha:~# vcgencmd get_throttled
throttled=0x0
2020-09-16 12:47:59 root@micha:~# vcgencmd measure_clock arm
frequency(48)=100000000
2020-09-16 12:48:05 root@micha:~# vcgencmd measure_clock arm
frequency(48)=100000000
2020-09-16 12:48:21 root@micha:~# vcgencmd get_config initial_turbo
initial_turbo=20
2020-09-16 12:48:31 root@micha:~# htop
2020-09-16 12:49:10 root@micha:~# vcgencmd measure_clock arm
frequency(48)=100000000
2020-09-16 12:49:12 root@micha:~# vcgencmd measure_clock arm
frequency(48)=100000000
2020-09-16 12:49:14 root@micha:~# vcgencmd measure_clock arm
frequency(48)=100000000
2020-09-16 12:49:15 root@micha:~# cat /sys/devices/system/cpu/cpufreq/policy0/cpuinfo_cur_freq
100000
2020-09-16 12:49:32 root@micha:~# cat /sys/devices/system/cpu/cpufreq/policy0/cpuinfo_cur_freq
900000

NB: The extremely low min/idle frequency was still applied in another testing context, but the same was observed with default arm_freq_min: MichaIng/DietPi#3719

Additional context
With dynamic governors (schedutil, ondemand, ...) it is not an issue. I can only guess that it is due to the fact that static governors like performance basically set the frequency once and then go to sleep. If the firmware is overriding the frequency due to initial_turbo or throttling and then "releases" it again, it seems to not "inform" the governor to reset the frequency and it seems to not monitor such by itself (somehow reasonably). A dynamic governor re-sets the frequency frequently anyway, so there is no need to do that. Touching the governor tunables seems to trigger it re-setting the frequency, strangely not immediately but with a few seconds delay from what we observed.

If my guess goes into the right direction, then I suggest that the firmware should somehow trigger the governor after turbo or throttling has ended.

[popcornmix]

I think your guess is correct. The arm currently needs to send a frequency request after the initial_turbo request has completed to stick.
The initial_turbo mechanism needs to be independent from the arm's cpufreq one, so the highest of both requests is respected. I'll look into it.

[MichaIng]

Lightspeed reaction, many thanks for looking into it. Reading through the issue on our repo again, I'm not even sure if throttling has the same result, as initial_turbo was enabled as well. I'm not keen to dig our some crappy USB cable to break voltage, but probably you can have a look if the mechanism of overriding and releasing the frequency is similar there.

[popcornmix]

I don't think throttling will have the same issue as initial_turbo. I'll test it when fixing the initial_turbo issue (probably tomorrow).

[popcornmix]

I've had a look and the issue is a bit more awkward that I assumed.
kernel is built with powersave as default governor, but we switch to ondemand in /etc/init.d/triggerhappy.
I've changed that to switch to performance and can see your issue.

This is the sequence:
init_turbo(0s): arm->1500
cpufreq(powersave) : arm->600
cpufreq(performance) : arm->1500
init_turbo(20s): arm->600

I'd assumed that cpufreq(performance) switched to 1500, but init_turbo clobbered that.
Actually that code is correct - we maintain separate frequencies for each and pick the max.

The issue is the cpufreq driver reads the current frequency which it sees as 1500 due to init_turbo, and then skips setting it.
After the firmware removes the boost it has no knowledge that the kernel wanted 1500.

I could imagine throttling causing a switch to the powersave governor to get lost, if when the frequency was throttled, it happened to match the desired frequency. I can't see how throttling could cause a switch to performance to get lost.

As the cpufreq driver is upstream code we try to avoid hacking it. We may want to make the frequency reported to the arm not include init_turbo or throttling effects, but this needs some thought.

[pelwell]

I'm happy to change upstream code if the end result is cleaner, but I think we have some options before doing that.

If we can confirm that the cpufreq driver is the first thing to query the core clock, and that it goes via the firmware clock interface, then I'd be tempted to get the firmware to lie the first time it is called and return either 0 or the minimum value.

[popcornmix]

I think the issue occurs more than just once at startup. Throttling is another case.

Another (hypothetical) case would be firmware side boosts.
The firmware camera driver requires core_freq=500 to operate and temporarily requests a boost.
The arm side kms driver requires core_freq=500 to switch to 4kp60.
The camera driver closes and removes it's boost.

We don't want the kms driver's request for core_freq=500 to have been discarded as "we were already at 500".

[pelwell]

You're right. I think we should just delete the check, or if necessary replace it with a check that we aren't requesting the same frequency we asked for last time.

[popcornmix]

The alternative is to only report to the arm frequencies it has set. Typically the arm doesn't know about throttled or firmware boosted frequencies unless it catches them by accident. e.g. /sys/devices/system/cpu/cpu0/cpufreq/scaling_cur_freq shows the frequency the arm last wrote, rather than the live frequency.
vcgencmd measure_clock arm is needed for actual frequency.

[pelwell]

That also works - we're changing the semantics of the mailbox call, but that sounds like an improvement.

[popcornmix]

Enabled logging for cpufreq driver. I think:
[ 8.405867] cpufreq: Warning: CPU frequency out of sync: cpufreq and timing core thinks of 600000, is 1500000 kHz
is the point that driver sees an unexpected 1500 from initial_turbo and so subsequently avoid setting it.

[    1.270911] cpufreq: trying to register driver cpufreq-dt
[    1.271717] cpu cpu0: cpufreq_add_dev: adding CPU0
[    1.272502] cpufreq: cpufreq_online: bringing CPU0 online
[    1.276362] cpufreq: handle_update for cpu 0 called
[    1.277232] cpufreq: setting new policy for CPU 0: 600000 - 1500000 kHz
[    1.277982] cpufreq: new min and max freqs are 600000 - 1500000 kHz
[    1.278700] cpufreq: governor switch
[    1.279407] cpufreq: cpufreq_init_governor: for CPU 0
[    1.280118] cpufreq: cpufreq_start_governor: for CPU 0
[    1.280860] cpufreq: target for CPU 0: 600000 kHz, relation 0, requested 600000 kHz
[    1.281557] cpufreq: __target_index: cpu: 0, oldfreq: 1500000, new freq: 600000
[    1.282252] cpufreq: notification 0 of frequency transition to 600000 kHz
[    1.285259] cpufreq: notification 1 of frequency transition to 600000 kHz
[    1.285956] cpufreq: FREQ: 600000 - CPUs: 0-3
[    1.286658] cpufreq: governor change
[    1.287344] cpufreq: initialization complete
[    1.288039] cpu cpu1: cpufreq_add_dev: adding CPU1
[    1.288715] cpufreq: cpufreq_online: bringing CPU1 online
[    1.289390] cpu cpu2: cpufreq_add_dev: adding CPU2
[    1.290042] cpufreq: cpufreq_online: bringing CPU2 online
[    1.290701] cpu cpu3: cpufreq_add_dev: adding CPU3
[    1.291352] cpufreq: cpufreq_online: bringing CPU3 online
[    1.292013] cpufreq: updating policy for CPU 0
[    1.292654] cpufreq: setting new policy for CPU 0: 600000 - 1500000 kHz
[    1.293326] cpufreq: new min and max freqs are 600000 - 1500000 kHz
[    1.293971] cpufreq: governor limits update
[    1.294622] cpufreq: cpufreq_governor_limits: for CPU 0
[    1.295270] cpufreq: target for CPU 0: 600000 kHz, relation 0, requested 600000 kHz
[    1.295942] cpufreq: handle_update for cpu 0 called
[    1.296606] cpufreq: updating policy for CPU 0
[    1.297266] cpufreq: setting new policy for CPU 0: 600000 - 1500000 kHz
[    1.297770] cpufreq: driver cpufreq-dt up and running
[    1.297948] cpufreq: new min and max freqs are 600000 - 1500000 kHz
[    1.299317] cpufreq: governor limits update
[    1.300649] cpufreq: cpufreq_governor_limits: for CPU 0
[    1.301987] cpufreq: target for CPU 0: 600000 kHz, relation 0, requested 600000 kHz
[    8.405785] cpufreq: setting new policy for CPU 0: 600000 - 1500000 kHz
[    8.405792] cpufreq: new min and max freqs are 600000 - 1500000 kHz
[    8.405797] cpufreq: governor switch
[    8.405804] cpufreq: cpufreq_stop_governor: for CPU 0
[    8.405809] cpufreq: cpufreq_exit_governor: for CPU 0
[    8.405815] cpufreq: cpufreq_init_governor: for CPU 0
[    8.405819] cpufreq: cpufreq_start_governor: for CPU 0
[    8.405867] cpufreq: Warning: CPU frequency out of sync: cpufreq and timing core thinks of 600000, is 1500000 kHz
[    8.405873] cpufreq: notification 0 of frequency transition to 1500000 kHz
[    8.405881] cpufreq: notification 1 of frequency transition to 1500000 kHz
[    8.405887] cpufreq: FREQ: 1500000 - CPUs: 0-3
[    8.405896] cpufreq: target for CPU 0: 1500000 kHz, relation 1, requested 1500000 kHz
[    8.405901] cpufreq: governor change

[pelwell]

This thread has gone cold - is there any reason not to change the mailbox semantics as outlined: to report only the values set via the mailbox?

[popcornmix]

It's been started, but changing the api to allow "arm request" to be plumbed through had quite a long tail so it's not currently working. And I'm not at "pi" today.

[pelwell]

No problem - I know what it's like.

[popcornmix]

@MichaIng can you test latest rpi-update firmware and let me know if it resolves issue?

[MichaIng]

Yes, I can confirm it's working with current kernel/firmware 5.4.68-v7+ #1343, many thanks 👍!