[PATCH 3/5] ftrace: add ftrace_bprintk()

[PATCH 3/5] ftrace: add ftrace_bprintk()

[Lai Jiangshan]

Impact: Add a generic printk() for ftrace, like ftrace_printk()

ftrace_bprintk() use the infrastructure to record events on ring_buffer.

Signed-off-by: Lai Jiangshan <laijs@cn.fujitsu.com>
---
 include/asm-generic/vmlinux.lds.h |    3
 include/linux/ftrace.h            |   21 ++++++
 include/linux/module.h            |    5 +
 kernel/module.c                   |    6 +
 kernel/trace/trace.c              |   15 ++++
 kernel/trace/trace_bprintk.c      |  118 +++++++++++++++++++++++++++++++++++++-
 6 files changed, 167 insertions(+), 1 deletion(-)
diff --git a/include/asm-generic/vmlinux.lds.h b/include/asm-generic/vmlinux.lds.h
index c61fab1..d5d5d42 100644
--- a/include/asm-generic/vmlinux.lds.h
+++ b/include/asm-generic/vmlinux.lds.h
@@ -91,6 +91,9 @@
 		*(__vermagic)		/* Kernel version magic */	\
 		*(__markers_strings)	/* Markers: strings */		\
 		*(__tracepoints_strings)/* Tracepoints: strings */	\
