[RFC PATCH] dynamic debug - adding ring buffer storage support

[RFC PATCH] dynamic debug - adding ring buffer storage support

[Jiri Olsa]

Hi,

as I use dynamic debug sometimes, I thought it could be useful having
the possibility to store the output somewhere else than dmesg.

The attached patch implements support for storing dynamic debug
messages to the ring buffer.

The dynamic debug allows simple addition of new flags,
so I added 'r' flag for ring buffer storage.

I used the ring buffer implementation from trace framework.

hopefuly this could be any use for others as well...
plz let me know what you think,

jirka

Signed-off-by: Jiri Olsa <jolsa@redhat.com>
---
 Documentation/dynamic-debug-howto.txt |   33 ++-
 include/linux/dynamic_debug.h         |   37 ++-
 lib/Kconfig.debug                     |    9 +
 lib/Makefile                          |    1 +
 lib/dynamic_debug.c                   |   15 +
 lib/dynamic_debug_rb.c                |  501 +++++++++++++++++++++++++++++++++
 6 files changed, 588 insertions(+), 8 deletions(-)

diff --git a/Documentation/dynamic-debug-howto.txt b/Documentation/dynamic-debug-howto.txt
index 674c566..aa05764 100644
--- a/Documentation/dynamic-debug-howto.txt
+++ b/Documentation/dynamic-debug-howto.txt
@@ -208,9 +208,34 @@ The flags are:
 p
     Causes a printk() message to be emitted to dmesg
 
-Note the regexp ^[-+=][scp]+$ matches a flags specification.
+r
+    Causes messages to be emitted to the ring buffer
+    (see 'Ring buffer output' section)
+
+Note the regexp ^[-+=][pr]+$ matches a flags specification.
 Note also that there is no convenient syntax to remove all
-the flags at once, you need to use "-psc".
+the flags at once, you need to use "-pr".
+
+Ring buffer output
+==================
+
+The ring buffer output ('r' flag) is enabled by config option
+CONFIG_DYNAMIC_DEBUG_RB. Having this option set 3 files are
+created under the '<debugfs>/dynamic_debug' directory:
+
+'trace'      - displays the current content of the ring buffer
+
+'trace_pipe' - displays and consumes all the current content of
+               the ring buffer.
+
+'rb_size_kb' - displays/set the ring buffer size in kB
+
+
+The 'trace_pipe' works in a similar manner like in the tracing
+framework. You can use 'cat trace_pipe' as a blocking reader
+for the messages.
+
+The ring buffer output can be enabled together with dmesg output.
 
 Examples
 ========
@@ -238,3 +263,7 @@ nullarbor:~ # echo -n 'func svc_process -p' >
 // enable messages for NFS calls READ, READLINK, READDIR and READDIR+.
 nullarbor:~ # echo -n 'format "nfsd: READ" +p' >
 				<debugfs>/dynamic_debug/control
+
+// enable all compiled messages output to ring buffer and dmesg
+nullarbor:~ # echo -n '+pr' >
+				<debugfs>/dynamic_debug/control
diff --git a/include/linux/dynamic_debug.h b/include/linux/dynamic_debug.h
index f8c2e17..79701ac 100644
--- a/include/linux/dynamic_debug.h
+++ b/include/linux/dynamic_debug.h
@@ -31,6 +31,7 @@ struct _ddebug {
  	 * writes commands to <debugfs>/dynamic_debug/ddebug
 	 */
 #define _DPRINTK_FLAGS_PRINT   (1<<0)  /* printk() a message using the format */
+#define _DPRINTK_FLAGS_RB      (1<<1)  /* store message to the ring buffer */
 #define _DPRINTK_FLAGS_DEFAULT 0
 	unsigned int flags:8;
 } __attribute__((aligned(8)));
@@ -50,15 +51,32 @@ extern int ddebug_remove_module(char *mod_name);
 					__ret = 1;			     \
 	__ret; })
 
+#ifdef CONFIG_DYNAMIC_DEBUG_RB
+struct dentry;
+extern int dynamic_debug_rb_init(struct dentry *dir);
+extern int dynamic_debug_rb_store(const char *fmt, ...);
+#else
+static inline int dynamic_debug_rb_store(const char *fmt, ...)
+{
+	return 0;
+}
+#endif
+
 #define dynamic_pr_debug(fmt, ...) do {					\
 	static struct _ddebug descriptor				\
 	__used								\
 	__attribute__((section("__verbose"), aligned(8))) =		\
 	{ KBUILD_MODNAME, __func__, __FILE__, fmt, DEBUG_HASH,	\
 		DEBUG_HASH2, __LINE__, _DPRINTK_FLAGS_DEFAULT };	\
