sunxi: cpufreq-dt usage causes schedule_delayed_work to execute sooner?

DISCUSSION Hans de Goede 3 participants 7 messages Mar 16, 2015 – Mar 18, 2015

Share & tools

Hans de Goede

author

2015-03-16 20:18 UTC #0 lore raw

Hi ChenYu, Maxime,

For the sunxi musb code I've been writing uses schedule_delayed_work in a few places, while looking at debugging printk-s in dmesg I noticed that the time stamps between scheduling the work and executing it are of.

If I build a kernel without cpufreq-dt or do:

echo performance > scaling_governor

The problem goes away.

I've done some debugging and the problem is not the actual timing of the code, the timestamps in the dmesg output are wrong, very wrong even here are 2 messages where I plugged in a cable, then waited 10 seconds using a clock with a second hand to count them of, then unplugged:

[  635.006201] musb vbus 0 -> 1
[  637.877098] musb vbus 1 -> 0

This is after doing:

echo powersave > scaling_governor

So it seems that the clocksource used by printk to generate timestamps goes slower as we scale down cpufreq, not good (tm).

This:

[root at localhost clocksource0]# cat available_clocksource arch_sys_counter timer hstimer
[root at localhost clocksource0]# echo timer > current_clocksource

[  725.728887] Switched to clocksource timer

Does not help.

I believe that the "sched_clock_register(sun5i_timer_sched_read, 32, rate);" call in drivers/clocksource/timer-sun5i.c is the culprit, it seems this ends up overriding the sched_clock_register call in drivers/clocksource/arm_arch_timer.c which likely does not suffer from cpufreq issues, and is faster (part of the cpucore) then using the hstimer anyways.

Note I've not tested yet if disabling the hstimer fixes things, but I believe it will. Note that the hstimer will likewise be a bad clockevent source too, this can be fixed by registering a cpufreq notifier and calling clockevents_update_freq whenever the cpufreq, and thus the hstimer clkrate changes.

Alternatively we could simply remove the driver altogether since the kernel prefers the sun4i_tick eventsource anyways.

Regards,

Hans

Chen-Yu Tsai

2015-03-17 02:39 UTC #1 lore raw

Hi Hans,

Quoted 53 lines · Hans de Goede

Hi ChenYu, Maxime,
For the sunxi musb code I've been writing uses schedule_delayed_work in a few places,
while looking at debugging printk-s in dmesg I noticed that the time stamps between
scheduling the work and executing it are of.
If I build a kernel without cpufreq-dt or do:
echo performance > scaling_governor
The problem goes away.
I've done some debugging and the problem is not the actual timing of the code, the timestamps in the dmesg output are wrong, very wrong even here are 2 messages where I plugged in a cable, then waited 10 seconds using a clock with a second hand to count them of, then unplugged:
[  635.006201] musb vbus 0 -> 1
[  637.877098] musb vbus 1 -> 0
This is after doing:
echo powersave > scaling_governor
So it seems that the clocksource used by printk to generate timestamps goes slower as we scale down cpufreq, not good (tm).
This:
[root at localhost clocksource0]# cat available_clocksource arch_sys_counter timer hstimer
[root at localhost clocksource0]# echo timer > current_clocksource
[  725.728887] Switched to clocksource timer
Does not help.
I believe that the "sched_clock_register(sun5i_timer_sched_read, 32, rate);" call in drivers/clocksource/timer-sun5i.c is the culprit, it seems this ends up overriding the sched_clock_register call in drivers/clocksource/arm_arch_timer.c which likely does not suffer from cpufreq
issues, and is faster (part of the cpucore) then using the hstimer anyways.
Note I've not tested yet if disabling the hstimer fixes things, but I believe
it will. Note that the hstimer will likewise be a bad clockevent source too, this can be fixed by registering a cpufreq notifier and calling clockevents_update_freq
whenever the cpufreq, and thus the hstimer clkrate changes.

Quoted 2 lines

Alternatively we could simply remove the driver altogether since the kernel prefers the sun4i_tick eventsource anyways.

