[RFC][PATCH 0/2] tracing: Add conditional to tracepoints

[RFC][PATCH 0/2] tracing: Add conditional to tracepoints

[Steven Rostedt]

This is an RFC that adds the TP_CONDITION() to the TRACE_EVENT()
code.

There are certain cases that a tracepoint only makes sense if
a specific condition is met. But because we do not want to dirty
the fast path (the non tracing case) with if statements that are
there only to avoid tracing, we just pass the condition variables
to the tracepoint, and let the user filter them out if needed.

A perfect example is the tracepoint sched_wakeup. It traces all
calls to try_to_wake_up() even if it fails to wake up. But if we add:

	if (success)
		trace_sched_wakeup(p);

We have that "if (success)" tested for every time we call try_to_wake_up().
Even when tracing is not (or never will be) enabled.

This patch set adds a variant TRACE_EVENT_CONDITIONAL()
(and DECLARE_EVENT_CLASS_CONDITIONAL()) that has a "cond" argument.
This argument is encapsulated with "TP_CONDITIONAL()" which turns into:

	if (!cond)
		return;

This is placed inside the called tracepoint routine, and is only tested
when the trace is enabled. Otherwise it is a nop as tracepoints normally
are when disabled.

Note, another variant of this, is to move the test directly into the
_DO_TRACE() macro, and not call any registered event callbacks. This would
even speed it up faster when tracing is enabled. I did not do this
orginially because I just thought of it now as I wrote this change log ;-)
I'm posting this version now just in case people prefer it instead.

The following patches are in:

  git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/linux-2.6-trace.git

    branch: rfc/trace-conditional


Steven Rostedt (2):
      tracing: Add TRACE_EVENT_CONDITIONAL()
      tracing: Only trace sched_wakeup if it actually work something up

----
 include/linux/tracepoint.h   |    3 ++
 include/trace/define_trace.h |    6 +++
 include/trace/events/sched.h |   12 +++---
 include/trace/ftrace.h       |   70 +++++++++++++++++++++++++++++++----------
 4 files changed, 68 insertions(+), 23 deletions(-)

[RFC][PATCH 1/2] [PATCH 1/2] tracing: Add TRACE_EVENT_CONDITIONAL()

[Steven Rostedt]

[-- Attachment #1: 0001-tracing-Add-TRACE_EVENT_CONDITIONAL.patch --]
[-- Type: text/plain, Size: 9574 bytes --]

From: Steven Rostedt <srostedt@redhat.com>

There are instances in the kernel that we only want to trace
a tracepoint when a certain condition is set. But we do not
want to test for that condition in the core kernel.
If we test for that condition before calling the tracepoin, then
we will be performing that test even when tracing is not enabled.
This is 99.99% of the time.

We currently can just filter out on that condition, but that happens
after we write to the trace buffer. We just wasted time writing to
the ring buffer for an event we never cared about.

This patch adds:

   TRACE_EVENT_CONDITION() and DECLARE_TRACE_CLASS_CONDITION()

These have a new TP_CONDITION() argument that comes right after
the TP_ARGS().  This condition can use the parameters of the
TRACE_EVENT() to determine if the tracepoint should be traced
or not. The TP_CONDITION() will be placed in a if (cond) trace;

For example, for the tracepoint sched_wakeup, it is useless to
trace an wakeup event where the caller never actually work
anything up (success = 0). So adding:

	TP_CONDITION(success),

which uses the "success" parameter of the wakeup tracepoint
will have it only trace when we have successfully woken up a
task.

Cc: Arjan van de Ven <arjan@infradead.org>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Thomas Gleixner <tglx@linutronix.de>
Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
---
 include/linux/tracepoint.h   |    3 ++
 include/trace/define_trace.h |    6 +++
 include/trace/events/sched.h |    2 +-
 include/trace/ftrace.h       |   70 +++++++++++++++++++++++++++++++----------
 4 files changed, 63 insertions(+), 18 deletions(-)

diff --git a/include/linux/tracepoint.h b/include/linux/tracepoint.h
index 5a6074f..380c807 100644
--- a/include/linux/tracepoint.h
+++ b/include/linux/tracepoint.h
@@ -344,12 +344,15 @@ do_trace:								\
  * TRACE_EVENT_FN to perform any (un)registration work.
  */
 
+#define DECLARE_EVENT_CLASS_CONDITION(name, proto, args, cond, tstruct, assign, print)
 #define DECLARE_EVENT_CLASS(name, proto, args, tstruct, assign, print)
 #define DEFINE_EVENT(template, name, proto, args)		\
 	DECLARE_TRACE(name, PARAMS(proto), PARAMS(args))
 #define DEFINE_EVENT_PRINT(template, name, proto, args, print)	\
 	DECLARE_TRACE(name, PARAMS(proto), PARAMS(args))
 
+#define TRACE_EVENT_CONDITION(name, proto, args, cond, struct, assign, print) \
+	DECLARE_TRACE(name, PARAMS(proto), PARAMS(args))
 #define TRACE_EVENT(name, proto, args, struct, assign, print)	\
 	DECLARE_TRACE(name, PARAMS(proto), PARAMS(args))
 #define TRACE_EVENT_FN(name, proto, args, struct,		\
diff --git a/include/trace/define_trace.h b/include/trace/define_trace.h
index 1dfab54..89cf844 100644
--- a/include/trace/define_trace.h
+++ b/include/trace/define_trace.h
@@ -26,6 +26,10 @@
 #define TRACE_EVENT(name, proto, args, tstruct, assign, print)	\
 	DEFINE_TRACE(name)
 
+#undef TRACE_EVENT_CONDITION
+#define TRACE_EVENT_CONDITION(name, proto, args, cond, tstruct, assign, print) \
+	DEFINE_TRACE(name)
+
 #undef TRACE_EVENT_FN
 #define TRACE_EVENT_FN(name, proto, args, tstruct,		\
 		assign, print, reg, unreg)			\