-	if (__dynamic_dbg_enabled(descriptor))				\
-		printk(KERN_DEBUG pr_fmt(fmt),	##__VA_ARGS__);		\
-	} while (0)
+	if (__dynamic_dbg_enabled(descriptor)) {			\
+		if (descriptor.flags & _DPRINTK_FLAGS_PRINT)		\
+			printk(KERN_DEBUG pr_fmt(fmt),	##__VA_ARGS__);	\
+		if (descriptor.flags & _DPRINTK_FLAGS_RB)		\
+			dynamic_debug_rb_store(KBUILD_MODNAME ":"	\
+						pr_fmt(fmt),		\
+						##__VA_ARGS__);		\
+	}								\
+} while (0)
 
 
 #define dynamic_dev_dbg(dev, fmt, ...) do {				\
@@ -67,9 +85,16 @@ extern int ddebug_remove_module(char *mod_name);
 	__attribute__((section("__verbose"), aligned(8))) =		\
 	{ KBUILD_MODNAME, __func__, __FILE__, fmt, DEBUG_HASH,	\
 		DEBUG_HASH2, __LINE__, _DPRINTK_FLAGS_DEFAULT };	\
-	if (__dynamic_dbg_enabled(descriptor))				\
-		dev_printk(KERN_DEBUG, dev, fmt, ##__VA_ARGS__);	\
-	} while (0)
+	if (__dynamic_dbg_enabled(descriptor)) {			\
+		if (descriptor.flags & _DPRINTK_FLAGS_PRINT)		\
+			dev_printk(KERN_DEBUG, dev, fmt, ##__VA_ARGS__);\
+		if (descriptor.flags & _DPRINTK_FLAGS_RB)		\
+			dynamic_debug_rb_store("%s %s: " fmt,		\
+					dev_driver_string(dev),		\
+					dev_name(dev),			\
+					##__VA_ARGS__);			\
+	}								\
+} while (0)
 
 #else
 
diff --git a/lib/Kconfig.debug b/lib/Kconfig.debug
index 9943601..eb0fdee 100644
--- a/lib/Kconfig.debug
+++ b/lib/Kconfig.debug
@@ -1056,6 +1056,15 @@ config DYNAMIC_DEBUG
 
 	  See Documentation/dynamic-debug-howto.txt for additional information.
 
+config DYNAMIC_DEBUG_RB
+	bool "Use ring buffer for output"
+	default n
+	depends on DYNAMIC_DEBUG
+	help
+	  Enables the support for storing DYNAMIC_DEBUG messages into the
+	  ring buffer. The ring_buffer is accesable by 'trace' or 'trace_pipe'
+	  files (see Documentation/dynamic-debug-howto.txt).
+
 config DMA_API_DEBUG
 	bool "Enable debugging of DMA-API usage"
 	depends on HAVE_DMA_API_DEBUG
diff --git a/lib/Makefile b/lib/Makefile
index 347ad8d..80ad152 100644
--- a/lib/Makefile
+++ b/lib/Makefile
@@ -88,6 +88,7 @@ obj-$(CONFIG_HAVE_LMB) += lmb.o
 obj-$(CONFIG_HAVE_ARCH_TRACEHOOK) += syscall.o
 
 obj-$(CONFIG_DYNAMIC_DEBUG) += dynamic_debug.o
+obj-$(CONFIG_DYNAMIC_DEBUG_RB) += dynamic_debug_rb.o
 
 obj-$(CONFIG_NLATTR) += nlattr.o
 
diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
index f935029..4c322f2 100644
--- a/lib/dynamic_debug.c
+++ b/lib/dynamic_debug.c
@@ -79,6 +79,10 @@ static char *ddebug_describe_flags(struct _ddebug *dp, char *buf,
 	BUG_ON(maxlen < 4);
 	if (dp->flags & _DPRINTK_FLAGS_PRINT)
 		*p++ = 'p';
+#ifdef CONFIG_DYNAMIC_DEBUG_RB
+	if (dp->flags & _DPRINTK_FLAGS_RB)
+		*p++ = 'r';
+#endif
 	if (p == buf)
 		*p++ = '-';
 	*p = '\0';
@@ -398,6 +402,11 @@ static int ddebug_parse_flags(const char *str, unsigned int *flagsp,
 		case 'p':
 			flags |= _DPRINTK_FLAGS_PRINT;
 			break;
+#ifdef CONFIG_DYNAMIC_DEBUG_RB
+		case 'r':
+			flags |= _DPRINTK_FLAGS_RB;
+			break;
+#endif
 		default:
 			return -EINVAL;
 		}
@@ -758,6 +767,12 @@ static int __init dynamic_debug_init(void)
 		}
 		ret = ddebug_add_module(iter_start, n, modname);
 	}
+
+#ifdef CONFIG_DYNAMIC_DEBUG_RB
+	if (!ret)
+		ret = dynamic_debug_rb_init(dir);
+#endif
+
 out_free:
 	if (ret) {
 		ddebug_remove_all_tables();
diff --git a/lib/dynamic_debug_rb.c b/lib/dynamic_debug_rb.c
new file mode 100644
index 0000000..95c8638
--- /dev/null
+++ b/lib/dynamic_debug_rb.c
@@ -0,0 +1,501 @@
+/*
+ * lib/dynamic_debug_rb.c
+ *
+ * This file provide ring buffer storage for the dynamic
+ * debug messages. The ring buffer implementation from
+ * kernel/trace/ring_buffer.c is used.
+ *
+ * Copyright (C) 2009 Jiri Olsa <jolsa@redhat.com>
+ */
+
+#include <linux/kernel.h>
+#include <linux/module.h>
+#include <linux/ring_buffer.h>
+#include <linux/debugfs.h>
+#include <linux/trace_seq.h>
+#include <linux/sched.h>
+#include <linux/uaccess.h>
+
+#define DDEBUG_RB_FLAGS	(RB_FL_OVERWRITE)
+#define DDEBUG_RB_SIZE	(1000)
+
+static struct ring_buffer *rb;
+static DEFINE_MUTEX(rb_lock);
+static unsigned long rb_size_kb = DDEBUG_RB_SIZE;
+
+#define DDEBUG_TRACE_SSIZE (500)
+static char *trace_str;
+
+enum {
+	DDEBUG_TRACE_ITER_READ,
+	DDEBUG_TRACE_ITER_CONS,
+};
+
+struct ddebug_trace_iter {
+	int type;
+	int cpu;
+
+	union {
+		struct {
+			struct ring_buffer_iter *rb_iter[NR_CPUS];
+			loff_t	pos;
+		} read;
+
+		struct trace_seq seq;
+	};
+};
+
+struct ddebug_trace_entry {
+	int len;
+	char data[0];
+};
+
+int dynamic_debug_rb_store(const char *fmt, ...)
+{
+	va_list args;
+	struct ring_buffer_event *event;
+	struct ddebug_trace_entry *entry;
+	char *str;
+	int rc;
+
+	/*
+	 * This code should be reentrant for multiple CPUs,
+	 * all we care about are interrupts.
+	 */
+	preempt_disable();
+	str = per_cpu_ptr(trace_str, raw_smp_processor_id());
+
+	va_start(args, fmt);
+	rc = snprintf(str, DDEBUG_TRACE_SSIZE, fmt, args);
+	va_end(args);
+
+	if (!rc)
+		goto out;
+
+	if (rc > DDEBUG_TRACE_SSIZE)
+		rc = DDEBUG_TRACE_SSIZE;
+
+	event = ring_buffer_lock_reserve(rb, rc + sizeof(*entry));
+	if (event == NULL)
+		goto out;
+
+	entry = ring_buffer_event_data(event);
+	entry->len = rc;
+	memcpy(entry->data, str, rc);
+
+	ring_buffer_unlock_commit(rb, event);
+
+out:
+	preempt_enable();
+	return 0;
+}
+EXPORT_SYMBOL(dynamic_debug_rb_store);
+
+static int dynamic_debug_rb_resize(unsigned long size)
+{
+	unsigned long val;
+
+	size <<= 10;
+
+	if (!size ||
+	    (size == rb_size_kb))
+		return -EINVAL;
+
+	if (!mutex_trylock(&rb_lock))
+		return -EBUSY;
+
+	val = ring_buffer_resize(rb, size);
+	mutex_unlock(&rb_lock);
+
+	if (val < 0)
+		return -EINVAL;
+
+	rb_size_kb = size;
+	return 0;
+}
+
+static struct ring_buffer_event *next_event(struct ddebug_trace_iter *iter,
+					    int *cpu_ret)
+{
+	struct ring_buffer_event *event = NULL;
+	struct ring_buffer_event *event_next = NULL;
+	int cpu, cpu_next = -1;
+	u64 ts, ts_next = -1;
+
+	for_each_cpu(cpu, cpu_possible_mask) {
+
+		if (iter->type == DDEBUG_TRACE_ITER_READ) {
+			struct ring_buffer_iter *rb_iter;
+
+			rb_iter = iter->read.rb_iter[cpu];
+			event = ring_buffer_iter_peek(rb_iter, &ts);
+		} else
+			event = ring_buffer_peek(rb, cpu, &ts);
+
+		if (event && (!event_next || ts < ts_next)) {
+			event_next = event;
+			cpu_next   = cpu;
+			ts_next    = ts;
+		}
+	}
+
+	*cpu_ret = cpu_next;
+	return event_next;
+}
+
+static void *s_next(struct seq_file *m, void *p, loff_t *pos)
+{
+	struct ddebug_trace_iter *iter = m->private;
+	void *data;
+	int cpu;
+
+	(*pos)++;
+
+	do {
+		data = next_event(iter, &cpu);
+
+		if (data)
+			ring_buffer_read(iter->read.rb_iter[cpu], NULL);
+
+		iter->read.pos++;
+
+	} while (data && iter->read.pos < *pos);
+
+	return data;
+}
+
+static void *s_start(struct seq_file *m, loff_t *pos)
+{
+	struct ddebug_trace_iter *iter = m->private;
+
+	mutex_lock(&rb_lock);
+
+	if (*pos != iter->read.pos) {
+		struct ring_buffer_iter *rb_iter;
+		int cpu;
+
+		for_each_cpu(cpu, cpu_possible_mask) {
+			rb_iter = iter->read.rb_iter[cpu];
+			if (!rb_iter)
+				continue;
+
+			ring_buffer_iter_reset(rb_iter);
+		}
+	}
+
+	if (iter->read.pos == -1)
+		iter->read.pos++;
+
+	return s_next(m, NULL, pos);
+}
+
+static void s_stop(struct seq_file *m, void *p)
+{
+	mutex_unlock(&rb_lock);
+}
+
+static int s_show(struct seq_file *m, void *p)
+{
+	struct ring_buffer_event *event = p;
+
+	if (event) {
+		struct ddebug_trace_entry *entry;
+
+		entry = ring_buffer_event_data(event);
+		seq_write(m, entry->data, entry->len);
+	}
+
+	return 0;
+}
+
+static const struct seq_operations ddebug_trace_seqops = {
+	.start = s_start,
+	.next = s_next,
+	.show = s_show,
+	.stop = s_stop
+};
+
+static void trace_iter_free(struct ddebug_trace_iter *iter)
+{
+	int cpu;
+
+	if (iter->type == DDEBUG_TRACE_ITER_READ) {
+		for_each_cpu(cpu, cpu_possible_mask) {
+			struct ring_buffer_iter *rb_iter;
+
+			rb_iter = iter->read.rb_iter[cpu];
+			if (rb_iter)
+				ring_buffer_read_finish(rb_iter);
+		}
+	}
+
+	kfree(iter);
+}
+
+static struct ddebug_trace_iter *trace_iter_alloc(int type)
+{
+	struct ddebug_trace_iter *iter;
+	int cpu;
+
+	iter = kzalloc(sizeof(*iter), GFP_KERNEL);
+	if (iter == NULL)
+		return NULL;
+
+	iter->type = type;
+
+	if (type == DDEBUG_TRACE_ITER_CONS)
+		return iter;
+
+	iter->read.pos = -1;
+
+	for_each_cpu(cpu, cpu_possible_mask) {
+		struct ring_buffer_iter *rb_iter;
+
+		rb_iter = ring_buffer_read_start(rb, cpu);
+		if (!rb_iter) {
+			trace_iter_free(iter);
+			return NULL;
+		}
+
+		iter->read.rb_iter[cpu] = rb_iter;
+		ring_buffer_iter_reset(rb_iter);
+	}
+
+	return iter;
+}
+
+static int check_write(struct file *file)
+{
+	if ((file->f_mode & FMODE_WRITE) &&
+	    (file->f_flags & O_TRUNC)) {
+
+		if (!mutex_trylock(&rb_lock))
+			return -EBUSY;
+
+		ring_buffer_reset(rb);
+		mutex_unlock(&rb_lock);
+	}
+
+	return 0;
+}
+
+static int trace_open(struct inode *inode, struct file *file)
+{
+	struct ddebug_trace_iter *iter;
+	int err;
+
+	if (check_write(file))
+		return -EBUSY;
+
+	iter = trace_iter_alloc(DDEBUG_TRACE_ITER_READ);
+	if (!iter)
+		return -ENOMEM;
+
+	err = seq_open(file, &ddebug_trace_seqops);
+	if (err)
+		trace_iter_free(iter);
+	else
+		((struct seq_file *) file->private_data)->private = iter;
+
+	return err;
+}
+
+static int trace_release(struct inode *inode, struct file *file)
+{
+	struct seq_file *m = (struct seq_file *)file->private_data;
+	struct ddebug_trace_iter *iter = m->private;
+
+	seq_release(inode, file);
+	trace_iter_free(iter);
+	return 0;
+}
+
+static int trace_pipe_open(struct inode *inode, struct file *file)
+{
+	struct ddebug_trace_iter *iter;
+
+	if (check_write(file))
+		return -EBUSY;
+
+	iter = trace_iter_alloc(DDEBUG_TRACE_ITER_CONS);
+	if (!iter)
+		return -ENOMEM;
+
+	file->private_data = iter;
+	return 0;
+}
+
+static int trace_wait(struct file *file)
+{
+	while (ring_buffer_empty(rb)) {
+		if ((file->f_flags & O_NONBLOCK))
+			return -EAGAIN;
+
+		set_current_state(TASK_INTERRUPTIBLE);
+		schedule_timeout(HZ / 10);
+
+		if (signal_pending(current))
+			return -EINTR;
+	}
+
+	return 0;
+}
+
+static ssize_t trace_pipe_read(struct file *file, char __user *buf,
+			       size_t size, loff_t *ppos)
+{
+	struct ddebug_trace_iter *iter = file->private_data;
+	struct ring_buffer_event *event;
+	ssize_t sret;
+	int cpu;
+	u64 ts;
+
+	sret = trace_seq_to_user(&iter->seq, buf, size);
+	if (sret != -EBUSY)
+		return sret;
+
+	trace_seq_init(&iter->seq);
+
+	mutex_lock(&rb_lock);
+
+wait:
+	sret = trace_wait(file);
+	if (sret < 0)
+		goto out;
+
+	if (size >= PAGE_SIZE)
+		size = PAGE_SIZE - 1;
+
+	while ((event = next_event(iter, &cpu))) {
+		struct ddebug_trace_entry *entry;
+
+		entry = ring_buffer_event_data(event);
+
+		if (!trace_seq_putmem(&iter->seq, entry->data, entry->len))
+			break;
+
+		ring_buffer_consume(rb, cpu, &ts);
+	}
+
+	sret = trace_seq_to_user(&iter->seq, buf, size);
+	if (sret == -EBUSY)
+		goto wait;
+
+out:
+	mutex_unlock(&rb_lock);
+	return sret;
+}
+
+static ssize_t rb_size_kb_write(struct file *filp, const char __user *ubuf,
+				size_t cnt, loff_t *ppos)
+{
+	unsigned long val;
+	char buf[64];
+	int 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 = dynamic_debug_rb_resize(val);
+	if (ret < 0)
+		return ret;
+
+	return cnt;
+}
+
+static ssize_t rb_size_kb_read(struct file *file, char __user *ubuf,
+			       size_t cnt, loff_t *ppos)
+{
+	char buf[64];
+	int r;
+
+	r = sprintf(buf, "%lu\n", rb_size_kb);
+	return simple_read_from_buffer(ubuf, cnt, ppos, buf, r);
+}
+
+static int trace_pipe_release(struct inode *inode, struct file *file)
+{
+	struct ddebug_trace_iter *iter = file->private_data;
+	trace_iter_free(iter);
+	return 0;
+}
+
+static const struct file_operations trace_fops = {
+	.owner = THIS_MODULE,
+	.open = trace_open,
+	.read = seq_read,
+	.llseek = seq_lseek,
+	.release = trace_release,
+};
+
+static const struct file_operations trace_pipe_fops = {
+	.owner = THIS_MODULE,
+	.open = trace_pipe_open,
+	.read = trace_pipe_read,
+	.release = trace_pipe_release,
+};
+
+static const struct file_operations rb_size_kb_fops = {
+	.owner = THIS_MODULE,
+	.read  = rb_size_kb_read,
+	.write = rb_size_kb_write,
+};
+
+int __init dynamic_debug_rb_init(struct dentry *dir)
+{
+	struct dentry *file_trace;
+	struct dentry *file_trace_pipe;
+	struct dentry *file_rb_size_kb;
+
+	rb = ring_buffer_alloc(rb_size_kb,
+			       DDEBUG_RB_FLAGS);
+	if (!rb) {
+		printk(KERN_ERR "failed to allocate ring buffer!\n");
+		return -ENOMEM;
+	}
+
+	file_trace = debugfs_create_file("trace", 0644, dir, NULL,
+					 &trace_fops);
+	if (!file_trace) {
+		printk(KERN_ERR "failed to create 'trace' file!\n");
+		goto out_free_rb;
+	}
+
+	file_trace_pipe = debugfs_create_file("trace_pipe", 0644, dir, NULL,
+					      &trace_pipe_fops);
+	if (!file_trace_pipe) {
+		printk(KERN_ERR "failed to create 'trace_pipe' file!\n");
+		goto out_free_trace;
+	}
+
+	file_rb_size_kb = debugfs_create_file("rb_size_kb", 0644, dir, NULL,
+					      &rb_size_kb_fops);
+	if (!file_rb_size_kb) {
+		printk(KERN_ERR "failed to create 'rb_size_kb' file!\n");
+		goto out_free_trace_pipe;
+	}
+
+	trace_str = __alloc_percpu(DDEBUG_TRACE_SSIZE,
+				   cache_line_size());
+	if (trace_str)
+		return 0;
+
+out_free_trace_pipe:
+	debugfs_remove(file_trace_pipe);
+
+out_free_trace:
+	debugfs_remove(file_trace);
+
+out_free_rb:
+	ring_buffer_free(rb);
+	return -ENOMEM;
+}

Re: [RFC PATCH] dynamic debug - adding ring buffer storage support

[Andi Kleen]

Jiri Olsa <jolsa@redhat.com> writes:

> Hi,
>
> as I use dynamic debug sometimes, I thought it could be useful having
> the possibility to store the output somewhere else than dmesg.
>
> The attached patch implements support for storing dynamic debug
> messages to the ring buffer.
>
> The dynamic debug allows simple addition of new flags,
> so I added 'r' flag for ring buffer storage.
>
> I used the ring buffer implementation from trace framework.
>
> hopefuly this could be any use for others as well...
> plz let me know what you think,

The basic idea sounds good, but doing it all inline is a horrible 
idea. That will bloat the kernel considerably because all
users have to expand this code.

I would suggest to implement an out of line dyndebug_printk()
which does all of this out of line.

-Andi
-- 
ak@linux.intel.com -- Speaking for myself only.

Re: [RFC PATCH] dynamic debug - adding ring buffer storage support

[Jiri Olsa]

On Tue, Dec 22, 2009 at 01:06:06PM +0100, Andi Kleen wrote:
> Jiri Olsa <jolsa@redhat.com> writes:
> 
> > Hi,
> >
> > as I use dynamic debug sometimes, I thought it could be useful having
> > the possibility to store the output somewhere else than dmesg.
> >
> > The attached patch implements support for storing dynamic debug
> > messages to the ring buffer.
> >
> > The dynamic debug allows simple addition of new flags,
> > so I added 'r' flag for ring buffer storage.
> >
> > I used the ring buffer implementation from trace framework.
> >
> > hopefuly this could be any use for others as well...
> > plz let me know what you think,
> 
> The basic idea sounds good, but doing it all inline is a horrible 
> idea. That will bloat the kernel considerably because all
> users have to expand this code.
> 
> I would suggest to implement an out of line dyndebug_printk()
> which does all of this out of line.

right, I'll try to squeeze it

thanks,
jirka

> 
> -Andi
> -- 
> ak@linux.intel.com -- Speaking for myself only.

Re: [RFC PATCH] dynamic debug - adding ring buffer storage support

[Jason Baron]

On Tue, Dec 22, 2009 at 12:32:06PM +0100, Jiri Olsa wrote:
> Hi,
> 
> as I use dynamic debug sometimes, I thought it could be useful having
> the possibility to store the output somewhere else than dmesg.
> 
> The attached patch implements support for storing dynamic debug
> messages to the ring buffer.
> 
> The dynamic debug allows simple addition of new flags,
> so I added 'r' flag for ring buffer storage.
> 
> I used the ring buffer implementation from trace framework.
> 
> hopefuly this could be any use for others as well...
> plz let me know what you think,
> 
> jirka
> 

hi,

I like the idea of using the ring buffer for output. However, I'm not
sure why we need a separate one for this. I like adding the 'r' for ring
buffer storage, by why not just make this path call 'trace_printk()', and
store the string in the existing kernel tracing ring buffer? That way it
can interleave with other trace data as well.

thanks,

-Jason

Re: [RFC PATCH] dynamic debug - adding ring buffer storage support

[Jiri Olsa]

On Tue, Dec 22, 2009 at 10:39:56AM -0500, Jason Baron wrote:
> On Tue, Dec 22, 2009 at 12:32:06PM +0100, Jiri Olsa wrote:
> > Hi,
> > 
> > as I use dynamic debug sometimes, I thought it could be useful having
> > the possibility to store the output somewhere else than dmesg.
> > 
> > The attached patch implements support for storing dynamic debug
> > messages to the ring buffer.
> > 
> > The dynamic debug allows simple addition of new flags,
> > so I added 'r' flag for ring buffer storage.
> > 
> > I used the ring buffer implementation from trace framework.
> > 
> > hopefuly this could be any use for others as well...
> > plz let me know what you think,
> > 
> > jirka
> > 
> 
> hi,
> 
> I like the idea of using the ring buffer for output. However, I'm not
> sure why we need a separate one for this. I like adding the 'r' for ring
> buffer storage, by why not just make this path call 'trace_printk()', and
> store the string in the existing kernel tracing ring buffer? That way it
> can interleave with other trace data as well.

that way you need to enable tracing as well... but thats ok I guess :)

I was investigating trace events for this, but did not find a way
to put variable length argument inside... and I overlooked the
trace_printk, I'll look on it and see how it fits, thanks

also having separate ring buffer makes the 'trace'/'trace_pipe' code
really simple (suprissingly) compared to ftrace, and I thought
on this place it could last for some time.. ;)

