summaryrefslogtreecommitdiffstats
diff options
context:
space:
mode:
authorAnna-Maria Gleixner <anna-maria@linutronix.de>2019-03-21 13:09:21 +0100
committerThomas Gleixner <tglx@linutronix.de>2019-03-24 20:29:33 +0100
commitf28d3d5346e97e60c81f933ac89ccf015430e5cf (patch)
tree64147609da31c5f0091f50e60eb3eae6f20e4438
parenttimer/trace: Replace deprecated vsprintf pointer extension %pf by %ps (diff)
downloadlinux-f28d3d5346e97e60c81f933ac89ccf015430e5cf.tar.xz
linux-f28d3d5346e97e60c81f933ac89ccf015430e5cf.zip
timer/trace: Improve timer tracing
Timers are added to the timer wheel off by one. This is required in case a timer is queued directly before incrementing jiffies to prevent early timer expiry. When reading a timer trace and relying only on the expiry time of the timer in the timer_start trace point and on the now in the timer_expiry_entry trace point, it seems that the timer fires late. With the current timer_expiry_entry trace point information only now=jiffies is printed but not the value of base->clk. This makes it impossible to draw a conclusion to the index of base->clk and makes it impossible to examine timer problems without additional trace points. Therefore add the base->clk value to the timer_expire_entry trace point, to be able to calculate the index the timer base is located at during collecting expired timers. Signed-off-by: Anna-Maria Gleixner <anna-maria@linutronix.de> Signed-off-by: Thomas Gleixner <tglx@linutronix.de> Cc: fweisbec@gmail.com Cc: peterz@infradead.org Cc: Steven Rostedt <rostedt@goodmis.org> Link: https://lkml.kernel.org/r/20190321120921.16463-5-anna-maria@linutronix.de
-rw-r--r--include/trace/events/timer.h11
-rw-r--r--kernel/time/timer.c17
2 files changed, 20 insertions, 8 deletions
diff --git a/include/trace/events/timer.h b/include/trace/events/timer.h
index da975d69c453..b7a904825e7d 100644
--- a/include/trace/events/timer.h
+++ b/include/trace/events/timer.h
@@ -89,24 +89,27 @@ TRACE_EVENT(timer_start,
*/
TRACE_EVENT(timer_expire_entry,
- TP_PROTO(struct timer_list *timer),
+ TP_PROTO(struct timer_list *timer, unsigned long baseclk),
- TP_ARGS(timer),
+ TP_ARGS(timer, baseclk),
TP_STRUCT__entry(
__field( void *, timer )
__field( unsigned long, now )
__field( void *, function)
+ __field( unsigned long, baseclk )
),
TP_fast_assign(
__entry->timer = timer;
__entry->now = jiffies;
__entry->function = timer->function;
+ __entry->baseclk = baseclk;
),
- TP_printk("timer=%p function=%ps now=%lu",
- __entry->timer, __entry->function, __entry->now)
+ TP_printk("timer=%p function=%ps now=%lu baseclk=%lu",
+ __entry->timer, __entry->function, __entry->now,
+ __entry->baseclk)
);
/**
diff --git a/kernel/time/timer.c b/kernel/time/timer.c
index 8d7918ae4d0c..a9b1bbc2d88d 100644
--- a/kernel/time/timer.c
+++ b/kernel/time/timer.c
@@ -1293,7 +1293,9 @@ int del_timer_sync(struct timer_list *timer)
EXPORT_SYMBOL(del_timer_sync);
#endif
-static void call_timer_fn(struct timer_list *timer, void (*fn)(struct timer_list *))
+static void call_timer_fn(struct timer_list *timer,
+ void (*fn)(struct timer_list *),
+ unsigned long baseclk)
{
int count = preempt_count();
@@ -1316,7 +1318,7 @@ static void call_timer_fn(struct timer_list *timer, void (*fn)(struct timer_list
*/
lock_map_acquire(&lockdep_map);
- trace_timer_expire_entry(timer);
+ trace_timer_expire_entry(timer, baseclk);
fn(timer);
trace_timer_expire_exit(timer);
@@ -1337,6 +1339,13 @@ static void call_timer_fn(struct timer_list *timer, void (*fn)(struct timer_list
static void expire_timers(struct timer_base *base, struct hlist_head *head)
{
+ /*
+ * This value is required only for tracing. base->clk was
+ * incremented directly before expire_timers was called. But expiry
+ * is related to the old base->clk value.
+ */
+ unsigned long baseclk = base->clk - 1;
+
while (!hlist_empty(head)) {
struct timer_list *timer;
void (*fn)(struct timer_list *);
@@ -1350,11 +1359,11 @@ static void expire_timers(struct timer_base *base, struct hlist_head *head)
if (timer->flags & TIMER_IRQSAFE) {
raw_spin_unlock(&base->lock);
- call_timer_fn(timer, fn);
+ call_timer_fn(timer, fn, baseclk);
raw_spin_lock(&base->lock);
} else {
raw_spin_unlock_irq(&base->lock);
- call_timer_fn(timer, fn);
+ call_timer_fn(timer, fn, baseclk);
raw_spin_lock_irq(&base->lock);
}
}