All of lore.kernel.org
 help / color / mirror / Atom feed
* [PATCH 0/4] timers: Fix and improve tracing and documentation
@ 2019-03-21 12:09 Anna-Maria Gleixner
  2019-03-21 12:09 ` [PATCH 1/4] tick-sched: Update tick_sched struct documentation Anna-Maria Gleixner
                   ` (4 more replies)
  0 siblings, 5 replies; 10+ messages in thread
From: Anna-Maria Gleixner @ 2019-03-21 12:09 UTC (permalink / raw)
  To: linux-kernel; +Cc: tglx, fweisbec, peterz, Anna-Maria Gleixner

Hi,

the patch series was developed during investigating timer problems and
timer improvements. It contains a struct documentation fix in tick-sched
and a fixes as well as an improvement for timer tracing.

Thanks,

        Anna-Maria


Anna-Maria Gleixner (4):
  tick-sched: Update tick_sched struct documentation
  timer: Move trace point to get proper index
  timer: Replace deprecated vsprintf pointer extension %pf by %ps
  trace/timer: Improve timer tracing

 include/trace/events/timer.h | 17 +++++++++++------
 kernel/time/tick-sched.h     | 13 ++++++++++---
 kernel/time/timer.c          | 30 +++++++++++++++++-------------
 3 files changed, 38 insertions(+), 22 deletions(-)

-- 
2.20.1


^ permalink raw reply	[flat|nested] 10+ messages in thread

* [PATCH 1/4] tick-sched: Update tick_sched struct documentation
  2019-03-21 12:09 [PATCH 0/4] timers: Fix and improve tracing and documentation Anna-Maria Gleixner
@ 2019-03-21 12:09 ` Anna-Maria Gleixner
  2019-03-24 20:19   ` [tip:timers/core] tick/sched: " tip-bot for Anna-Maria Gleixner
  2019-03-21 12:09 ` [PATCH 2/4] timer: Move trace point to get proper index Anna-Maria Gleixner
                   ` (3 subsequent siblings)
  4 siblings, 1 reply; 10+ messages in thread
From: Anna-Maria Gleixner @ 2019-03-21 12:09 UTC (permalink / raw)
  To: linux-kernel; +Cc: tglx, fweisbec, peterz, Anna-Maria Gleixner

Adapt the documentation order of struct members to effective order of
struct members and add missing descriptions.

Signed-off-by: Anna-Maria Gleixner <anna-maria@linutronix.de>
---
 kernel/time/tick-sched.h | 13 ++++++++++---
 1 file changed, 10 insertions(+), 3 deletions(-)

