Donate to e Foundation | Murena handsets with /e/OS | Own a part of Murena! Learn more

Commit da4d0302 authored by Steven Rostedt's avatar Steven Rostedt
Browse files

tracing: new format for specialized trace points



Impact: clean up and enhancement

The TRACE_EVENT_FORMAT macro looks quite ugly and is limited in its
ability to save data as well as to print the record out. Working with
Ingo Molnar, we came up with a new format that is much more pleasing to
the eye of C developers. This new macro is more C style than the old
macro, and is more obvious to what it does.

Here's the example. The only updated macro in this patch is the
sched_switch trace point.

The old method looked like this:

 TRACE_EVENT_FORMAT(sched_switch,
        TP_PROTO(struct rq *rq, struct task_struct *prev,
                struct task_struct *next),
        TP_ARGS(rq, prev, next),
        TP_FMT("task %s:%d ==> %s:%d",
              prev->comm, prev->pid, next->comm, next->pid),
        TRACE_STRUCT(
                TRACE_FIELD(pid_t, prev_pid, prev->pid)
                TRACE_FIELD(int, prev_prio, prev->prio)
                TRACE_FIELD_SPECIAL(char next_comm[TASK_COMM_LEN],
                                    next_comm,
                                    TP_CMD(memcpy(TRACE_ENTRY->next_comm,
                                                 next->comm,
                                                 TASK_COMM_LEN)))
                TRACE_FIELD(pid_t, next_pid, next->pid)
                TRACE_FIELD(int, next_prio, next->prio)
        ),
        TP_RAW_FMT("prev %d:%d ==> next %s:%d:%d")
        );

The above method is hard to read and requires two format fields.

The new method:

 /*
  * Tracepoint for task switches, performed by the scheduler:
  *
  * (NOTE: the 'rq' argument is not used by generic trace events,
  *        but used by the latency tracer plugin. )
  */
 TRACE_EVENT(sched_switch,

	TP_PROTO(struct rq *rq, struct task_struct *prev,
		 struct task_struct *next),

	TP_ARGS(rq, prev, next),

	TP_STRUCT__entry(
		__array(	char,	prev_comm,	TASK_COMM_LEN	)
		__field(	pid_t,	prev_pid			)
		__field(	int,	prev_prio			)
		__array(	char,	next_comm,	TASK_COMM_LEN	)
		__field(	pid_t,	next_pid			)
		__field(	int,	next_prio			)
	),

	TP_printk("task %s:%d [%d] ==> %s:%d [%d]",
		__entry->prev_comm, __entry->prev_pid, __entry->prev_prio,
		__entry->next_comm, __entry->next_pid, __entry->next_prio),

	TP_fast_assign(
		memcpy(__entry->next_comm, next->comm, TASK_COMM_LEN);
		__entry->prev_pid	= prev->pid;
		__entry->prev_prio	= prev->prio;
		memcpy(__entry->prev_comm, prev->comm, TASK_COMM_LEN);
		__entry->next_pid	= next->pid;
		__entry->next_prio	= next->prio;
	)
 );

This macro is called TRACE_EVENT, it is broken up into 5 parts:

 TP_PROTO:        the proto type of the trace point
 TP_ARGS:         the arguments of the trace point
 TP_STRUCT_entry: the structure layout of the entry in the ring buffer
 TP_printk:       the printk format
 TP_fast_assign:  the method used to write the entry into the ring buffer

The structure is the definition of how the event will be saved in the
ring buffer. The printk is used by the internal tracing in case of
an oops, and the kernel needs to print out the format of the record
to the console. This the TP_printk gives a means to show the records
in a human readable format. It is also used to print out the data
from the trace file.

The TP_fast_assign is executed directly. It is basically like a C function,
where the __entry is the handle to the record.

Signed-off-by: default avatarSteven Rostedt <srostedt@redhat.com>
parent 9cc26a26
Loading
Loading
Loading
Loading
+3 −0
Original line number Diff line number Diff line
@@ -160,4 +160,7 @@ static inline void tracepoint_synchronize_unregister(void)
#define TRACE_EVENT_FORMAT(name, proto, args, fmt, struct, tpfmt)	\
	TRACE_FORMAT(name, PARAMS(proto), PARAMS(args), PARAMS(fmt))

#define TRACE_EVENT(name, proto, args, struct, print, assign)	\
	DECLARE_TRACE(name, PARAMS(proto), PARAMS(args))

#endif
+32 −16
Original line number Diff line number Diff line
@@ -62,24 +62,40 @@ TRACE_EVENT_FORMAT(sched_wakeup_new,
	TP_RAW_FMT("task %d success=%d")
	);