jirka

> 
> thanks,
> 
> -Jason

Re: [RFC PATCH] dynamic debug - adding ring buffer storage support

[Ingo Molnar]

* Jiri Olsa <jolsa@redhat.com> wrote:

> On Tue, Dec 22, 2009 at 10:39:56AM -0500, Jason Baron wrote:
> > On Tue, Dec 22, 2009 at 12:32:06PM +0100, Jiri Olsa wrote:
> > > Hi,
> > > 
> > > as I use dynamic debug sometimes, I thought it could be useful having
> > > the possibility to store the output somewhere else than dmesg.
> > > 
> > > The attached patch implements support for storing dynamic debug
> > > messages to the ring buffer.
> > > 
> > > The dynamic debug allows simple addition of new flags,
> > > so I added 'r' flag for ring buffer storage.
> > > 
> > > I used the ring buffer implementation from trace framework.
> > > 
> > > hopefuly this could be any use for others as well...
> > > plz let me know what you think,
> > > 
> > > jirka
> > > 
> > 
> > hi,
> > 
> > I like the idea of using the ring buffer for output. However, I'm not
> > sure why we need a separate one for this. I like adding the 'r' for ring
> > buffer storage, by why not just make this path call 'trace_printk()', and
> > store the string in the existing kernel tracing ring buffer? That way it
> > can interleave with other trace data as well.
> 
> that way you need to enable tracing as well... but thats ok I guess :)
> 
> I was investigating trace events for this, but did not find a way
> to put variable length argument inside... and I overlooked the
> trace_printk, I'll look on it and see how it fits, thanks
> 
> also having separate ring buffer makes the 'trace'/'trace_pipe' code
> really simple (suprissingly) compared to ftrace, and I thought
> on this place it could last for some time.. ;)