diff --git a/kernel/time/tick-sched.h b/kernel/time/tick-sched.h
index 6de959a854b2..4fb06527cf64 100644
--- a/kernel/time/tick-sched.h
+++ b/kernel/time/tick-sched.h
@@ -24,12 +24,19 @@ enum tick_nohz_mode {
  * struct tick_sched - sched tick emulation and no idle tick control/stats
  * @sched_timer:	hrtimer to schedule the periodic tick in high
  *			resolution mode
+ * @check_clocks:	Notification mechanism about clocksource changes
+ * @nohz_mode:		Mode - one state of tick_nohz_mode
+ * @inidle:		Indicator that the CPU is in the tick idle mode
+ * @tick_stopped:	Indicator that the idle tick has been stopped
+ * @idle_active:	Indicator that the CPU is actively in the tick idle mode;
+ *			it is resetted during irq handling phases.
+ * @do_timer_lst:	CPU was the last one doing do_timer before going idle
+ * @got_idle_tick:	Tick timer function has run with @inidle set
  * @last_tick:		Store the last tick expiry time when the tick
  *			timer is modified for nohz sleeps. This is necessary
  *			to resume the tick timer operation in the timeline
  *			when the CPU returns from nohz sleep.
  * @next_tick:		Next tick to be fired when in dynticks mode.
- * @tick_stopped:	Indicator that the idle tick has been stopped
  * @idle_jiffies:	jiffies at the entry to idle for idle time accounting
  * @idle_calls:		Total number of idle calls
  * @idle_sleeps:	Number of idle calls, where the sched tick was stopped
@@ -40,8 +47,8 @@ enum tick_nohz_mode {
  * @iowait_sleeptime:	Sum of the time slept in idle with sched tick stopped, with IO outstanding
  * @timer_expires:	Anticipated timer expiration time (in case sched tick is stopped)
  * @timer_expires_base:	Base time clock monotonic for @timer_expires
- * @do_timer_lst:	CPU was the last one doing do_timer before going idle
- * @got_idle_tick:	Tick timer function has run with @inidle set
+ * @next_timer:		Expiry time of next expiring timer for debugging purpose only
+ * @tick_dep_mask:	Tick dependency mask - is set, if someone needs the tick
  */
 struct tick_sched {
 	struct hrtimer			sched_timer;
-- 
2.20.1


^ permalink raw reply	[flat|nested] 10+ messages in thread

* [PATCH 2/4] timer: Move trace point to get proper index
  2019-03-21 12:09 [PATCH 0/4] timers: Fix and improve tracing and documentation Anna-Maria Gleixner
  2019-03-21 12:09 ` [PATCH 1/4] tick-sched: Update tick_sched struct documentation Anna-Maria Gleixner
@ 2019-03-21 12:09 ` Anna-Maria Gleixner
  2019-03-24 20:19   ` [tip:timers/core] " tip-bot for Anna-Maria Gleixner
  2019-03-21 12:09 ` [PATCH 3/4] timer: Replace deprecated vsprintf pointer extension %pf by %ps Anna-Maria Gleixner
                   ` (2 subsequent siblings)
  4 siblings, 1 reply; 10+ messages in thread
From: Anna-Maria Gleixner @ 2019-03-21 12:09 UTC (permalink / raw)
  To: linux-kernel; +Cc: tglx, fweisbec, peterz, Anna-Maria Gleixner

When placing the timer_start trace point before timer wheel bucket
index is calculated, index information in trace point is useless.

It is not possible to simply move debug_activate() call after index
calculation, because debug_object_activate() function needs to be
called before touching the object.

Therefore split debug_activate() function and move trace point into
timer enqueue after index calculation. debug_object_activate() call
remains at the original place.

Signed-off-by: Anna-Maria Gleixner <anna-maria@linutronix.de>
---
 kernel/time/timer.c | 13 ++++---------
 1 file changed, 4 insertions(+), 9 deletions(-)

diff --git a/kernel/time/timer.c b/kernel/time/timer.c
index 2fce056f8a49..8d7918ae4d0c 100644
--- a/kernel/time/timer.c
+++ b/kernel/time/timer.c
@@ -536,6 +536,8 @@ static void enqueue_timer(struct timer_base *base, struct timer_list *timer,
 	hlist_add_head(&timer->entry, base->vectors + idx);
 	__set_bit(idx, base->pending_map);
 	timer_set_idx(timer, idx);
+
+	trace_timer_start(timer, timer->expires, timer->flags);
 }
 
 static void
@@ -757,13 +759,6 @@ static inline void debug_init(struct timer_list *timer)
 	trace_timer_init(timer);
 }
 
-static inline void
-debug_activate(struct timer_list *timer, unsigned long expires)
-{
-	debug_timer_activate(timer);
-	trace_timer_start(timer, expires, timer->flags);
-}
-
 static inline void debug_deactivate(struct timer_list *timer)
 {
 	debug_timer_deactivate(timer);
@@ -1037,7 +1032,7 @@ __mod_timer(struct timer_list *timer, unsigned long expires, unsigned int option
 		}
 	}
 
-	debug_activate(timer, expires);
+	debug_timer_activate(timer);
 
 	timer->expires = expires;
 	/*
@@ -1171,7 +1166,7 @@ void add_timer_on(struct timer_list *timer, int cpu)
 	}
 	forward_timer_base(base);
 
-	debug_activate(timer, timer->expires);
+	debug_timer_activate(timer);
 	internal_add_timer(base, timer);
 	raw_spin_unlock_irqrestore(&base->lock, flags);
 }
-- 
2.20.1


^ permalink raw reply	[flat|nested] 10+ messages in thread

* [PATCH 3/4] timer: Replace deprecated vsprintf pointer extension %pf by %ps
  2019-03-21 12:09 [PATCH 0/4] timers: Fix and improve tracing and documentation Anna-Maria Gleixner
  2019-03-21 12:09 ` [PATCH 1/4] tick-sched: Update tick_sched struct documentation Anna-Maria Gleixner
  2019-03-21 12:09 ` [PATCH 2/4] timer: Move trace point to get proper index Anna-Maria Gleixner
@ 2019-03-21 12:09 ` Anna-Maria Gleixner
  2019-03-24 20:20   ` [tip:timers/core] timer/trace: " tip-bot for Anna-Maria Gleixner
  2019-03-21 12:09 ` [PATCH 4/4] trace/timer: Improve timer tracing Anna-Maria Gleixner
  2019-04-03 13:39 ` [PATCH 0/4] timers: Fix and improve tracing and documentation Peter Zijlstra
  4 siblings, 1 reply; 10+ messages in thread
From: Anna-Maria Gleixner @ 2019-03-21 12:09 UTC (permalink / raw)
  To: linux-kernel; +Cc: tglx, fweisbec, peterz, Anna-Maria Gleixner

Since commit 04b8eb7a4ccd ("symbol lookup: introduce
dereference_symbol_descriptor()") %pf is deprecated, because %ps is smart
enough to handle function pointer dereference on platforms where such
dereference is required.

While at it shorten touched lines not to contain more than 80 characters.

Signed-off-by: Anna-Maria Gleixner <anna-maria@linutronix.de>
---
 include/trace/events/timer.h | 10 ++++++----
 1 file changed, 6 insertions(+), 4 deletions(-)

diff --git a/include/trace/events/timer.h b/include/trace/events/timer.h
index a57e4ee989d6..da975d69c453 100644
--- a/include/trace/events/timer.h
+++ b/include/trace/events/timer.h
@@ -73,7 +73,7 @@ TRACE_EVENT(timer_start,
 		__entry->flags		= flags;
 	),
 
-	TP_printk("timer=%p function=%pf expires=%lu [timeout=%ld] cpu=%u idx=%u flags=%s",
+	TP_printk("timer=%p function=%ps expires=%lu [timeout=%ld] cpu=%u idx=%u flags=%s",
 		  __entry->timer, __entry->function, __entry->expires,
 		  (long)__entry->expires - __entry->now,
 		  __entry->flags & TIMER_CPUMASK,
@@ -105,7 +105,8 @@ TRACE_EVENT(timer_expire_entry,
 		__entry->function	= timer->function;
 	),
 
-	TP_printk("timer=%p function=%pf now=%lu", __entry->timer, __entry->function,__entry->now)
+	TP_printk("timer=%p function=%ps now=%lu",
+		  __entry->timer, __entry->function, __entry->now)
 );
 
 /**
@@ -210,7 +211,7 @@ TRACE_EVENT(hrtimer_start,
 		__entry->mode		= mode;
 	),
 
-	TP_printk("hrtimer=%p function=%pf expires=%llu softexpires=%llu "
+	TP_printk("hrtimer=%p function=%ps expires=%llu softexpires=%llu "
 		  "mode=%s", __entry->hrtimer, __entry->function,
 		  (unsigned long long) __entry->expires,
 		  (unsigned long long) __entry->softexpires,
@@ -243,7 +244,8 @@ TRACE_EVENT(hrtimer_expire_entry,
 		__entry->function	= hrtimer->function;
 	),
 
-	TP_printk("hrtimer=%p function=%pf now=%llu", __entry->hrtimer, __entry->function,
+	TP_printk("hrtimer=%p function=%ps now=%llu",
+		  __entry->hrtimer, __entry->function,
 		  (unsigned long long) __entry->now)
 );
 
-- 
2.20.1


^ permalink raw reply	[flat|nested] 10+ messages in thread

* [PATCH 4/4] trace/timer: Improve timer tracing
  2019-03-21 12:09 [PATCH 0/4] timers: Fix and improve tracing and documentation Anna-Maria Gleixner
                   ` (2 preceding siblings ...)
  2019-03-21 12:09 ` [PATCH 3/4] timer: Replace deprecated vsprintf pointer extension %pf by %ps Anna-Maria Gleixner
@ 2019-03-21 12:09 ` Anna-Maria Gleixner
  2019-03-24 20:21   ` [tip:timers/core] timer/trace: " tip-bot for Anna-Maria Gleixner
  2019-04-03 13:39 ` [PATCH 0/4] timers: Fix and improve tracing and documentation Peter Zijlstra
  4 siblings, 1 reply; 10+ messages in thread
From: Anna-Maria Gleixner @ 2019-03-21 12:09 UTC (permalink / raw)
  To: linux-kernel; +Cc: tglx, fweisbec, peterz, Anna-Maria Gleixner

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 timer_start trace point and on the now in 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>
---
 include/trace/events/timer.h | 11 +++++++----
 kernel/time/timer.c          | 17 +++++++++++++----
 2 files changed, 20 insertions(+), 8 deletions(-)

diff --git a/include/trace/events/timer.h b/include/trace/events/timer.h
index da975d69c453..dade735657ef 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 base->clk=%lu",
+		  __entry->timer, __entry->function, __entry->now,
+		  __entry->baseclk)
 );
 
 /**
diff --git a/kernel/time/timer.c b/kernel/time/timer.c
index 8d7918ae4d0c..c0233c1a4ccb 100644
--- a/kernel/time/timer.c
+++ b/kernel/time/timer.c
@@ -1293,7 +1293,8 @@ 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(unsigned long baseclk, struct timer_list *timer,
+			  void (*fn)(struct timer_list *))
 {
 	int count = preempt_count();
 
@@ -1316,7 +1317,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 +1338,14 @@ 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 for tracing only
+	 *
+	 * 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(baseclk, timer, fn);
 			raw_spin_lock(&base->lock);
 		} else {
 			raw_spin_unlock_irq(&base->lock);
-			call_timer_fn(timer, fn);
+			call_timer_fn(baseclk, timer, fn);
 			raw_spin_lock_irq(&base->lock);
 		}
 	}
-- 
2.20.1


^ permalink raw reply	[flat|nested] 10+ messages in thread

* [tip:timers/core] tick/sched: Update tick_sched struct documentation
  2019-03-21 12:09 ` [PATCH 1/4] tick-sched: Update tick_sched struct documentation Anna-Maria Gleixner
@ 2019-03-24 20:19   ` tip-bot for Anna-Maria Gleixner
  0 siblings, 0 replies; 10+ messages in thread
From: tip-bot for Anna-Maria Gleixner @ 2019-03-24 20:19 UTC (permalink / raw)
  To: linux-tip-commits; +Cc: hpa, tglx, mingo, linux-kernel, anna-maria

Commit-ID:  d6b87eaf10bd061914f6d277d7428b3285d8850e
Gitweb:     https://git.kernel.org/tip/d6b87eaf10bd061914f6d277d7428b3285d8850e
Author:     Anna-Maria Gleixner <anna-maria@linutronix.de>
AuthorDate: Thu, 21 Mar 2019 13:09:18 +0100
Committer:  Thomas Gleixner <tglx@linutronix.de>
CommitDate: Sun, 24 Mar 2019 20:29:32 +0100

tick/sched: Update tick_sched struct documentation

Adapt the documentation order of struct members to the effective order of
struct members and add missing descriptions.

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
Link: https://lkml.kernel.org/r/20190321120921.16463-2-anna-maria@linutronix.de

---
 kernel/time/tick-sched.h | 13 ++++++++++---
 1 file changed, 10 insertions(+), 3 deletions(-)

diff --git a/kernel/time/tick-sched.h b/kernel/time/tick-sched.h
index 6de959a854b2..4fb06527cf64 100644
--- a/kernel/time/tick-sched.h
+++ b/kernel/time/tick-sched.h
@@ -24,12 +24,19 @@ enum tick_nohz_mode {
  * struct tick_sched - sched tick emulation and no idle tick control/stats
  * @sched_timer:	hrtimer to schedule the periodic tick in high
  *			resolution mode
+ * @check_clocks:	Notification mechanism about clocksource changes
+ * @nohz_mode:		Mode - one state of tick_nohz_mode
+ * @inidle:		Indicator that the CPU is in the tick idle mode
+ * @tick_stopped:	Indicator that the idle tick has been stopped
+ * @idle_active:	Indicator that the CPU is actively in the tick idle mode;
+ *			it is resetted during irq handling phases.
+ * @do_timer_lst:	CPU was the last one doing do_timer before going idle
+ * @got_idle_tick:	Tick timer function has run with @inidle set
  * @last_tick:		Store the last tick expiry time when the tick
  *			timer is modified for nohz sleeps. This is necessary
  *			to resume the tick timer operation in the timeline
  *			when the CPU returns from nohz sleep.
  * @next_tick:		Next tick to be fired when in dynticks mode.
- * @tick_stopped:	Indicator that the idle tick has been stopped
  * @idle_jiffies:	jiffies at the entry to idle for idle time accounting
  * @idle_calls:		Total number of idle calls
  * @idle_sleeps:	Number of idle calls, where the sched tick was stopped
@@ -40,8 +47,8 @@ enum tick_nohz_mode {
  * @iowait_sleeptime:	Sum of the time slept in idle with sched tick stopped, with IO outstanding
  * @timer_expires:	Anticipated timer expiration time (in case sched tick is stopped)
  * @timer_expires_base:	Base time clock monotonic for @timer_expires
- * @do_timer_lst:	CPU was the last one doing do_timer before going idle
- * @got_idle_tick:	Tick timer function has run with @inidle set
+ * @next_timer:		Expiry time of next expiring timer for debugging purpose only
+ * @tick_dep_mask:	Tick dependency mask - is set, if someone needs the tick
  */
 struct tick_sched {
 	struct hrtimer			sched_timer;

^ permalink raw reply	[flat|nested] 10+ messages in thread

* [tip:timers/core] timer: Move trace point to get proper index
  2019-03-21 12:09 ` [PATCH 2/4] timer: Move trace point to get proper index Anna-Maria Gleixner
@ 2019-03-24 20:19   ` tip-bot for Anna-Maria Gleixner
  0 siblings, 0 replies; 10+ messages in thread
From: tip-bot for Anna-Maria Gleixner @ 2019-03-24 20:19 UTC (permalink / raw)
  To: linux-tip-commits; +Cc: rostedt, linux-kernel, tglx, mingo, anna-maria, hpa

Commit-ID:  dc1e7dc5ac6254ba0502323381a7ec847e408f1d
Gitweb:     https://git.kernel.org/tip/dc1e7dc5ac6254ba0502323381a7ec847e408f1d
Author:     Anna-Maria Gleixner <anna-maria@linutronix.de>
AuthorDate: Thu, 21 Mar 2019 13:09:19 +0100
Committer:  Thomas Gleixner <tglx@linutronix.de>
CommitDate: Sun, 24 Mar 2019 20:29:32 +0100

timer: Move trace point to get proper index

When placing the timer_start trace point before the timer wheel bucket
index is calculated, the index information in the trace point is useless.

It is not possible to simply move the debug_activate() call after the index
calculation, because debug_object_activate() needs to be called before
touching the object.

Therefore split debug_activate() and move the trace point into
enqueue_timer() after the new index has been calculated. The
debug_object_activate() call remains at the original place.

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-3-anna-maria@linutronix.de

---
 kernel/time/timer.c | 13 ++++---------
 1 file changed, 4 insertions(+), 9 deletions(-)

diff --git a/kernel/time/timer.c b/kernel/time/timer.c
index 2fce056f8a49..8d7918ae4d0c 100644
--- a/kernel/time/timer.c
+++ b/kernel/time/timer.c
@@ -536,6 +536,8 @@ static void enqueue_timer(struct timer_base *base, struct timer_list *timer,
 	hlist_add_head(&timer->entry, base->vectors + idx);
 	__set_bit(idx, base->pending_map);
 	timer_set_idx(timer, idx);
+
+	trace_timer_start(timer, timer->expires, timer->flags);
 }
 
 static void
@@ -757,13 +759,6 @@ static inline void debug_init(struct timer_list *timer)
 	trace_timer_init(timer);
 }
 
-static inline void
-debug_activate(struct timer_list *timer, unsigned long expires)
-{
-	debug_timer_activate(timer);
-	trace_timer_start(timer, expires, timer->flags);
-}
-
 static inline void debug_deactivate(struct timer_list *timer)
 {
 	debug_timer_deactivate(timer);
@@ -1037,7 +1032,7 @@ __mod_timer(struct timer_list *timer, unsigned long expires, unsigned int option
 		}
 	}
 
-	debug_activate(timer, expires);
+	debug_timer_activate(timer);
 
 	timer->expires = expires;
 	/*
@@ -1171,7 +1166,7 @@ void add_timer_on(struct timer_list *timer, int cpu)
 	}
 	forward_timer_base(base);
 
-	debug_activate(timer, timer->expires);
+	debug_timer_activate(timer);
 	internal_add_timer(base, timer);
 	raw_spin_unlock_irqrestore(&base->lock, flags);
 }

^ permalink raw reply	[flat|nested] 10+ messages in thread

* [tip:timers/core] timer/trace: Replace deprecated vsprintf pointer extension %pf by %ps
  2019-03-21 12:09 ` [PATCH 3/4] timer: Replace deprecated vsprintf pointer extension %pf by %ps Anna-Maria Gleixner
@ 2019-03-24 20:20   ` tip-bot for Anna-Maria Gleixner
  0 siblings, 0 replies; 10+ messages in thread
From: tip-bot for Anna-Maria Gleixner @ 2019-03-24 20:20 UTC (permalink / raw)
  To: linux-tip-commits; +Cc: linux-kernel, rostedt, hpa, mingo, tglx, anna-maria

Commit-ID:  6849cbb0f9a8dbc1ba56e9abc6955613103e01e3
Gitweb:     https://git.kernel.org/tip/6849cbb0f9a8dbc1ba56e9abc6955613103e01e3
Author:     Anna-Maria Gleixner <anna-maria@linutronix.de>
AuthorDate: Thu, 21 Mar 2019 13:09:20 +0100
Committer:  Thomas Gleixner <tglx@linutronix.de>
CommitDate: Sun, 24 Mar 2019 20:29:33 +0100

timer/trace: Replace deprecated vsprintf pointer extension %pf by %ps

Since commit 04b8eb7a4ccd ("symbol lookup: introduce
dereference_symbol_descriptor()") %pf is deprecated, because %ps is smart
enough to handle function pointer dereference on platforms where such a
dereference is required.

While at it add proper line breaks to stay in the 80 character limit.

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-4-anna-maria@linutronix.de

---
 include/trace/events/timer.h | 10 ++++++----
 1 file changed, 6 insertions(+), 4 deletions(-)

diff --git a/include/trace/events/timer.h b/include/trace/events/timer.h
index a57e4ee989d6..da975d69c453 100644
--- a/include/trace/events/timer.h
+++ b/include/trace/events/timer.h
@@ -73,7 +73,7 @@ TRACE_EVENT(timer_start,
 		__entry->flags		= flags;
 	),
 
-	TP_printk("timer=%p function=%pf expires=%lu [timeout=%ld] cpu=%u idx=%u flags=%s",
+	TP_printk("timer=%p function=%ps expires=%lu [timeout=%ld] cpu=%u idx=%u flags=%s",
 		  __entry->timer, __entry->function, __entry->expires,
 		  (long)__entry->expires - __entry->now,
 		  __entry->flags & TIMER_CPUMASK,
@@ -105,7 +105,8 @@ TRACE_EVENT(timer_expire_entry,
 		__entry->function	= timer->function;
 	),
 
-	TP_printk("timer=%p function=%pf now=%lu", __entry->timer, __entry->function,__entry->now)
+	TP_printk("timer=%p function=%ps now=%lu",
+		  __entry->timer, __entry->function, __entry->now)
 );
 
 /**
@@ -210,7 +211,7 @@ TRACE_EVENT(hrtimer_start,
 		__entry->mode		= mode;
 	),
 
-	TP_printk("hrtimer=%p function=%pf expires=%llu softexpires=%llu "
+	TP_printk("hrtimer=%p function=%ps expires=%llu softexpires=%llu "
 		  "mode=%s", __entry->hrtimer, __entry->function,
 		  (unsigned long long) __entry->expires,
 		  (unsigned long long) __entry->softexpires,
@@ -243,7 +244,8 @@ TRACE_EVENT(hrtimer_expire_entry,
 		__entry->function	= hrtimer->function;
 	),
 
-	TP_printk("hrtimer=%p function=%pf now=%llu", __entry->hrtimer, __entry->function,
+	TP_printk("hrtimer=%p function=%ps now=%llu",
+		  __entry->hrtimer, __entry->function,
 		  (unsigned long long) __entry->now)
 );
 

^ permalink raw reply	[flat|nested] 10+ messages in thread

* [tip:timers/core] timer/trace: Improve timer tracing
  2019-03-21 12:09 ` [PATCH 4/4] trace/timer: Improve timer tracing Anna-Maria Gleixner
@ 2019-03-24 20:21   ` tip-bot for Anna-Maria Gleixner
  0 siblings, 0 replies; 10+ messages in thread
From: tip-bot for Anna-Maria Gleixner @ 2019-03-24 20:21 UTC (permalink / raw)
  To: linux-tip-commits; +Cc: rostedt, tglx, hpa, anna-maria, linux-kernel, mingo

Commit-ID:  f28d3d5346e97e60c81f933ac89ccf015430e5cf
Gitweb:     https://git.kernel.org/tip/f28d3d5346e97e60c81f933ac89ccf015430e5cf
Author:     Anna-Maria Gleixner <anna-maria@linutronix.de>
AuthorDate: Thu, 21 Mar 2019 13:09:21 +0100
Committer:  Thomas Gleixner <tglx@linutronix.de>
CommitDate: Sun, 24 Mar 2019 20:29:33 +0100

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

---
 include/trace/events/timer.h | 11 +++++++----
 kernel/time/timer.c          | 17 +++++++++++++----
 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);
 		}
 	}

^ permalink raw reply	[flat|nested] 10+ messages in thread

* Re: [PATCH 0/4] timers: Fix and improve tracing and documentation
  2019-03-21 12:09 [PATCH 0/4] timers: Fix and improve tracing and documentation Anna-Maria Gleixner
                   ` (3 preceding siblings ...)
  2019-03-21 12:09 ` [PATCH 4/4] trace/timer: Improve timer tracing Anna-Maria Gleixner
@ 2019-04-03 13:39 ` Peter Zijlstra
  4 siblings, 0 replies; 10+ messages in thread
From: Peter Zijlstra @ 2019-04-03 13:39 UTC (permalink / raw)
  To: Anna-Maria Gleixner; +Cc: linux-kernel, tglx, fweisbec

On Thu, Mar 21, 2019 at 01:09:17PM +0100, Anna-Maria Gleixner wrote:
> Hi,
> 
> the patch series was developed during investigating timer problems and
> timer improvements. It contains a struct documentation fix in tick-sched
> and a fixes as well as an improvement for timer tracing.
> 
> Thanks,
> 
>         Anna-Maria
> 
> 
> Anna-Maria Gleixner (4):
>   tick-sched: Update tick_sched struct documentation
>   timer: Move trace point to get proper index
>   timer: Replace deprecated vsprintf pointer extension %pf by %ps
>   trace/timer: Improve timer tracing
> 
>  include/trace/events/timer.h | 17 +++++++++++------
>  kernel/time/tick-sched.h     | 13 ++++++++++---
>  kernel/time/timer.c          | 30 +++++++++++++++++-------------
>  3 files changed, 38 insertions(+), 22 deletions(-)

Acked-by: Peter Zijlstra (Intel) <peterz@infradead.org>

^ permalink raw reply	[flat|nested] 10+ messages in thread

end of thread, other threads:[~2019-04-03 13:39 UTC | newest]

Thread overview: 10+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2019-03-21 12:09 [PATCH 0/4] timers: Fix and improve tracing and documentation Anna-Maria Gleixner
2019-03-21 12:09 ` [PATCH 1/4] tick-sched: Update tick_sched struct documentation Anna-Maria Gleixner
2019-03-24 20:19   ` [tip:timers/core] tick/sched: " tip-bot for Anna-Maria Gleixner
2019-03-21 12:09 ` [PATCH 2/4] timer: Move trace point to get proper index Anna-Maria Gleixner
2019-03-24 20:19   ` [tip:timers/core] " tip-bot for Anna-Maria Gleixner
2019-03-21 12:09 ` [PATCH 3/4] timer: Replace deprecated vsprintf pointer extension %pf by %ps Anna-Maria Gleixner
2019-03-24 20:20   ` [tip:timers/core] timer/trace: " tip-bot for Anna-Maria Gleixner
2019-03-21 12:09 ` [PATCH 4/4] trace/timer: Improve timer tracing Anna-Maria Gleixner
2019-03-24 20:21   ` [tip:timers/core] timer/trace: " tip-bot for Anna-Maria Gleixner
2019-04-03 13:39 ` [PATCH 0/4] timers: Fix and improve tracing and documentation Peter Zijlstra

This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.