[RFC][PATCH 0/2] tracing: Have trace_printk()s in the events/ directory

[RFC][PATCH 0/2] tracing: Have trace_printk()s in the events/ directory

[Steven Rostedt]

As suggested in:

LKML-Reference: <20101116221726.GB26243@nowhere>
  or
http://marc.info/?l=linux-kernel&m=128994587230629

To have trace_printks in the events directory.

This patch set just does it for ftrace, although it can also lay the
ground work for both perf and trace (are they different tools?)

This patch set converts the current trace_printk() into ftrace_printk()
(back to it's original name) and that stays the same.

The new trace_printk() is off by default (we can change that later
with a kernel command line option perhaps), but it can be enable now
with the events directory.

Each trace_printk() added will get a entry in the debugfs/tracing/events/
directory as  debugfs/tracing/entry/path/to/trace_printk/

For example, I added a trace_printk() in kernel/sched.c at line 2180
and it creates:

# ls /debug/tracing/events/printk/kernel/sched.c/2180/
enable  format

The format is the printk format:

# cat /debug/tracing/events/printk/kernel/sched.c/2180/format 
"migrate task %s:%d
"


Every directory has an "enable" file. By echoing 0 or 1 into this
file, it will enable all the trace_printk's below it.

This also uses jump_label() to keep overhead down when disabled.

Note, modules are not (yet) supported.

This is just the ground work. I'm busy doing other things so
if you need more, feel free to take this and carry on.

-- Steve

The following patches are in:

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

    branch: rfc/event-printk


Steven Rostedt (2):
      tracing: Rename trace_printk to ftrace_printk
      tracing: Make event based trace_printk()

----
 include/asm-generic/vmlinux.lds.h |    7 +-
 include/linux/kernel.h            |   16 +-
 include/trace/event_printk.h      |   52 ++++++
 kernel/trace/Makefile             |    1 +
 kernel/trace/event_printk.c       |  365 +++++++++++++++++++++++++++++++++++++
 kernel/trace/trace.h              |    1 +
 kernel/trace/trace_events.c       |    2 +-
 7 files changed, 435 insertions(+), 9 deletions(-)

[RFC][PATCH 1/2] [PATCH 1/2] tracing: Rename trace_printk to ftrace_printk

[Steven Rostedt]

[-- Attachment #1: 0001-tracing-Rename-trace_printk-to-ftrace_printk.patch --]
[-- Type: text/plain, Size: 2283 bytes --]

From: Steven Rostedt <srostedt@redhat.com>

In order to make a bit more generic trace_printk(), this patch
simply renames the trace_printk() macro to its original ftrace_printk()
name, since it only writes into the ftrace ring buffer.

Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
---
 include/linux/kernel.h |   14 +++++++-------
 1 files changed, 7 insertions(+), 7 deletions(-)

diff --git a/include/linux/kernel.h b/include/linux/kernel.h
index b6de9a6..12151e5 100644
--- a/include/linux/kernel.h
+++ b/include/linux/kernel.h
@@ -318,11 +318,11 @@ do {									\
 } while (0)
 
 /**
- * trace_printk - printf formatting in the ftrace buffer
+ * ftrace_printk - printf formatting in the ftrace buffer
  * @fmt: the printf format for printing
  *
- * Note: __trace_printk is an internal function for trace_printk and
- *       the @ip is passed in via the trace_printk macro.
+ * Note: __trace_printk is an internal function for ftrace_printk and
+ *       the @ip is passed in via the ftrace_printk macro.
  *
  * This function allows a kernel developer to debug fast path sections
  * that printk is not appropriate for. By scattering in various
@@ -330,11 +330,11 @@ do {									\
  * where problems are occurring.
  *
  * This is intended as a debugging tool for the developer only.
- * Please refrain from leaving trace_printks scattered around in
+ * Please refrain from leaving ftrace_printks scattered around in
  * your code.
  */
 
-#define trace_printk(fmt, args...)					\
+#define ftrace_printk(fmt, args...)					\
 do {									\
 	__trace_printk_check_format(fmt, ##args);			\
 	if (__builtin_constant_p(fmt)) {				\
@@ -383,14 +383,14 @@ __ftrace_vprintk(unsigned long ip, const char *fmt, va_list ap);
 extern void ftrace_dump(enum ftrace_dump_mode oops_dump_mode);
 #else
 static inline int
-trace_printk(const char *fmt, ...) __attribute__ ((format (printf, 1, 2)));
+ftrace_printk(const char *fmt, ...) __attribute__ ((format (printf, 1, 2)));
 
 static inline void tracing_start(void) { }
 static inline void tracing_stop(void) { }
 static inline void ftrace_off_permanent(void) { }
 static inline void trace_dump_stack(void) { }
 static inline int
-trace_printk(const char *fmt, ...)
+ftrace_printk(const char *fmt, ...)
 {
 	return 0;
 }
-- 
1.7.1

[RFC][PATCH 2/2] [PATCH 2/2] tracing: Make event based trace_printk()

[Steven Rostedt]

[-- Attachment #1: 0002-tracing-Make-event-based-trace_printk.patch --]
[-- Type: text/plain, Size: 13600 bytes --]

From: Steven Rostedt <srostedt@redhat.com>

Add the trace_printk() that places the usage in the
/debug/tracing/events/printk directory.

Adding a trace_printk() into sched.c at line 2181, we have:

[root@bxf ~]# ls -R /debug/tracing/events/printk/
/debug/tracing/events/printk/:
enable  kernel

/debug/tracing/events/printk/kernel:
enable  sched.c

/debug/tracing/events/printk/kernel/sched.c:
2180  enable

/debug/tracing/events/printk/kernel/sched.c/2180:
enable  format

and

[root@bxf ~]# cat /debug/tracing/events/printk/kernel/sched.c/2180/format
"migrate task %s:%d
"

Note, although the trace_printk's are now in the event directories,
the top level events/enable file does not enable or disable trace_printk
events.

Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
---
 include/asm-generic/vmlinux.lds.h |    7 +-
 include/linux/kernel.h            |    2 +
 include/trace/event_printk.h      |   52 ++++++
 kernel/trace/Makefile             |    1 +
 kernel/trace/event_printk.c       |  365 +++++++++++++++++++++++++++++++++++++
 kernel/trace/trace.h              |    1 +
 kernel/trace/trace_events.c       |    2 +-
 7 files changed, 428 insertions(+), 2 deletions(-)
 create mode 100644 include/trace/event_printk.h
 create mode 100644 kernel/trace/event_printk.c

diff --git a/include/asm-generic/vmlinux.lds.h b/include/asm-generic/vmlinux.lds.h
index bd69d79..e74dac7 100644
--- a/include/asm-generic/vmlinux.lds.h
+++ b/include/asm-generic/vmlinux.lds.h
@@ -131,10 +131,14 @@
 #endif
 
 #ifdef CONFIG_TRACING
-#define TRACE_PRINTKS() VMLINUX_SYMBOL(__start___trace_bprintk_fmt) = .;      \
+#define FTRACE_PRINTKS() VMLINUX_SYMBOL(__start___trace_bprintk_fmt) = .;      \
 			 *(__trace_printk_fmt) /* Trace_printk fmt' pointer */ \
 			 VMLINUX_SYMBOL(__stop___trace_bprintk_fmt) = .;
+#define TRACE_PRINTKS()	VMLINUX_SYMBOL(__start_trace_printk) = .;   \
+				*(_trace_printk)		      \
+				VMLINUX_SYMBOL(__stop_trace_printk) = .;
 #else
+#define FTRACE_PRINTKS()
 #define TRACE_PRINTKS()
 #endif
 
@@ -169,6 +173,7 @@
 	LIKELY_PROFILE()		       				\
 	BRANCH_PROFILE()						\
 	TRACE_PRINTKS()							\
+	FTRACE_PRINTKS()						\
 									\
 	STRUCT_ALIGN();							\
 	FTRACE_EVENTS()							\
diff --git a/include/linux/kernel.h b/include/linux/kernel.h
index 12151e5..8a376d5 100644
--- a/include/linux/kernel.h
+++ b/include/linux/kernel.h
@@ -402,6 +402,8 @@ ftrace_vprintk(const char *fmt, va_list ap)
 static inline void ftrace_dump(enum ftrace_dump_mode oops_dump_mode) { }
 #endif /* CONFIG_TRACING */
 
+#include <trace/event_printk.h>
+
 /*
  * min()/max()/clamp() macros that also do
  * strict type-checking.. See the
diff --git a/include/trace/event_printk.h b/include/trace/event_printk.h
new file mode 100644
index 0000000..8ef9bda
--- /dev/null
+++ b/include/trace/event_printk.h
@@ -0,0 +1,52 @@
+#ifndef _EVENT_PRINTK_H
+#define _EVENT_PRINTK_H
+
+#ifdef CONFIG_TRACING
+#include <linux/jump_label.h>
+
+struct event_printk_struct {
+	const char		*format;
+	const char		*func;
+	const char		*file;
+	int			line;
+	char			enable;
+};
+
+static inline int __event_printk_test(char *key)
+{
+	JUMP_LABEL(key, do_trace);
+	return 0;
+do_trace:
+	return 1;
+}
+
+/* Compiler time bug */
+extern void trace_printk_can_only_have_constant_format(void);
+
+#define trace_printk(fmt, args...)					\
+	do {								\
+		static struct event_printk_struct			\
+		__attribute__((__aligned__(4)))				\
+		__attribute__((section("_trace_printk")))		\
+		______t = {						\
+			.format = fmt,					\
+			.func = __func__,				\
+			.file = __FILE__,				\
+			.line = __LINE__,				\
+		};							\
+		__trace_printk_check_format(fmt, ##args);		\
+		if (!__builtin_constant_p(fmt))				\
+			trace_printk_can_only_have_constant_format();	\
+		if (unlikely(__event_printk_test(&______t.enable)))	\
+			__trace_bprintk(_THIS_IP_, fmt, ##args); \
+	} while (0)
+
+#else
+static inline int
+trace_printk(const char *fmt, ...) __attribute__ ((format (printf, 1, 2)));
+{
+	return 0;
+}
+#endif /* CONFIG_TRACING */
+
+#endif /* _EVENT_PRINTK_H */
diff --git a/kernel/trace/Makefile b/kernel/trace/Makefile
index 53f3381..44bea92 100644
--- a/kernel/trace/Makefile
+++ b/kernel/trace/Makefile
@@ -29,6 +29,7 @@ obj-$(CONFIG_TRACING) += trace.o
 obj-$(CONFIG_TRACING) += trace_output.o
 obj-$(CONFIG_TRACING) += trace_stat.o
 obj-$(CONFIG_TRACING) += trace_printk.o
+obj-$(CONFIG_TRACING) += event_printk.o
 obj-$(CONFIG_CONTEXT_SWITCH_TRACER) += trace_sched_switch.o
 obj-$(CONFIG_FUNCTION_TRACER) += trace_functions.o
 obj-$(CONFIG_IRQSOFF_TRACER) += trace_irqsoff.o
diff --git a/kernel/trace/event_printk.c b/kernel/trace/event_printk.c
new file mode 100644
index 0000000..1134e3b
--- /dev/null
+++ b/kernel/trace/event_printk.c
@@ -0,0 +1,365 @@
+#include <linux/spinlock.h>
+#include <linux/debugfs.h>
+#include <linux/uaccess.h>
+#include <linux/module.h>
+#include <linux/ctype.h>
+#include <linux/slab.h>
+#include <linux/delay.h>
+
+#include <asm/setup.h>
+
+#include "trace.h"
+
+#include <trace/event_printk.h>
+
+extern struct event_printk_struct __start_trace_printk[];
+extern struct event_printk_struct __stop_trace_printk[];
+
+struct printk_nodes {
+	struct printk_nodes		*next;
+	struct dentry			*entry;
+	char				*name;
+	struct printk_nodes		*children;
+	struct event_printk_struct	*print;
+};
+
+static struct printk_nodes	*printk_nodes;
+struct dentry			*printk_root;
+
+#define for_each_printk(p, start, end)			\
+	for (p = start;					\
+	     (unsigned long)p < (unsigned long)end;	\
+	     p++)
+
+static struct printk_nodes *find_node(struct printk_nodes *list, char *name)
+{
+	struct printk_nodes *item;
+
+	for (item = list; item; item = item->next) {
+		if (strcmp(name, item->name) == 0)
+			break;
+	}
+	return item;
+}
+
+static int find_set(struct printk_nodes *node, int set, int paranoid)
+{
+	/* If we already have a mixture, just finish */
+	if (set == 3)
+		return set;
+
+	/* If this is a leaf, return its enabled node */
+	if (node && node->print)
+		return set | (1 << !!node->print->enable);
+
+	if (WARN_ONCE(paranoid > 9, "Printk directories too deep"))
+		return set;
+
+	if (!node)
+		node = printk_nodes;
+	else
+		node = node->children;
+
+	for (; node; node = node->next) {
+		set |= find_set(node, set, paranoid + 1);
+		if (set == 3)
+			break;
+	}
+
+	return set;
+}
+
+static int update_values(struct printk_nodes *node, int val, int paranoid)
+{
+	int ret = 0;
+
+	/* For leaf nodes just update the print */
+	if (node && node->print) {
+		if (!node->print->enable && val) {
+			jump_label_enable(&node->print->enable);
+			node->print->enable = val;
+		} else if (node->print->enable && !val) {
+			jump_label_disable(&node->print->enable);
+			node->print->enable = val;
+		}
+		return 0;
+	}
+
+	if (WARN_ONCE(paranoid > 9, "Printk directories too deep"))
+		return -EIO;
+
+	if (!node)
+		node = printk_nodes;
+	else
+		node = node->children;
+
+	for (; node; node = node->next) {
+		ret = update_values(node, val, paranoid + 1);
+		if (ret)
+			break;
+	}
+
+	return ret;
+}
+
+static ssize_t
+printk_format_read(struct file *filp, char __user *ubuf, size_t cnt,
+		   loff_t *ppos)
+{
+	struct printk_nodes *node = filp->private_data;
+	char *buf;
+	int ret;
+
+	if (!node->print)
+		return -EIO;
+
+	buf = kmalloc(strlen(node->print->format) + 4, GFP_KERNEL);
+	if (!buf)
+		return -ENOMEM;
+
+	sprintf(buf, "\"%s\"\n", node->print->format);
+
+	ret = simple_read_from_buffer(ubuf, cnt, ppos, buf, strlen(buf));
+
+	kfree(buf);
+
+	return ret;
+}
+
+static const struct file_operations trace_printk_format_fops = {
+	.open = tracing_open_generic,
+	.read = printk_format_read,
+};
+
+static ssize_t
+printk_enable_read(struct file *filp, char __user *ubuf, size_t cnt,
+		   loff_t *ppos)
+{
+	const char set_to_char[4] = { '?', '0', '1', 'X' };
+	struct printk_nodes *node = filp->private_data;
+	char buf[2];
+	int set;
+	int ret;
+
+	set = find_set(node, 0, 0);
+
+	buf[0] = set_to_char[set];
+	buf[1] = '\n';
+
+	ret = simple_read_from_buffer(ubuf, cnt, ppos, buf, 2);
+
+	return ret;
+}
+
+static ssize_t
+printk_enable_write(struct file *filp, const char __user *ubuf, size_t cnt,
+		    loff_t *ppos)
+{
+	struct printk_nodes *node = filp->private_data;
+	unsigned long val;
+	char buf[64];
+	ssize_t ret;
+
+	if (cnt >= sizeof(buf))
+		return -EINVAL;
+
+	if (copy_from_user(&buf, ubuf, cnt))
+		return -EFAULT;
+
+	buf[cnt] = 0;
+
+	ret = strict_strtoul(buf, 10, &val);
+	if (ret < 0)
+		return ret;
+
+	ret = tracing_update_buffers();
+	if (ret < 0)
+		return ret;
+
+	if (val != 0 && val != 1)
+		return -EINVAL;
+
+	ret = update_values(node, val, 0);
+	if (ret)
+		goto out;
+
+	ret = cnt;
+
+out:
+	*ppos += cnt;
+
+	return ret;
+}
+
+static const struct file_operations trace_printk_enable_fops = {
+	.open = tracing_open_generic,
+	.read = printk_enable_read,
+	.write = printk_enable_write,
+	.llseek = default_llseek,
+};
+
+static struct printk_nodes *
+add_node(struct printk_nodes *parent, const char *p, int len)
+{
+	struct printk_nodes **list;
+	struct printk_nodes *item;
+	struct dentry *dentry;
+	char *name;
+
+	if (!parent) {
+		list = &printk_nodes;
+		dentry = printk_root;
+	} else {
+		list = &parent->children;
+		dentry = parent->entry;
+	}
+
+	name = kstrndup(p, len, GFP_KERNEL);
+	if (WARN_ON(!name))
+		return NULL;
+
+	item = find_node(*list, name);
+
+	if (item) {
+		kfree(name);
+		return item;
+	}
+
+	item = kzalloc(sizeof(*item), GFP_KERNEL);
+	if (WARN_ON(!item)) {
+		kfree(name);
+		return NULL;
+	}
+	item->name = name;
+	item->entry = debugfs_create_dir(name, dentry);
+	if (WARN_ON(!item->entry)) {
+		kfree(name);
+		kfree(item);
+		return NULL;
+	}
+	trace_create_file("enable", 0644, item->entry,
+			  item, &trace_printk_enable_fops);
+	item->next = *list;
+	*list = item;
+	return item;
+}
+
+static struct printk_nodes *
+process_parent(struct printk_nodes *parent, const char *p, int len)
+{
+	struct printk_nodes *node;
+
+	node = add_node(parent, p, len);
+	if (!node)
+		return NULL;
+
+	return node;
+}
+
+static void
+process_leaf(struct printk_nodes *parent,
+	     struct event_printk_struct *print, const char *p)
+{
+	struct printk_nodes *dir;
+	struct printk_nodes *node;
+	char buf[30];
+	int i=0;
+
+	dir = add_node(parent, p, strlen(p));
+	if (!dir)
+		return;
+
+	/*
+	 * Make sure this is a unique node. If more than one trace_printk
+	 * is on the same line (probably do to macros) then just append
+	 * a -# to the name.
+	 */
+
+	snprintf(buf, 30, "%d", print->line);
+	while ((node = find_node(dir->children, buf)))
+		snprintf(buf, 30, "%d-%d", print->line, ++i);
+	node = add_node(dir, buf, strlen(buf));
+	if (!node)
+		return;
+
+	trace_create_file("format", 0644, node->entry,
+			  node, &trace_printk_format_fops);
+
+	node->print = print;
+}
+
+static void add_event_printk(const char *topdir, int len,
+			     struct event_printk_struct *print)
+{
+	struct printk_nodes *parent = NULL;
+	const char *p;
+	const char *n;
+
+	if (WARN_ON_ONCE(strncmp(topdir, print->file, len) != 0)) {
+		printk(KERN_INFO "Entry \"%s\" not in path \"%s\"\n",
+		       print->file, topdir);
+		return;
+	}
+
+	for (p = print->file + len; p; p = n) {
+		n = strstr(p, "/");
+		if (n) {
+			parent = process_parent(parent, p, n - p);
+			n++;
+		} else
+			process_leaf(parent, print, p);
+	}
+}
+
+static __init int event_printk_init(void)
+{
+	struct event_printk_struct *print;
+	struct dentry *d_events;
+	char *topdir;
+	char *p;
+	int len;
+	int ret = -1;
+
+	/*
+	 * Do nothing if we have no trace printks.
+	 * May change in the future when we support modules.
+	 */
+	if (__start_trace_printk == __stop_trace_printk)
+		return 0;
+
+	/*
+	 * Use this file to find the path for other
+	 * files. That is, __FILE__ returns the full path,
+	 * but we don't want the top dir path, so we must
+	 * chop it off. We know the path of this file as it
+	 * is (kernel/trace/event_printk.c), so we simply
+	 * cut that off and then we have the path to cut
+	 * off of other files.
+	 */
+	topdir = kstrdup(__FILE__, GFP_KERNEL);
+	if (WARN(!topdir, "failed to allocate printk info"))
+		return -1;
+
+	p = strstr(topdir, "kernel/trace/event_printk.c");
+	if (WARN(!p, "event_printk.c not found. Did the file move?"))
+		goto out;
+	*p = '\0';
+
+	d_events = event_trace_events_dir();
+
+	printk_root = debugfs_create_dir("printk", d_events);
+	if (WARN(!printk_root, "Could not create printk entry"))
+		goto out;
+
+	trace_create_file("enable", 0644, printk_root,
+			  NULL, &trace_printk_enable_fops);
+
+	len = strlen(topdir);
+	for_each_printk(print, __start_trace_printk, __stop_trace_printk)
+		add_event_printk(topdir, len, print);
+
+ out:
+	kfree(topdir);
+	return ret;
+}
+fs_initcall(event_printk_init);
diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
index 9021f8c..c99c79f 100644
--- a/kernel/trace/trace.h
+++ b/kernel/trace/trace.h
@@ -295,6 +295,7 @@ struct dentry *trace_create_file(const char *name,
 				 const struct file_operations *fops);
 
 struct dentry *tracing_init_dentry(void);
+struct dentry *event_trace_events_dir(void);
 
 struct ring_buffer_event;
 
diff --git a/kernel/trace/trace_events.c b/kernel/trace/trace_events.c
index 0725eea..4e96e09 100644
--- a/kernel/trace/trace_events.c
+++ b/kernel/trace/trace_events.c
@@ -975,7 +975,7 @@ static const struct file_operations ftrace_show_header_fops = {
 	.llseek = default_llseek,
 };
 
-static struct dentry *event_trace_events_dir(void)
+struct dentry *event_trace_events_dir(void)
 {
 	static struct dentry *d_tracer;
 	static struct dentry *d_events;
-- 
1.7.1

Re: [RFC][PATCH 2/2] [PATCH 2/2] tracing: Make event based trace_printk()

[Steven Rostedt]

On Wed, 2010-11-17 at 22:58 -0500, Steven Rostedt wrote:

> +static __init int event_printk_init(void)
> +{
> +	struct event_printk_struct *print;
> +	struct dentry *d_events;
> +	char *topdir;
> +	char *p;
> +	int len;
> +	int ret = -1;
> +
> +	/*
> +	 * Do nothing if we have no trace printks.
> +	 * May change in the future when we support modules.
> +	 */
> +	if (__start_trace_printk == __stop_trace_printk)
> +		return 0;
> +
> +	/*
> +	 * Use this file to find the path for other
> +	 * files. That is, __FILE__ returns the full path,
> +	 * but we don't want the top dir path, so we must
> +	 * chop it off. We know the path of this file as it
> +	 * is (kernel/trace/event_printk.c), so we simply
> +	 * cut that off and then we have the path to cut
> +	 * off of other files.
> +	 */
> +	topdir = kstrdup(__FILE__, GFP_KERNEL);
> +	if (WARN(!topdir, "failed to allocate printk info"))
> +		return -1;
> +
> +	p = strstr(topdir, "kernel/trace/event_printk.c");
> +	if (WARN(!p, "event_printk.c not found. Did the file move?"))
> +		goto out;
> +	*p = '\0';
> +
> +	d_events = event_trace_events_dir();
> +
> +	printk_root = debugfs_create_dir("printk", d_events);
> +	if (WARN(!printk_root, "Could not create printk entry"))
> +		goto out;
> +
> +	trace_create_file("enable", 0644, printk_root,
> +			  NULL, &trace_printk_enable_fops);
> +
> +	len = strlen(topdir);
> +	for_each_printk(print, __start_trace_printk, __stop_trace_printk)
> +		add_event_printk(topdir, len, print);

Oops, I'm missing a:

	ret = 0;

here.

-- Steve

> +
> + out:
> +	kfree(topdir);
> +	return ret;
> +}

Re: [RFC][PATCH 2/2] [PATCH 2/2] tracing: Make event based trace_printk()

[Lai Jiangshan]

On 11/18/2010 11:58 AM, Steven Rostedt wrote:
> +#define trace_printk(fmt, args...)					\
> +	do {								\
> +		static struct event_printk_struct			\
> +		__attribute__((__aligned__(4)))				\
> +		__attribute__((section("_trace_printk")))		\
> +		______t = {						\
> +			.format = fmt,					\

if fmt is not constant, the compiler will complain...

> +			.func = __func__,				\
> +			.file = __FILE__,				\
> +			.line = __LINE__,				\
> +		};							\
> +		__trace_printk_check_format(fmt, ##args);		\
> +		if (!__builtin_constant_p(fmt))				\
> +			trace_printk_can_only_have_constant_format();	\

so this is not need.

> +		if (unlikely(__event_printk_test(&______t.enable)))	\
> +			__trace_bprintk(_THIS_IP_, fmt, ##args); \
> +	} while (0)

Re: [RFC][PATCH 2/2] [PATCH 2/2] tracing: Make event based trace_printk()

[Steven Rostedt]

On Thu, 2010-11-18 at 13:50 +0800, Lai Jiangshan wrote:
> On 11/18/2010 11:58 AM, Steven Rostedt wrote:
> > +#define trace_printk(fmt, args...)					\
> > +	do {								\
> > +		static struct event_printk_struct			\
> > +		__attribute__((__aligned__(4)))				\
> > +		__attribute__((section("_trace_printk")))		\
> > +		______t = {						\
> > +			.format = fmt,					\
> 
> if fmt is not constant, the compiler will complain...

Ah you are right. I added that after I wrote all this code and wanted
the format to print in the file. The original code required the compile
check below.

-- Steve

> 
> > +			.func = __func__,				\
> > +			.file = __FILE__,				\
> > +			.line = __LINE__,				\
> > +		};							\
> > +		__trace_printk_check_format(fmt, ##args);		\
> > +		if (!__builtin_constant_p(fmt))				\
> > +			trace_printk_can_only_have_constant_format();	\
> 
> so this is not need.
> 
> > +		if (unlikely(__event_printk_test(&______t.enable)))	\
> > +			__trace_bprintk(_THIS_IP_, fmt, ##args); \
> > +	} while (0)

Re: [RFC][PATCH 2/2] [PATCH 2/2] tracing: Make event based trace_printk()

[Mathieu Desnoyers]

* Steven Rostedt (rostedt@goodmis.org) wrote:
> From: Steven Rostedt <srostedt@redhat.com>
> 
> Add the trace_printk() that places the usage in the
> /debug/tracing/events/printk directory.
> 
> Adding a trace_printk() into sched.c at line 2181, we have:

I'm curious: how do you handle two trace_printk on the same line ?

It might be OK to let the interface activate both at once, but nothing should
crash per se.

Thanks,

Mathieu

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

Re: [RFC][PATCH 2/2] [PATCH 2/2] tracing: Make event based trace_printk()

[Steven Rostedt]

On Thu, 2010-11-18 at 06:58 -0500, Mathieu Desnoyers wrote:
> * Steven Rostedt (rostedt@goodmis.org) wrote:
> > From: Steven Rostedt <srostedt@redhat.com>
> > 
> > Add the trace_printk() that places the usage in the
> > /debug/tracing/events/printk directory.
> > 
> > Adding a trace_printk() into sched.c at line 2181, we have:
> 
> I'm curious: how do you handle two trace_printk on the same line ?
> 
> It might be OK to let the interface activate both at once, but nothing should
> crash per se.

You get 2181, and 2181-1

-- Steve

Re: [RFC][PATCH 0/2] tracing: Have trace_printk()s in the events/ directory

[Peter Zijlstra]

On Wed, 2010-11-17 at 22:58 -0500, Steven Rostedt wrote:
> For example, I added a trace_printk() in kernel/sched.c at line 2180
> and it creates:
> 
> # ls /debug/tracing/events/printk/kernel/sched.c/2180/
> enable  format
> 
> The format is the printk format:
> 
> # cat /debug/tracing/events/printk/kernel/sched.c/2180/format 
> "migrate task %s:%d"

*groan*, so you're creating a tracepoint per instance?

That's going to be massive pain for perf.. I really don't see the point
in splitting all that out.

Re: [RFC][PATCH 0/2] tracing: Have trace_printk()s in the events/ directory

[Steven Rostedt]

On Thu, 2010-11-18 at 11:41 +0100, Peter Zijlstra wrote:
> On Wed, 2010-11-17 at 22:58 -0500, Steven Rostedt wrote:
> > For example, I added a trace_printk() in kernel/sched.c at line 2180
> > and it creates:
> > 
> > # ls /debug/tracing/events/printk/kernel/sched.c/2180/
> > enable  format
> > 
> > The format is the printk format:
> > 
> > # cat /debug/tracing/events/printk/kernel/sched.c/2180/format 
> > "migrate task %s:%d"
> 
> *groan*, so you're creating a tracepoint per instance?
> 
> That's going to be massive pain for perf.. I really don't see the point
> in splitting all that out.

a) The file directory was what was asked about in the referenced email.
b) This is just an example of a way to display it to the user, which
seems to be very intuitive.
c) Perf can implement the details anyway it wants. It can make a single
tracepoint callback and have the enabling of the points as a special
filter.
d) This was just an RFC that Frederic asked if I would do. I thought it
would be a fun challenge and did it. Let it bit rot in hell for all I
care, I wasn't taking it any further anyway.

-- Steve

Re: [RFC][PATCH 0/2] tracing: Have trace_printk()s in the events/ directory

[Mathieu Desnoyers]

* Steven Rostedt (rostedt@goodmis.org) wrote:
> On Thu, 2010-11-18 at 11:41 +0100, Peter Zijlstra wrote:
> > On Wed, 2010-11-17 at 22:58 -0500, Steven Rostedt wrote:
> > > For example, I added a trace_printk() in kernel/sched.c at line 2180
> > > and it creates:
> > > 
> > > # ls /debug/tracing/events/printk/kernel/sched.c/2180/
> > > enable  format
> > > 
> > > The format is the printk format:
> > > 
> > > # cat /debug/tracing/events/printk/kernel/sched.c/2180/format 
> > > "migrate task %s:%d"
> > 
> > *groan*, so you're creating a tracepoint per instance?
> > 
> > That's going to be massive pain for perf.. I really don't see the point
> > in splitting all that out.
> 
> a) The file directory was what was asked about in the referenced email.
> b) This is just an example of a way to display it to the user, which
> seems to be very intuitive.
> c) Perf can implement the details anyway it wants. It can make a single
> tracepoint callback and have the enabling of the points as a special
> filter.
> d) This was just an RFC that Frederic asked if I would do. I thought it
> would be a fun challenge and did it. Let it bit rot in hell for all I
> care, I wasn't taking it any further anyway.

Hi Steven,

The LTTng tree still keeps the "trace_mark()" kernel markers, which are
very very similar to ftrace_printk(). I'd be happy to combine the two
eventually. This one file per line approach seems very good -- rather than
explicitely naming each instance, as I did in trace_mark(), you end up
automatically naming them by file/line number.

How does this behave from within static inlines called multiple times and
unrolled loops ?

Thanks,

Mathieu

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

Re: [RFC][PATCH 0/2] tracing: Have trace_printk()s in the events/ directory

[Steven Rostedt]

On Thu, 2010-11-18 at 07:06 -0500, Mathieu Desnoyers wrote:
> * Steven Rostedt (rostedt@goodmis.org) wrote:
> > On Thu, 2010-11-18 at 11:41 +0100, Peter Zijlstra wrote:
> > > On Wed, 2010-11-17 at 22:58 -0500, Steven Rostedt wrote:
> > > > For example, I added a trace_printk() in kernel/sched.c at line 2180
> > > > and it creates:
> > > > 
> > > > # ls /debug/tracing/events/printk/kernel/sched.c/2180/
> > > > enable  format
> > > > 
> > > > The format is the printk format:
> > > > 
> > > > # cat /debug/tracing/events/printk/kernel/sched.c/2180/format 
> > > > "migrate task %s:%d"
> > > 
> > > *groan*, so you're creating a tracepoint per instance?
> > > 
> > > That's going to be massive pain for perf.. I really don't see the point
> > > in splitting all that out.
> > 
> > a) The file directory was what was asked about in the referenced email.
> > b) This is just an example of a way to display it to the user, which
> > seems to be very intuitive.
> > c) Perf can implement the details anyway it wants. It can make a single
> > tracepoint callback and have the enabling of the points as a special
> > filter.
> > d) This was just an RFC that Frederic asked if I would do. I thought it
> > would be a fun challenge and did it. Let it bit rot in hell for all I
> > care, I wasn't taking it any further anyway.
> 
> Hi Steven,
> 
> The LTTng tree still keeps the "trace_mark()" kernel markers, which are
> very very similar to ftrace_printk(). I'd be happy to combine the two
> eventually. This one file per line approach seems very good -- rather than
> explicitely naming each instance, as I did in trace_mark(), you end up
> automatically naming them by file/line number.
> 
> How does this behave from within static inlines called multiple times and
> unrolled loops ?

Actually you mean macros:

You'll get a 2181-1, 2181-2, 2181-3, etc.

Although a trace_printk() in a header static inline may be interesting.

-- Steve

Re: [RFC][PATCH 0/2] tracing: Have trace_printk()s in the events/ directory

[Mathieu Desnoyers]

* Steven Rostedt (rostedt@goodmis.org) wrote:
> On Thu, 2010-11-18 at 07:06 -0500, Mathieu Desnoyers wrote:
> > * Steven Rostedt (rostedt@goodmis.org) wrote:
> > > On Thu, 2010-11-18 at 11:41 +0100, Peter Zijlstra wrote:
> > > > On Wed, 2010-11-17 at 22:58 -0500, Steven Rostedt wrote:
> > > > > For example, I added a trace_printk() in kernel/sched.c at line 2180
> > > > > and it creates:
> > > > > 
> > > > > # ls /debug/tracing/events/printk/kernel/sched.c/2180/
> > > > > enable  format
> > > > > 
> > > > > The format is the printk format:
> > > > > 
> > > > > # cat /debug/tracing/events/printk/kernel/sched.c/2180/format 
> > > > > "migrate task %s:%d"
> > > > 
> > > > *groan*, so you're creating a tracepoint per instance?
> > > > 
> > > > That's going to be massive pain for perf.. I really don't see the point
> > > > in splitting all that out.
> > > 
> > > a) The file directory was what was asked about in the referenced email.
> > > b) This is just an example of a way to display it to the user, which
> > > seems to be very intuitive.
> > > c) Perf can implement the details anyway it wants. It can make a single
> > > tracepoint callback and have the enabling of the points as a special
> > > filter.
> > > d) This was just an RFC that Frederic asked if I would do. I thought it
> > > would be a fun challenge and did it. Let it bit rot in hell for all I
> > > care, I wasn't taking it any further anyway.
> > 
> > Hi Steven,
> > 
> > The LTTng tree still keeps the "trace_mark()" kernel markers, which are
> > very very similar to ftrace_printk(). I'd be happy to combine the two
> > eventually. This one file per line approach seems very good -- rather than
> > explicitely naming each instance, as I did in trace_mark(), you end up
> > automatically naming them by file/line number.
> > 
> > How does this behave from within static inlines called multiple times and
> > unrolled loops ?
> 
> Actually you mean macros:
> 
> You'll get a 2181-1, 2181-2, 2181-3, etc.

