On Fri, 24 Jun 2022 16:00:11, Rei Yamamoto wrote:
> dmesg
> :
> [ 1462.836971] start repro_hrtimer_interrupt
> [ 1462.836976] test_handler = test_handler [repro] 0xffff9788f7bb3048
> :
> [ 1462.879117] hrtimer: CPU 7, entry_time = 1462807264840, interrupt took
> 60048886 ns ^^^^^ ^^^^^^^^^^^^^
>
> cat /sys/kernel/debug/tracing/trace
> :
> <idle>-0 [007] d.h1. 1462.838075: hrtimer_expire_entry:
> ^^^^^
> hrtimer=0000000041fcee42 function=test_handler [repro] now=1462807264840
> ^^^^^^^^^^^^^
test_handler() keeps running for 20 milliseconds due to a loop,
and it leads to exceed next_expire.
# grep -A 21 "hrtimer_restart test_handler" repro.c
static enum hrtimer_restart test_handler(struct hrtimer *hrtimer)
{
ktime_t start, end;
printk(KERN_INFO "start test_handler %d times\n", count);
hrtimer_forward_now(hrtimer, ns_to_ktime(TICK_NSEC));
start = ktime_get();
for(;;){
end = ktime_get();
if((ktime_sub(end, start)) > 20000000)
break;
}
if(count < 20){
count++;
return HRTIMER_RESTART;
}else{
return HRTIMER_NORESTART;
}
}
Thanks,
Rei
Hi, Thomas Gleixner.
On Fri, 24 Jun 2022 16:00:11, Rei Yamamoto wrote:
> A warning message in hrtimer_interrupt() is output up to 5 times
> by default, and CPU and entry_time are also shown.
> These changes are helpful that the function spending a lot of time is clear
> by using ftrace:
> -----
> dmesg
> :
> [ 1462.836971] start repro_hrtimer_interrupt
> [ 1462.836976] test_handler = test_handler [repro] 0xffff9788f7bb3048
> :
> [ 1462.879117] hrtimer: CPU 7, entry_time = 1462807264840, interrupt took
> 60048886 ns ^^^^^ ^^^^^^^^^^^^^
>
> cat /sys/kernel/debug/tracing/trace
> :
> <idle>-0 [007] d.h1. 1462.838075: hrtimer_expire_entry:
> ^^^^^
> hrtimer=0000000041fcee42 function=test_handler [repro] now=1462807264840
> ^^^^^^^^^^^^^
> -----
>
> Signed-off-by: Rei Yamamoto <[email protected]>
> ---
> include/linux/hrtimer.h | 1 +
> kernel/sysctl.c | 10 ++++++++++
> kernel/time/hrtimer.c | 16 +++++++++++++++-
> 3 files changed, 26 insertions(+), 1 deletion(-)
>
> diff --git a/include/linux/hrtimer.h b/include/linux/hrtimer.h
> index 0ee140176f10..1a6e03b3015b 100644
> --- a/include/linux/hrtimer.h
> +++ b/include/linux/hrtimer.h
> @@ -317,6 +317,7 @@ static inline int hrtimer_is_hres_active(struct hrtimer *timer)
> struct clock_event_device;
>
> extern void hrtimer_interrupt(struct clock_event_device *dev);
> +extern int sysctl_hrtimer_interrupt_warnings;
>
> extern unsigned int hrtimer_resolution;
>
> diff --git a/kernel/sysctl.c b/kernel/sysctl.c
> index e52b6e372c60..b0420d60cec9 100644
> --- a/kernel/sysctl.c
> +++ b/kernel/sysctl.c
> @@ -64,6 +64,7 @@
> #include <linux/mount.h>
> #include <linux/userfaultfd_k.h>
> #include <linux/pid.h>
> +#include <linux/hrtimer.h>
>
> #include "../lib/kstrtox.h"
>
> @@ -2038,6 +2039,15 @@ static struct ctl_table kern_table[] = {
> .extra1 = SYSCTL_ONE,
> .extra2 = SYSCTL_INT_MAX,
> },
> +#endif
> +#ifdef CONFIG_HIGH_RES_TIMERS
> + {
> + .procname = "hrtimer_interrupt_warnings",
> + .data = &sysctl_hrtimer_interrupt_warnings,
> + .maxlen = sizeof(int),
> + .mode = 0644,
> + .proc_handler = proc_dointvec,
> + },
> #endif
> { }
> };
> diff --git a/kernel/time/hrtimer.c b/kernel/time/hrtimer.c
> index 0ea8702eb516..19adcbcf92e4 100644
> --- a/kernel/time/hrtimer.c
> +++ b/kernel/time/hrtimer.c
> @@ -1773,6 +1773,7 @@ static __latent_entropy void hrtimer_run_softirq(struct softirq_action *h)
> }
>
> #ifdef CONFIG_HIGH_RES_TIMERS
> +int sysctl_hrtimer_interrupt_warnings = 5;
>
> /*
> * High resolution timer interrupt
> @@ -1866,7 +1867,20 @@ void hrtimer_interrupt(struct clock_event_device *dev)
> else
> expires_next = ktime_add(now, delta);
> tick_program_event(expires_next, 1);
> - pr_warn_once("hrtimer: interrupt took %llu ns\n", ktime_to_ns(delta));
> +
> + /*
> + * If a message is output many times, the delayed funciton
> + * may be identified by resetting sysctl_hrtimer_interrupt_warnings
> + * and enabling ftrace.
> + */
> + if (sysctl_hrtimer_interrupt_warnings) {
> + if (sysctl_hrtimer_interrupt_warnings > 0)
> + sysctl_hrtimer_interrupt_warnings--;
> + pr_warn("hrtimer: CPU %d, entry_time = %llu, "
> + "interrupt took %llu ns\n",
> + cpu_base->cpu, entry_time,
> + ktime_to_ns(delta));
> + }
> }
>
> /* called with interrupts disabled */
Could you pick this patch up?
Thanks,
Rei
Hi, Thomas Gleixner.
On Fri, 9 Sep 2022 14:22:11, Rei Yamamoto wrote:
> On Fri, 24 Jun 2022 16:00:11, Rei Yamamoto wrote:
>> A warning message in hrtimer_interrupt() is output up to 5 times
>> by default, and CPU and entry_time are also shown.
>> These changes are helpful that the function spending a lot of time is clear
>> by using ftrace:
>> -----
>> dmesg
>> :
>> [ 1462.836971] start repro_hrtimer_interrupt
>> [ 1462.836976] test_handler = test_handler [repro] 0xffff9788f7bb3048
>> :
>> [ 1462.879117] hrtimer: CPU 7, entry_time = 1462807264840, interrupt took
>> 60048886 ns ^^^^^ ^^^^^^^^^^^^^
>>
>> cat /sys/kernel/debug/tracing/trace
>> :
>> <idle>-0 [007] d.h1. 1462.838075: hrtimer_expire_entry:
>> ^^^^^
>> hrtimer=0000000041fcee42 function=test_handler [repro] now=1462807264840
>> ^^^^^^^^^^^^^
>> -----
>>
>> Signed-off-by: Rei Yamamoto <[email protected]>
>> ---
>> include/linux/hrtimer.h | 1 +
>> kernel/sysctl.c | 10 ++++++++++
>> kernel/time/hrtimer.c | 16 +++++++++++++++-
>> 3 files changed, 26 insertions(+), 1 deletion(-)
>>
>> diff --git a/include/linux/hrtimer.h b/include/linux/hrtimer.h
>> index 0ee140176f10..1a6e03b3015b 100644
>> --- a/include/linux/hrtimer.h
>> +++ b/include/linux/hrtimer.h
>> @@ -317,6 +317,7 @@ static inline int hrtimer_is_hres_active(struct hrtimer *timer)
>> struct clock_event_device;
>>
>> extern void hrtimer_interrupt(struct clock_event_device *dev);
>> +extern int sysctl_hrtimer_interrupt_warnings;
>>
>> extern unsigned int hrtimer_resolution;
>>
>> diff --git a/kernel/sysctl.c b/kernel/sysctl.c
>> index e52b6e372c60..b0420d60cec9 100644
>> --- a/kernel/sysctl.c
>> +++ b/kernel/sysctl.c
>> @@ -64,6 +64,7 @@
>> #include <linux/mount.h>
>> #include <linux/userfaultfd_k.h>
>> #include <linux/pid.h>
>> +#include <linux/hrtimer.h>
>>
>> #include "../lib/kstrtox.h"
>>
>> @@ -2038,6 +2039,15 @@ static struct ctl_table kern_table[] = {
>> .extra1 = SYSCTL_ONE,
>> .extra2 = SYSCTL_INT_MAX,
>> },
>> +#endif
>> +#ifdef CONFIG_HIGH_RES_TIMERS
>> + {
>> + .procname = "hrtimer_interrupt_warnings",
>> + .data = &sysctl_hrtimer_interrupt_warnings,
>> + .maxlen = sizeof(int),
>> + .mode = 0644,
>> + .proc_handler = proc_dointvec,
>> + },
>> #endif
>> { }
>> };
>> diff --git a/kernel/time/hrtimer.c b/kernel/time/hrtimer.c
>> index 0ea8702eb516..19adcbcf92e4 100644
>> --- a/kernel/time/hrtimer.c
>> +++ b/kernel/time/hrtimer.c
>> @@ -1773,6 +1773,7 @@ static __latent_entropy void hrtimer_run_softirq(struct softirq_action *h)
>> }
>>
>> #ifdef CONFIG_HIGH_RES_TIMERS
>> +int sysctl_hrtimer_interrupt_warnings = 5;
>>
>> /*
>> * High resolution timer interrupt
>> @@ -1866,7 +1867,20 @@ void hrtimer_interrupt(struct clock_event_device *dev)
>> else
>> expires_next = ktime_add(now, delta);
>> tick_program_event(expires_next, 1);
>> - pr_warn_once("hrtimer: interrupt took %llu ns\n", ktime_to_ns(delta));
>> +
>> + /*
>> + * If a message is output many times, the delayed funciton
>> + * may be identified by resetting sysctl_hrtimer_interrupt_warnings
>> + * and enabling ftrace.
>> + */
>> + if (sysctl_hrtimer_interrupt_warnings) {
>> + if (sysctl_hrtimer_interrupt_warnings > 0)
>> + sysctl_hrtimer_interrupt_warnings--;
>> + pr_warn("hrtimer: CPU %d, entry_time = %llu, "
>> + "interrupt took %llu ns\n",
>> + cpu_base->cpu, entry_time,
>> + ktime_to_ns(delta));
>> + }
>> }
>>
>> /* called with interrupts disabled */
>
> Could you pick this patch up?
Do you have any comments?
Thanks,
Rei