Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]

Groups > linux.kernel > #1472394 > unrolled thread

[PATCH v4 0/3] *** Latency histograms - IRQSOFF,PREEMPTOFF ***

Back to article view | Back to linux.kernel

Contents

  [PATCH v4 0/3] *** Latency histograms - IRQSOFF,PREEMPTOFF *** Binoy Jayan <binoy.jayan@linaro.org> - 2016-08-30 12:30 +0200
    [PATCH v4 1/3] tracing: Deference pointers without RCU checks Binoy Jayan <binoy.jayan@linaro.org> - 2016-08-30 12:30 +0200
    [PATCH v4 3/3] tracing: Histogram for missed timer offsets Binoy Jayan <binoy.jayan@linaro.org> - 2016-08-30 12:30 +0200
      Re: [PATCH v4 3/3] tracing: Histogram for missed timer offsets Masami Hiramatsu <masami.hiramatsu@linaro.org> - 2016-08-30 13:00 +0200
        Re: [PATCH v4 3/3] tracing: Histogram for missed timer offsets Binoy Jayan <binoy.jayan@linaro.org> - 2016-09-02 14:50 +0200
          Re: [PATCH v4 3/3] tracing: Histogram for missed timer offsets Masami Hiramatsu <masami.hiramatsu@linaro.org> - 2016-09-02 18:00 +0200
      Re: [PATCH v4 3/3] tracing: Histogram for missed timer offsets Steven Rostedt <rostedt@goodmis.org> - 2016-08-30 16:20 +0200
        Re: [PATCH v4 3/3] tracing: Histogram for missed timer offsets Binoy Jayan <binoy.jayan@linaro.org> - 2016-08-31 13:40 +0200
          Re: [PATCH v4 3/3] tracing: Histogram for missed timer offsets Steven Rostedt <rostedt@goodmis.org> - 2016-08-31 14:50 +0200
    Re: [PATCH v4 0/3] *** Latency histograms - IRQSOFF,PREEMPTOFF *** Daniel Wagner <daniel.wagner@bmw-carit.de> - 2016-08-30 13:50 +0200
      Re: [PATCH v4 0/3] *** Latency histograms - IRQSOFF,PREEMPTOFF *** Masami Hiramatsu <masami.hiramatsu@linaro.org> - 2016-08-30 14:10 +0200

#1472394 — [PATCH v4 0/3] *** Latency histograms - IRQSOFF,PREEMPTOFF ***

Hi,

Thank you Daniel for reviewing v3 throroughly.
These set of patches [v4] capture latency events caused by interrupts and
premption disabled in kernel. The patches are based on the hist trigger
feature developed by Tom Zanussi.

v3: https://lkml.org/lkml/2016/8/29/50
v2: https://lkml.org/lkml/2016/8/24/296

Mount Debugfs

mount -t debugfs nodev /sys/kernel/debug

Examples of triggers:
echo 'hist:key=latency.log2:val=hitcount:sort=latency' > /sys/kernel/debug/tracing/events/latency/latency_preempt/trigger
echo 'hist:key=cpu,latency:val=hitcount:sort=latency if cpu==1' > /sys/kernel/debug/tracing/events/latency/latency_preempt/trigger
echo 'hist:key=ltype,cpu:val=latency:sort=ltype,cpu if ltype==0' > /sys/kernel/debug/tracing/events/latency/latency_preempt/trigger

Histogram output:
cat /sys/kernel/debug/tracing/events/latency/latency_preempt/hist

Changes from v3 as per comments from Daniel
  - A few coding style changes
  - Dropped the field 'cpu' from the event format fields.

TODO:
1. perf interface. Not sure if this is needed
2. Latency histograms - process wakeup latency

Binoy

Binoy Jayan (2):
  tracing: Add trace_irqsoff tracepoints
  tracing: Histogram for missed timer offsets

Daniel Wagner (1):
  tracing: Deference pointers without RCU checks

 include/linux/hrtimer.h             |  3 ++
 include/linux/rculist.h             | 36 +++++++++++++++++++++
 include/linux/tracepoint.h          |  4 +--
 include/trace/events/latency.h      | 64 +++++++++++++++++++++++++++++++++++++
 kernel/time/hrtimer.c               | 40 +++++++++++++++++++++++
 kernel/trace/trace_events_filter.c  |  4 +--
 kernel/trace/trace_events_trigger.c |  6 ++--
 kernel/trace/trace_irqsoff.c        | 42 ++++++++++++++++++++++++
 8 files changed, 192 insertions(+), 7 deletions(-)
 create mode 100644 include/trace/events/latency.h

-- 
The Qualcomm Innovation Center, Inc. is a member of the Code Aurora Forum,
a Linux Foundation Collaborative Project