Maxime has a series of patches to fix this:

    https://lkml.org/lkml/2015/1/11/52

Another thing we could do is mux AHB to PLL6 on sun5+i. I have a clock driver patch somewhere...

ChenYu

Maxime Ripard

2015-03-17 08:37 UTC #2 lore raw

Quoted 59 lines · Chen-Yu Tsai

Hi Hans,
Quoted 53 lines · Hans de Goede
Hi ChenYu, Maxime,
For the sunxi musb code I've been writing uses schedule_delayed_work in a few places,
while looking at debugging printk-s in dmesg I noticed that the time stamps between
scheduling the work and executing it are of.
If I build a kernel without cpufreq-dt or do:
echo performance > scaling_governor
The problem goes away.
I've done some debugging and the problem is not the actual timing of the code, the timestamps in the dmesg output are wrong, very wrong even here are 2 messages where I plugged in a cable, then waited 10 seconds using a clock with a second hand to count them of, then unplugged:
[  635.006201] musb vbus 0 -> 1
[  637.877098] musb vbus 1 -> 0
This is after doing:
echo powersave > scaling_governor
So it seems that the clocksource used by printk to generate timestamps goes slower as we scale down cpufreq, not good (tm).
This:
[root at localhost clocksource0]# cat available_clocksource arch_sys_counter timer hstimer
[root at localhost clocksource0]# echo timer > current_clocksource
[  725.728887] Switched to clocksource timer
Does not help.
I believe that the "sched_clock_register(sun5i_timer_sched_read, 32, rate);" call in drivers/clocksource/timer-sun5i.c is the culprit, it seems this ends up overriding the sched_clock_register call in drivers/clocksource/arm_arch_timer.c which likely does not suffer from cpufreq
issues, and is faster (part of the cpucore) then using the hstimer anyways.
Note I've not tested yet if disabling the hstimer fixes things, but I believe
it will. Note that the hstimer will likewise be a bad clockevent source too, this can be fixed by registering a cpufreq notifier and calling clockevents_update_freq
whenever the cpufreq, and thus the hstimer clkrate changes.
Quoted 2 lines
Alternatively we could simply remove the driver altogether since the kernel prefers the sun4i_tick eventsource anyways.

Quoted 6 lines

Maxime has a series of patches to fix this:
    https://lkml.org/lkml/2015/1/11/52
Another thing we could do is mux AHB to PLL6 on sun5+i. I have a clock driver patch somewhere...

That wouldn't really fix things.

If we reparent the clock during the boot, it will very likely be after the timer has been registered. The slowdown won't be dynamic depending on the cpu frequency, but it would still be there.

Maxime

Signature · 10 lines

Maxime Ripard, Free Electrons
Embedded Linux, Kernel and Android engineering
http://free-electrons.com
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 819 bytes
Desc: Digital signature
URL: <http://lists.infradead.org/pipermail/linux-arm-kernel/attachments/20150317/f313c293/attachment.sig>

Chen-Yu Tsai

2015-03-17 08:45 UTC #3 lore raw

Quoted 64 lines · Maxime Ripard