This is neat, great ! :)

> 
> Although a trace_printk() in a header static inline may be interesting.

Yep, food for thoughts. ;-)

Thank you !

Mathieu

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

Re: [RFC][PATCH 0/2] tracing: Have trace_printk()s in the events/ directory

[Frederic Weisbecker]

On Thu, Nov 18, 2010 at 11:41:06AM +0100, Peter Zijlstra wrote:
> On Wed, 2010-11-17 at 22:58 -0500, Steven Rostedt wrote:
> > For example, I added a trace_printk() in kernel/sched.c at line 2180
> > and it creates:
> > 
> > # ls /debug/tracing/events/printk/kernel/sched.c/2180/
> > enable  format
> > 
> > The format is the printk format:
> > 
> > # cat /debug/tracing/events/printk/kernel/sched.c/2180/format 
> > "migrate task %s:%d"
> 
> *groan*, so you're creating a tracepoint per instance?
> 
> That's going to be massive pain for perf.. I really don't see the point
> in splitting all that out.


Because it makes it very flexible, makes it easy to display the user
where are his trace_printk() and which one he could interact with.

Why would it be a massive pain for perf? People are not going to play
with thousands trace_printk() at once I guess.

Of course, a problem may arise if dynamic_printk() is handled into this
scheme, because of the number of fds to handle. In this case probably this
scheme should allow a group of trace_printk to be a (virtual) trace_event itself.

