Messages in this thread Patch in this message | | | From | Rei Yamamoto <> | Subject | [PATCH] hrtimer: CPU and entry_time is added to a warning message in hrtimer_interrupt() | Date | Fri, 24 Jun 2022 16:00:11 +0900 |
| |
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@jp.fujitsu.com> --- 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 */ -- 2.27.0
| |