Quoted 63 lines · Chen-Yu Tsai
Hi Hans,
Quoted 53 lines · Hans de Goede
Hi ChenYu, Maxime,
For the sunxi musb code I've been writing uses schedule_delayed_work in a few places,
while looking at debugging printk-s in dmesg I noticed that the time stamps between
scheduling the work and executing it are of.
If I build a kernel without cpufreq-dt or do:
echo performance > scaling_governor
The problem goes away.
I've done some debugging and the problem is not the actual timing of the code, the timestamps in the dmesg output are wrong, very wrong even here are 2 messages where I plugged in a cable, then waited 10 seconds using a clock with a second hand to count them of, then unplugged:
[  635.006201] musb vbus 0 -> 1
[  637.877098] musb vbus 1 -> 0
This is after doing:
echo powersave > scaling_governor
So it seems that the clocksource used by printk to generate timestamps goes slower as we scale down cpufreq, not good (tm).
This:
[root at localhost clocksource0]# cat available_clocksource arch_sys_counter timer hstimer
[root at localhost clocksource0]# echo timer > current_clocksource
[  725.728887] Switched to clocksource timer
Does not help.
I believe that the "sched_clock_register(sun5i_timer_sched_read, 32, rate);" call in drivers/clocksource/timer-sun5i.c is the culprit, it seems this ends up overriding the sched_clock_register call in drivers/clocksource/arm_arch_timer.c which likely does not suffer from cpufreq
issues, and is faster (part of the cpucore) then using the hstimer anyways.
Note I've not tested yet if disabling the hstimer fixes things, but I believe
it will. Note that the hstimer will likewise be a bad clockevent source too, this can be fixed by registering a cpufreq notifier and calling clockevents_update_freq
whenever the cpufreq, and thus the hstimer clkrate changes.
Quoted 2 lines
Alternatively we could simply remove the driver altogether since the kernel prefers the sun4i_tick eventsource anyways.
Maxime has a series of patches to fix this:
    https://lkml.org/lkml/2015/1/11/52

Quoted 8 lines

Quoted 2 lines
Another thing we could do is mux AHB to PLL6 on sun5+i. I have a clock driver patch somewhere...
That wouldn't really fix things.
If we reparent the clock during the boot, it will very likely be after the timer has been registered. The slowdown won't be dynamic depending on the cpu frequency, but it would still be there.

Not if we reparent as part of the clock register process, using the "assigned clock parents and rates" bindings. Though I think someone was against that.

ChenYu

Hans de Goede

author

2015-03-17 08:52 UTC #4 lore raw

In reply to Maxime Ripard

Hi,

Quoted 60 lines · Maxime Ripard

Quoted 59 lines · Chen-Yu Tsai
Hi Hans,
Quoted 55 lines · Hans de Goede
Hi ChenYu, Maxime,
For the sunxi musb code I've been writing uses schedule_delayed_work in a few places,
while looking at debugging printk-s in dmesg I noticed that the time stamps between
scheduling the work and executing it are of.
If I build a kernel without cpufreq-dt or do:
echo performance > scaling_governor
The problem goes away.
I've done some debugging and the problem is not the actual timing of the code, the timestamps in the dmesg output are wrong, very wrong even here are 2 messages where I plugged in a cable, then waited 10 seconds using a clock with a second hand to count them of, then unplugged:
[  635.006201] musb vbus 0 -> 1
[  637.877098] musb vbus 1 -> 0
This is after doing:
echo powersave > scaling_governor
So it seems that the clocksource used by printk to generate timestamps goes slower as we scale down cpufreq, not good (tm).
This:
[root at localhost clocksource0]# cat available_clocksource arch_sys_counter timer hstimer
[root at localhost clocksource0]# echo timer > current_clocksource
[  725.728887] Switched to clocksource timer
Does not help.
I believe that the "sched_clock_register(sun5i_timer_sched_read, 32, rate);" call in drivers/clocksource/timer-sun5i.c is the culprit, it seems this ends up overriding the sched_clock_register call in drivers/clocksource/arm_arch_timer.c which likely does not suffer from cpufreq
issues, and is faster (part of the cpucore) then using the hstimer anyways.
Note I've not tested yet if disabling the hstimer fixes things, but I believe
it will. Note that the hstimer will likewise be a bad clockevent source too, this can be fixed by registering a cpufreq notifier and calling clockevents_update_freq
whenever the cpufreq, and thus the hstimer clkrate changes.
Alternatively we could simply remove the driver altogether since the kernel prefers the sun4i_tick eventsource anyways.

Quoted 8 lines

Quoted 6 lines
Maxime has a series of patches to fix this:
     https://lkml.org/lkml/2015/1/11/52
Another thing we could do is mux AHB to PLL6 on sun5+i. I have a clock driver patch somewhere...
That wouldn't really fix things.

Unless we do this in u-boot, I know that does not fix things for people with older u-boot, but I think that making the AHB speed not scale with the cpu clock is a good thing to do in general.