I mean if you have two trace_printk() in kernel/sched.c and some
others in kernel/, you could either create once perf_event for
every trace_printk() in kernel/ or one for every trace_prink() in
kernel/sched.c, or one for kernel/sched.c:118

That's easy if you have an id file at each level.

An other solution, which have been talking with Thomas yesterday, would be
to allow having a single fd for several perf_events at once. That would
solve some problems when you have hundreds of events opened (think about
wide tracing, or use of all individual syscalls).

Re: [RFC][PATCH 0/2] tracing: Have trace_printk()s in the events/ directory

[Steven Rostedt]

On Thu, 2010-11-18 at 13:53 +0100, Frederic Weisbecker wrote:
> n other solution, which have been talking with Thomas yesterday, would be
> to allow having a single fd for several perf_events at once. That would
> solve some problems when you have hundreds of events opened (think about
> wide tracing, or use of all individual syscalls).

I would highly recommend this. One type of tracing I do all the time is
to enable all events (over 600). I don't think that is currently
possible with trace and/or perf.

Ftrace has no issue simple because it just stores all the events into a
single buffer (per cpu though). It does not care if there's one event or
1000.

You need to figure out how to do this as well with the function tracer.
Of course you can just have it as a single event and filter as needed.

-- Steve

Re: [RFC][PATCH 0/2] tracing: Have trace_printk()s in the events/ directory