+		VMLINUX_SYMBOL(__start___trace_bprintk_fmt) = .;	\
+		*(__trace_printk_fmt)	/* Trace_printk fmt' pointer */	\
+		VMLINUX_SYMBOL(__stop___trace_bprintk_fmt) = .;		\
 	}								\
 									\
 	.rodata1          : AT(ADDR(.rodata1) - LOAD_OFFSET) {		\
diff --git a/include/linux/ftrace.h b/include/linux/ftrace.h
index 0ec4752..9be4b3c 100644
--- a/include/linux/ftrace.h
+++ b/include/linux/ftrace.h
@@ -183,6 +183,27 @@ extern int ftrace_make_call(struct dyn_ftrace *rec, unsigned long addr);
 
 #ifdef CONFIG_TRACE_BPRINTK
 extern int trace_vbprintk(unsigned long ip, const char *fmt, va_list args);
+extern int __ftrace_bprintk(unsigned long ip, const char *fmt, ...)
+		__attribute__ ((format (printf, 2, 3)));
+
+static inline void  ____ftrace_bprintk_check_format(const char *fmt, ...)
+		__attribute__ ((format (printf, 1, 2)));
+static inline void ____ftrace_bprintk_check_format(const char *fmt, ...) {}
+#define __ftrace_bprintk_check_format(fmt, args...)			\
+do {									\
+	if (0)								\
+		____ftrace_bprintk_check_format(fmt, ##args);		\
+} while (0)
+
+#define ftrace_bprintk(fmt, args...)					\
+do {									\
+	static char *__attribute__((section("__trace_bprintk_fmt")))	\
+			ftrace_bprintk_fmt = fmt;			\
+	__ftrace_bprintk_check_format(fmt, ##args);			\
+	__ftrace_bprintk(_THIS_IP_, ftrace_bprintk_fmt, ##args);	\
+} while (0)
+#else
+#define ftrace_bprintk ftrace_printk
 #endif
 
 /* May be defined in arch */
diff --git a/include/linux/module.h b/include/linux/module.h
index 3bfed01..89fc51c 100644
--- a/include/linux/module.h
+++ b/include/linux/module.h
@@ -337,6 +337,11 @@ struct module
 	unsigned int num_tracepoints;
 #endif
 
+#ifdef CONFIG_TRACE_BPRINTK
+	const char **trace_bprintk_fmt_start;
+	unsigned int num_trace_bprintk_fmt;
+#endif
+
 #ifdef CONFIG_MODULE_UNLOAD
 	/* What modules depend on me? */
 	struct list_head modules_which_use_me;
diff --git a/kernel/module.c b/kernel/module.c
index dd2a541..3a1e000 100644
--- a/kernel/module.c
+++ b/kernel/module.c
@@ -2126,6 +2126,12 @@ static noinline struct module *load_module(void __user *umod,
 					&mod->num_tracepoints);
 #endif
 
+#ifdef CONFIG_TRACE_BPRINTK
+	mod->trace_bprintk_fmt_start = section_objs(hdr, sechdrs, secstrings,
+			"__trace_bprintk_fmt", sizeof(char *),
+			&mod->num_trace_bprintk_fmt);
+#endif
+
 #ifdef CONFIG_MODVERSIONS
 	if ((mod->num_syms && !mod->crcs)
 	    || (mod->num_gpl_syms && !mod->gpl_crcs)
diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index 6e5c9df..61c9108 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -3084,6 +3084,21 @@ out:
 }
 EXPORT_SYMBOL_GPL(trace_vbprintk);
 
+int __ftrace_bprintk(unsigned long ip, const char *fmt, ...)
+{
+	int ret;
+	va_list ap;
+
+	if (!fmt)
+		return 0;
+
+	va_start(ap, fmt);
+	ret = trace_vbprintk(ip, fmt, ap);
+	va_end(ap);
+	return ret;
+}
+EXPORT_SYMBOL_GPL(__ftrace_bprintk);
+
 static int trace_panic_handler(struct notifier_block *this,
 			       unsigned long event, void *unused)
 {
diff --git a/kernel/trace/trace_bprintk.c b/kernel/trace/trace_bprintk.c
index 1f8e532..84c7a9c 100644
--- a/kernel/trace/trace_bprintk.c
+++ b/kernel/trace/trace_bprintk.c
@@ -19,6 +19,8 @@
 
 #include "trace.h"
 
+static inline void shrink_trace_bprintk_fmt(void);
+
 /* binary printk basic */
 static DEFINE_MUTEX(btrace_mutex);
 static int btrace_metadata_count;
@@ -44,9 +46,116 @@ static void put_btrace_metadata(void)
 {
 	lock_btrace();
 	btrace_metadata_count--;
+
+	if (!btrace_metadata_count) {
+		shrink_trace_bprintk_fmt();
+	}
 	unlock_btrace();
 }
 
+/*
+ * modules ftrace_bprintk()'s formats are autosaved in struct trace_bprintk_fmt
+ * which are queued on trace_bprintk_fmt_list.
+ */
+static LIST_HEAD(trace_bprintk_fmt_list);
+
+struct trace_bprintk_fmt {
+	struct list_head list;
+	int count;
+	char fmt[0];
+};
+
+/*
+ * If trace_bprintk() is not active, we release the trace_bprintk's
+ * formats that no modules has reference to.
+ */
+static inline void shrink_trace_bprintk_fmt(void)
+{
+	struct trace_bprintk_fmt *pos, *next;
+	list_for_each_entry_safe(pos, next, &trace_bprintk_fmt_list, list) {
+		if (!pos->count) {
+			list_del(&pos->list);
+			kfree(pos);
+		}
+	}
+}
+
+static inline struct trace_bprintk_fmt *lookup_format(const char *fmt)
+{
+	struct trace_bprintk_fmt *pos;
+	list_for_each_entry(pos, &trace_bprintk_fmt_list, list) {
+		if (!strcmp(pos->fmt, fmt))
+			return pos;
+	}
+	return NULL;
+}
+
+static
+void hold_module_trace_bprintk_format(const char **start, const char **end)
+{
+	const char **iter;
+	lock_btrace();
+	for (iter = start; iter < end; iter++) {
+		struct trace_bprintk_fmt *tb_fmt = lookup_format(*iter);
+		if (tb_fmt) {
+			tb_fmt->count++;
+			*iter = tb_fmt->fmt;
+			continue;
+		}
+
+		tb_fmt = kmalloc(offsetof(struct trace_bprintk_fmt, fmt)
+				+ strlen(*iter) + 1, GFP_KERNEL);
+		if (tb_fmt) {
+			list_add_tail(&tb_fmt->list, &trace_bprintk_fmt_list);
+			tb_fmt->count = 1;
+			strcpy(tb_fmt->fmt, *iter);
+			*iter = tb_fmt->fmt;
+		} else
+			*iter = NULL;
+	}
+	unlock_btrace();
+}
+
+static
+void release_module_trace_bprintk_format(const char **start, const char **end)
+{
+	const char **iter;
+	lock_btrace();
+	for (iter = start; iter < end; iter++) {
+		struct trace_bprintk_fmt *tb_fmt;
+		if (!*iter)
+			continue;
+
+		tb_fmt = container_of(*iter, struct trace_bprintk_fmt, fmt[0]);
+		tb_fmt->count--;
+		if (!tb_fmt->count && !btrace_metadata_count) {
+			list_del(&tb_fmt->list);
+			kfree(tb_fmt);
+		}
+	}
+	unlock_btrace();
+}
+
+static int module_trace_bprintk_format_notify(struct notifier_block *self,
+		unsigned long val, void *data)
+{
+	struct module *mod = data;
+	if (mod->num_trace_bprintk_fmt) {
+		const char **start = mod->trace_bprintk_fmt_start;
+		const char **end = start + mod->num_trace_bprintk_fmt;
+
+		if (val == MODULE_STATE_COMING)
+			hold_module_trace_bprintk_format(start, end);
+		else if (val == MODULE_STATE_GOING)
+			release_module_trace_bprintk_format(start, end);
+	}
+	return 0;
+}
+
+static struct notifier_block module_trace_bprintk_format_nb = {
+	.notifier_call = module_trace_bprintk_format_notify,
+};
+
 /* events tracer */
 int trace_bprintk_enable;
 
@@ -81,7 +190,14 @@ static struct tracer bprintk_trace __read_mostly =
 
 static __init int init_bprintk(void)
 {
-	return register_tracer(&bprintk_trace);
+	int ret = register_module_notifier(&module_trace_bprintk_format_nb);
+	if (ret)
+		return ret;
+
+	ret = register_tracer(&bprintk_trace);
+	if (ret)
+		unregister_module_notifier(&module_trace_bprintk_format_nb);
+	return ret;
 }
 
 device_initcall(init_bprintk);

Re: [PATCH][RFC] vsprintf: unify the format decoding layer for its 3 users

[Ingo Molnar]

* Frederic Weisbecker <fweisbec@gmail.com> wrote:

> > instead? Wouldn't that be nicer? I suspect it would make the 
> > code look nicer too (instead of doing "*base = x", you'd see 
> > "spec->base = x" and it would look less like line noise in 
> > the callee, an the caller could just do a single "struct 
> > format_spec spec = { 0, }" to initialize that thing).
> > 
> > 		Linus
> 
> You're right, that's much proper.
> See the V2 below:

Just a few (very) small code style pet peeves:

> +struct printf_spec {
> +	enum format_type type;
> +	int flags;			/* flags to number() */
> +	int field_width;		/* width of output field */
> +	int base;
> +	/* min. # of digits for integers; max number of chars for from string */
> +	int precision;
> +	int qualifier;
> +};

doesnt it look a bit tidier this way:

 struct printf_spec {
	enum format_type	type;
	int			flags;		/* flags to number()     */
	int			field_width;	/* width of output field */
	int			base;
	int			precision;	/* # of digits/chars     */
	int			qualifier;
 };

?

> +		case '+':
> +			spec->flags |= PLUS;
> +			break;
> +		case ' ':
> +			spec->flags |= SPACE;
> +			break;
> +		case '#':
> +			spec->flags |= SPECIAL;
> +			break;
> +		case '0':
> +			spec->flags |= ZEROPAD;
> +			break;
> +		default:
> +			found = false;

btw., this is one of the cases where i think the original style 
was more useful:

> +		case '+':	spec->flags |= PLUS;  break;
> +		case ' ':	spec->flags |= SPACE; break;
[etc.]

as it's always good to compress repetitive patterns of code.

(If checkpatch complains about this then ignore checkpatch.)

> +	case 'n':
> +		/* FIXME:
> +		* What does C99 say about the overflow case here? */

(this comment looks a bit funny.)

> +		default: {
> +			enum format_type type = spec.type;
> +
> +			if (type == FORMAT_TYPE_LONG_LONG)
> +				num = get_arg(long long);
> +			else if (type == FORMAT_TYPE_ULONG)
> +				num = get_arg(unsigned long);
> +			else if (type == FORMAT_TYPE_LONG)
> +				num = get_arg(unsigned long);
> +			else if (type == FORMAT_TYPE_SIZE_T)
> +				num = get_arg(size_t);
> +			else if (type == FORMAT_TYPE_PTRDIFF)
> +				num = get_arg(ptrdiff_t);
> +			else if (type == FORMAT_TYPE_USHORT)
> +				num = get_arg(unsigned short);
> +			else if (type == FORMAT_TYPE_SHORT)
> +				num = get_arg(short);
> +			else if (type == FORMAT_TYPE_UINT)
> +				num = get_arg(unsigned int);
> +			else
> +				num = get_arg(int);

Wouldnt it be cleaner as a switch() statement and to put into a 
helper function?

Also, could you please resend the current stuff with a 0/ 
description and a diffstat in the 0 mail so that we can all see 
all the patches again and the total impact?

	Ingo

[PATCH 3/5] ftrace: add ftrace_bprintk()

[Frederic Weisbecker]

From: Lai Jiangshan <laijs@cn.fujitsu.com>

Impact: Add a generic printk() for ftrace, like ftrace_printk()

ftrace_bprintk() use the infrastructure to record events on ring_buffer.

[fweisbec@gmail.com: ported to latest -tip and made it work if !CONFIG_MODULES]

Signed-off-by: Lai Jiangshan <laijs@cn.fujitsu.com>
Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
---
 include/asm-generic/vmlinux.lds.h |    3 +
 include/linux/ftrace.h            |   21 ++++++
 include/linux/module.h            |    5 ++
 kernel/module.c                   |    6 ++
 kernel/trace/trace.c              |   15 ++++
 kernel/trace/trace_bprintk.c      |  132 ++++++++++++++++++++++++++++++++++++-
 6 files changed, 181 insertions(+), 1 deletions(-)

diff --git a/include/asm-generic/vmlinux.lds.h b/include/asm-generic/vmlinux.lds.h
index 9d97491..13f20f4 100644
--- a/include/asm-generic/vmlinux.lds.h
+++ b/include/asm-generic/vmlinux.lds.h
@@ -100,6 +100,9 @@
 		*(__vermagic)		/* Kernel version magic */	\
 		*(__markers_strings)	/* Markers: strings */		\
 		*(__tracepoints_strings)/* Tracepoints: strings */	\
+		VMLINUX_SYMBOL(__start___trace_bprintk_fmt) = .;	\
+		*(__trace_printk_fmt)	/* Trace_printk fmt' pointer */	\
+		VMLINUX_SYMBOL(__stop___trace_bprintk_fmt) = .;		\
 	}								\
 									\
 	.rodata1          : AT(ADDR(.rodata1) - LOAD_OFFSET) {		\
diff --git a/include/linux/ftrace.h b/include/linux/ftrace.h
index 8ac2fac..f82b986 100644
--- a/include/linux/ftrace.h
+++ b/include/linux/ftrace.h
@@ -224,6 +224,27 @@ extern int ftrace_make_call(struct dyn_ftrace *rec, unsigned long addr);
 
 #ifdef CONFIG_TRACE_BPRINTK
 extern int trace_vbprintk(unsigned long ip, const char *fmt, va_list args);
+extern int __ftrace_bprintk(unsigned long ip, const char *fmt, ...)
+		__attribute__ ((format (printf, 2, 3)));
+
+static inline void  ____ftrace_bprintk_check_format(const char *fmt, ...)
+		__attribute__ ((format (printf, 1, 2)));
+static inline void ____ftrace_bprintk_check_format(const char *fmt, ...) {}
+#define __ftrace_bprintk_check_format(fmt, args...)			\
+do {									\
+	if (0)								\
+		____ftrace_bprintk_check_format(fmt, ##args);		\
+} while (0)
+
+#define ftrace_bprintk(fmt, args...)					\
+do {									\
+	static char *__attribute__((section("__trace_bprintk_fmt")))	\
+			ftrace_bprintk_fmt = fmt;			\
+	__ftrace_bprintk_check_format(fmt, ##args);			\
+	__ftrace_bprintk(_THIS_IP_, ftrace_bprintk_fmt, ##args);	\
+} while (0)
+#else
+#define ftrace_bprintk ftrace_printk
 #endif
 
 /* May be defined in arch */
diff --git a/include/linux/module.h b/include/linux/module.h
index 07b1cb4..c4f2845 100644
--- a/include/linux/module.h
+++ b/include/linux/module.h
@@ -347,6 +347,11 @@ struct module
 	unsigned int num_tracepoints;
 #endif
 
+#ifdef CONFIG_TRACE_BPRINTK
+	const char **trace_bprintk_fmt_start;
+	unsigned int num_trace_bprintk_fmt;
+#endif
+
 #ifdef CONFIG_MODULE_UNLOAD
 	/* What modules depend on me? */
 	struct list_head modules_which_use_me;
diff --git a/kernel/module.c b/kernel/module.c
index 90a6d63..fa96909 100644
--- a/kernel/module.c
+++ b/kernel/module.c
@@ -2192,6 +2192,12 @@ static noinline struct module *load_module(void __user *umod,
 					&mod->num_tracepoints);
 #endif
 
+#ifdef CONFIG_TRACE_BPRINTK
+	mod->trace_bprintk_fmt_start = section_objs(hdr, sechdrs, secstrings,
+			"__trace_bprintk_fmt", sizeof(char *),
+			&mod->num_trace_bprintk_fmt);
+#endif
+
 #ifdef CONFIG_MODVERSIONS
 	if ((mod->num_syms && !mod->crcs)
 	    || (mod->num_gpl_syms && !mod->gpl_crcs)
diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index 3a3ae19..0e30dce 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -3627,6 +3627,21 @@ out:
 }
 EXPORT_SYMBOL_GPL(trace_vbprintk);
 
+int __ftrace_bprintk(unsigned long ip, const char *fmt, ...)
+{
+	int ret;
+	va_list ap;
+
+	if (!fmt)
+		return 0;
+
+	va_start(ap, fmt);
+	ret = trace_vbprintk(ip, fmt, ap);
+	va_end(ap);
+	return ret;
+}
+EXPORT_SYMBOL_GPL(__ftrace_bprintk);
+
 static int trace_panic_handler(struct notifier_block *this,
 			       unsigned long event, void *unused)
 {
diff --git a/kernel/trace/trace_bprintk.c b/kernel/trace/trace_bprintk.c
index 1f8e532..28e6286 100644
--- a/kernel/trace/trace_bprintk.c
+++ b/kernel/trace/trace_bprintk.c
@@ -19,9 +19,23 @@
 
 #include "trace.h"
 
+#ifdef CONFIG_MODULES
+
 /* binary printk basic */
 static DEFINE_MUTEX(btrace_mutex);
 static int btrace_metadata_count;
+/*
+ * modules ftrace_bprintk()'s formats are autosaved in struct trace_bprintk_fmt
+ * which are queued on trace_bprintk_fmt_list.
+ */
+static LIST_HEAD(trace_bprintk_fmt_list);
+
+struct trace_bprintk_fmt {
+	struct list_head list;
+	int count;
+	char fmt[0];
+};
+
 
 static inline void lock_btrace(void)
 {
@@ -33,6 +47,93 @@ static inline void unlock_btrace(void)
 	mutex_unlock(&btrace_mutex);
 }
 
+/*
+ * If trace_bprintk() is not active, we release the trace_bprintk's
+ * formats that no modules has reference to.
+ */
+static inline void shrink_trace_bprintk_fmt(void)
+{
+	struct trace_bprintk_fmt *pos, *next;
+	list_for_each_entry_safe(pos, next, &trace_bprintk_fmt_list, list) {
+		if (!pos->count) {
+			list_del(&pos->list);
+			kfree(pos);
+		}
+	}
+}
+
+static inline struct trace_bprintk_fmt *lookup_format(const char *fmt)
+{
+	struct trace_bprintk_fmt *pos;
+	list_for_each_entry(pos, &trace_bprintk_fmt_list, list) {
+		if (!strcmp(pos->fmt, fmt))
+			return pos;
+	}
+	return NULL;
+}
+
+static
+void hold_module_trace_bprintk_format(const char **start, const char **end)
+{
+	const char **iter;
+	lock_btrace();
+	for (iter = start; iter < end; iter++) {
+		struct trace_bprintk_fmt *tb_fmt = lookup_format(*iter);
+		if (tb_fmt) {
+			tb_fmt->count++;
+			*iter = tb_fmt->fmt;
+			continue;
+		}
+
+		tb_fmt = kmalloc(offsetof(struct trace_bprintk_fmt, fmt)
+				+ strlen(*iter) + 1, GFP_KERNEL);
+		if (tb_fmt) {
+			list_add_tail(&tb_fmt->list, &trace_bprintk_fmt_list);
+			tb_fmt->count = 1;
+			strcpy(tb_fmt->fmt, *iter);
+			*iter = tb_fmt->fmt;
+		} else
+			*iter = NULL;
+	}
+	unlock_btrace();
+}
+
+static
+void release_module_trace_bprintk_format(const char **start, const char **end)
+{
+	const char **iter;
+	lock_btrace();
+	for (iter = start; iter < end; iter++) {
+		struct trace_bprintk_fmt *tb_fmt;
+		if (!*iter)
+			continue;
+
+		tb_fmt = container_of(*iter, struct trace_bprintk_fmt, fmt[0]);
+		tb_fmt->count--;
+		if (!tb_fmt->count && !btrace_metadata_count) {
+			list_del(&tb_fmt->list);
+			kfree(tb_fmt);
+		}
+	}
+	unlock_btrace();
+}
+
+static int module_trace_bprintk_format_notify(struct notifier_block *self,
+		unsigned long val, void *data)
+{
+	struct module *mod = data;
+	if (mod->num_trace_bprintk_fmt) {
+		const char **start = mod->trace_bprintk_fmt_start;
+		const char **end = start + mod->num_trace_bprintk_fmt;
+
+		if (val == MODULE_STATE_COMING)
+			hold_module_trace_bprintk_format(start, end);
+		else if (val == MODULE_STATE_GOING)
+			release_module_trace_bprintk_format(start, end);
+	}
+	return 0;
+}
+
 static void get_btrace_metadata(void)
 {
 	lock_btrace();
@@ -44,9 +145,31 @@ static void put_btrace_metadata(void)
 {
 	lock_btrace();
 	btrace_metadata_count--;
+
+	if (!btrace_metadata_count) {
+		shrink_trace_bprintk_fmt();
+	}
 	unlock_btrace();
 }
 
+#else /* !CONFIG_MODULES */
+__init static int
+module_trace_bprintk_format_notify(struct notifier_block *self,
+		unsigned long val, void *data)
+{
+	return 0;
+}
+
+static inline void get_btrace_metadata(void) { }
+static inline void put_btrace_metadata(void) { }
+#endif /* CONFIG_MODULES */
+
+
+__initdata_or_module static
+struct notifier_block module_trace_bprintk_format_nb = {
+	.notifier_call = module_trace_bprintk_format_notify,
+};
+
 /* events tracer */
 int trace_bprintk_enable;
 
@@ -81,7 +204,14 @@ static struct tracer bprintk_trace __read_mostly =
 
 static __init int init_bprintk(void)
 {
-	return register_tracer(&bprintk_trace);
+	int ret = register_module_notifier(&module_trace_bprintk_format_nb);
+	if (ret)
+		return ret;
+
+	ret = register_tracer(&bprintk_trace);
+	if (ret)
+		unregister_module_notifier(&module_trace_bprintk_format_nb);
+	return ret;
 }
 
 device_initcall(init_bprintk);
-- 
1.6.1

Re: [PATCH 3/5] ftrace: add ftrace_bprintk()

[Steven Rostedt]

On Sat, 28 Feb 2009, Frederic Weisbecker wrote:

> From: Lai Jiangshan <laijs@cn.fujitsu.com>
> 
> Impact: Add a generic printk() for ftrace, like ftrace_printk()
> 
> ftrace_bprintk() use the infrastructure to record events on ring_buffer.
> 
> [fweisbec@gmail.com: ported to latest -tip and made it work if !CONFIG_MODULES]
> 
> Signed-off-by: Lai Jiangshan <laijs@cn.fujitsu.com>
> Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
> ---
>  include/asm-generic/vmlinux.lds.h |    3 +
>  include/linux/ftrace.h            |   21 ++++++
>  include/linux/module.h            |    5 ++
>  kernel/module.c                   |    6 ++
>  kernel/trace/trace.c              |   15 ++++
>  kernel/trace/trace_bprintk.c      |  132 ++++++++++++++++++++++++++++++++++++-
>  6 files changed, 181 insertions(+), 1 deletions(-)
> 
> diff --git a/include/asm-generic/vmlinux.lds.h b/include/asm-generic/vmlinux.lds.h
> index 9d97491..13f20f4 100644
> --- a/include/asm-generic/vmlinux.lds.h
> +++ b/include/asm-generic/vmlinux.lds.h
> @@ -100,6 +100,9 @@
>  		*(__vermagic)		/* Kernel version magic */	\
>  		*(__markers_strings)	/* Markers: strings */		\
>  		*(__tracepoints_strings)/* Tracepoints: strings */	\
> +		VMLINUX_SYMBOL(__start___trace_bprintk_fmt) = .;	\
> +		*(__trace_printk_fmt)	/* Trace_printk fmt' pointer */	\
> +		VMLINUX_SYMBOL(__stop___trace_bprintk_fmt) = .;		\

If this can only be done when tracing is enabled, I would wrap that up
in a macro that is a nop when tracing is disabled.

>  	}								\
>  									\
>  	.rodata1          : AT(ADDR(.rodata1) - LOAD_OFFSET) {		\
> diff --git a/include/linux/ftrace.h b/include/linux/ftrace.h
> index 8ac2fac..f82b986 100644
> --- a/include/linux/ftrace.h
> +++ b/include/linux/ftrace.h
> @@ -224,6 +224,27 @@ extern int ftrace_make_call(struct dyn_ftrace *rec, unsigned long addr);
>  
>  #ifdef CONFIG_TRACE_BPRINTK
>  extern int trace_vbprintk(unsigned long ip, const char *fmt, va_list args);
> +extern int __ftrace_bprintk(unsigned long ip, const char *fmt, ...)
> +		__attribute__ ((format (printf, 2, 3)));
> +
> +static inline void  ____ftrace_bprintk_check_format(const char *fmt, ...)
> +		__attribute__ ((format (printf, 1, 2)));
> +static inline void ____ftrace_bprintk_check_format(const char *fmt, ...) {}
> +#define __ftrace_bprintk_check_format(fmt, args...)			\
> +do {									\
> +	if (0)								\
> +		____ftrace_bprintk_check_format(fmt, ##args);		\
> +} while (0)
> +
> +#define ftrace_bprintk(fmt, args...)					\
> +do {									\
> +	static char *__attribute__((section("__trace_bprintk_fmt")))	\
> +			ftrace_bprintk_fmt = fmt;			\
> +	__ftrace_bprintk_check_format(fmt, ##args);			\
> +	__ftrace_bprintk(_THIS_IP_, ftrace_bprintk_fmt, ##args);	\
> +} while (0)
> +#else
> +#define ftrace_bprintk ftrace_printk
>  #endif
>  
>  /* May be defined in arch */
> diff --git a/include/linux/module.h b/include/linux/module.h
> index 07b1cb4..c4f2845 100644
> --- a/include/linux/module.h
> +++ b/include/linux/module.h
> @@ -347,6 +347,11 @@ struct module
>  	unsigned int num_tracepoints;
>  #endif
>  
> +#ifdef CONFIG_TRACE_BPRINTK
> +	const char **trace_bprintk_fmt_start;
> +	unsigned int num_trace_bprintk_fmt;
> +#endif
> +
>  #ifdef CONFIG_MODULE_UNLOAD
>  	/* What modules depend on me? */
>  	struct list_head modules_which_use_me;
> diff --git a/kernel/module.c b/kernel/module.c
> index 90a6d63..fa96909 100644
> --- a/kernel/module.c
> +++ b/kernel/module.c
> @@ -2192,6 +2192,12 @@ static noinline struct module *load_module(void __user *umod,
>  					&mod->num_tracepoints);
>  #endif
>  
> +#ifdef CONFIG_TRACE_BPRINTK
> +	mod->trace_bprintk_fmt_start = section_objs(hdr, sechdrs, secstrings,
> +			"__trace_bprintk_fmt", sizeof(char *),
> +			&mod->num_trace_bprintk_fmt);
> +#endif
> +
>  #ifdef CONFIG_MODVERSIONS
>  	if ((mod->num_syms && !mod->crcs)
>  	    || (mod->num_gpl_syms && !mod->gpl_crcs)
> diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
> index 3a3ae19..0e30dce 100644
> --- a/kernel/trace/trace.c
> +++ b/kernel/trace/trace.c
> @@ -3627,6 +3627,21 @@ out:
>  }
>  EXPORT_SYMBOL_GPL(trace_vbprintk);
>  
> +int __ftrace_bprintk(unsigned long ip, const char *fmt, ...)
> +{
> +	int ret;
> +	va_list ap;
> +
> +	if (!fmt)
> +		return 0;
> +
> +	va_start(ap, fmt);
> +	ret = trace_vbprintk(ip, fmt, ap);
> +	va_end(ap);
> +	return ret;
> +}
> +EXPORT_SYMBOL_GPL(__ftrace_bprintk);
> +
>  static int trace_panic_handler(struct notifier_block *this,
>  			       unsigned long event, void *unused)
>  {
> diff --git a/kernel/trace/trace_bprintk.c b/kernel/trace/trace_bprintk.c
> index 1f8e532..28e6286 100644
> --- a/kernel/trace/trace_bprintk.c
> +++ b/kernel/trace/trace_bprintk.c
> @@ -19,9 +19,23 @@
>  
>  #include "trace.h"
>  
> +#ifdef CONFIG_MODULE> +
>  /* binary printk basic */
>  static DEFINE_MUTEX(btrace_mutex);
>  static int btrace_metadata_count;
> +/*
> + * modules ftrace_bprintk()'s formats are autosaved in struct trace_bprintk_fmt
> + * which are queued on trace_bprintk_fmt_list.
> + */
> +static LIST_HEAD(trace_bprintk_fmt_list);
> +
> +struct trace_bprintk_fmt {
> +	struct list_head list;
> +	int count;
> +	char fmt[0];
> +};
> +
>  
>  static inline void lock_btrace(void)
>  {
> @@ -33,6 +47,93 @@ static inline void unlock_btrace(void)
>  	mutex_unlock(&btrace_mutex);
>  }
>  
> +/*
> + * If trace_bprintk() is not active, we release the trace_bprintk's
> + * formats that no modules has reference to.
> + */
> +static inline void shrink_trace_bprintk_fmt(void)
> +{
> +	struct trace_bprintk_fmt *pos, *next;
> +	list_for_each_entry_safe(pos, next, &trace_bprintk_fmt_list, list) {
> +		if (!pos->count) {
> +			list_del(&pos->list);
> +			kfree(pos);
> +		}
> +	}
> +}
> +
> +static inline struct trace_bprintk_fmt *lookup_format(const char *fmt)
> +{
> +	struct trace_bprintk_fmt *pos;
> +	list_for_each_entry(pos, &trace_bprintk_fmt_list, list) {
> +		if (!strcmp(pos->fmt, fmt))
> +			return pos;
> +	}
> +	return NULL;
> +}
> +
> +static
> +void hold_module_trace_bprintk_format(const char **start, const char **end)
> +{
> +	const char **iter;
> +	lock_btrace();
> +	for (iter = start; iter < end; iter++) {
> +		struct trace_bprintk_fmt *tb_fmt = lookup_format(*iter);
> +		if (tb_fmt) {
> +			tb_fmt->count++;
> +			*iter = tb_fmt->fmt;
> +			continue;
> +		}
> +
> +		tb_fmt = kmalloc(offsetof(struct trace_bprintk_fmt, fmt)
> +				+ strlen(*iter) + 1, GFP_KERNEL);
> +		if (tb_fmt) {
> +			list_add_tail(&tb_fmt->list, &trace_bprintk_fmt_list);
> +			tb_fmt->count = 1;
> +			strcpy(tb_fmt->fmt, *iter);
> +			*iter = tb_fmt->fmt;
> +		} else
> +			*iter = NULL;
> +	}
> +	unlock_btrace();
> +}
> +
> +static
> +void release_module_trace_bprintk_format(const char **start, const char **end)
> +{
> +	const char **iter;
> +	lock_btrace();
> +	for (iter = start; iter < end; iter++) {
> +		struct trace_bprintk_fmt *tb_fmt;
> +		if (!*iter)
> +			continue;
> +
> +		tb_fmt = container_of(*iter, struct trace_bprintk_fmt, fmt[0]);
> +		tb_fmt->count--;
> +		if (!tb_fmt->count && !btrace_metadata_count) {
> +			list_del(&tb_fmt->list);
> +			kfree(tb_fmt);

Shouldn't *iter get assigned to NULL somewhere here?

-- Steve


> +		}
> +	}
> +	unlock_btrace();
> +}
> +
> +static int module_trace_bprintk_format_notify(struct notifier_block *self,
> +		unsigned long val, void *data)
> +{
> +	struct module *mod = data;
> +	if (mod->num_trace_bprintk_fmt) {
> +		const char **start = mod->trace_bprintk_fmt_start;
> +		const char **end = start + mod->num_trace_bprintk_fmt;
> +
> +		if (val == MODULE_STATE_COMING)
> +			hold_module_trace_bprintk_format(start, end);
> +		else if (val == MODULE_STATE_GOING)
> +			release_module_trace_bprintk_format(start, end);
> +	}
> +	return 0;
> +}
> +
>  static void get_btrace_metadata(void)
>  {
>  	lock_btrace();
> @@ -44,9 +145,31 @@ static void put_btrace_metadata(void)
>  {
>  	lock_btrace();
>  	btrace_metadata_count--;
> +
> +	if (!btrace_metadata_count) {
> +		shrink_trace_bprintk_fmt();
> +	}
>  	unlock_btrace();
>  }
>  
> +#else /* !CONFIG_MODULES */
> +__init static int
> +module_trace_bprintk_format_notify(struct notifier_block *self,
> +		unsigned long val, void *data)
> +{
> +	return 0;
> +}
> +
> +static inline void get_btrace_metadata(void) { }
> +static inline void put_btrace_metadata(void) { }
> +#endif /* CONFIG_MODULES */
> +
> +
> +__initdata_or_module static
> +struct notifier_block module_trace_bprintk_format_nb = {
> +	.notifier_call = module_trace_bprintk_format_notify,
> +};
> +
>  /* events tracer */
>  int trace_bprintk_enable;
>  
> @@ -81,7 +204,14 @@ static struct tracer bprintk_trace __read_mostly =
>  
>  static __init int init_bprintk(void)
>  {
> -	return register_tracer(&bprintk_trace);
> +	int ret = register_module_notifier(&module_trace_bprintk_format_nb);
> +	if (ret)
> +		return ret;
> +
> +	ret = register_tracer(&bprintk_trace);
> +	if (ret)
> +		unregister_module_notifier(&module_trace_bprintk_format_nb);
> +	return ret;
>  }
>  
>  device_initcall(init_bprintk);
> -- 
> 1.6.1
> 
> 
> 

Re: [PATCH 3/5] ftrace: add ftrace_bprintk()

[Frédéric Weisbecker]

2009/3/2 Steven Rostedt <rostedt@goodmis.org>:
>
> On Sat, 28 Feb 2009, Frederic Weisbecker wrote:
>
>> From: Lai Jiangshan <laijs@cn.fujitsu.com>
>>
>> Impact: Add a generic printk() for ftrace, like ftrace_printk()
>>
>> ftrace_bprintk() use the infrastructure to record events on ring_buffer.
>>
>> [fweisbec@gmail.com: ported to latest -tip and made it work if !CONFIG_MODULES]
>>
>> Signed-off-by: Lai Jiangshan <laijs@cn.fujitsu.com>
>> Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
>> ---
>>  include/asm-generic/vmlinux.lds.h |    3 +
>>  include/linux/ftrace.h            |   21 ++++++
>>  include/linux/module.h            |    5 ++
>>  kernel/module.c                   |    6 ++
>>  kernel/trace/trace.c              |   15 ++++
>>  kernel/trace/trace_bprintk.c      |  132 ++++++++++++++++++++++++++++++++++++-
>>  6 files changed, 181 insertions(+), 1 deletions(-)
>>
>> diff --git a/include/asm-generic/vmlinux.lds.h b/include/asm-generic/vmlinux.lds.h
>> index 9d97491..13f20f4 100644
>> --- a/include/asm-generic/vmlinux.lds.h
>> +++ b/include/asm-generic/vmlinux.lds.h
>> @@ -100,6 +100,9 @@
>>               *(__vermagic)           /* Kernel version magic */      \
>>               *(__markers_strings)    /* Markers: strings */          \
>>               *(__tracepoints_strings)/* Tracepoints: strings */      \
>> +             VMLINUX_SYMBOL(__start___trace_bprintk_fmt) = .;        \
>> +             *(__trace_printk_fmt)   /* Trace_printk fmt' pointer */ \
>> +             VMLINUX_SYMBOL(__stop___trace_bprintk_fmt) = .;         \
>
> If this can only be done when tracing is enabled, I would wrap that up
> in a macro that is a nop when tracing is disabled.


Ah, good catch.


>>       }                                                               \
>>                                                                       \
>>       .rodata1          : AT(ADDR(.rodata1) - LOAD_OFFSET) {          \
>> diff --git a/include/linux/ftrace.h b/include/linux/ftrace.h
>> index 8ac2fac..f82b986 100644
>> --- a/include/linux/ftrace.h
>> +++ b/include/linux/ftrace.h
>> @@ -224,6 +224,27 @@ extern int ftrace_make_call(struct dyn_ftrace *rec, unsigned long addr);
>>
>>  #ifdef CONFIG_TRACE_BPRINTK
>>  extern int trace_vbprintk(unsigned long ip, const char *fmt, va_list args);
>> +extern int __ftrace_bprintk(unsigned long ip, const char *fmt, ...)
>> +             __attribute__ ((format (printf, 2, 3)));
>> +
>> +static inline void  ____ftrace_bprintk_check_format(const char *fmt, ...)
>> +             __attribute__ ((format (printf, 1, 2)));
>> +static inline void ____ftrace_bprintk_check_format(const char *fmt, ...) {}
>> +#define __ftrace_bprintk_check_format(fmt, args...)                  \
>> +do {                                                                 \
>> +     if (0)                                                          \
>> +             ____ftrace_bprintk_check_format(fmt, ##args);           \
>> +} while (0)
>> +
>> +#define ftrace_bprintk(fmt, args...)                                 \
>> +do {                                                                 \
>> +     static char *__attribute__((section("__trace_bprintk_fmt")))    \
>> +                     ftrace_bprintk_fmt = fmt;                       \
>> +     __ftrace_bprintk_check_format(fmt, ##args);                     \
>> +     __ftrace_bprintk(_THIS_IP_, ftrace_bprintk_fmt, ##args);        \
>> +} while (0)
>> +#else
>> +#define ftrace_bprintk ftrace_printk
>>  #endif
>>
>>  /* May be defined in arch */
>> diff --git a/include/linux/module.h b/include/linux/module.h
>> index 07b1cb4..c4f2845 100644
>> --- a/include/linux/module.h
>> +++ b/include/linux/module.h
>> @@ -347,6 +347,11 @@ struct module
>>       unsigned int num_tracepoints;
>>  #endif
>>
>> +#ifdef CONFIG_TRACE_BPRINTK
>> +     const char **trace_bprintk_fmt_start;
>> +     unsigned int num_trace_bprintk_fmt;
>> +#endif
>> +
>>  #ifdef CONFIG_MODULE_UNLOAD
>>       /* What modules depend on me? */
>>       struct list_head modules_which_use_me;
>> diff --git a/kernel/module.c b/kernel/module.c
>> index 90a6d63..fa96909 100644
>> --- a/kernel/module.c
>> +++ b/kernel/module.c
>> @@ -2192,6 +2192,12 @@ static noinline struct module *load_module(void __user *umod,
>>                                       &mod->num_tracepoints);
>>  #endif
>>
>> +#ifdef CONFIG_TRACE_BPRINTK
>> +     mod->trace_bprintk_fmt_start = section_objs(hdr, sechdrs, secstrings,
>> +                     "__trace_bprintk_fmt", sizeof(char *),
>> +                     &mod->num_trace_bprintk_fmt);
>> +#endif
>> +
>>  #ifdef CONFIG_MODVERSIONS
>>       if ((mod->num_syms && !mod->crcs)
>>           || (mod->num_gpl_syms && !mod->gpl_crcs)
>> diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
>> index 3a3ae19..0e30dce 100644
>> --- a/kernel/trace/trace.c
>> +++ b/kernel/trace/trace.c
>> @@ -3627,6 +3627,21 @@ out:
>>  }
>>  EXPORT_SYMBOL_GPL(trace_vbprintk);
>>
>> +int __ftrace_bprintk(unsigned long ip, const char *fmt, ...)
>> +{
>> +     int ret;
>> +     va_list ap;
>> +
>> +     if (!fmt)
>> +             return 0;
>> +
>> +     va_start(ap, fmt);
>> +     ret = trace_vbprintk(ip, fmt, ap);
>> +     va_end(ap);
>> +     return ret;
>> +}
>> +EXPORT_SYMBOL_GPL(__ftrace_bprintk);
>> +
>>  static int trace_panic_handler(struct notifier_block *this,
>>                              unsigned long event, void *unused)
>>  {
>> diff --git a/kernel/trace/trace_bprintk.c b/kernel/trace/trace_bprintk.c
>> index 1f8e532..28e6286 100644
>> --- a/kernel/trace/trace_bprintk.c
>> +++ b/kernel/trace/trace_bprintk.c
>> @@ -19,9 +19,23 @@
>>
>>  #include "trace.h"
>>
>> +#ifdef CONFIG_MODULE> +
>>  /* binary printk basic */
>>  static DEFINE_MUTEX(btrace_mutex);
>>  static int btrace_metadata_count;
>> +/*
>> + * modules ftrace_bprintk()'s formats are autosaved in struct trace_bprintk_fmt
>> + * which are queued on trace_bprintk_fmt_list.
>> + */
>> +static LIST_HEAD(trace_bprintk_fmt_list);
>> +
>> +struct trace_bprintk_fmt {
>> +     struct list_head list;
>> +     int count;
>> +     char fmt[0];
>> +};
>> +
>>
>>  static inline void lock_btrace(void)
>>  {
>> @@ -33,6 +47,93 @@ static inline void unlock_btrace(void)
>>       mutex_unlock(&btrace_mutex);
>>  }
>>
>> +/*
>> + * If trace_bprintk() is not active, we release the trace_bprintk's
>> + * formats that no modules has reference to.
>> + */
>> +static inline void shrink_trace_bprintk_fmt(void)
>> +{
>> +     struct trace_bprintk_fmt *pos, *next;
>> +     list_for_each_entry_safe(pos, next, &trace_bprintk_fmt_list, list) {
>> +             if (!pos->count) {
>> +                     list_del(&pos->list);
>> +                     kfree(pos);
>> +             }
>> +     }
>> +}
>> +
>> +static inline struct trace_bprintk_fmt *lookup_format(const char *fmt)
>> +{
>> +     struct trace_bprintk_fmt *pos;
>> +     list_for_each_entry(pos, &trace_bprintk_fmt_list, list) {
>> +             if (!strcmp(pos->fmt, fmt))
>> +                     return pos;
>> +     }
>> +     return NULL;
>> +}
>> +
>> +static
>> +void hold_module_trace_bprintk_format(const char **start, const char **end)
>> +{
>> +     const char **iter;
>> +     lock_btrace();
>> +     for (iter = start; iter < end; iter++) {
>> +             struct trace_bprintk_fmt *tb_fmt = lookup_format(*iter);
>> +             if (tb_fmt) {
>> +                     tb_fmt->count++;
>> +                     *iter = tb_fmt->fmt;
>> +                     continue;
>> +             }
>> +
>> +             tb_fmt = kmalloc(offsetof(struct trace_bprintk_fmt, fmt)
>> +                             + strlen(*iter) + 1, GFP_KERNEL);
>> +             if (tb_fmt) {
>> +                     list_add_tail(&tb_fmt->list, &trace_bprintk_fmt_list);
>> +                     tb_fmt->count = 1;
>> +                     strcpy(tb_fmt->fmt, *iter);
>> +                     *iter = tb_fmt->fmt;
>> +             } else
>> +                     *iter = NULL;
>> +     }
>> +     unlock_btrace();
>> +}
>> +
>> +static
>> +void release_module_trace_bprintk_format(const char **start, const char **end)
>> +{
>> +     const char **iter;
>> +     lock_btrace();
>> +     for (iter = start; iter < end; iter++) {
>> +             struct trace_bprintk_fmt *tb_fmt;
>> +             if (!*iter)
>> +                     continue;
>> +
>> +             tb_fmt = container_of(*iter, struct trace_bprintk_fmt, fmt[0]);
>> +             tb_fmt->count--;
>> +             if (!tb_fmt->count && !btrace_metadata_count) {
>> +                     list_del(&tb_fmt->list);
>> +                     kfree(tb_fmt);
>
> Shouldn't *iter get assigned to NULL somewhere here?
>
> -- Steve


Hm, why?

>
>> +             }
>> +     }
>> +     unlock_btrace();
>> +}
>> +
>> +static int module_trace_bprintk_format_notify(struct notifier_block *self,
>> +             unsigned long val, void *data)
>> +{
>> +     struct module *mod = data;
>> +     if (mod->num_trace_bprintk_fmt) {
>> +             const char **start = mod->trace_bprintk_fmt_start;
>> +             const char **end = start + mod->num_trace_bprintk_fmt;
>> +
>> +             if (val == MODULE_STATE_COMING)
>> +                     hold_module_trace_bprintk_format(start, end);
>> +             else if (val == MODULE_STATE_GOING)
>> +                     release_module_trace_bprintk_format(start, end);
>> +     }
>> +     return 0;
>> +}
>> +
>>  static void get_btrace_metadata(void)
>>  {
>>       lock_btrace();
>> @@ -44,9 +145,31 @@ static void put_btrace_metadata(void)
>>  {
>>       lock_btrace();
>>       btrace_metadata_count--;
>> +
>> +     if (!btrace_metadata_count) {
>> +             shrink_trace_bprintk_fmt();
>> +     }
>>       unlock_btrace();
>>  }
>>
>> +#else /* !CONFIG_MODULES */
>> +__init static int
>> +module_trace_bprintk_format_notify(struct notifier_block *self,
>> +             unsigned long val, void *data)
>> +{
>> +     return 0;
>> +}
>> +
>> +static inline void get_btrace_metadata(void) { }
>> +static inline void put_btrace_metadata(void) { }
>> +#endif /* CONFIG_MODULES */
>> +
>> +
>> +__initdata_or_module static
>> +struct notifier_block module_trace_bprintk_format_nb = {
>> +     .notifier_call = module_trace_bprintk_format_notify,
>> +};
>> +
>>  /* events tracer */
>>  int trace_bprintk_enable;
>>
>> @@ -81,7 +204,14 @@ static struct tracer bprintk_trace __read_mostly =
>>
>>  static __init int init_bprintk(void)
>>  {
>> -     return register_tracer(&bprintk_trace);
>> +     int ret = register_module_notifier(&module_trace_bprintk_format_nb);
>> +     if (ret)
>> +             return ret;
>> +
>> +     ret = register_tracer(&bprintk_trace);
>> +     if (ret)
>> +             unregister_module_notifier(&module_trace_bprintk_format_nb);
>> +     return ret;
>>  }
>>
>>  device_initcall(init_bprintk);
>> --
>> 1.6.1
>>
>>
>>
>

Re: [PATCH 3/5] ftrace: add ftrace_bprintk()

[Steven Rostedt]

[-- Attachment #1: Type: TEXT/PLAIN, Size: 883 bytes --]


On Mon, 2 Mar 2009, Fr?d?ric Weisbecker wrote:
> >> +
> >> +static
> >> +void release_module_trace_bprintk_format(const char **start, const char **end)
> >> +{
> >> +     const char **iter;
> >> +     lock_btrace();
> >> +     for (iter = start; iter < end; iter++) {
> >> +             struct trace_bprintk_fmt *tb_fmt;
> >> +             if (!*iter)
> >> +                     continue;
> >> +
> >> +             tb_fmt = container_of(*iter, struct trace_bprintk_fmt, fmt[0]);
> >> +             tb_fmt->count--;
> >> +             if (!tb_fmt->count && !btrace_metadata_count) {
> >> +                     list_del(&tb_fmt->list);
> >> +                     kfree(tb_fmt);
> >
> > Shouldn't *iter get assigned to NULL somewhere here?
> >
> > -- Steve
> 
> 
> Hm, why?

Well, after we free tb_fmt, the *iter will then point to garbage. Right?

-- Steve

Re: [PATCH 3/5] ftrace: add ftrace_bprintk()

[Frédéric Weisbecker]

2009/3/2 Steven Rostedt <rostedt@goodmis.org>:
>
> On Mon, 2 Mar 2009, Fr?d?ric Weisbecker wrote:
>> >> +
>> >> +static
>> >> +void release_module_trace_bprintk_format(const char **start, const char **end)
>> >> +{
>> >> +     const char **iter;
>> >> +     lock_btrace();
>> >> +     for (iter = start; iter < end; iter++) {
>> >> +             struct trace_bprintk_fmt *tb_fmt;
>> >> +             if (!*iter)
>> >> +                     continue;
>> >> +
>> >> +             tb_fmt = container_of(*iter, struct trace_bprintk_fmt, fmt[0]);
>> >> +             tb_fmt->count--;
>> >> +             if (!tb_fmt->count && !btrace_metadata_count) {
>> >> +                     list_del(&tb_fmt->list);
>> >> +                     kfree(tb_fmt);
>> >
>> > Shouldn't *iter get assigned to NULL somewhere here?
>> >
>> > -- Steve
>>
>>
>> Hm, why?
>
> Well, after we free tb_fmt, the *iter will then point to garbage. Right?
>
> -- Steve


Now that you say it, I have some doubts about the possible sites that
can still dereference it
at this point.
I have to review and test it more seriously. I was convinced that the
count field kept track
of all references but now I'm not so sure, there can be still one
pending event that uses it into
the ring buffer, or it can be perhaps in use at the same time it is freed.
We should perhaps use rcu here, will see.

Re: [PATCH 3/5] ftrace: add ftrace_bprintk()

[Steven Rostedt]

[-- Attachment #1: Type: TEXT/PLAIN, Size: 2763 bytes --]


On Mon, 2 Mar 2009, Fr?d?ric Weisbecker wrote:

> 2009/3/2 Steven Rostedt <rostedt@goodmis.org>:
> >
> > On Mon, 2 Mar 2009, Fr?d?ric Weisbecker wrote:
> >> >> +
> >> >> +static
> >> >> +void release_module_trace_bprintk_format(const char **start, const char **end)
> >> >> +{
> >> >> +     const char **iter;
> >> >> +     lock_btrace();
> >> >> +     for (iter = start; iter < end; iter++) {
> >> >> +             struct trace_bprintk_fmt *tb_fmt;
> >> >> +             if (!*iter)
> >> >> +                     continue;
> >> >> +
> >> >> +             tb_fmt = container_of(*iter, struct trace_bprintk_fmt, fmt[0]);
> >> >> +             tb_fmt->count--;
> >> >> +             if (!tb_fmt->count && !btrace_metadata_count) {
> >> >> +                     list_del(&tb_fmt->list);
> >> >> +                     kfree(tb_fmt);
> >> >
> >> > Shouldn't *iter get assigned to NULL somewhere here?
> >> >
> >> > -- Steve
> >>
> >>
> >> Hm, why?
> >
> > Well, after we free tb_fmt, the *iter will then point to garbage. Right?
> >
> > -- Steve
> 
> 
> Now that you say it, I have some doubts about the possible sites that
> can still dereference it
> at this point.
> I have to review and test it more seriously. I was convinced that the
> count field kept track
> of all references but now I'm not so sure, there can be still one
> pending event that uses it into
> the ring buffer, or it can be perhaps in use at the same time it is freed.
> We should perhaps use rcu here, will see.
> 

How do you deal with ref counters in the ring buffer? If the ring buffer 
is set to overwrite mode (in which is usually is), then you will never 
know if a print was erased.

I haven't looked too deep into the implementation. But one safe way to
do this, with respect to modules, is the following:

#define ftrace_bprintk(fmt, args...) \
	do { \
		static const char __attribute__((section(ftrace_fmt))\
			*f = fmt; \
		_ftrace_bprintk(&f, args); \
	} while(0)

On output, you can do:

	trace_print_bprintk(...)
	{
		char **f = field->f;

		if (!f)
			trace_seq_printf(s, "MODULE UNLOADED?\n");
		trace_seq_printf(s, *f, ...)

Do you see what I'm doing?

Make the ftrace_printk create a constant pointer to the format instead
of passing in the format. It will istead pass in the address of something
pointing to the format.

Then on module load, you allocate the area and copy in all the ftrace_fmt 
sections.

On module unload, you just NULL out that area. You could probably reuse 
those NULL spots, but you would need some kind of checksum to be added 
such that a new module will be detected on print out.


This is the reason I avoided doing ftrace printk via pointers :-/

-- Steve

Re: [PATCH 3/5] ftrace: add ftrace_bprintk()

[Frédéric Weisbecker]

2009/3/2 Steven Rostedt <rostedt@goodmis.org>:
>
> On Mon, 2 Mar 2009, Fr?d?ric Weisbecker wrote:
>
>> 2009/3/2 Steven Rostedt <rostedt@goodmis.org>:
>> >
>> > On Mon, 2 Mar 2009, Fr?d?ric Weisbecker wrote:
>> >> >> +
>> >> >> +static
>> >> >> +void release_module_trace_bprintk_format(const char **start, const char **end)
>> >> >> +{
>> >> >> +     const char **iter;
>> >> >> +     lock_btrace();
>> >> >> +     for (iter = start; iter < end; iter++) {
>> >> >> +             struct trace_bprintk_fmt *tb_fmt;
>> >> >> +             if (!*iter)
>> >> >> +                     continue;
>> >> >> +
>> >> >> +             tb_fmt = container_of(*iter, struct trace_bprintk_fmt, fmt[0]);
>> >> >> +             tb_fmt->count--;
>> >> >> +             if (!tb_fmt->count && !btrace_metadata_count) {
>> >> >> +                     list_del(&tb_fmt->list);
>> >> >> +                     kfree(tb_fmt);
>> >> >
>> >> > Shouldn't *iter get assigned to NULL somewhere here?
>> >> >
>> >> > -- Steve
>> >>
>> >>
>> >> Hm, why?
>> >
>> > Well, after we free tb_fmt, the *iter will then point to garbage. Right?
>> >
>> > -- Steve
>>
>>
>> Now that you say it, I have some doubts about the possible sites that
>> can still dereference it
>> at this point.
>> I have to review and test it more seriously. I was convinced that the
>> count field kept track
>> of all references but now I'm not so sure, there can be still one
>> pending event that uses it into
>> the ring buffer, or it can be perhaps in use at the same time it is freed.
>> We should perhaps use rcu here, will see.
>>
>
> How do you deal with ref counters in the ring buffer? If the ring buffer
> is set to overwrite mode (in which is usually is), then you will never
> know if a print was erased.


Ah, I didn't think about it.

>
> I haven't looked too deep into the implementation. But one safe way to
> do this, with respect to modules, is the following:
>
> #define ftrace_bprintk(fmt, args...) \
>        do { \
>                static const char __attribute__((section(ftrace_fmt))\
>                        *f = fmt; \
>                _ftrace_bprintk(&f, args); \
>        } while(0)
>
> On output, you can do:
>
>        trace_print_bprintk(...)
>        {
>                char **f = field->f;
>
>                if (!f)
>                        trace_seq_printf(s, "MODULE UNLOADED?\n");
>                trace_seq_printf(s, *f, ...)
>
> Do you see what I'm doing?
>
> Make the ftrace_printk create a constant pointer to the format instead
> of passing in the format. It will istead pass in the address of something
> pointing to the format.
>
> Then on module load, you allocate the area and copy in all the ftrace_fmt
> sections.
>
> On module unload, you just NULL out that area. You could probably reuse
> those NULL spots, but you would need some kind of checksum to be added
> such that a new module will be detected on print out.


Yeah ok, but it seems rather complex.
I think we can still use this list of format pointers but:

- make it a hashlist of format strings
- if a module is loaded we make a copy of each printk formats but
firstly we verify if it already exists into the hashlist. If so, then
only override the format pointer on the module (don't allocate any new
thing)

_when it is unloaded...don't do anything.

So yes, perhaps we will never free these strings, but at least we
avoid duplicated formats on the
list and then somewhat limit the bad consequences.

Hm?

>
> This is the reason I avoided doing ftrace printk via pointers :-/
>
> -- Steve
>