So lets assume we make this change in u-boot to make things better in the long run (when everyone has a new u-boot).

Then we're left with a number of different but related issues:

1) sched_clock implementation

1a) hstimer sched_clock is suboptimal on sun7i, the ARM arch timer is a better sched_clock source and we should not override it -> only register sched_clock on sun5i

1b) sched_clock is unreliable when ahb clock may change -> add some code in the sun5i hstimer triver to detect what the parent is, and if the parent is PLL1 do not register sched_clock

2) timer implementation

This too is sensitive to ahb clock changes, we need Maxime's patchset for this.

Regards,

Hans

Maxime Ripard

2015-03-18 09:40 UTC #5 lore raw

Hi,

Quoted 72 lines · Hans de Goede

Hi,
Quoted 60 lines · Maxime Ripard
Quoted 59 lines · Chen-Yu Tsai
Hi Hans,
Quoted 55 lines · Hans de Goede
Hi ChenYu, Maxime,
For the sunxi musb code I've been writing uses schedule_delayed_work in a few places,
while looking at debugging printk-s in dmesg I noticed that the time stamps between
scheduling the work and executing it are of.
If I build a kernel without cpufreq-dt or do:
echo performance > scaling_governor
The problem goes away.
I've done some debugging and the problem is not the actual timing of the code, the timestamps in the dmesg output are wrong, very wrong even here are 2 messages where I plugged in a cable, then waited 10 seconds using a clock with a second hand to count them of, then unplugged:
[  635.006201] musb vbus 0 -> 1
[  637.877098] musb vbus 1 -> 0
This is after doing:
echo powersave > scaling_governor
So it seems that the clocksource used by printk to generate timestamps goes slower as we scale down cpufreq, not good (tm).
This:
[root at localhost clocksource0]# cat available_clocksource arch_sys_counter timer hstimer
[root at localhost clocksource0]# echo timer > current_clocksource
[  725.728887] Switched to clocksource timer
Does not help.
I believe that the "sched_clock_register(sun5i_timer_sched_read, 32, rate);" call in drivers/clocksource/timer-sun5i.c is the culprit, it seems this ends up overriding the sched_clock_register call in drivers/clocksource/arm_arch_timer.c which likely does not suffer from cpufreq
issues, and is faster (part of the cpucore) then using the hstimer anyways.
Note I've not tested yet if disabling the hstimer fixes things, but I believe
it will. Note that the hstimer will likewise be a bad clockevent source too, this can be fixed by registering a cpufreq notifier and calling clockevents_update_freq
whenever the cpufreq, and thus the hstimer clkrate changes.
Alternatively we could simply remove the driver altogether since the kernel prefers the sun4i_tick eventsource anyways.
Quoted 8 lines
Quoted 6 lines
Maxime has a series of patches to fix this:
    https://lkml.org/lkml/2015/1/11/52
Another thing we could do is mux AHB to PLL6 on sun5+i. I have a clock driver patch somewhere...
That wouldn't really fix things.

Quoted 8 lines

Unless we do this in u-boot, I know that does not fix things for people with older u-boot, but I think that making the AHB speed not scale with the cpu clock is a good thing to do in general.
So lets assume we make this change in u-boot to make things better in the long run (when everyone has a new u-boot).
Then we're left with a number of different but related issues:

To sum up our IRC discussion:

Quoted 9 lines

1) sched_clock implementation
1a) hstimer sched_clock is suboptimal on sun7i, the ARM arch timer is a better sched_clock source and we should not override it -> only register sched_clock on sun5i
1b) sched_clock is unreliable when ahb clock may change -> add some code in the sun5i hstimer triver to detect what the parent is, and if the parent is PLL1 do not register sched_clock

This actually boils down to the fact that the sched_clock has no priority what so ever, and that it frequency can't be updated.

This will be solved by:
- Removing the hstimer sched_clock implementation
- Register a sched clock for the sun4i timer only on sun4i and sun5i, since on the other SoCs, we will have the arch timer sched_clock. That would also allow to have only a single sched_clock implementation registered, together with allowing to shutdown entirely the sun4i timer.