[Frederic Weisbecker]

On Thu, Nov 18, 2010 at 08:06:36AM -0500, Steven Rostedt wrote:
> On Thu, 2010-11-18 at 13:53 +0100, Frederic Weisbecker wrote:
> > n other solution, which have been talking with Thomas yesterday, would be
> > to allow having a single fd for several perf_events at once. That would
> > solve some problems when you have hundreds of events opened (think about
> > wide tracing, or use of all individual syscalls).
> 
> I would highly recommend this. One type of tracing I do all the time is
> to enable all events (over 600). I don't think that is currently
> possible with trace and/or perf.


Yep.



> Ftrace has no issue simple because it just stores all the events into a
> single buffer (per cpu though). It does not care if there's one event or
> 1000.
> 
> You need to figure out how to do this as well with the function tracer.


Yeah for the function (and graph) tracers, I really plan to make it a single
event. I mean one for the function tracer and one for the function graph.
Although we may want two for the function graph tracer actually. One for
entry, one for exit.

Re: [RFC][PATCH 0/2] tracing: Have trace_printk()s in the events/ directory

[Peter Zijlstra]

On Thu, 2010-11-18 at 13:53 +0100, Frederic Weisbecker wrote:
> 
> 
> An other solution, which have been talking with Thomas yesterday, would be
> to allow having a single fd for several perf_events at once. That would
> solve some problems when you have hundreds of events opened (think about
> wide tracing, or use of all individual syscalls).