I think what we want is a unified channel of events, of which printk (and 
dynamic-printk) is one form. I.e. we should add printk events and 
dynamic-printk events as well, which would show up in /debug/tracing/events/ 
in a standard ftrace event form and would be accessible to tooling that way.

For printk a single event would be enough i suspect (we dont want a separate 
event for every printk), and for dynamic-printk we want to map the existing 
dyn-printk topologies into /debug/tracing/events, to preserve the distinctions 
and controls available there.

This way in the long run we'd have one unified facility.

	Ingo

Re: [RFC PATCH] dynamic debug - adding ring buffer storage support

[Frederic Weisbecker]

On Mon, Dec 28, 2009 at 10:24:02AM +0100, Ingo Molnar wrote:
> > that way you need to enable tracing as well... but thats ok I guess :)
> > 
> > I was investigating trace events for this, but did not find a way
> > to put variable length argument inside... and I overlooked the
> > trace_printk, I'll look on it and see how it fits, thanks
> > 
> > also having separate ring buffer makes the 'trace'/'trace_pipe' code
> > really simple (suprissingly) compared to ftrace, and I thought
> > on this place it could last for some time.. ;)
> 
> I think what we want is a unified channel of events, of which printk (and 
> dynamic-printk) is one form. I.e. we should add printk events and 
> dynamic-printk events as well, which would show up in /debug/tracing/events/ 
> in a standard ftrace event form and would be accessible to tooling that way.
> 
> For printk a single event would be enough i suspect (we dont want a separate 
> event for every printk), and for dynamic-printk we want to map the existing 
> dyn-printk topologies into /debug/tracing/events, to preserve the distinctions 
> and controls available there.
> 
> This way in the long run we'd have one unified facility.
> 
> 	Ingo