@@ -75,7 +79,9 @@
 
 #undef TRACE_EVENT
 #undef TRACE_EVENT_FN
+#undef TRACE_EVENT_CONDITION
 #undef DECLARE_EVENT_CLASS
+#undef DECLARE_EVENT_CLASS_CONDITION
 #undef DEFINE_EVENT
 #undef DEFINE_EVENT_PRINT
 #undef TRACE_HEADER_MULTI_READ
diff --git a/include/trace/events/sched.h b/include/trace/events/sched.h
index f633478..67456f0 100644
--- a/include/trace/events/sched.h
+++ b/include/trace/events/sched.h
@@ -10,7 +10,7 @@
 /*
  * Tracepoint for calling kthread_stop, performed to end a kthread:
  */
-TRACE_EVENT(sched_kthread_stop,
+TRACE_EVENT_CONDITION(sched_kthread_stop,
 
 	TP_PROTO(struct task_struct *t),
 
diff --git a/include/trace/ftrace.h b/include/trace/ftrace.h
index e718a91..30f5da0 100644
--- a/include/trace/ftrace.h
+++ b/include/trace/ftrace.h
@@ -29,14 +29,41 @@
  */
 #undef TRACE_EVENT
 #define TRACE_EVENT(name, proto, args, tstruct, assign, print) \
-	DECLARE_EVENT_CLASS(name,			       \
+	TRACE_EVENT_CONDITION(name,			       \
 			     PARAMS(proto),		       \
 			     PARAMS(args),		       \
+			     TP_CONDITION(1),		       \
+			     PARAMS(tstruct),		       \
+			     PARAMS(assign),		       \
+			     PARAMS(print));
+
+#undef TRACE_EVENT_CONDITION
+#define TRACE_EVENT_CONDITION(name, proto, args, cond, tstruct, assign, print) \
+	DECLARE_EVENT_CLASS_CONDITION(name,			\
+			     PARAMS(proto),		       \
+			     PARAMS(args),		       \
+			     PARAMS(cond),		       \
 			     PARAMS(tstruct),		       \
 			     PARAMS(assign),		       \
 			     PARAMS(print));		       \
 	DEFINE_EVENT(name, name, PARAMS(proto), PARAMS(args));
 
+#undef DECLARE_EVENT_CLASS
+#define DECLARE_EVENT_CLASS(name, proto, args, tstruct, assign, print)	\
+	DECLARE_EVENT_CLASS_CONDITION(name,				\
+		PARAMS(proto),						\
+		PARAMS(args),						\
+		TP_CONDITION(1),					\
+		PARAMS(tstruct),					\
+		PARAMS(assign),						\
+		PARAMS(print))
+
+/*
+ * Just to shorten the name, we use _DECLARE_EVENT_CLASS instead
+ * of DECLARE_EVENT_CLASS_CONDITION.
+ */
+#undef DECLARE_EVENT_CLASS_CONDITION
+#define DECLARE_EVENT_CLASS_CONDITION _DECLARE_EVENT_CLASS
 
 #undef __field
 #define __field(type, item)		type	item;
@@ -56,8 +83,13 @@
 #undef TP_STRUCT__entry
 #define TP_STRUCT__entry(args...) args
 
-#undef DECLARE_EVENT_CLASS
-#define DECLARE_EVENT_CLASS(name, proto, args, tstruct, assign, print)	\
+#undef TP_CONDITION
+#define TP_CONDITION(cond)			\
+	if (!(cond))				\
+		return;
+
+#undef _DECLARE_EVENT_CLASS
+#define _DECLARE_EVENT_CLASS(name, proto, args, cond, tstruct, assign, print) \
 	struct ftrace_raw_##name {					\
 		struct trace_entry	ent;				\
 		tstruct							\
@@ -120,8 +152,8 @@
 #undef __string
 #define __string(item, src) __dynamic_array(char, item, -1)
 
-#undef DECLARE_EVENT_CLASS
-#define DECLARE_EVENT_CLASS(call, proto, args, tstruct, assign, print)	\
+#undef _DECLARE_EVENT_CLASS
+#define _DECLARE_EVENT_CLASS(call, proto, args, cond, tstruct, assign, print) \
 	struct ftrace_data_offsets_##call {				\
 		tstruct;						\
 	};
@@ -208,8 +240,8 @@
 #undef __print_hex
 #define __print_hex(buf, buf_len) ftrace_print_hex_seq(p, buf, buf_len)
 
-#undef DECLARE_EVENT_CLASS
-#define DECLARE_EVENT_CLASS(call, proto, args, tstruct, assign, print)	\
+#undef _DECLARE_EVENT_CLASS
+#define _DECLARE_EVENT_CLASS(call, proto, args, cond, tstruct, assign, print) \
 static notrace enum print_line_t					\
 ftrace_raw_output_##call(struct trace_iterator *iter, int flags,	\
 			 struct trace_event *trace_event)		\
@@ -314,8 +346,8 @@ static struct trace_event_functions ftrace_event_type_funcs_##call = {	\
 #undef __string
 #define __string(item, src) __dynamic_array(char, item, -1)
 
-#undef DECLARE_EVENT_CLASS
-#define DECLARE_EVENT_CLASS(call, proto, args, tstruct, func, print)	\
+#undef _DECLARE_EVENT_CLASS
+#define _DECLARE_EVENT_CLASS(call, proto, args, cond, tstruct, func, print) \
 static int notrace							\
 ftrace_define_fields_##call(struct ftrace_event_call *event_call)	\
 {									\
@@ -362,8 +394,8 @@ ftrace_define_fields_##call(struct ftrace_event_call *event_call)	\
 #undef __string
 #define __string(item, src) __dynamic_array(char, item, strlen(src) + 1)
 
-#undef DECLARE_EVENT_CLASS
-#define DECLARE_EVENT_CLASS(call, proto, args, tstruct, assign, print)	\
+#undef _DECLARE_EVENT_CLASS
+#define _DECLARE_EVENT_CLASS(call, proto, args, cond, tstruct, assign, print) \
 static inline notrace int ftrace_get_offsets_##call(			\
 	struct ftrace_data_offsets_##call *__data_offsets, proto)       \
 {									\
@@ -491,8 +523,8 @@ static inline notrace int ftrace_get_offsets_##call(			\
 #undef TP_perf_assign
 #define TP_perf_assign(args...)
 
-#undef DECLARE_EVENT_CLASS
-#define DECLARE_EVENT_CLASS(call, proto, args, tstruct, assign, print)	\
+#undef _DECLARE_EVENT_CLASS
+#define _DECLARE_EVENT_CLASS(call, proto, args, cond, tstruct, assign, print) \
 									\
 static notrace void							\
 ftrace_raw_event_##call(void *__data, proto)				\
@@ -506,6 +538,8 @@ ftrace_raw_event_##call(void *__data, proto)				\
 	int __data_size;						\
 	int pc;								\
 									\
+	cond;								\
+									\
 	local_save_flags(irq_flags);					\
 	pc = preempt_count();						\
 									\
@@ -556,8 +590,8 @@ static inline void ftrace_test_probe_##call(void)			\
 #undef TP_printk
 #define TP_printk(fmt, args...) "\"" fmt "\", "  __stringify(args)
 
-#undef DECLARE_EVENT_CLASS
-#define DECLARE_EVENT_CLASS(call, proto, args, tstruct, assign, print)	\
+#undef _DECLARE_EVENT_CLASS
+#define _DECLARE_EVENT_CLASS(call, proto, args, cond, tstruct, assign, print) \
 _TRACE_PERF_PROTO(call, PARAMS(proto));					\
 static const char print_fmt_##call[] = print;				\
 static struct ftrace_event_class __used event_class_##call = {		\
@@ -690,8 +724,8 @@ __attribute__((section("_ftrace_events"))) event_##call = {		\
 #undef __perf_count
 #define __perf_count(c) __count = (c)
 
-#undef DECLARE_EVENT_CLASS
-#define DECLARE_EVENT_CLASS(call, proto, args, tstruct, assign, print)	\
+#undef _DECLARE_EVENT_CLASS
+#define _DECLARE_EVENT_CLASS(call, proto, args, cond, tstruct, assign, print) \
 static notrace void							\
 perf_trace_##call(void *__data, proto)					\
 {									\
@@ -705,6 +739,8 @@ perf_trace_##call(void *__data, proto)					\
 	int __data_size;						\
 	int rctx;							\
 									\
+	cond;								\
+									\
 	perf_fetch_caller_regs(&__regs);				\
 									\
 	__data_size = ftrace_get_offsets_##call(&__data_offsets, args); \
-- 
1.7.2.3

Re: [RFC][PATCH 1/2] [PATCH 1/2] tracing: Add TRACE_EVENT_CONDITIONAL()

[David Daney]

On 12/02/2010 02:36 PM, Steven Rostedt wrote:
> From: Steven Rostedt<srostedt@redhat.com>
>
> There are instances in the kernel that we only want to trace
> a tracepoint when a certain condition is set. But we do not
> want to test for that condition in the core kernel.
> If we test for that condition before calling the tracepoin, then
> we will be performing that test even when tracing is not enabled.
> This is 99.99% of the time.
>
> We currently can just filter out on that condition, but that happens
> after we write to the trace buffer. We just wasted time writing to
> the ring buffer for an event we never cared about.
>
> This patch adds:
>
>     TRACE_EVENT_CONDITION() and DECLARE_TRACE_CLASS_CONDITION()
>
> These have a new TP_CONDITION() argument that comes right after
> the TP_ARGS().  This condition can use the parameters of the
> TRACE_EVENT() to determine if the tracepoint should be traced
> or not. The TP_CONDITION() will be placed in a if (cond) trace;
>
> For example, for the tracepoint sched_wakeup, it is useless to
> trace an wakeup event where the caller never actually work
> anything up (success = 0). So adding:
                       ^^^
                    s/=/==/

As much as I hate to be a pedant, I would suggest changing this change 
log for the sake of clarity.

David Daney

Re: [RFC][PATCH 1/2] [PATCH 1/2] tracing: Add TRACE_EVENT_CONDITIONAL()

[Steven Rostedt]

On Thu, 2010-12-02 at 14:58 -0800, David Daney wrote:
> On 12/02/2010 02:36 PM, Steven Rostedt wrote:

> > For example, for the tracepoint sched_wakeup, it is useless to
> > trace an wakeup event where the caller never actually work
> > anything up (success = 0). So adding:
>                        ^^^
>                     s/=/==/
> 
> As much as I hate to be a pedant, I would suggest changing this change 
> log for the sake of clarity.

Eek! Yeah I'll fix that, along with s/work anything/woke anything/.

Thanks,

-- Steve

[RFC][PATCH 2/2] [PATCH 2/2] tracing: Only trace sched_wakeup if it actually work something up

[Steven Rostedt]

[-- Attachment #1: 0002-tracing-Only-trace-sched_wakeup-if-it-actually-work-.patch --]
[-- Type: text/plain, Size: 1976 bytes --]

From: Steven Rostedt <srostedt@redhat.com>

Currently the tracepoint sched_wakeup traces the wakeup event even
if the wakeup failed to wake anything up. This is quite stupid
but it happens because we did not want to add a conditional
to the core kernel code that would just slow down the wakeup events.

This patch changes the wakeup tracepoints to use the

 DECLARE_EVENT_CLASS_CONDITIONAL()

to test the "success" parameter and will only trace the event if
the wakeup was successfull.

The success field in the tracepoint is removed since it is no
longer needed.

Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
---
 include/trace/events/sched.h |   10 +++++-----
 1 files changed, 5 insertions(+), 5 deletions(-)

diff --git a/include/trace/events/sched.h b/include/trace/events/sched.h
index 67456f0..0807a25 100644
--- a/include/trace/events/sched.h
+++ b/include/trace/events/sched.h
@@ -52,17 +52,18 @@ TRACE_EVENT(sched_kthread_stop_ret,
 /*
  * Tracepoint for waking up a task:
  */
-DECLARE_EVENT_CLASS(sched_wakeup_template,
+DECLARE_EVENT_CLASS_CONDITION(sched_wakeup_template,
 
 	TP_PROTO(struct task_struct *p, int success),
 
 	TP_ARGS(p, success),
 
+	TP_CONDITION(success),
+
 	TP_STRUCT__entry(
 		__array(	char,	comm,	TASK_COMM_LEN	)
 		__field(	pid_t,	pid			)
 		__field(	int,	prio			)
-		__field(	int,	success			)
 		__field(	int,	target_cpu		)
 	),
 
@@ -70,13 +71,12 @@ DECLARE_EVENT_CLASS(sched_wakeup_template,
 		memcpy(__entry->comm, p->comm, TASK_COMM_LEN);
 		__entry->pid		= p->pid;
 		__entry->prio		= p->prio;
-		__entry->success	= success;
 		__entry->target_cpu	= task_cpu(p);
 	),
 
-	TP_printk("comm=%s pid=%d prio=%d success=%d target_cpu=%03d",
+	TP_printk("comm=%s pid=%d prio=%d target_cpu=%03d",
 		  __entry->comm, __entry->pid, __entry->prio,
-		  __entry->success, __entry->target_cpu)
+		  __entry->target_cpu)
 );
 
 DEFINE_EVENT(sched_wakeup_template, sched_wakeup,
-- 
1.7.2.3

Re: [RFC][PATCH 0/2] tracing: Add conditional to tracepoints

[Frederic Weisbecker]

On Thu, Dec 02, 2010 at 05:36:54PM -0500, Steven Rostedt wrote:
> This is an RFC that adds the TP_CONDITION() to the TRACE_EVENT()
> code.
> 
> There are certain cases that a tracepoint only makes sense if
> a specific condition is met. But because we do not want to dirty
> the fast path (the non tracing case) with if statements that are
> there only to avoid tracing, we just pass the condition variables
> to the tracepoint, and let the user filter them out if needed.
> 
> A perfect example is the tracepoint sched_wakeup. It traces all
> calls to try_to_wake_up() even if it fails to wake up. But if we add:
> 
> 	if (success)
> 		trace_sched_wakeup(p);
> 
> We have that "if (success)" tested for every time we call try_to_wake_up().
> Even when tracing is not (or never will be) enabled.
> 
> This patch set adds a variant TRACE_EVENT_CONDITIONAL()
> (and DECLARE_EVENT_CLASS_CONDITIONAL()) that has a "cond" argument.
> This argument is encapsulated with "TP_CONDITIONAL()" which turns into:
> 
> 	if (!cond)
> 		return;
> 
> This is placed inside the called tracepoint routine, and is only tested
> when the trace is enabled. Otherwise it is a nop as tracepoints normally
> are when disabled.
> 
> Note, another variant of this, is to move the test directly into the
> _DO_TRACE() macro, and not call any registered event callbacks. This would
> even speed it up faster when tracing is enabled. I did not do this
> orginially because I just thought of it now as I wrote this change log ;-)

Hehe :)

Yeah indeed. And that looks fairly possible.


> I'm posting this version now just in case people prefer it instead.
> 
> The following patches are in:
> 
>   git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/linux-2.6-trace.git
> 
>     branch: rfc/trace-conditional
> 
> 
> Steven Rostedt (2):
>       tracing: Add TRACE_EVENT_CONDITIONAL()
>       tracing: Only trace sched_wakeup if it actually work something up
> 
> ----
>  include/linux/tracepoint.h   |    3 ++
>  include/trace/define_trace.h |    6 +++
>  include/trace/events/sched.h |   12 +++---
>  include/trace/ftrace.h       |   70 +++++++++++++++++++++++++++++++----------
>  4 files changed, 68 insertions(+), 23 deletions(-)

Re: [RFC][PATCH 0/2] tracing: Add conditional to tracepoints

[Mathieu Desnoyers]

* Frederic Weisbecker (fweisbec@gmail.com) wrote:
> On Thu, Dec 02, 2010 at 05:36:54PM -0500, Steven Rostedt wrote:
> > 
> > Note, another variant of this, is to move the test directly into the
> > _DO_TRACE() macro, and not call any registered event callbacks. This would
> > even speed it up faster when tracing is enabled. I did not do this
> > orginially because I just thought of it now as I wrote this change log ;-)
> 
> Hehe :)
> 
> Yeah indeed. And that looks fairly possible.

I'd very much prefer if the test is performed before the call, within
the block that contains the stack setup and the tracepoint function
call. Having an utterly low performance impact for the events that are
filtered out is very important for my client's use-cases. Also, moving
it outside of the tracepoint probe function allows us to filter only
once for all the registered handlers.

All it would require is to skip over the function call rather than doing
a "return".

For the rest, it looks nice. :-)

Thanks,

Mathieu

-- 
Mathieu Desnoyers
Operating System Efficiency R&D Consultant
EfficiOS Inc.
http://www.efficios.com