TRACE_EVENT_FORMAT(sched_switch,
/*
 * Tracepoint for task switches, performed by the scheduler:
 *
 * (NOTE: the 'rq' argument is not used by generic trace events,
 *        but used by the latency tracer plugin. )
 */
TRACE_EVENT(sched_switch,

	TP_PROTO(struct rq *rq, struct task_struct *prev,
		 struct task_struct *next),

	TP_ARGS(rq, prev, next),
	TP_FMT("task %s:%d ==> %s:%d",
	      prev->comm, prev->pid, next->comm, next->pid),
	TRACE_STRUCT(
		TRACE_FIELD(pid_t, prev_pid, prev->pid)
		TRACE_FIELD(int, prev_prio, prev->prio)
		TRACE_FIELD_SPECIAL(char next_comm[TASK_COMM_LEN],
				    next_comm,
				    TP_CMD(memcpy(TRACE_ENTRY->next_comm,
						 next->comm,
						 TASK_COMM_LEN)))
		TRACE_FIELD(pid_t, next_pid, next->pid)
		TRACE_FIELD(int, next_prio, next->prio)

	TP_STRUCT__entry(
		__array(	char,	prev_comm,	TASK_COMM_LEN	)
		__field(	pid_t,	prev_pid			)
		__field(	int,	prev_prio			)
		__array(	char,	next_comm,	TASK_COMM_LEN	)
		__field(	pid_t,	next_pid			)
		__field(	int,	next_prio			)
	),
	TP_RAW_FMT("prev %d:%d ==> next %s:%d:%d")

	TP_printk("task %s:%d [%d] ==> %s:%d [%d]",
		__entry->prev_comm, __entry->prev_pid, __entry->prev_prio,
		__entry->next_comm, __entry->next_pid, __entry->next_prio),

	TP_fast_assign(
		memcpy(__entry->next_comm, next->comm, TASK_COMM_LEN);
		__entry->prev_pid	= prev->pid;
		__entry->prev_prio	= prev->prio;
		memcpy(__entry->prev_comm, prev->comm, TASK_COMM_LEN);
		__entry->next_pid	= next->pid;
		__entry->next_prio	= next->prio;
	)
);

TRACE_EVENT_FORMAT(sched_migrate_task,
+0 −5
Original line number Diff line number Diff line
@@ -751,12 +751,7 @@ struct ftrace_event_call {
	int		(*regfunc)(void);
	void		(*unregfunc)(void);
	int		id;
	struct dentry	*raw_dir;
	int		raw_enabled;
	int		type;
	int		(*raw_init)(void);
	int		(*raw_reg)(void);
	void		(*raw_unreg)(void);
	int		(*show_format)(struct trace_seq *s);
};

+2 −1
Original line number Diff line number Diff line
@@ -106,9 +106,10 @@ TRACE_EVENT_FORMAT(print, TRACE_PRINT, print_entry, ignore,
	TRACE_STRUCT(
		TRACE_FIELD(unsigned long, ip, ip)
		TRACE_FIELD(unsigned int, depth, depth)
		TRACE_FIELD(char *, fmt, fmt)
		TRACE_FIELD_ZERO_CHAR(buf)
	),
	TP_RAW_FMT("%08lx (%d) %s")
	TP_RAW_FMT("%08lx (%d) fmt:%p %s")
);

TRACE_EVENT_FORMAT(branch, TRACE_BRANCH, trace_branch, ignore,
+3 −156
Original line number Diff line number Diff line
@@ -59,22 +59,12 @@ static void ftrace_event_enable_disable(struct ftrace_event_call *call,
			call->enabled = 0;
			call->unregfunc();
		}
		if (call->raw_enabled) {
			call->raw_enabled = 0;
			call->raw_unreg();
		}
		break;
	case 1:
		if (!call->enabled &&
		    (call->type & TRACE_EVENT_TYPE_PRINTF)) {
		if (!call->enabled) {
			call->enabled = 1;
			call->regfunc();
		}
		if (!call->raw_enabled &&
		    (call->type & TRACE_EVENT_TYPE_RAW)) {
			call->raw_enabled = 1;
			call->raw_reg();
		}
		break;
	}
}
@@ -300,7 +290,7 @@ event_enable_read(struct file *filp, char __user *ubuf, size_t cnt,
	struct ftrace_event_call *call = filp->private_data;
	char *buf;

	if (call->enabled || call->raw_enabled)
	if (call->enabled)
		buf = "1\n";
	else
		buf = "0\n";
@@ -346,107 +336,6 @@ event_enable_write(struct file *filp, const char __user *ubuf, size_t cnt,
	return cnt;
}

static ssize_t
event_type_read(struct file *filp, char __user *ubuf, size_t cnt,
		loff_t *ppos)
{
	struct ftrace_event_call *call = filp->private_data;
	char buf[16];
	int r = 0;

	if (call->type & TRACE_EVENT_TYPE_PRINTF)
		r += sprintf(buf, "printf\n");

	if (call->type & TRACE_EVENT_TYPE_RAW)
		r += sprintf(buf+r, "raw\n");

	return simple_read_from_buffer(ubuf, cnt, ppos, buf, r);
}

static ssize_t
event_type_write(struct file *filp, const char __user *ubuf, size_t cnt,
		 loff_t *ppos)
{
	struct ftrace_event_call *call = filp->private_data;
	char buf[64];

	/*
	 * If there's only one type, we can't change it.
	 * And currently we always have printf type, and we
	 * may or may not have raw type.
	 *
	 * This is a redundant check, the file should be read
	 * only if this is the case anyway.
	 */

	if (!call->raw_init)
		return -EPERM;

	if (cnt >= sizeof(buf))
		return -EINVAL;

	if (copy_from_user(&buf, ubuf, cnt))
		return -EFAULT;

	buf[cnt] = 0;

	if (!strncmp(buf, "printf", 6) &&
	    (!buf[6] || isspace(buf[6]))) {

		call->type = TRACE_EVENT_TYPE_PRINTF;

		/*
		 * If raw enabled, the disable it and enable
		 * printf type.
		 */
		if (call->raw_enabled) {
			call->raw_enabled = 0;
			call->raw_unreg();

			call->enabled = 1;
			call->regfunc();
		}

	} else if (!strncmp(buf, "raw", 3) &&
	    (!buf[3] || isspace(buf[3]))) {

		call->type = TRACE_EVENT_TYPE_RAW;

		/*
		 * If printf enabled, the disable it and enable
		 * raw type.
		 */
		if (call->enabled) {
			call->enabled = 0;
			call->unregfunc();

			call->raw_enabled = 1;
			call->raw_reg();
		}
	} else
		return -EINVAL;

	*ppos += cnt;

	return cnt;
}

static ssize_t
event_available_types_read(struct file *filp, char __user *ubuf, size_t cnt,
			   loff_t *ppos)
{
	struct ftrace_event_call *call = filp->private_data;
	char buf[16];
	int r = 0;

	r += sprintf(buf, "printf\n");

	if (call->raw_init)
		r += sprintf(buf+r, "raw\n");

	return simple_read_from_buffer(ubuf, cnt, ppos, buf, r);
}

#undef FIELD
#define FIELD(type, name)						\
	#type, #name, (unsigned int)offsetof(typeof(field), name),	\
@@ -470,6 +359,7 @@ static int trace_write_header(struct trace_seq *s)
				FIELD(int, pid),
				FIELD(int, tgid));
}

static ssize_t
event_format_read(struct file *filp, char __user *ubuf, size_t cnt,
		  loff_t *ppos)
@@ -527,13 +417,6 @@ static const struct seq_operations show_set_event_seq_ops = {
	.stop = t_stop,
};

static const struct file_operations ftrace_avail_fops = {
	.open = ftrace_event_seq_open,
	.read = seq_read,
	.llseek = seq_lseek,
	.release = seq_release,
};

static const struct file_operations ftrace_set_event_fops = {
	.open = ftrace_event_seq_open,
	.read = seq_read,
@@ -548,17 +431,6 @@ static const struct file_operations ftrace_enable_fops = {
	.write = event_enable_write,
};

static const struct file_operations ftrace_type_fops = {
	.open = tracing_open_generic,
	.read = event_type_read,
	.write = event_type_write,
};

static const struct file_operations ftrace_available_types_fops = {
	.open = tracing_open_generic,
	.read = event_available_types_read,
};

static const struct file_operations ftrace_event_format_fops = {
	.open = tracing_open_generic,
	.read = event_format_read,
@@ -647,9 +519,6 @@ event_create_dir(struct ftrace_event_call *call, struct dentry *d_events)
		}
	}

	/* default the output to printf */
	call->type = TRACE_EVENT_TYPE_PRINTF;

	call->dir = debugfs_create_dir(call->name, d_events);
	if (!call->dir) {
		pr_warning("Could not create debugfs "
@@ -665,21 +534,6 @@ event_create_dir(struct ftrace_event_call *call, struct dentry *d_events)
				   "'%s/enable' entry\n", call->name);
	}

	/* Only let type be writable, if we can change it */
	entry = debugfs_create_file("type",
				    call->raw_init ? 0644 : 0444,
				    call->dir, call,
				    &ftrace_type_fops);
	if (!entry)
		pr_warning("Could not create debugfs "
			   "'%s/type' entry\n", call->name);

	entry = debugfs_create_file("available_types", 0444, call->dir, call,
				    &ftrace_available_types_fops);
	if (!entry)
		pr_warning("Could not create debugfs "
			   "'%s/available_types' entry\n", call->name);

	/* A trace may not want to export its format */
	if (!call->show_format)
		return 0;
@@ -704,13 +558,6 @@ static __init int event_trace_init(void)
	if (!d_tracer)
		return 0;

	entry = debugfs_create_file("available_events", 0444, d_tracer,
				    (void *)&show_event_seq_ops,
				    &ftrace_avail_fops);
	if (!entry)
		pr_warning("Could not create debugfs "
			   "'available_events' entry\n");

	entry = debugfs_create_file("set_event", 0644, d_tracer,
				    (void *)&show_set_event_seq_ops,
				    &ftrace_set_event_fops);
Loading