That said, I sometimes dream about one event per printk.

Having, say:

/debug/tracing/events/printk/
         |
         ---- kernel/
         |      |
         |      ------- time/
         |      |        |
         |      |        ---- clocksource.c
         |      |                 |
         |      |                 --- clocksource_unstable:218/
         |      |                 |            |
         |      |                 |            ---- format
         |      |                 |            |
         |      |                 |            ---- filter
         |      |                 |            |
         |      |                 |            ---- enable
         |      |                 --- [...]
         |      ------- [...]
         |
         ---- drivers/
         |       |
         |       ---- [...]
         |
         ---- [...]


That would give a total control over every printk, trace_printk, etc...

Too bad that would bloat the memory.
Well, that could be wrapped in a single, wildly implemented (understand:
not using TRACE_EVENT macro) trace event, something able to walk through
every calls of printk, trace_printk, early_printk, etc... and imitate
a per printk event granularity.

But still it needs to be useful...

Re: [RFC PATCH] dynamic debug - adding ring buffer storage support

[Steven Rostedt]

On Wed, 2009-12-30 at 23:50 +0100, Frederic Weisbecker wrote:

> That said, I sometimes dream about one event per printk.
> 
> Having, say:
> 
> /debug/tracing/events/printk/
>          |
>          ---- kernel/
>          |      |
>          |      ------- time/
>          |      |        |
>          |      |        ---- clocksource.c
>          |      |                 |
>          |      |                 --- clocksource_unstable:218/
>          |      |                 |            |
>          |      |                 |            ---- format
>          |      |                 |            |
>          |      |                 |            ---- filter
>          |      |                 |            |
>          |      |                 |            ---- enable
>          |      |                 --- [...]
>          |      ------- [...]
>          |
>          ---- drivers/
>          |       |
>          |       ---- [...]
>          |
>          ---- [...]
> 
> 
> That would give a total control over every printk, trace_printk, etc...
> 
> Too bad that would bloat the memory.
> Well, that could be wrapped in a single, wildly implemented (understand:
> not using TRACE_EVENT macro) trace event, something able to walk through
> every calls of printk, trace_printk, early_printk, etc... and imitate
> a per printk event granularity.
> 
> But still it needs to be useful...