Quoted 3 lines

2) timer implementation
This too is sensitive to ahb clock changes, we need Maxime's patchset for this.

And for that, we already have the patches sent, that just need to be picked up by Daniel.

This will also be solved by moving the AHB clock to a PLL of its own, so that the whole clock won't be impacted by the CPU clock rate changes. That would be also an acceptable change for 4.0 fixes.

So we actually need to merge a few patches:
- One to reparent the AHB clock to PLL6.
+ Chen-Yu has some code to do that already, it needs to be sent for reviews.

- One to fix the hstimer by removing its sched_clock and adding a clock notifier to handle the case where the hstimer clock rate would change (if that ever happens)
+ It's actually part of serie I already sent, that doesn't seem to be having a lot of issues left, and need to be picked by Daniel

- One to register only the sched_clock on the sun4i timer driver on

    A10, A10s and A13.

Maxime

Signature · 10 lines

Maxime Ripard, Free Electrons
Embedded Linux, Kernel and Android engineering
http://free-electrons.com
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 819 bytes
Desc: Digital signature
URL: <http://lists.infradead.org/pipermail/linux-arm-kernel/attachments/20150318/a3194cd1/attachment.sig>

Maxime Ripard

2015-03-17 08:34 UTC #6 lore raw

In reply to Hans de Goede

Hi,

Quoted 21 lines · Hans de Goede

Hi ChenYu, Maxime,
For the sunxi musb code I've been writing uses schedule_delayed_work in a few places, while looking at debugging printk-s in dmesg I noticed that the time stamps between scheduling the work and executing it are of.
If I build a kernel without cpufreq-dt or do:
echo performance > scaling_governor
The problem goes away.
I've done some debugging and the problem is not the actual timing of the code, the timestamps in the dmesg output are wrong, very wrong even here are 2 messages where I plugged in a cable, then waited 10 seconds using a clock with a second hand to count them of, then unplugged:
[  635.006201] musb vbus 0 -> 1
[  637.877098] musb vbus 1 -> 0

Quoted 6 lines

This is after doing:
echo powersave > scaling_governor
So it seems that the clocksource used by printk to generate timestamps goes slower as we scale down cpufreq, not good (tm).

Indeed.

Quoted 7 lines

This:
[root at localhost clocksource0]# cat available_clocksource arch_sys_counter timer hstimer
[root at localhost clocksource0]# echo timer > current_clocksource
[  725.728887] Switched to clocksource timer

Quoted 7 lines

Does not help.
I believe that the "sched_clock_register(sun5i_timer_sched_read, 32, rate);" call in drivers/clocksource/timer-sun5i.c is the culprit, it seems this ends up overriding the sched_clock_register call in drivers/clocksource/arm_arch_timer.c which likely does not suffer from cpufreq issues, and is faster (part of the cpucore) then using the hstimer anyways.

We were kind of having the same issues on the A31, with the AHB clock that gets reparented to PLL6 halfway through the boot, and after the timer has been probed.

I have a patchset that handles this by removing the sched_clock registration and add a clock notifier to handle that the clock change for clock sources and clock events.

http://lists.infradead.org/pipermail/linux-arm-kernel/2015-March/328115.html

Since the system won't use the hstimer by default anyway, could you just test applying this patch ?

http://lists.infradead.org/pipermail/linux-arm-kernel/2015-March/328114.html

Quoted 4 lines

Note I've not tested yet if disabling the hstimer fixes things, but I believe it will. Note that the hstimer will likewise be a bad clockevent source too, this can be fixed by registering a cpufreq notifier and calling clockevents_update_freq whenever the cpufreq, and thus the hstimer clkrate changes.

Without the above set, yep, it will.

Maxime

Signature · 10 lines

Maxime Ripard, Free Electrons
Embedded Linux, Kernel and Android engineering
http://free-electrons.com
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 819 bytes
Desc: Digital signature
URL: <http://lists.infradead.org/pipermail/linux-arm-kernel/attachments/20150317/647b587a/attachment.sig>