I'm working on that, but that doesn't make me like this crap any more.

Re: [RFC][PATCH 0/2] tracing: Have trace_printk()s in the events/ directory

[Frederic Weisbecker]

On Thu, Nov 18, 2010 at 02:21:26PM +0100, Peter Zijlstra wrote:
> On Thu, 2010-11-18 at 13:53 +0100, Frederic Weisbecker wrote:
> > 
> > 
> > An other solution, which have been talking with Thomas yesterday, would be
> > to allow having a single fd for several perf_events at once. That would
> > solve some problems when you have hundreds of events opened (think about
> > wide tracing, or use of all individual syscalls).
> 
> I'm working on that, but that doesn't make me like this crap any more.


No problem, we have more important things to focus on for now anyway.
We may unearth it one day if the context makes it more useful.

Thanks.

Re: [RFC][PATCH 0/2] tracing: Have trace_printk()s in the events/ directory

[Frederic Weisbecker]

On Wed, Nov 17, 2010 at 10:58:03PM -0500, Steven Rostedt wrote:
> As suggested in:
> 
> LKML-Reference: <20101116221726.GB26243@nowhere>
>   or
> http://marc.info/?l=linux-kernel&m=128994587230629
> 
> To have trace_printks in the events directory.

(Note, I don't remember who got that idea. Perhaps
that was Ingo while discussing that with him like one year
ago, or may be me, not sure, whatever)...