I think we can do the above without bloating memory. Yes we would not
need the TRACE_EVENT macro for this. The TRACE_EVENT macro is just for
generic tracing, but we could easily come up with something specific for
the printk's that will not bloat the kernel as much.

When I get some time, I may try to play with this idea.

-- Steve

Re: [RFC PATCH] dynamic debug - adding ring buffer storage support

[Ingo Molnar]

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

> On Mon, Dec 28, 2009 at 10:24:02AM +0100, Ingo Molnar wrote:
> > > that way you need to enable tracing as well... but thats ok I guess :)
> > > 
> > > I was investigating trace events for this, but did not find a way
> > > to put variable length argument inside... and I overlooked the
> > > trace_printk, I'll look on it and see how it fits, thanks
> > > 
> > > also having separate ring buffer makes the 'trace'/'trace_pipe' code
> > > really simple (suprissingly) compared to ftrace, and I thought
> > > on this place it could last for some time.. ;)
> > 
> > I think what we want is a unified channel of events, of which printk (and 
> > dynamic-printk) is one form. I.e. we should add printk events and 
> > dynamic-printk events as well, which would show up in /debug/tracing/events/ 
> > in a standard ftrace event form and would be accessible to tooling that way.
> > 
> > For printk a single event would be enough i suspect (we dont want a separate 
> > event for every printk), and for dynamic-printk we want to map the existing 
> > dyn-printk topologies into /debug/tracing/events, to preserve the distinctions 
> > and controls available there.
> > 
> > This way in the long run we'd have one unified facility.
> > 
> > 	Ingo
> 
> 
> That said, I sometimes dream about one event per printk.

