[RFC - beta][PATCH] tracing: Introduce TRACE_MARKER() no argument trace event

[RFC - beta][PATCH] tracing: Introduce TRACE_MARKER() no argument trace event

[Steven Rostedt]

A while back ago, Wolfgang (and others) have asked about the ability to
add a trace event that recorder no data other than the fact that the
trace event was hit.

I've been reluctant to do so, but I noticed that one already exists in
the iwlwifi tracepoints (iwlwifi_dev_irq) where it does a wasteful:

        /* TP_printk("") doesn't compile */
        TP_printk("%d", 0)

The reason this is wasteful, is that there's a lot of code generated by
the TRACE_EVENT() macros that end up basically being nops.

I figured I would instead create a TRACE_MARKER(name, print) that would
be something like:

Added to tracepoint header:

 TRACE_MARKER(tpname, "Show this message");

Then you have:

	trace_tpname();

in the code.

Notice that the tracepoint function (trace_<name>()) has no arguments.
That's because the message is stored in the tracepoint (in one place)
and is printed when the tracepoint is read. That is, the message isn't
even recorded in the ring buffer.

It still shows up in the tracepoint format file:

name: tpname
ID: 281
format:
	field:unsigned short common_type;	offset:0;	size:2;	signed:0;
	field:unsigned char common_flags;	offset:2;	size:1;	signed:0;
	field:unsigned char common_preempt_count;	offset:3;	size:1;	signed:0;
	field:int common_pid;	offset:4;	size:4;	signed:1;


print fmt: "Show this message"

The TRACE_MARKER() is basically an optimized version of TRACE_EVENT()
with no arguments. It can be enabled and disabled the same way as any
other event, and stays within the system it was created in.

Is this worth doing?

Attached is a patch that implements this idea, but it is very much in a
beta form. It requires comments, documentation, updates to perf, etc.

-- Steve

diff --git a/include/linux/ftrace_event.h b/include/linux/ftrace_event.h
index 884d8ad..e464511 100644
--- a/include/linux/ftrace_event.h
+++ b/include/linux/ftrace_event.h
@@ -526,6 +526,12 @@ extern int trace_define_field(struct ftrace_event_call *call, const char *type,
 			      int is_signed, int filter_type);
 extern int trace_add_event_call(struct ftrace_event_call *call);
 extern int trace_remove_event_call(struct ftrace_event_call *call);
+extern void ftrace_raw_event_trace_marker(void *data);
+
+struct ftrace_raw_trace_marker {
+	struct trace_entry	ent;
+};
+extern struct trace_event_functions ftrace_event_type_funcs_trace_marker;
 
 #define is_signed_type(type)	(((type)(-1)) < (type)1)
 
diff --git a/include/linux/tracepoint.h b/include/linux/tracepoint.h
index accc497..171e3aa 100644
--- a/include/linux/tracepoint.h
+++ b/include/linux/tracepoint.h
@@ -399,6 +399,9 @@ static inline void tracepoint_synchronize_unregister(void)
 	DECLARE_TRACE_CONDITION(name, PARAMS(proto),		\
 				PARAMS(args), PARAMS(cond))
 
+#define TRACE_MARKER(name, print)				\
+	DECLARE_TRACE_NOARGS(name)
+
 #define TRACE_EVENT_FLAGS(event, flag)
 
 #define TRACE_EVENT_PERF_PERM(event, expr...)
diff --git a/include/trace/define_trace.h b/include/trace/define_trace.h
index 02e1003..773d05a 100644
--- a/include/trace/define_trace.h
+++ b/include/trace/define_trace.h
@@ -60,6 +60,10 @@
 #define DECLARE_TRACE(name, proto, args)	\
 	DEFINE_TRACE(name)
 
+#undef TRACE_MARKER
+#define TRACE_MARKER(name, print)		\
+	DEFINE_TRACE(name)
+
 #undef TRACE_INCLUDE
 #undef __TRACE_INCLUDE
 
@@ -93,6 +97,7 @@
 #undef TRACE_EVENT
 #undef TRACE_EVENT_FN
 #undef TRACE_EVENT_CONDITION
+#undef TRACE_MARKER
 #undef DECLARE_EVENT_CLASS
 #undef DEFINE_EVENT
 #undef DEFINE_EVENT_FN
diff --git a/include/trace/events/sched.h b/include/trace/events/sched.h
index 67e1bbf..fab482f 100644
--- a/include/trace/events/sched.h
+++ b/include/trace/events/sched.h
@@ -8,6 +8,10 @@
 #include <linux/tracepoint.h>
 #include <linux/binfmts.h>
 
