[PATCH RFC] trace: correct off by one preempt counter while recording the trace-event

[PATCH RFC] trace: correct off by one preempt counter while recording the trace-event

[Sebastian Andrzej Siewior]

Trace events like raw_syscalls show always a preempt code of one. The
reason is that on PREEMPT kernels rcu_read_lock_sched_notrace()
increases the preemption counter and the function recording the counter
is caller within the RCU section.

Signed-off-by: Sebastian Andrzej Siewior <bigeasy@linutronix.de>
---
I am not sure if this is the only spot that needs correction of the
preemption counter. If it is it could be corrected directly in
trace_event_buffer_reserve().

 include/linux/tracepoint.h  | 13 +++++++++++++
 kernel/trace/trace_events.c |  2 +-
 2 files changed, 14 insertions(+), 1 deletion(-)

diff --git a/include/linux/tracepoint.h b/include/linux/tracepoint.h
index be586c632a0c..12cb3bb40c1c 100644
--- a/include/linux/tracepoint.h
+++ b/include/linux/tracepoint.h
@@ -33,6 +33,19 @@ struct trace_enum_map {
 
 #define TRACEPOINT_DEFAULT_PRIO	10
 
+/*
+ * The preempt count recorded in trace_event_raw_event_# are off by one due to
+ * rcu_read_lock_sched_notrace() in __DO_TRACE. This is corrected here.
+ */
+static inline int event_preempt_count(void)
+{
+#ifdef CONFIG_PREEMPT
+	return preempt_count() - 1;
+#else
+	return 0;
+#endif
+}
+
 extern int
 tracepoint_probe_register(struct tracepoint *tp, void *probe, void *data);
 extern int
diff --git a/kernel/trace/trace_events.c b/kernel/trace/trace_events.c
index 52c4fffaddcd..90b40cf6ec98 100644
--- a/kernel/trace/trace_events.c
+++ b/kernel/trace/trace_events.c
@@ -245,7 +245,7 @@ void *trace_event_buffer_reserve(struct trace_event_buffer *fbuffer,
 		return NULL;
 
 	local_save_flags(fbuffer->flags);
-	fbuffer->pc = preempt_count();
+	fbuffer->pc = event_preempt_count();
 	fbuffer->trace_file = trace_file;
 
 	fbuffer->event =
-- 
2.8.1

Re: [PATCH RFC] trace: correct off by one preempt counter while recording the trace-event

[Steven Rostedt]

On Wed, 25 May 2016 15:25:37 +0200
Sebastian Andrzej Siewior <bigeasy@linutronix.de> wrote:

> ---
> I am not sure if this is the only spot that needs correction of the
> preemption counter. If it is it could be corrected directly in
> trace_event_buffer_reserve().
> 
>  include/linux/tracepoint.h  | 13 +++++++++++++
>  kernel/trace/trace_events.c |  2 +-
>  2 files changed, 14 insertions(+), 1 deletion(-)
> 
> diff --git a/include/linux/tracepoint.h b/include/linux/tracepoint.h
> index be586c632a0c..12cb3bb40c1c 100644
> --- a/include/linux/tracepoint.h
> +++ b/include/linux/tracepoint.h
> @@ -33,6 +33,19 @@ struct trace_enum_map {
>  
>  #define TRACEPOINT_DEFAULT_PRIO	10
>  
> +/*
> + * The preempt count recorded in trace_event_raw_event_# are off by one due to
> + * rcu_read_lock_sched_notrace() in __DO_TRACE. This is corrected here.
> + */
> +static inline int event_preempt_count(void)
> +{
> +#ifdef CONFIG_PREEMPT
> +	return preempt_count() - 1;
> +#else
> +	return 0;
> +#endif
> +}
> +
>  extern int
>  tracepoint_probe_register(struct tracepoint *tp, void *probe, void *data);
>  extern int
> diff --git a/kernel/trace/trace_events.c b/kernel/trace/trace_events.c
> index 52c4fffaddcd..90b40cf6ec98 100644
> --- a/kernel/trace/trace_events.c
> +++ b/kernel/trace/trace_events.c
> @@ -245,7 +245,7 @@ void *trace_event_buffer_reserve(struct trace_event_buffer *fbuffer,
>  		return NULL;
>  
>  	local_save_flags(fbuffer->flags);
> -	fbuffer->pc = preempt_count();
> +	fbuffer->pc = event_preempt_count();
>  	fbuffer->trace_file = trace_file;
>  
>  	fbuffer->event =

Hmm, what about this? This is a bit cleaner IMO.

-- Steve

>From c95e5401296b643d3ad8a331b23e2976459cdf11 Mon Sep 17 00:00:00 2001
From: "Steven Rostedt (Red Hat)" <rostedt@goodmis.org>
Date: Fri, 17 Jun 2016 17:40:58 -0400
Subject: [PATCH] tracing: Show the preempt count of when the event was called

Because tracepoint callbacks are done with preemption enabled, the trace
events are always called with preempt disable due to the
rcu_read_lock_sched_notrace() in __DO_TRACE(). This causes the preempt count
shown in the recorded trace event to be inaccurate. It is always one more
that what the preempt_count was when the tracepoint was called.

If CONFIG_PREEMPT is enabled, subtract 1 from the preempt_count before
recording it in the trace buffer.

Link: http://lkml.kernel.org/r/20160525132537.GA10808@linutronix.de

Reported-by: Sebastian Andrzej Siewior <bigeasy@linutronix.de>
Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
---
 kernel/trace/trace_events.c | 8 ++++++++
 1 file changed, 8 insertions(+)

diff --git a/kernel/trace/trace_events.c b/kernel/trace/trace_events.c
index fd449eb138cf..03c0a48c3ac4 100644
--- a/kernel/trace/trace_events.c
+++ b/kernel/trace/trace_events.c
@@ -261,6 +261,14 @@ void *trace_event_buffer_reserve(struct trace_event_buffer *fbuffer,
 
 	local_save_flags(fbuffer->flags);
 	fbuffer->pc = preempt_count();
+	/*
+	 * If CONFIG_PREEMPT is enabled, then the tracepoint itself disables
+	 * preemption (adding one to the preempt_count). Since we are
+	 * interested in the preempt_count at the time the tracepoint was
+	 * hit, we need to subtract one to offset the increment.
+	 */
+	if (IS_ENABLED(CONFIG_PREEMPT))
+		fbuffer->pc--;
 	fbuffer->trace_file = trace_file;
 
 	fbuffer->event =
-- 
1.9.3