Yeah - but it's only really useful if we could properly encode/extract the 
record format as well.

The one person's printk would become another person's programmable tracepoint.

> Too bad that would bloat the memory.

Should be optional of course, and then developers/distros pick instrumentation 
landscape winners/losers. To most people memory overhead is not a big issue, 
if the result is sufficiently useful.

	Ingo

Re: [RFC PATCH] dynamic debug - adding ring buffer storage support

[Jason Baron]

On Wed, Dec 30, 2009 at 08:44:17PM -0500, Steven Rostedt wrote:
> 
> > That said, I sometimes dream about one event per printk.
> > 
> > Having, say:
> > 
> > /debug/tracing/events/printk/
> >          |
> >          ---- kernel/
> >          |      |
> >          |      ------- time/
> >          |      |        |
> >          |      |        ---- clocksource.c
> >          |      |                 |
> >          |      |                 --- clocksource_unstable:218/
> >          |      |                 |            |
> >          |      |                 |            ---- format
> >          |      |                 |            |
> >          |      |                 |            ---- filter
> >          |      |                 |            |
> >          |      |                 |            ---- enable
> >          |      |                 --- [...]
> >          |      ------- [...]
> >          |
> >          ---- drivers/
> >          |       |
> >          |       ---- [...]
> >          |
> >          ---- [...]
> > 
> > 
> > That would give a total control over every printk, trace_printk, etc...
> > 
> > Too bad that would bloat the memory.
> > Well, that could be wrapped in a single, wildly implemented (understand:
> > not using TRACE_EVENT macro) trace event, something able to walk through
> > every calls of printk, trace_printk, early_printk, etc... and imitate
> > a per printk event granularity.
> > 
> > But still it needs to be useful...
> 
> 
> I think we can do the above without bloating memory. Yes we would not
> need the TRACE_EVENT macro for this. The TRACE_EVENT macro is just for
> generic tracing, but we could easily come up with something specific for
> the printk's that will not bloat the kernel as much.
> 
> When I get some time, I may try to play with this idea.
> 
> -- Steve
> 

I agree with this direction...in terms of the implementation I was
thinking it could be very similar to the tracepoint optimization i've
been working on. Where we basically end up with just a 'nop' in place of
the printk and then when we enable it we patch the 'nop' with a jump to
the proper printk location...

-Jason