Skip to contentSkip to conversation

trace: correct off by one preempt counter while recording the trace-event

RFC PATCH In review Sebastian Andrzej Siewior 2 participants 2 messages May 25, 2016 – Jun 17, 2016 Tracing

lore
Share & tools
lore

Sebastian Andrzej Siewior

author
#0 lore raw

RFC PATCH 1/1 trace: correct off by one preempt counter while recording the trace-event

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 <[email protected]>

---
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(-)
include/linux/tracepoint.h +13 -0
index be586c632a0c..12cb3bb40c1c 100644
@@ -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
kernel/trace/trace_events.c +1 -1
index 52c4fffaddcd..90b40cf6ec98 100644
@@ -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 =
Signature · 1 line
2.8.1
maintainer
#1 lore raw
Quoted 38 lines · On Wed, 25 May 2016 15:25:37 +0200 Sebastian Andrzej Siewior…

---
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(-)
include/linux/tracepoint.h +13 -0
index be586c632a0c..12cb3bb40c1c 100644
@@ -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
kernel/trace/trace_events.c +0 -0
index 52c4fffaddcd..90b40cf6ec98 100644

kernel/trace/trace_events.c void *trace_event_buffer_reserve(struct trace_event_buffer *fbuffer, · line 251

Quoted 8 lines
kernel/trace/trace_events.c +1 -1
@@ -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

Quoted 1 line

From c95e5401296b643d3ad8a331b23e2976459cdf11 Mon Sep 17 00:00:00 2001

From: "Steven Rostedt (Red Hat)" <[email protected]>
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/[email protected] open here
Reported-by Sebastian Andrzej Siewior <[email protected]>
Signed-off-by Steven Rostedt <[email protected]>
---
 kernel/trace/trace_events.c | 8 ++++++++
 1 file changed, 8 insertions(+)
kernel/trace/trace_events.c +8 -0
index fd449eb138cf..03c0a48c3ac4 100644
@@ -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 =
Signature · 1 line
1.9.3