[toc] | [next] | [standalone]

#1472396 — [PATCH v4 1/3] tracing: Deference pointers without RCU checks

From: Daniel Wagner <daniel.wagner@bmw-carit.de>

The tracepoint can't be used in code section where we are in the
middle of a state transition.

For example if we place a tracepoint inside start/stop_critical_section(),
lockdep complains with

[    0.035589] WARNING: CPU: 0 PID: 3 at kernel/locking/lockdep.c:3560 \
check_flags.part.36+0x1bc/0x210() [    0.036000] \
DEBUG_LOCKS_WARN_ON(current->softirqs_enabled) [    0.036000] Kernel panic - not \
syncing: panic_on_warn set ... [    0.036000]
[    0.036000] CPU: 0 PID: 3 Comm: ksoftirqd/0 Not tainted 4.0.0-rc7+ #460
[    0.036000] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS \
1.7.5-20140709_153950- 04/01/2014 [    0.036000]  ffffffff81f2463a ffff88007c93bb98 \
ffffffff81afb317 0000000000000001 [    0.036000]  ffffffff81f212b3 ffff88007c93bc18 \
ffffffff81af7bc2 ffff88007c93bbb8 [    0.036000]  ffffffff00000008 ffff88007c93bc28 \
ffff88007c93bbc8 000000000093bbd8 [    0.036000] Call Trace:
[    0.036000]  [<ffffffff81afb317>] dump_stack+0x4f/0x7b
[    0.036000]  [<ffffffff81af7bc2>] panic+0xc0/0x1e9
[    0.036000]  [<ffffffff81b07188>] ? _raw_spin_unlock_irqrestore+0x38/0x80
[    0.036000]  [<ffffffff81052a60>] warn_slowpath_common+0xc0/0xc0
[    0.036000]  [<ffffffff81057116>] ? __local_bh_enable+0x36/0x70
[    0.036000]  [<ffffffff81052aa6>] warn_slowpath_fmt+0x46/0x50
[    0.036000]  [<ffffffff810a468c>] check_flags.part.36+0x1bc/0x210
[    0.036000]  [<ffffffff810a5168>] lock_is_held+0x78/0x90
[    0.036000]  [<ffffffff81057116>] ? __local_bh_enable+0x36/0x70
[    0.036000]  [<ffffffff810588ab>] ? __do_softirq+0x3db/0x500
[    0.036000]  [<ffffffff81134495>] trace_preempt_on+0x255/0x260
[    0.036000]  [<ffffffff81081c0b>] preempt_count_sub+0xab/0xf0
[    0.036000]  [<ffffffff81057116>] __local_bh_enable+0x36/0x70
[    0.036000]  [<ffffffff810588ab>] __do_softirq+0x3db/0x500
[    0.036000]  [<ffffffff810589ef>] run_ksoftirqd+0x1f/0x60
[    0.036000]  [<ffffffff81079653>] smpboot_thread_fn+0x193/0x2a0
[    0.036000]  [<ffffffff810794c0>] ? SyS_setgroups+0x150/0x150
[    0.036000]  [<ffffffff81075312>] kthread+0xf2/0x110
[    0.036000]  [<ffffffff81b026b3>] ? wait_for_completion+0xc3/0x120
[    0.036000]  [<ffffffff81081c0b>] ? preempt_count_sub+0xab/0xf0
[    0.036000]  [<ffffffff81075220>] ? kthread_create_on_node+0x240/0x240
[    0.036000]  [<ffffffff81b07cc8>] ret_from_fork+0x58/0x90
[    0.036000]  [<ffffffff81075220>] ? kthread_create_on_node+0x240/0x240
[    0.036000] ---[ end Kernel panic - not syncing: panic_on_warn set ...

PeterZ was so kind to explain it to me what is happening:

"__local_bh_enable() tests if this is the last SOFTIRQ_OFFSET, if so it
tells lockdep softirqs are enabled with trace_softirqs_on() after that
we go an actually modify the preempt_count with preempt_count_sub().
Then in preempt_count_sub() you call into trace_preempt_on() if this
was the last preempt_count increment but you do that _before_ you
actually change the preempt_count with __preempt_count_sub() at this
point lockdep and preempt_count think the world differs and *boom*"

So the simplest way to avoid this is by disabling the consistency
checks.

We also need to take care of the iterating in trace_events_trigger.c
to avoid a splatter in conjunction with the hist trigger.

Signed-off-by: Daniel Wagner <daniel.wagner@bmw-carit.de>
Signed-off-by: Binoy Jayan <binoy.jayan@linaro.org>
---
 include/linux/rculist.h             | 36 ++++++++++++++++++++++++++++++++++++
 include/linux/tracepoint.h          |  4 ++--
 kernel/trace/trace_events_filter.c  |  4 ++--
 kernel/trace/trace_events_trigger.c |  6 +++---
 4 files changed, 43 insertions(+), 7 deletions(-)

diff --git a/include/linux/rculist.h b/include/linux/rculist.h
index 8beb98d..bee836b 100644
--- a/include/linux/rculist.h
+++ b/include/linux/rculist.h
@@ -279,6 +279,24 @@ static inline void list_splice_tail_init_rcu(struct list_head *list,
 	container_of(lockless_dereference(ptr), type, member)
 
 /**
+ * list_entry_rcu_notrace - get the struct for this entry (for tracing)
+ * @ptr:        the &struct list_head pointer.
+ * @type:       the type of the struct this is embedded in.
+ * @member:     the name of the list_head within the struct.
+ *
+ * This primitive may safely run concurrently with the _rcu list-mutation
+ * primitives such as list_add_rcu() as long as it's guarded by rcu_read_lock().
+ *
+ * This is the same as list_entry_rcu() except that it does
+ * not do any RCU debugging or tracing.
+ */
+#define list_entry_rcu_notrace(ptr, type, member) \
+({ \
+	typeof(*ptr) __rcu *__ptr = (typeof(*ptr) __rcu __force *)ptr; \
+	container_of((typeof(ptr))rcu_dereference_raw_notrace(__ptr), type, member); \
+})
+
+/**
  * Where are list_empty_rcu() and list_first_entry_rcu()?
  *
  * Implementing those functions following their counterparts list_empty() and
@@ -391,6 +409,24 @@ static inline void list_splice_tail_init_rcu(struct list_head *list,
 	     pos = list_entry_lockless(pos->member.next, typeof(*pos), member))
 
 /**
+ * list_for_each_entry_rcu_notrace	-	iterate over rcu list of given type (for tracing)
+ * @pos:	the type * to use as a loop cursor.
+ * @head:	the head for your list.
+ * @member:	the name of the list_head within the struct.
+ *
+ * This list-traversal primitive may safely run concurrently with
+ * the _rcu list-mutation primitives such as list_add_rcu()
+ * as long as the traversal is guarded by rcu_read_lock().
+ *
+ * This is the same as list_for_each_entry_rcu() except that it does
+ * not do any RCU debugging or tracing.
+ */
+#define list_for_each_entry_rcu_notrace(pos, head, member) \
+	for (pos = list_entry_rcu_notrace((head)->next, typeof(*pos), member); \
+		&pos->member != (head); \
+		pos = list_entry_rcu_notrace(pos->member.next, typeof(*pos), member))
+
+/**
  * list_for_each_entry_continue_rcu - continue iteration over list of given type
  * @pos:	the type * to use as a loop cursor.
  * @head:	the head for your list.
diff --git a/include/linux/tracepoint.h b/include/linux/tracepoint.h
index be586c6..d0e2a82 100644
--- a/include/linux/tracepoint.h
+++ b/include/linux/tracepoint.h
@@ -138,7 +138,7 @@ extern void syscall_unregfunc(void);
 			return;						\
 		prercu;							\
 		rcu_read_lock_sched_notrace();				\
-		it_func_ptr = rcu_dereference_sched((tp)->funcs);	\
+		it_func_ptr = rcu_dereference_raw_notrace((tp)->funcs);	\
 		if (it_func_ptr) {					\
 			do {						\
 				it_func = (it_func_ptr)->func;		\
@@ -189,7 +189,7 @@ extern void syscall_unregfunc(void);
 				TP_CONDITION(cond),,);			\
 		if (IS_ENABLED(CONFIG_LOCKDEP) && (cond)) {		\
 			rcu_read_lock_sched_notrace();			\
-			rcu_dereference_sched(__tracepoint_##name.funcs);\
+			rcu_dereference_raw_notrace(__tracepoint_##name.funcs);\
 			rcu_read_unlock_sched_notrace();		\
 		}							\
 	}								\
diff --git a/kernel/trace/trace_events_filter.c b/kernel/trace/trace_events_filter.c
index 9daa9b3..a00a8d5 100644
--- a/kernel/trace/trace_events_filter.c
+++ b/kernel/trace/trace_events_filter.c
@@ -608,11 +608,11 @@ int filter_match_preds(struct event_filter *filter, void *rec)
 	/*
 	 * n_preds, root and filter->preds are protect with preemption disabled.
 	 */
-	root = rcu_dereference_sched(filter->root);
+	root = rcu_dereference_raw_notrace(filter->root);
 	if (!root)
 		return 1;
 
-	data.preds = preds = rcu_dereference_sched(filter->preds);
+	data.preds = preds = rcu_dereference_raw_notrace(filter->preds);
 	ret = walk_pred_tree(preds, root, filter_match_preds_cb, &data);
 	WARN_ON(ret);
 	return data.match;
diff --git a/kernel/trace/trace_events_trigger.c b/kernel/trace/trace_events_trigger.c
index a975571..4489fb4 100644
--- a/kernel/trace/trace_events_trigger.c
+++ b/kernel/trace/trace_events_trigger.c
@@ -71,14 +71,14 @@ event_triggers_call(struct trace_event_file *file, void *rec)
 	if (list_empty(&file->triggers))
 		return tt;
 
-	list_for_each_entry_rcu(data, &file->triggers, list) {
+	list_for_each_entry_rcu_notrace(data, &file->triggers, list) {
 		if (data->paused)
 			continue;
 		if (!rec) {
 			data->ops->func(data, rec);
 			continue;
 		}
-		filter = rcu_dereference_sched(data->filter);
+		filter = rcu_dereference_raw_notrace(data->filter);
 		if (filter && !filter_match_preds(filter, rec))
 			continue;
 		if (event_command_post_trigger(data->cmd_ops)) {
@@ -111,7 +111,7 @@ event_triggers_post_call(struct trace_event_file *file,
 {
 	struct event_trigger_data *data;
 
-	list_for_each_entry_rcu(data, &file->triggers, list) {
+	list_for_each_entry_rcu_notrace(data, &file->triggers, list) {
 		if (data->paused)
 			continue;
 		if (data->cmd_ops->trigger_type & tt)
-- 
The Qualcomm Innovation Center, Inc. is a member of the Code Aurora Forum,
a Linux Foundation Collaborative Project

[toc] | [prev] | [next] | [standalone]

#1472398 — [PATCH v4 3/3] tracing: Histogram for missed timer offsets

Latencies of missed timer offsets. Generate a histogram of missed
timer offsets in microseconds. This will be a based along with irq
and preemption latencies to calculate the effective process wakeup
latencies.

The following filter(s) may be used

'hist:key=common_pid.execname'
'hist:key=common_pid.execname:val=toffset,hitcount'

Signed-off-by: Binoy Jayan <binoy.jayan@linaro.org>
---
 include/linux/hrtimer.h        |  3 +++
 include/trace/events/latency.h | 29 +++++++++++++++++++++++++++++
 kernel/time/hrtimer.c          | 40 ++++++++++++++++++++++++++++++++++++++++
 3 files changed, 72 insertions(+)

diff --git a/include/linux/hrtimer.h b/include/linux/hrtimer.h
index 5e00f80..e09de14 100644
--- a/include/linux/hrtimer.h
+++ b/include/linux/hrtimer.h
@@ -104,6 +104,9 @@ struct hrtimer {
 	struct hrtimer_clock_base	*base;
 	u8				state;
 	u8				is_rel;
+#if defined(CONFIG_PREEMPT_TRACER) || defined(CONFIG_IRQSOFF_TRACER)
+	ktime_t				praecox;
+#endif
 #ifdef CONFIG_TIMER_STATS
 	int				start_pid;
 	void				*start_site;
diff --git a/include/trace/events/latency.h b/include/trace/events/latency.h
index e89be12..7fca7cd 100644
--- a/include/trace/events/latency.h
+++ b/include/trace/events/latency.h
@@ -29,6 +29,35 @@ DEFINE_EVENT(latency_template, latency_preempt,
 	    TP_PROTO(int ltype, cycles_t latency),
 	    TP_ARGS(ltype, latency));
 
+TRACE_EVENT(latency_hrtimer_interrupt,
+
+	TP_PROTO(long long toffset, struct task_struct *curr,
+		struct task_struct *task),
+
+	TP_ARGS(toffset, curr, task),
+
+	TP_STRUCT__entry(
+		__field(long long,	toffset)
+		__array(char,		ccomm,	TASK_COMM_LEN)
+		__field(int,		cprio)
+		__array(char,		tcomm,	TASK_COMM_LEN)
+		__field(int,		tprio)
+	),
+
+	TP_fast_assign(
+		__entry->toffset = toffset;
+		memcpy(__entry->ccomm, curr->comm, TASK_COMM_LEN);
+		__entry->cprio  = curr->prio;
+		memcpy(__entry->tcomm, task != NULL ? task->comm : "<none>",
+			task != NULL ? TASK_COMM_LEN : 7);
+		__entry->tprio  = task != NULL ? task->prio : -1;
+	),
+
+	TP_printk("toffset=%lld curr=%s[%d] thread=%s[%d]",
+		__entry->toffset, __entry->ccomm, __entry->cprio,
+		__entry->tcomm, __entry->tprio)
+);
+
 #endif /* _TRACE_HIST_H */
 
 /* This part must be outside protection */
diff --git a/kernel/time/hrtimer.c b/kernel/time/hrtimer.c
index 9ba7c82..f3e1d92 100644
--- a/kernel/time/hrtimer.c
+++ b/kernel/time/hrtimer.c
@@ -53,9 +53,12 @@
 #include <asm/uaccess.h>
 
 #include <trace/events/timer.h>
+#include <trace/events/latency.h>
 
 #include "tick-internal.h"
 
+static enum hrtimer_restart hrtimer_wakeup(struct hrtimer *timer);
+
 /*
  * The timer bases:
  *
@@ -960,6 +963,39 @@ static inline ktime_t hrtimer_update_lowres(struct hrtimer *timer, ktime_t tim,
 	return tim;
 }
 
+static inline void trace_latency_hrtimer_mark_ts(struct hrtimer *timer,
+					 struct hrtimer_clock_base *new_base,
+					 ktime_t tim)
+{
+#if defined(CONFIG_PREEMPT_TRACER) || defined(CONFIG_IRQSOFF_TRACER)
+	if (trace_latency_hrtimer_interrupt_enabled()) {
+		ktime_t now = new_base->get_time();
+
+		if (ktime_to_ns(tim) < ktime_to_ns(now))
+			timer->praecox = now;
+		else
+			timer->praecox = ktime_set(0, 0);
+	}
+#endif
+}
+
+static inline void trace_latency_missed_hrtimer(struct hrtimer *timer,
+						ktime_t basenow)
+{
+#if defined(CONFIG_PREEMPT_TRACER) || defined(CONFIG_IRQSOFF_TRACER)
+	if (trace_latency_hrtimer_interrupt_enabled())
+		trace_latency_hrtimer_interrupt(
+			ktime_to_ns(ktime_sub(ktime_to_ns(timer->praecox) ?
+				timer->praecox : hrtimer_get_expires(timer),
+				basenow)),
+			current,
+			timer->function == hrtimer_wakeup ?
+				container_of(timer, struct hrtimer_sleeper,
+					timer)->task : NULL);
+#endif
+
+}
+
 /**
  * hrtimer_start_range_ns - (re)start an hrtimer on the current CPU
  * @timer:	the timer to be added
@@ -992,6 +1028,8 @@ void hrtimer_start_range_ns(struct hrtimer *timer, ktime_t tim,
 
 	timer_stats_hrtimer_set_start_info(timer);
 
+	trace_latency_hrtimer_mark_ts(timer, new_base, tim);
+
 	leftmost = enqueue_hrtimer(timer, new_base);
 	if (!leftmost)
 		goto unlock;
@@ -1284,6 +1322,8 @@ static void __hrtimer_run_queues(struct hrtimer_cpu_base *cpu_base, ktime_t now)
 
 			timer = container_of(node, struct hrtimer, node);
 
+			trace_latency_missed_hrtimer(timer, basenow);
+
 			/*
 			 * The immediate goal for using the softexpires is
 			 * minimizing wakeups, not running timers at the
-- 
The Qualcomm Innovation Center, Inc. is a member of the Code Aurora Forum,
a Linux Foundation Collaborative Project

[toc] | [prev] | [next] | [standalone]

#1472407 — Re: [PATCH v4 3/3] tracing: Histogram for missed timer offsets

Hi Binoy,

2016-08-30 19:28 GMT+09:00 Binoy Jayan <binoy.jayan@linaro.org>:
> Latencies of missed timer offsets. Generate a histogram of missed
> timer offsets in microseconds. This will be a based along with irq
> and preemption latencies to calculate the effective process wakeup
> latencies.
>
> The following filter(s) may be used
>
> 'hist:key=common_pid.execname'
> 'hist:key=common_pid.execname:val=toffset,hitcount'
>
> Signed-off-by: Binoy Jayan <binoy.jayan@linaro.org>
> ---
>  include/linux/hrtimer.h        |  3 +++
>  include/trace/events/latency.h | 29 +++++++++++++++++++++++++++++
>  kernel/time/hrtimer.c          | 40 ++++++++++++++++++++++++++++++++++++++++
>  3 files changed, 72 insertions(+)
>
> diff --git a/include/linux/hrtimer.h b/include/linux/hrtimer.h
> index 5e00f80..e09de14 100644
> --- a/include/linux/hrtimer.h
> +++ b/include/linux/hrtimer.h
> @@ -104,6 +104,9 @@ struct hrtimer {
>         struct hrtimer_clock_base       *base;
>         u8                              state;
>         u8                              is_rel;
> +#if defined(CONFIG_PREEMPT_TRACER) || defined(CONFIG_IRQSOFF_TRACER)
> +       ktime_t                         praecox;
> +#endif
>  #ifdef CONFIG_TIMER_STATS
>         int                             start_pid;
>         void                            *start_site;
> diff --git a/include/trace/events/latency.h b/include/trace/events/latency.h
> index e89be12..7fca7cd 100644
> --- a/include/trace/events/latency.h
> +++ b/include/trace/events/latency.h
> @@ -29,6 +29,35 @@ DEFINE_EVENT(latency_template, latency_preempt,
>             TP_PROTO(int ltype, cycles_t latency),
>             TP_ARGS(ltype, latency));
>
> +TRACE_EVENT(latency_hrtimer_interrupt,
> +
> +       TP_PROTO(long long toffset, struct task_struct *curr,
> +               struct task_struct *task),
> +
> +       TP_ARGS(toffset, curr, task),
> +
> +       TP_STRUCT__entry(
> +               __field(long long,      toffset)
> +               __array(char,           ccomm,  TASK_COMM_LEN)
> +               __field(int,            cprio)
> +               __array(char,           tcomm,  TASK_COMM_LEN)
> +               __field(int,            tprio)
> +       ),
> +
> +       TP_fast_assign(
> +               __entry->toffset = toffset;
> +               memcpy(__entry->ccomm, curr->comm, TASK_COMM_LEN);
> +               __entry->cprio  = curr->prio;
> +               memcpy(__entry->tcomm, task != NULL ? task->comm : "<none>",
> +                       task != NULL ? TASK_COMM_LEN : 7);
> +               __entry->tprio  = task != NULL ? task->prio : -1;
> +       ),
> +
> +       TP_printk("toffset=%lld curr=%s[%d] thread=%s[%d]",
> +               __entry->toffset, __entry->ccomm, __entry->cprio,
> +               __entry->tcomm, __entry->tprio)
> +);
> +
>  #endif /* _TRACE_HIST_H */
>
>  /* This part must be outside protection */
> diff --git a/kernel/time/hrtimer.c b/kernel/time/hrtimer.c
> index 9ba7c82..f3e1d92 100644
> --- a/kernel/time/hrtimer.c
> +++ b/kernel/time/hrtimer.c
> @@ -53,9 +53,12 @@
>  #include <asm/uaccess.h>
>
>  #include <trace/events/timer.h>
> +#include <trace/events/latency.h>
>
>  #include "tick-internal.h"
>
> +static enum hrtimer_restart hrtimer_wakeup(struct hrtimer *timer);
> +
>  /*
>   * The timer bases:
>   *
> @@ -960,6 +963,39 @@ static inline ktime_t hrtimer_update_lowres(struct hrtimer *timer, ktime_t tim,
>         return tim;
>  }
>
> +static inline void trace_latency_hrtimer_mark_ts(struct hrtimer *timer,
> +                                        struct hrtimer_clock_base *new_base,
> +                                        ktime_t tim)
> +{
> +#if defined(CONFIG_PREEMPT_TRACER) || defined(CONFIG_IRQSOFF_TRACER)
> +       if (trace_latency_hrtimer_interrupt_enabled()) {

You would better use unlikely() here.

> +               ktime_t now = new_base->get_time();
> +
> +               if (ktime_to_ns(tim) < ktime_to_ns(now))

Wouldn't we need to consider the case of wrap around?

> +                       timer->praecox = now;
> +               else
> +                       timer->praecox = ktime_set(0, 0);
> +       }
> +#endif
> +}
> +
> +static inline void trace_latency_missed_hrtimer(struct hrtimer *timer,
> +                                               ktime_t basenow)
> +{
> +#if defined(CONFIG_PREEMPT_TRACER) || defined(CONFIG_IRQSOFF_TRACER)
> +       if (trace_latency_hrtimer_interrupt_enabled())

Here, you'd better add unlikely() too.

> +               trace_latency_hrtimer_interrupt(
> +                       ktime_to_ns(ktime_sub(ktime_to_ns(timer->praecox) ?
> +                               timer->praecox : hrtimer_get_expires(timer),
> +                               basenow)),
> +                       current,
> +                       timer->function == hrtimer_wakeup ?
> +                               container_of(timer, struct hrtimer_sleeper,
> +                                       timer)->task : NULL);
> +#endif
> +
> +}
> +
>  /**
>   * hrtimer_start_range_ns - (re)start an hrtimer on the current CPU
>   * @timer:     the timer to be added
> @@ -992,6 +1028,8 @@ void hrtimer_start_range_ns(struct hrtimer *timer, ktime_t tim,
>
>         timer_stats_hrtimer_set_start_info(timer);
>
> +       trace_latency_hrtimer_mark_ts(timer, new_base, tim);

Hmm, since these calls are not actual tracepoints, it should not start
with "trace_".
I would like to ask you to use other function name, like
hrtimer_mark_start_timestamp()

> +
>         leftmost = enqueue_hrtimer(timer, new_base);
>         if (!leftmost)
>                 goto unlock;
> @@ -1284,6 +1322,8 @@ static void __hrtimer_run_queues(struct hrtimer_cpu_base *cpu_base, ktime_t now)
>
>                         timer = container_of(node, struct hrtimer, node);
>
> +                       trace_latency_missed_hrtimer(timer, basenow);

Here, too. hrtimer_expired_latency() etc.

BTW, I think "missed" is a bit misleadable, since the timer itself is
not missed,
it may be just not in time. :)

Thank you,

> +
>                         /*
>                          * The immediate goal for using the softexpires is
>                          * minimizing wakeups, not running timers at the
> --
> The Qualcomm Innovation Center, Inc. is a member of the Code Aurora Forum,
> a Linux Foundation Collaborative Project
>



-- 
Masami Hiramatsu

[toc] | [prev] | [next] | [standalone]

#1475117 — Re: [PATCH v4 3/3] tracing: Histogram for missed timer offsets

On 30 August 2016 at 16:20, Masami Hiramatsu
<masami.hiramatsu@linaro.org> wrote:
> Hi Binoy,
>>
>> +static inline void trace_latency_hrtimer_mark_ts(struct hrtimer *timer,
>> +                                        struct hrtimer_clock_base *new_base,
>> +                                        ktime_t tim)
>> +{
>> +#if defined(CONFIG_PREEMPT_TRACER) || defined(CONFIG_IRQSOFF_TRACER)
>> +       if (trace_latency_hrtimer_interrupt_enabled()) {
>
> You would better use unlikely() here.
>
>> +               ktime_t now = new_base->get_time();
>> +
>> +               if (ktime_to_ns(tim) < ktime_to_ns(now))
>
> Wouldn't we need to consider the case of wrap around?
>
>> +                       timer->praecox = now;
>> +               else
>> +                       timer->praecox = ktime_set(0, 0);
>> +       }
>> +#endif
>> +}

Hi Masami,

I always see these values to be relative and not absolute time. I
found 'praecox' to be always zero during test.
What do you think.

Binoy

[toc] | [prev] | [next] | [standalone]

#1475301 — Re: [PATCH v4 3/3] tracing: Histogram for missed timer offsets

2016-09-02 21:41 GMT+09:00 Binoy Jayan <binoy.jayan@linaro.org>:
> On 30 August 2016 at 16:20, Masami Hiramatsu
> <masami.hiramatsu@linaro.org> wrote:
>> Hi Binoy,
>>>
>>> +static inline void trace_latency_hrtimer_mark_ts(struct hrtimer *timer,
>>> +                                        struct hrtimer_clock_base *new_base,
>>> +                                        ktime_t tim)
>>> +{
>>> +#if defined(CONFIG_PREEMPT_TRACER) || defined(CONFIG_IRQSOFF_TRACER)
>>> +       if (trace_latency_hrtimer_interrupt_enabled()) {
>>
>> You would better use unlikely() here.
>>
>>> +               ktime_t now = new_base->get_time();
>>> +
>>> +               if (ktime_to_ns(tim) < ktime_to_ns(now))
>>
>> Wouldn't we need to consider the case of wrap around?
>>
>>> +                       timer->praecox = now;
>>> +               else
>>> +                       timer->praecox = ktime_set(0, 0);
>>> +       }
>>> +#endif
>>> +}
>
> Hi Masami,
>
> I always see these values to be relative and not absolute time. I
> found 'praecox' to be always zero during test.
> What do you think.

Ah, right. Since "tim" is expire time (timer target), that should
always be "now + x"
(x is enough larger than how long setting the hrtimer takes). Or,
hrtimer expires
before finished to set. :)

Thank you,
-- 
Masami Hiramatsu

[toc] | [prev] | [next] | [standalone]

#1472504 — Re: [PATCH v4 3/3] tracing: Histogram for missed timer offsets

On Tue, 30 Aug 2016 15:58:44 +0530
Binoy Jayan <binoy.jayan@linaro.org> wrote:

> +TRACE_EVENT(latency_hrtimer_interrupt,
> +
> +	TP_PROTO(long long toffset, struct task_struct *curr,
> +		struct task_struct *task),
> +
> +	TP_ARGS(toffset, curr, task),
> +
> +	TP_STRUCT__entry(
> +		__field(long long,	toffset)
> +		__array(char,		ccomm,	TASK_COMM_LEN)

Can curr be different than current? If not, lets not record it.

-- Steve


> +		__field(int,		cprio)
> +		__array(char,		tcomm,	TASK_COMM_LEN)
> +		__field(int,		tprio)
> +	),

[toc] | [prev] | [next] | [standalone]

#1473352 — Re: [PATCH v4 3/3] tracing: Histogram for missed timer offsets

On 30 August 2016 at 19:45, Steven Rostedt <rostedt@goodmis.org> wrote:
> On Tue, 30 Aug 2016 15:58:44 +0530
> Binoy Jayan <binoy.jayan@linaro.org> wrote:
>
>> +
>> +     TP_STRUCT__entry(
>> +             __field(long long,      toffset)
>> +             __array(char,           ccomm,  TASK_COMM_LEN)
>
> Can curr be different than current? If not, lets not record it.
>
> -- Steve
>

Hi Steve,

If my understanding is right, I think both are not the same. The
predefined field relates to the current
process which was interrupted by the hrtimer. This I guess does not
have a meaning in this context.
Mostly it is the idle process which is interrupted by the hrtimer. But
the ccomm field refers to the task
woken up by the process. The latencies are measured for this task. So
I it is needed.

-Binoy

[toc] | [prev] | [next] | [standalone]

#1473427 — Re: [PATCH v4 3/3] tracing: Histogram for missed timer offsets

On Wed, 31 Aug 2016 17:04:54 +0530
Binoy Jayan <binoy.jayan@linaro.org> wrote:

> On 30 August 2016 at 19:45, Steven Rostedt <rostedt@goodmis.org> wrote:
> > On Tue, 30 Aug 2016 15:58:44 +0530
> > Binoy Jayan <binoy.jayan@linaro.org> wrote:
> >  
> >> +
> >> +     TP_STRUCT__entry(
> >> +             __field(long long,      toffset)
> >> +             __array(char,           ccomm,  TASK_COMM_LEN)  
> >
> > Can curr be different than current? If not, lets not record it.
> >
> > -- Steve
> >  
> 
> Hi Steve,
> 
> If my understanding is right, I think both are not the same. The
> predefined field relates to the current
> process which was interrupted by the hrtimer. This I guess does not
> have a meaning in this context.
> Mostly it is the idle process which is interrupted by the hrtimer. But
> the ccomm field refers to the task
> woken up by the process. The latencies are measured for this task. So
> I it is needed.
> 

Then what is tcomm?

-- Steve

[toc] | [prev] | [next] | [standalone]

#1472434

Hi Binoy,

On 08/30/2016 12:28 PM, Binoy Jayan wrote:
> Examples of triggers:
> echo 'hist:key=latency.log2:val=hitcount:sort=latency' > /sys/kernel/debug/tracing/events/latency/latency_preempt/trigger
> echo 'hist:key=cpu,latency:val=hitcount:sort=latency if cpu==1' > /sys/kernel/debug/tracing/events/latency/latency_preempt/trigger
> echo 'hist:key=ltype,cpu:val=latency:sort=ltype,cpu if ltype==0' > /sys/kernel/debug/tracing/events/latency/latency_preempt/trigger
>
> Histogram output:
> cat /sys/kernel/debug/tracing/events/latency/latency_preempt/hist

Could you also add couple of test cases to 
tools/testing/selftests/ftrace/test.d/trigger?

Especially the sorting thing you mentioned in the other mail? Obviously 
first we need to figure out what is the expected behavior of it :)

cheers,
daniel

[toc] | [prev] | [next] | [standalone]

#1472442

2016-08-30 20:39 GMT+09:00 Daniel Wagner <daniel.wagner@bmw-carit.de>:
> Hi Binoy,
>
> On 08/30/2016 12:28 PM, Binoy Jayan wrote:
>>
>> Examples of triggers:
>> echo 'hist:key=latency.log2:val=hitcount:sort=latency' >
>> /sys/kernel/debug/tracing/events/latency/latency_preempt/trigger
>> echo 'hist:key=cpu,latency:val=hitcount:sort=latency if cpu==1' >
>> /sys/kernel/debug/tracing/events/latency/latency_preempt/trigger
>> echo 'hist:key=ltype,cpu:val=latency:sort=ltype,cpu if ltype==0' >
>> /sys/kernel/debug/tracing/events/latency/latency_preempt/trigger
>>
>> Histogram output:
>> cat /sys/kernel/debug/tracing/events/latency/latency_preempt/hist
>
>
> Could you also add couple of test cases to
> tools/testing/selftests/ftrace/test.d/trigger?
>
> Especially the sorting thing you mentioned in the other mail? Obviously
> first we need to figure out what is the expected behavior of it :)

Good idea! And also, for both patch, could you show the output examples?
It might help people to imagine what it provides.

Thank you,



-- 
Masami Hiramatsu

[toc] | [prev] | [standalone]

Back to top | Article view | linux.kernel

csiph-web