+TRACE_MARKER(sched_mark1, "This is a test");
+
+TRACE_MARKER(sched_mark2, "This is another test");
+
 /*
  * Tracepoint for calling kthread_stop, performed to end a kthread:
  */
diff --git a/include/trace/ftrace.h b/include/trace/ftrace.h
index 623ddf3..85e2740 100644
--- a/include/trace/ftrace.h
+++ b/include/trace/ftrace.h
@@ -18,6 +18,23 @@
 
 #include <linux/ftrace_event.h>
 
+#ifdef TRACE_SYSTEM
+#define __TRACE_MARKER_CLASS(system) event_trace_marker_class_##system
+#define TRACE_MARKER_CLASS(system) __TRACE_MARKER_CLASS(system)
+/*
+ * Each system has its own trace marker class, but gcc will compile it
+ * out if it is not referenced.
+ */
+static struct ftrace_event_class __maybe_unused
+TRACE_MARKER_CLASS(TRACE_SYSTEM) = {
+	.system		= __stringify(TRACE_SYSTEM),
+	.fields		= LIST_HEAD_INIT(TRACE_MARKER_CLASS(TRACE_SYSTEM).fields),
+	.raw_init	= trace_event_raw_init,
+	.probe		= ftrace_raw_event_trace_marker,
+	.reg		= ftrace_event_reg,
+};
+#endif
+
 /*
  * DECLARE_EVENT_CLASS can be used to add a generic function
  * handlers for events. That is, if all events have the same
@@ -94,6 +111,10 @@
 #define TRACE_EVENT_PERF_PERM(name, expr...)				\
 	__TRACE_EVENT_PERF_PERM(name, expr)
 
+#undef TRACE_MARKER
+#define TRACE_MARKER(name, print)				\
+	DEFINE_EVENT(unused, name, unsued, unused)
+
 #include TRACE_INCLUDE(TRACE_INCLUDE_FILE)
 
 
@@ -147,6 +168,9 @@
 #undef TRACE_EVENT_PERF_PERM
 #define TRACE_EVENT_PERF_PERM(event, expr...)
 
+#undef TRACE_MARKER
+#define TRACE_MARKER(name, print)
+
 #include TRACE_INCLUDE(TRACE_INCLUDE_FILE)
 
 /*
@@ -626,6 +650,22 @@ static struct ftrace_event_call __used event_##call = {			\
 static struct ftrace_event_call __used					\
 __attribute__((section("_ftrace_events"))) *__event_##call = &event_##call
 
+
+#undef TRACE_MARKER
+#define TRACE_MARKER(call, print)					\
+									\
+static const char print_fmt_##call[] = "\"" print "\"";			\
+									\
+static struct ftrace_event_call __used event_##call = {			\
+	.name			= #call,				\
+	.class			= &TRACE_MARKER_CLASS(TRACE_SYSTEM),	\
+	.event.funcs		= &ftrace_event_type_funcs_trace_marker,\
+	.print_fmt		= print_fmt_##call,			\
+};									\
+static struct ftrace_event_call __used					\
+__attribute__((section("_ftrace_events"))) *__event_##call = &event_##call
+
+
 #include TRACE_INCLUDE(TRACE_INCLUDE_FILE)
 
 
@@ -650,6 +690,9 @@ __attribute__((section("_ftrace_events"))) *__event_##call = &event_##call
 #undef __perf_task
 #define __perf_task(t)	(__pe.task = (t))
 
+#undef TRACE_MARKER
+#define TRACE_MARKER(name, print)
+
 #undef DECLARE_EVENT_CLASS
 #define DECLARE_EVENT_CLASS(call, proto, args, tstruct, assign, print)	\
 static notrace void							\
diff --git a/kernel/sched/core.c b/kernel/sched/core.c
index b46131e..00bcf93 100644
--- a/kernel/sched/core.c
+++ b/kernel/sched/core.c
@@ -2656,6 +2656,7 @@ static void __sched __schedule(void)
 	struct rq *rq;
 	int cpu;
 
+	trace_sched_mark1();
 need_resched:
 	preempt_disable();
 	cpu = smp_processor_id();
@@ -2848,6 +2849,7 @@ asmlinkage void __sched preempt_schedule_irq(void)
 int default_wake_function(wait_queue_t *curr, unsigned mode, int wake_flags,
 			  void *key)
 {
+	trace_sched_mark2();
 	return try_to_wake_up(curr->private, mode, wake_flags);
 }
 EXPORT_SYMBOL(default_wake_function);
diff --git a/kernel/trace/trace_events.c b/kernel/trace/trace_events.c
index 22826c7..f82c936 100644
--- a/kernel/trace/trace_events.c
+++ b/kernel/trace/trace_events.c
@@ -86,6 +86,51 @@ __find_event_field(struct list_head *head, char *name)
 	return NULL;
 }
 
+/* TRACE_MARKER() class */
+
+enum print_line_t
+ftrace_raw_output_trace_marker(struct trace_iterator *iter, int flags,
+			       struct trace_event *trace_event)
+{
+	struct ftrace_event_call *event_call;
+	struct trace_seq *s = &iter->seq;
+	int ret;
+
+	ret = ftrace_raw_output_prep(iter, trace_event);
+	if (ret)
+		return ret;
+
+	event_call = container_of(trace_event, typeof(*event_call), event);
+
+	ret = trace_seq_printf(s, "%s\n", event_call->print_fmt);
+	if (!ret)
+		return TRACE_TYPE_PARTIAL_LINE;
+
+	return TRACE_TYPE_HANDLED;
+}
+
+struct trace_event_functions ftrace_event_type_funcs_trace_marker = {
+	.trace			= ftrace_raw_output_trace_marker,
+};
+
+void ftrace_raw_event_trace_marker(void *data)
+{
+	struct ftrace_event_file *ftrace_file = data;
+	struct ftrace_event_call *event_call = ftrace_file->event_call;
+	struct ftrace_event_buffer fbuffer;
+	struct ftrace_raw_trace_marker *entry;
+
+	if (ftrace_trigger_soft_disabled(ftrace_file))
+		return;
+
+	entry = ftrace_event_buffer_reserve(&fbuffer, ftrace_file,
+				event_call->event.type, sizeof(*entry));
+	if (!entry)
+		return;
+	ftrace_event_buffer_commit(&fbuffer, event_call);
+}
+
+
 struct ftrace_event_field *
 trace_find_event_field(struct ftrace_event_call *call, char *name)
 {
@@ -1533,7 +1578,7 @@ event_create_dir(struct dentry *parent, struct ftrace_event_file *file)
 	 * the fields if they are not already defined.
 	 */
 	head = trace_get_fields(call);
-	if (list_empty(head)) {
+	if (list_empty(head) && call->class->define_fields) {
 		ret = call->class->define_fields(call);
 		if (ret < 0) {
 			pr_warning("Could not initialize trace point"

Re: [RFC - beta][PATCH] tracing: Introduce TRACE_MARKER() no argument trace event

[Steven Rostedt]

On Fri, 7 Feb 2014 11:23:57 -0500
Steven Rostedt <rostedt@goodmis.org> wrote:

> 
> The TRACE_MARKER() is basically an optimized version of TRACE_EVENT()
> with no arguments. It can be enabled and disabled the same way as any
> other event, and stays within the system it was created in.
> 
> Is this worth doing?
> 

I'm thinking no. And unless someone can give me a good reason that we
should have such a thing, I will Nack my own patch!

Johannes,

What's up with trace_iwlwifi_dev_irq()?  You are tracing it but not
saving any information. There's obviously a reason for the
iwl_pcie_isr() to be called (it's handling something). Does it do the
exact same thing every time?  No variables are needed then?

What I'm trying to say is, if you go through the trouble of inserting a
tracepoint into some location, might as well extract data from it.
Otherwise you are wasting space in memory. If all you want to know is
if the function was called or not, then simply use a kprobe or function
trace that function (noinline to allow ftrace to trace it).

Unless I get some feedback to why this is a good idea...

Nacked-myself-by: Steven Rostedt <rostedt@goodmis.org>

-- Steve

Re: [RFC - beta][PATCH] tracing: Introduce TRACE_MARKER() no argument trace event

[Johannes Berg]

On Fri, 2014-02-07 at 15:28 -0500, Steven Rostedt wrote:

> I'm thinking no. And unless someone can give me a good reason that we
> should have such a thing, I will Nack my own patch!

:)

> What's up with trace_iwlwifi_dev_irq()?  You are tracing it but not
> saving any information. There's obviously a reason for the
> iwl_pcie_isr() to be called (it's handling something). Does it do the
> exact same thing every time?  No variables are needed then?
> 
> What I'm trying to say is, if you go through the trouble of inserting a
> tracepoint into some location, might as well extract data from it.
> Otherwise you are wasting space in memory. If all you want to know is
> if the function was called or not, then simply use a kprobe or function
> trace that function (noinline to allow ftrace to trace it).

I think right now the tracepoint is misplaced, I meant it to be in the
function that's now iwl_pcie_isr() but I guess I haven't used it much.

In any case, the reasoning was that we don't yet know any useful data,
we really only know that an interrupt happened. We later have this ICT
(interrupt cause table or something) that we read the information from,
but for tracing I want to know each field in the table even though only
the OR of all of them is later relevant.

So originally we had "interrupt" and then "interrupt reason"
tracepoints. Looking at the code now, that seems to have been lost, so I
guess I should instead add the reason to the tracepoint and only have
the ICT tracing separate when ICT is enabled (in fact, if ICT isn't
enabled, I don't have the reason status at all...)


Looking at this I'd agree that having a special 'hit only' trace event
isn't really needed (any more), at least not for this particular case.

johannes

Re: [RFC - beta][PATCH] tracing: Introduce TRACE_MARKER() no argument trace event

[Frederic Weisbecker]

On Fri, Feb 07, 2014 at 11:23:57AM -0500, Steven Rostedt wrote:
> A while back ago, Wolfgang (and others) have asked about the ability to
> add a trace event that recorder no data other than the fact that the
> trace event was hit.
> 
> I've been reluctant to do so, but I noticed that one already exists in
> the iwlwifi tracepoints (iwlwifi_dev_irq) where it does a wasteful:
> 
>         /* TP_printk("") doesn't compile */
>         TP_printk("%d", 0)
> 
> The reason this is wasteful, is that there's a lot of code generated by
> the TRACE_EVENT() macros that end up basically being nops.
> 
> I figured I would instead create a TRACE_MARKER(name, print) that would
> be something like:
> 
> Added to tracepoint header:
> 
>  TRACE_MARKER(tpname, "Show this message");
> 
> Then you have:
> 
> 	trace_tpname();
> 
> in the code.
> 
> Notice that the tracepoint function (trace_<name>()) has no arguments.
> That's because the message is stored in the tracepoint (in one place)
> and is printed when the tracepoint is read. That is, the message isn't
> even recorded in the ring buffer.
> 
> It still shows up in the tracepoint format file:
> 
> name: tpname
> ID: 281
> format:
> 	field:unsigned short common_type;	offset:0;	size:2;	signed:0;
> 	field:unsigned char common_flags;	offset:2;	size:1;	signed:0;
> 	field:unsigned char common_preempt_count;	offset:3;	size:1;	signed:0;
> 	field:int common_pid;	offset:4;	size:4;	signed:1;
> 
> 
> print fmt: "Show this message"
> 
> The TRACE_MARKER() is basically an optimized version of TRACE_EVENT()
> with no arguments. It can be enabled and disabled the same way as any
> other event, and stays within the system it was created in.
> 
> Is this worth doing?

It sounds worth yeah. I've run into this situation multiple times where I had
to pass 0 instead of nothing on a tracepoint.

Now about the name, why not TRACE_EVENT_EMPTY?

Thanks.

Re: [RFC - beta][PATCH] tracing: Introduce TRACE_MARKER() no argument trace event

[Steven Rostedt]

On Thu, 13 Feb 2014 15:26:42 +0100
Frederic Weisbecker <fweisbec@gmail.com> wrote:

> > Is this worth doing?
> 
> It sounds worth yeah. I've run into this situation multiple times where I had

Is it?

> to pass 0 instead of nothing on a tracepoint.

What tracepoints?

The problem I have with a tracepoint that does not pass any information
what's so ever, is that it can be too tempting to use. Tracepoints do
not have zero overhead when not used, but a negligible one. Too many
tracepoints add up, and their foot print can start to be noticed.

Point being, why have a tracepoint if you are not recording any data?
Just do a function trace, or add a kprobe. That's easy enough.

But that said, see below.

> 
> Now about the name, why not TRACE_EVENT_EMPTY?

Because that's an ugly name ;-)

Also a bit misleading, because it sounds like the there's no items
attached or something. It is too close to "list_empty()". My original
name was TRACE_EVENT_NOARGS(), which could work too.

Now another possible solution is to just introduce a trace_marker()
function that you could place anywhere. And then they could show up in
trace/events/markers/file-func-line/

We could do something like:

struct trace_marker {
	char *file;
	char *func;
	int line;
	struct static_key key;
};

#define trace_marker() __trace_marker(__FILE__,__func__, __LINE__)
static inline void __trace_marker(const char *file,
				const char *func, int line)
{
	static struct trace_marker marker
		__attribute__((section("__trace_marker"))) = {
		.file = file,
		.func = func,
		.line = line
	};

	if (static_key_false(&marker.key))
		trace_marker_call(&marker);
}

As marker would be a static value, gcc should hard code the first
parameter to it and make the call. Basically something like:

	mov $0x<marker-address>, %rdi
	call trace_marker_call

If we really want to be efficient, we could extend jump labels for each
arch, and remove the call completely.

	asm goto ("1:"
		  ".byte NOP\n"
		  ".pushsection __trace_marker_struct\n"
		  "2:.quad 1b\n"
		  ".quad %file\n"
		  ".quad %func\n'
		  ".word %line\n"
		  ".popsection\n"
		  ".pushsection __trace_marker_ptrs\n"
		  ".quad 2b\n"
		  ".popsection\n"
		 : : file, func, line);

[ OK, I didn't follow the true format for asm syntax, but that's
because I'm just trying to relay an idea, not actually make working
code ]

Then the only thing that would be inserted in the code is a nop. We
could then replace that nop with a call to a trampoline (similar to
mcount) that can call a C function with the address that it came from
so that the function could do a look up to find the matching marker to
trace.

OK, this is probably a bit too much, but it is feasible. Most likely
not worth the pain.

-- Steve

Re: [RFC - beta][PATCH] tracing: Introduce TRACE_MARKER() no argument trace event

[Frederic Weisbecker]

On Thu, Feb 13, 2014 at 10:25:52AM -0500, Steven Rostedt wrote:
> On Thu, 13 Feb 2014 15:26:42 +0100
> Frederic Weisbecker <fweisbec@gmail.com> wrote:
> 
> > > Is this worth doing?
> > 
> > It sounds worth yeah. I've run into this situation multiple times where I had
> 
> Is it?
> 
> > to pass 0 instead of nothing on a tracepoint.
> 
> What tracepoints?

The context tracking ones. Yeah TBH that sole user doesn't justify the feature :)

> 
> The problem I have with a tracepoint that does not pass any information
> what's so ever, is that it can be too tempting to use. Tracepoints do
> not have zero overhead when not used, but a negligible one. Too many
> tracepoints add up, and their foot print can start to be noticed.

Yeah, that maybe overused. I don't know, actually the problem hasn't arised
much.
 
> Point being, why have a tracepoint if you are not recording any data?
> Just do a function trace, or add a kprobe. That's easy enough.

Yeah but it's still easier to use static tracepoints. Especially when you
need to ask somebody to report some traces.

One of the point of static tracepoints is also to propose some key events
to the user. It matters when we do all-events wide tracing for example.

> 
> But that said, see below.
> 
> > 
> > Now about the name, why not TRACE_EVENT_EMPTY?
> 
> Because that's an ugly name ;-)
> 
> Also a bit misleading, because it sounds like the there's no items
> attached or something. It is too close to "list_empty()". My original
> name was TRACE_EVENT_NOARGS(), which could work too.
> 
> Now another possible solution is to just introduce a trace_marker()
> function that you could place anywhere. And then they could show up in
> trace/events/markers/file-func-line/
> 
> We could do something like:
> 
> struct trace_marker {
> 	char *file;
> 	char *func;
> 	int line;
> 	struct static_key key;
> };
> 
> #define trace_marker() __trace_marker(__FILE__,__func__, __LINE__)
> static inline void __trace_marker(const char *file,
> 				const char *func, int line)
> {
> 	static struct trace_marker marker
> 		__attribute__((section("__trace_marker"))) = {
> 		.file = file,
> 		.func = func,
> 		.line = line
> 	};
> 
> 	if (static_key_false(&marker.key))
> 		trace_marker_call(&marker);
> }
> 
> As marker would be a static value, gcc should hard code the first
> parameter to it and make the call. Basically something like:
> 
> 	mov $0x<marker-address>, %rdi
> 	call trace_marker_call
> 
> If we really want to be efficient, we could extend jump labels for each
> arch, and remove the call completely.
> 
> 	asm goto ("1:"
> 		  ".byte NOP\n"
> 		  ".pushsection __trace_marker_struct\n"
> 		  "2:.quad 1b\n"
> 		  ".quad %file\n"
> 		  ".quad %func\n'
> 		  ".word %line\n"
> 		  ".popsection\n"
> 		  ".pushsection __trace_marker_ptrs\n"
> 		  ".quad 2b\n"
> 		  ".popsection\n"
> 		 : : file, func, line);
> 
> [ OK, I didn't follow the true format for asm syntax, but that's
> because I'm just trying to relay an idea, not actually make working
> code ]
> 
> Then the only thing that would be inserted in the code is a nop. We
> could then replace that nop with a call to a trampoline (similar to
> mcount) that can call a C function with the address that it came from
> so that the function could do a look up to find the matching marker to
> trace.
> 
> OK, this is probably a bit too much, but it is feasible. Most likely
> not worth the pain.

Anyway yeah, given the complication and the fact there are very few actual users, lets forget that feature.

Thanks.