Commit f28d3d53 authored by Anna-Maria Gleixner's avatar Anna-Maria Gleixner Committed by Thomas Gleixner
Browse files

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: default avatarAnna-Maria Gleixner <anna-maria@linutronix.de>
Signed-off-by: default avatarThomas 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
parent 6849cbb0

include/trace/events/timer.h

+7 −4
Original line number Diff line number Diff line
@@ -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)

);



/**

kernel/time/timer.c

+13 −4
Original line number Diff line number Diff line
@@ -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);

		}

	}

CRA Git | Maintained and supported by SUSTech CRA and CCSE