Re: [PATCH] hrtimer: CPU and entry_time is added to a warning message in hrtimer_interrupt()

[Rei Yamamoto]

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 <yamamoto.rei@xxxxxxxxxxxxxx>
>> ---
>>  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