lkml.org 
[lkml]   [2022]   [Jun]   [24]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
Patch in this message
/
From
Subject[PATCH] hrtimer: CPU and entry_time is added to a warning message in hrtimer_interrupt()
Date
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
\
 
 \ /
  Last update: 2022-06-24 09:23    [W:0.069 / U:0.260 seconds]
©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site