* [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 related [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 related [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 related [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 related [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 related [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 related [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 related [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 related [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