> This patch set just does it for ftrace, although it can also lay the
> ground work for both perf and trace (are they different tools?)

The trace tool uses perf. But no worry about perf, I can handle the hook
for it.


> This patch set converts the current trace_printk() into ftrace_printk()
> (back to it's original name) and that stays the same.
> 
> The new trace_printk() is off by default (we can change that later
> with a kernel command line option perhaps), but it can be enable now
> with the events directory.

Cool. So disablement/re-enablement are nice features. That said it should
be enabled by default I think, to keep the previous (and intuitive) behaviour.

 
> Each trace_printk() added will get a entry in the debugfs/tracing/events/
> directory as  debugfs/tracing/entry/path/to/trace_printk/
> 
> For example, I added a trace_printk() in kernel/sched.c at line 2180
> and it creates:
> 
> # ls /debug/tracing/events/printk/kernel/sched.c/2180/
> enable  format

Ok, we'll probably need to add the ID as well.

 
> The format is the printk format:
> 
> # cat /debug/tracing/events/printk/kernel/sched.c/2180/format 
> "migrate task %s:%d
> "

Do you think we can make it more compatible with the common pattern?

Like:

Name: sched.c:2180
ID: 120
format:
	field:unsigned long ip;	offset:16;	size:8;	signed:0;
	field:const char * fmt;	offset:24;	size:8;	signed:0; <-- can be retrieved from printk_format
	field:u32 buf;	offset:32;	size:0;	signed:0;

print fmt: "given format", REC->ip, REC->fm


Does that look possible to you or have you run into troubles?

I don't know how much that's possible given the bprintk format. May be
we should first try with the already formatted trace_printk version.


> Every directory has an "enable" file. By echoing 0 or 1 into this
> file, it will enable all the trace_printk's below it.
> 
> This also uses jump_label() to keep overhead down when disabled.
> 
> Note, modules are not (yet) supported.
> 
> This is just the ground work. I'm busy doing other things so
> if you need more, feel free to take this and carry on.
> 
> -- Steve


Thanks a lot!


> 
> The following patches are in:
> 
>   git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/linux-2.6-trace.git
> 
>     branch: rfc/event-printk
> 
> 
> Steven Rostedt (2):
>       tracing: Rename trace_printk to ftrace_printk
>       tracing: Make event based trace_printk()
> 
> ----
>  include/asm-generic/vmlinux.lds.h |    7 +-
>  include/linux/kernel.h            |   16 +-
>  include/trace/event_printk.h      |   52 ++++++
>  kernel/trace/Makefile             |    1 +
>  kernel/trace/event_printk.c       |  365 +++++++++++++++++++++++++++++++++++++
>  kernel/trace/trace.h              |    1 +
>  kernel/trace/trace_events.c       |    2 +-
>  7 files changed, 435 insertions(+), 9 deletions(-)