[PATCH 00/11] various fixes v2

[PATCH 00/11] various fixes v2

[Jason Baron]

Hi,

A bunch of dynamic debug fixes and cleanups. Since the last post I've
incorporated review feedback, and added an additional patch, so that
we no longer need to use KERN_CONT.

Thanks,

-Jason

Joe Perches (4):
  dynamic_debug: Add __dynamic_dev_dbg
  dynamic_debug: Consolidate prefix output to single routine
  dynamic_debug: Remove uses of KERN_CONT in dynamic_emit_prefix
  dynamic_debug: Convert printks to pr_<level>

Jason Baron (7):
  dynamic_debug: remove unused control variables
  dynamic_debug: add Jason Baron as maintainer
  dynamic_debug: make netdev_dbg() call __netdev_printk()
  dynamic_debug: make netif_dbg() call __netdev_printk()
  dynamic_debug: consolidate repetitive struct _ddebug descriptor definitions
  dynamic_debug: remove num_enabled accounting
  dynamic_debug: use a single printk() to emit msgs

 MAINTAINERS                   |    6 ++
 drivers/base/core.c           |    5 +-
 include/linux/device.h        |    5 +
 include/linux/dynamic_debug.h |   51 +++++++-----
 include/linux/netdevice.h     |   10 +-
 lib/dynamic_debug.c           |  173 ++++++++++++++++++++++++++++-------------
 net/core/dev.c                |    3 +-
 7 files changed, 171 insertions(+), 82 deletions(-)

-- 
1.7.5.4

[PATCH 01/11] dynamic_debug: Add __dynamic_dev_dbg

[Jason Baron]

From: Joe Perches <joe@perches.com>

Unlike dynamic_pr_debug, dynamic uses of dev_dbg can not
currently add task_pid/KBUILD_MODNAME/__func__/__LINE__
to selected debug output.

Add a new function similar to dynamic_pr_debug to
optionally emit these prefixes.

Cc: Aloisio Almeida <aloisio.almeida@openbossa.org>
Noticed-by: Aloisio Almeida <aloisio.almeida@openbossa.org>
Signed-off-by: Joe Perches <joe@perches.com>
Signed-off-by: Jason Baron <jbaron@redhat.com>
---
 drivers/base/core.c           |    5 +++--
 include/linux/device.h        |    5 +++++
 include/linux/dynamic_debug.h |   10 ++++++++--
 lib/dynamic_debug.c           |   38 ++++++++++++++++++++++++++++++++++++++
 4 files changed, 54 insertions(+), 4 deletions(-)

diff --git a/drivers/base/core.c b/drivers/base/core.c
index bc8729d..82c8654 100644
--- a/drivers/base/core.c
+++ b/drivers/base/core.c
@@ -1764,8 +1764,8 @@ void device_shutdown(void)
 
 #ifdef CONFIG_PRINTK
 
-static int __dev_printk(const char *level, const struct device *dev,
-			struct va_format *vaf)
+int __dev_printk(const char *level, const struct device *dev,
+		 struct va_format *vaf)
 {
 	if (!dev)
 		return printk("%s(NULL device *): %pV", level, vaf);
@@ -1773,6 +1773,7 @@ static int __dev_printk(const char *level, const struct device *dev,
 	return printk("%s%s %s: %pV",
 		      level, dev_driver_string(dev), dev_name(dev), vaf);
 }
+EXPORT_SYMBOL(__dev_printk);
 
 int dev_printk(const char *level, const struct device *dev,
 	       const char *fmt, ...)
diff --git a/include/linux/device.h b/include/linux/device.h
index e4f62d8..53711f2 100644
--- a/include/linux/device.h
+++ b/include/linux/device.h
@@ -785,6 +785,8 @@ extern const char *dev_driver_string(const struct device *dev);
 
 #ifdef CONFIG_PRINTK
 
+extern int __dev_printk(const char *level, const struct device *dev,
+			struct va_format *vaf);
 extern int dev_printk(const char *level, const struct device *dev,
 		      const char *fmt, ...)
 	__attribute__ ((format (printf, 3, 4)));
@@ -805,6 +807,9 @@ extern int _dev_info(const struct device *dev, const char *fmt, ...)
 
 #else
 
+static inline int __dev_printk(const char *level, const struct device *dev,
+			       struct va_format *vaf)
+	 { return 0; }
 static inline int dev_printk(const char *level, const struct device *dev,
 		      const char *fmt, ...)
 	__attribute__ ((format (printf, 3, 4)));
diff --git a/include/linux/dynamic_debug.h b/include/linux/dynamic_debug.h
index e747ecd..bdf1531 100644
--- a/include/linux/dynamic_debug.h
+++ b/include/linux/dynamic_debug.h
@@ -47,6 +47,13 @@ extern int ddebug_remove_module(const char *mod_name);
 extern int __dynamic_pr_debug(struct _ddebug *descriptor, const char *fmt, ...)
 	__attribute__ ((format (printf, 2, 3)));
 
+struct device;
+
+extern int __dynamic_dev_dbg(struct _ddebug *descriptor,
+			     const struct device *dev,
+			     const char *fmt, ...)
+	__attribute__ ((format (printf, 3, 4)));
+
 #define dynamic_pr_debug(fmt, ...) do {					\
 	static struct _ddebug descriptor				\
 	__used								\
@@ -57,7 +64,6 @@ extern int __dynamic_pr_debug(struct _ddebug *descriptor, const char *fmt, ...)
 		__dynamic_pr_debug(&descriptor, pr_fmt(fmt), ##__VA_ARGS__); \
 	} while (0)
 
-
 #define dynamic_dev_dbg(dev, fmt, ...) do {				\
 	static struct _ddebug descriptor				\
 	__used								\
@@ -65,7 +71,7 @@ extern int __dynamic_pr_debug(struct _ddebug *descriptor, const char *fmt, ...)
 	{ KBUILD_MODNAME, __func__, __FILE__, fmt, __LINE__,		\
 		_DPRINTK_FLAGS_DEFAULT };				\
 	if (unlikely(descriptor.enabled))				\
-		dev_printk(KERN_DEBUG, dev, fmt, ##__VA_ARGS__);	\
+		__dynamic_dev_dbg(&descriptor, dev, fmt, ##__VA_ARGS__);	\
 	} while (0)
 
 #else
diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
index 75ca78f..63b6f95 100644
--- a/lib/dynamic_debug.c
+++ b/lib/dynamic_debug.c
@@ -30,6 +30,7 @@
 #include <linux/jump_label.h>
 #include <linux/hardirq.h>
 #include <linux/sched.h>
+#include <linux/device.h>
 
 extern struct _ddebug __start___verbose[];
 extern struct _ddebug __stop___verbose[];
@@ -456,6 +457,43 @@ int __dynamic_pr_debug(struct _ddebug *descriptor, const char *fmt, ...)
 }
 EXPORT_SYMBOL(__dynamic_pr_debug);
 
+int __dynamic_dev_dbg(struct _ddebug *descriptor,
+		      const struct device *dev, const char *fmt, ...)
+{
+	struct va_format vaf;
+	va_list args;
+	int res;
+
+	BUG_ON(!descriptor);
+	BUG_ON(!fmt);
+
+	va_start(args, fmt);
+
+	vaf.fmt = fmt;
+	vaf.va = &args;
+
+	res = printk(KERN_DEBUG);
+	if (descriptor->flags & _DPRINTK_FLAGS_INCL_TID) {
+		if (in_interrupt())
+			res += printk(KERN_CONT "<intr> ");
+		else
+			res += printk(KERN_CONT "[%d] ", task_pid_vnr(current));
+	}
+	if (descriptor->flags & _DPRINTK_FLAGS_INCL_MODNAME)
+		res += printk(KERN_CONT "%s:", descriptor->modname);
+	if (descriptor->flags & _DPRINTK_FLAGS_INCL_FUNCNAME)
+		res += printk(KERN_CONT "%s:", descriptor->function);
+	if (descriptor->flags & _DPRINTK_FLAGS_INCL_LINENO)
+		res += printk(KERN_CONT "%d ", descriptor->lineno);
+
+	res += __dev_printk(KERN_CONT, dev, &vaf);
+
+	va_end(args);
+
+	return res;
+}
+EXPORT_SYMBOL(__dynamic_dev_dbg);
+
 static __initdata char ddebug_setup_string[1024];
 static __init int ddebug_setup_query(char *str)
 {
-- 
1.7.5.4

[PATCH 02/11] dynamic_debug: Consolidate prefix output to single routine

[Jason Baron]

From: Joe Perches <joe@perches.com>

Adding dynamic_dev_dbg duplicated prefix output.
Consolidate that output to a single routine.

Signed-off-by: Joe Perches <joe@perches.com>
Signed-off-by: Jason Baron <jbaron@redhat.com>
---
 lib/dynamic_debug.c |   38 ++++++++++++++++++--------------------
 1 files changed, 18 insertions(+), 20 deletions(-)

diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
index 63b6f95..3721709 100644
--- a/lib/dynamic_debug.c
+++ b/lib/dynamic_debug.c
@@ -428,15 +428,10 @@ static int ddebug_exec_query(char *query_string)
 	return 0;
 }
 
-int __dynamic_pr_debug(struct _ddebug *descriptor, const char *fmt, ...)
+static int dynamic_emit_prefix(const struct _ddebug *descriptor)
 {
-	va_list args;
 	int res;
 
-	BUG_ON(!descriptor);
-	BUG_ON(!fmt);
-
-	va_start(args, fmt);
 	res = printk(KERN_DEBUG);
 	if (descriptor->flags & _DPRINTK_FLAGS_INCL_TID) {
 		if (in_interrupt())
@@ -450,7 +445,23 @@ int __dynamic_pr_debug(struct _ddebug *descriptor, const char *fmt, ...)
 		res += printk(KERN_CONT "%s:", descriptor->function);
 	if (descriptor->flags & _DPRINTK_FLAGS_INCL_LINENO)
 		res += printk(KERN_CONT "%d ", descriptor->lineno);
+
+	return res;
+}
+
+int __dynamic_pr_debug(struct _ddebug *descriptor, const char *fmt, ...)
+{
+	va_list args;
+	int res;
+
+	BUG_ON(!descriptor);
+	BUG_ON(!fmt);
+
+	va_start(args, fmt);
+
+	res = dynamic_emit_prefix(descriptor);
 	res += vprintk(fmt, args);
+
 	va_end(args);
 
 	return res;
@@ -472,20 +483,7 @@ int __dynamic_dev_dbg(struct _ddebug *descriptor,
 	vaf.fmt = fmt;
 	vaf.va = &args;
 
-	res = printk(KERN_DEBUG);
-	if (descriptor->flags & _DPRINTK_FLAGS_INCL_TID) {
-		if (in_interrupt())
-			res += printk(KERN_CONT "<intr> ");
-		else
-			res += printk(KERN_CONT "[%d] ", task_pid_vnr(current));
-	}
-	if (descriptor->flags & _DPRINTK_FLAGS_INCL_MODNAME)
-		res += printk(KERN_CONT "%s:", descriptor->modname);
-	if (descriptor->flags & _DPRINTK_FLAGS_INCL_FUNCNAME)
-		res += printk(KERN_CONT "%s:", descriptor->function);
-	if (descriptor->flags & _DPRINTK_FLAGS_INCL_LINENO)
-		res += printk(KERN_CONT "%d ", descriptor->lineno);
-
+	res = dynamic_emit_prefix(descriptor);
 	res += __dev_printk(KERN_CONT, dev, &vaf);
 
 	va_end(args);
-- 
1.7.5.4

[PATCH 03/11] dynamic_debug: Remove uses of KERN_CONT in dynamic_emit_prefix

[Jason Baron]

From: Joe Perches <joe@perches.com>

Multiple printks with KERN_CONT can be interleaved by
other printks.  Reduce the likelihood of that interleaving
by consolidating multiple calls to printk.

Signed-off-by: Joe Perches <joe@perches.com>
Signed-off-by: Jason Baron <jbaron@redhat.com>
---
 lib/dynamic_debug.c |   34 +++++++++++++++++++++++-----------
 1 files changed, 23 insertions(+), 11 deletions(-)

diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
index 3721709..a3eb6ab 100644
--- a/lib/dynamic_debug.c
+++ b/lib/dynamic_debug.c
@@ -430,23 +430,35 @@ static int ddebug_exec_query(char *query_string)
 
 static int dynamic_emit_prefix(const struct _ddebug *descriptor)
 {
-	int res;
+	char tid[sizeof(int) + sizeof(int)/2 + 4];
+	char lineno[sizeof(int) + sizeof(int)/2];
 
-	res = printk(KERN_DEBUG);
 	if (descriptor->flags & _DPRINTK_FLAGS_INCL_TID) {
 		if (in_interrupt())
-			res += printk(KERN_CONT "<intr> ");
+			snprintf(tid, sizeof(tid), "%s", "<intr> ");
 		else
-			res += printk(KERN_CONT "[%d] ", task_pid_vnr(current));
+			snprintf(tid, sizeof(tid), "[%d] ",
+				 task_pid_vnr(current));
+	} else {
+		tid[0] = 0;
 	}
-	if (descriptor->flags & _DPRINTK_FLAGS_INCL_MODNAME)
-		res += printk(KERN_CONT "%s:", descriptor->modname);
-	if (descriptor->flags & _DPRINTK_FLAGS_INCL_FUNCNAME)
-		res += printk(KERN_CONT "%s:", descriptor->function);
-	if (descriptor->flags & _DPRINTK_FLAGS_INCL_LINENO)
-		res += printk(KERN_CONT "%d ", descriptor->lineno);
 
-	return res;
+	if (descriptor->flags & _DPRINTK_FLAGS_INCL_LINENO)
+		snprintf(lineno, sizeof(lineno), "%d", descriptor->lineno);
+	else
+		lineno[0] = 0;
+
+	return printk(KERN_DEBUG "%s%s%s%s%s%s",
+		      tid,
+		      (descriptor->flags & _DPRINTK_FLAGS_INCL_MODNAME) ?
+		      descriptor->modname : "",
+		      (descriptor->flags & _DPRINTK_FLAGS_INCL_MODNAME) ?
+		      ":" : "",
+		      (descriptor->flags & _DPRINTK_FLAGS_INCL_FUNCNAME) ?
+		      descriptor->function : "",
+		      (descriptor->flags & _DPRINTK_FLAGS_INCL_FUNCNAME) ?
+		      ":" : "",
+		      lineno);
 }
 
 int __dynamic_pr_debug(struct _ddebug *descriptor, const char *fmt, ...)
-- 
1.7.5.4

[PATCH 04/11] dynamic_debug: Convert printks to pr_<level>

[Jason Baron]

From: Joe Perches <joe@perches.com>

Add pr_fmt(fmt) with __func__.
Converts "ddebug:" prefix to "dynamic_debug:".

Most likely the if (verbose) outputs could
also be converted from pr_info to pr_debug.

Signed-off-by: Joe Perches <joe@perches.com>
Signed-off-by: Jason Baron <jbaron@redhat.com>
---
 lib/dynamic_debug.c |   59 ++++++++++++++++++++++----------------------------
 1 files changed, 26 insertions(+), 33 deletions(-)

diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
index a3eb6ab..4fc03dd 100644
--- a/lib/dynamic_debug.c
+++ b/lib/dynamic_debug.c
@@ -10,6 +10,8 @@
  * Copyright (C) 2011 Bart Van Assche.  All Rights Reserved.
  */
 
+#define pr_fmt(fmt) KBUILD_MODNAME ":%s: " fmt, __func__
+
 #include <linux/kernel.h>
 #include <linux/module.h>
 #include <linux/moduleparam.h>
@@ -160,8 +162,7 @@ static void ddebug_change(const struct ddebug_query *query,
 			else
 				dp->enabled = 0;
 			if (verbose)
-				printk(KERN_INFO
-					"ddebug: changed %s:%d [%s]%s %s\n",
+				pr_info("changed %s:%d [%s]%s %s\n",
 					dp->filename, dp->lineno,
 					dt->mod_name, dp->function,
 					ddebug_describe_flags(dp, flagbuf,
@@ -171,7 +172,7 @@ static void ddebug_change(const struct ddebug_query *query,
 	mutex_unlock(&ddebug_lock);
 
 	if (!nfound && verbose)
-		printk(KERN_INFO "ddebug: no matches for query\n");
+		pr_info("no matches for query\n");
 }
 
 /*
@@ -216,10 +217,10 @@ static int ddebug_tokenize(char *buf, char *words[], int maxwords)
 
 	if (verbose) {
 		int i;
-		printk(KERN_INFO "%s: split into words:", __func__);
+		pr_info("split into words:");
 		for (i = 0 ; i < nwords ; i++)
-			printk(" \"%s\"", words[i]);
-		printk("\n");
+			pr_cont(" \"%s\"", words[i]);
+		pr_cont("\n");
 	}
 
 	return nwords;
@@ -331,16 +332,15 @@ static int ddebug_parse_query(char *words[], int nwords,
 			}
 		} else {
 			if (verbose)
-				printk(KERN_ERR "%s: unknown keyword \"%s\"\n",
-					__func__, words[i]);
+				pr_err("unknown keyword \"%s\"\n", words[i]);
 			return -EINVAL;
 		}
 	}
 
 	if (verbose)
-		printk(KERN_INFO "%s: q->function=\"%s\" q->filename=\"%s\" "
-		       "q->module=\"%s\" q->format=\"%s\" q->lineno=%u-%u\n",
-			__func__, query->function, query->filename,
+		pr_info("q->function=\"%s\" q->filename=\"%s\" "
+			"q->module=\"%s\" q->format=\"%s\" q->lineno=%u-%u\n",
+			query->function, query->filename,
 			query->module, query->format, query->first_lineno,
 			query->last_lineno);
 
@@ -369,7 +369,7 @@ static int ddebug_parse_flags(const char *str, unsigned int *flagsp,
 		return -EINVAL;
 	}
 	if (verbose)
-		printk(KERN_INFO "%s: op='%c'\n", __func__, op);
+		pr_info("op='%c'\n", op);
 
 	for ( ; *str ; ++str) {
 		for (i = ARRAY_SIZE(opt_array) - 1; i >= 0; i--) {
@@ -384,7 +384,7 @@ static int ddebug_parse_flags(const char *str, unsigned int *flagsp,
 	if (flags == 0)
 		return -EINVAL;
 	if (verbose)
-		printk(KERN_INFO "%s: flags=0x%x\n", __func__, flags);
+		pr_info("flags=0x%x\n", flags);
 
 	/* calculate final *flagsp, *maskp according to mask and op */
 	switch (op) {
@@ -402,8 +402,7 @@ static int ddebug_parse_flags(const char *str, unsigned int *flagsp,
 		break;
 	}
 	if (verbose)
-		printk(KERN_INFO "%s: *flagsp=0x%x *maskp=0x%x\n",
-			__func__, *flagsp, *maskp);
+		pr_info("*flagsp=0x%x *maskp=0x%x\n", *flagsp, *maskp);
 	return 0;
 }
 
@@ -508,7 +507,7 @@ static __initdata char ddebug_setup_string[1024];
 static __init int ddebug_setup_query(char *str)
 {
 	if (strlen(str) >= 1024) {
-		pr_warning("ddebug boot param string too large\n");
+		pr_warn("ddebug boot param string too large\n");
 		return 0;
 	}
 	strcpy(ddebug_setup_string, str);
@@ -536,8 +535,7 @@ static ssize_t ddebug_proc_write(struct file *file, const char __user *ubuf,
 		return -EFAULT;
 	tmpbuf[len] = '\0';
 	if (verbose)
-		printk(KERN_INFO "%s: read %d bytes from userspace\n",
-			__func__, (int)len);
+		pr_info("read %d bytes from userspace\n", (int)len);
 
 	ret = ddebug_exec_query(tmpbuf);
 	if (ret)
@@ -600,8 +598,7 @@ static void *ddebug_proc_start(struct seq_file *m, loff_t *pos)
 	int n = *pos;
 
 	if (verbose)
-		printk(KERN_INFO "%s: called m=%p *pos=%lld\n",
-			__func__, m, (unsigned long long)*pos);
+		pr_info("called m=%p *pos=%lld\n", m, (unsigned long long)*pos);
 
 	mutex_lock(&ddebug_lock);
 
@@ -626,8 +623,8 @@ static void *ddebug_proc_next(struct seq_file *m, void *p, loff_t *pos)
 	struct _ddebug *dp;
 
 	if (verbose)
-		printk(KERN_INFO "%s: called m=%p p=%p *pos=%lld\n",
-			__func__, m, p, (unsigned long long)*pos);
+		pr_info("called m=%p p=%p *pos=%lld\n",
+			m, p, (unsigned long long)*pos);
 
 	if (p == SEQ_START_TOKEN)
 		dp = ddebug_iter_first(iter);
@@ -650,8 +647,7 @@ static int ddebug_proc_show(struct seq_file *m, void *p)
 	char flagsbuf[8];
 
 	if (verbose)
-		printk(KERN_INFO "%s: called m=%p p=%p\n",
-			__func__, m, p);
+		pr_info("called m=%p p=%p\n", m, p);
 
 	if (p == SEQ_START_TOKEN) {
 		seq_puts(m,
@@ -676,8 +672,7 @@ static int ddebug_proc_show(struct seq_file *m, void *p)
 static void ddebug_proc_stop(struct seq_file *m, void *p)
 {
 	if (verbose)
-		printk(KERN_INFO "%s: called m=%p p=%p\n",
-			__func__, m, p);
+		pr_info("called m=%p p=%p\n", m, p);
 	mutex_unlock(&ddebug_lock);
 }
 
@@ -700,7 +695,7 @@ static int ddebug_proc_open(struct inode *inode, struct file *file)
 	int err;
 
 	if (verbose)
-		printk(KERN_INFO "%s: called\n", __func__);
+		pr_info("called\n");
 
 	iter = kzalloc(sizeof(*iter), GFP_KERNEL);
 	if (iter == NULL)
@@ -752,8 +747,7 @@ int ddebug_add_module(struct _ddebug *tab, unsigned int n,
 	mutex_unlock(&ddebug_lock);
 
 	if (verbose)
-		printk(KERN_INFO "%u debug prints in module %s\n",
-				 n, dt->mod_name);
+		pr_info("%u debug prints in module %s\n", n, dt->mod_name);
 	return 0;
 }
 EXPORT_SYMBOL_GPL(ddebug_add_module);
@@ -775,8 +769,7 @@ int ddebug_remove_module(const char *mod_name)
 	int ret = -ENOENT;
 
 	if (verbose)
-		printk(KERN_INFO "%s: removing module \"%s\"\n",
-				__func__, mod_name);
+		pr_info("removing module \"%s\"\n", mod_name);
 
 	mutex_lock(&ddebug_lock);
 	list_for_each_entry_safe(dt, nextdt, &ddebug_tables, link) {
@@ -852,8 +845,8 @@ static int __init dynamic_debug_init(void)
 	if (ddebug_setup_string[0] != '\0') {
 		ret = ddebug_exec_query(ddebug_setup_string);
 		if (ret)
-			pr_warning("Invalid ddebug boot param %s",
-				   ddebug_setup_string);
+			pr_warn("Invalid ddebug boot param %s",
+				ddebug_setup_string);
 		else
 			pr_info("ddebug initialized with string %s",
 				ddebug_setup_string);
-- 
1.7.5.4

[PATCH 05/11] dynamic_debug: remove unused control variables

[Jason Baron]

From: Jason Baron <jbaron@redhat.com>

Remove no longer used dynamic debug control variables. The
definitions were removed a while ago, but we forgot to clean
up the extern references.

Signed-off-by: Jason Baron <jbaron@redhat.com>
---
 include/linux/dynamic_debug.h |    7 -------
 1 files changed, 0 insertions(+), 7 deletions(-)

diff --git a/include/linux/dynamic_debug.h b/include/linux/dynamic_debug.h
index bdf1531..843cb9e 100644
--- a/include/linux/dynamic_debug.h
+++ b/include/linux/dynamic_debug.h
@@ -1,13 +1,6 @@
 #ifndef _DYNAMIC_DEBUG_H
 #define _DYNAMIC_DEBUG_H
 
-/* dynamic_printk_enabled, and dynamic_printk_enabled2 are bitmasks in which
- * bit n is set to 1 if any modname hashes into the bucket n, 0 otherwise. They
- * use independent hash functions, to reduce the chance of false positives.
- */
-extern long long dynamic_debug_enabled;
-extern long long dynamic_debug_enabled2;
-
 /*
  * An instance of this structure is created in a special
  * ELF section at every dynamic debug callsite.  At runtime,
-- 
1.7.5.4

[PATCH 06/11] dynamic_debug: add Jason Baron as maintainer

[Jason Baron]

From: Jason Baron <jbaron@redhat.com>

Add a maintainers entry for dynamic debug. Hopefully nobody
will object to me as maintainer...

Signed-off-by: Jason Baron <jbaron@redhat.com>
---
 MAINTAINERS |    6 ++++++
 1 files changed, 6 insertions(+), 0 deletions(-)

diff --git a/MAINTAINERS b/MAINTAINERS
index 187282d..84133a0 100644
--- a/MAINTAINERS
+++ b/MAINTAINERS
@@ -2274,6 +2274,12 @@ L:	netdev@vger.kernel.org
 S:	Maintained
 F:	drivers/net/wan/dscc4.c
 
+DYNAMIC DEBUG
+M:	Jason Baron <jbaron@redhat.com>
+S:	Maintained
+F:	lib/dynamic_debug.c
+F:	include/linux/dynamic_debug.h
+
 DZ DECSTATION DZ11 SERIAL DRIVER
 M:	"Maciej W. Rozycki" <macro@linux-mips.org>
 S:	Maintained
-- 
1.7.5.4

[PATCH 07/11] dynamic_debug: make netdev_dbg() call __netdev_printk()

[Jason Baron]

From: Jason Baron <jbaron@redhat.com>

Previously, if dynamic debug was enabled netdev_dbg() was using
dynamic_dev_dbg() to print out the underlying msg. Fix this by making
sure netdev_dbg() uses __netdev_printk().

Cc: David S. Miller <davem@davemloft.net>
Signed-off-by: Jason Baron <jbaron@redhat.com>
---
 include/linux/dynamic_debug.h |   17 +++++++++++++++++
 include/linux/netdevice.h     |    6 ++++--
 lib/dynamic_debug.c           |   25 +++++++++++++++++++++++++
 net/core/dev.c                |    3 ++-
 4 files changed, 48 insertions(+), 3 deletions(-)

diff --git a/include/linux/dynamic_debug.h b/include/linux/dynamic_debug.h
index 843cb9e..feaac1e 100644
--- a/include/linux/dynamic_debug.h
+++ b/include/linux/dynamic_debug.h
@@ -47,6 +47,13 @@ extern int __dynamic_dev_dbg(struct _ddebug *descriptor,
 			     const char *fmt, ...)
 	__attribute__ ((format (printf, 3, 4)));
 
+struct net_device;
+
+extern int __dynamic_netdev_dbg(struct _ddebug *descriptor,
+			     const struct net_device *dev,
+			     const char *fmt, ...)
+	__attribute__ ((format (printf, 3, 4)));
+
 #define dynamic_pr_debug(fmt, ...) do {					\
 	static struct _ddebug descriptor				\
 	__used								\
@@ -67,6 +74,16 @@ extern int __dynamic_dev_dbg(struct _ddebug *descriptor,
 		__dynamic_dev_dbg(&descriptor, dev, fmt, ##__VA_ARGS__);	\
 	} while (0)
 
+#define dynamic_netdev_dbg(dev, fmt, ...) do {				\
+	static struct _ddebug descriptor				\
+	__used								\
+	__attribute__((section("__verbose"), aligned(8))) =		\
+	{ KBUILD_MODNAME, __func__, __FILE__, fmt, __LINE__,		\
+		_DPRINTK_FLAGS_DEFAULT };				\
+	if (unlikely(descriptor.enabled))				\
+		__dynamic_netdev_dbg(&descriptor, dev, fmt, ##__VA_ARGS__);\
+	} while (0)
+
 #else
 
 static inline int ddebug_remove_module(const char *mod)
diff --git a/include/linux/netdevice.h b/include/linux/netdevice.h
index 54b8b4d..9b132ef 100644
--- a/include/linux/netdevice.h
+++ b/include/linux/netdevice.h
@@ -2635,6 +2635,9 @@ static inline const char *netdev_name(const struct net_device *dev)
 	return dev->name;
 }
 
+extern int __netdev_printk(const char *level, const struct net_device *dev,
+			struct va_format *vaf);
+
 extern int netdev_printk(const char *level, const struct net_device *dev,
 			 const char *format, ...)
 	__attribute__ ((format (printf, 3, 4)));
@@ -2662,8 +2665,7 @@ extern int netdev_info(const struct net_device *dev, const char *format, ...)
 #elif defined(CONFIG_DYNAMIC_DEBUG)
 #define netdev_dbg(__dev, format, args...)			\
 do {								\
-	dynamic_dev_dbg((__dev)->dev.parent, "%s: " format,	\
-			netdev_name(__dev), ##args);		\
+	dynamic_netdev_dbg(__dev, format, ##args);		\
 } while (0)
 #else
 #define netdev_dbg(__dev, format, args...)			\
diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
index 4fc03dd..ee3b9ba 100644
--- a/lib/dynamic_debug.c
+++ b/lib/dynamic_debug.c
@@ -33,6 +33,7 @@
 #include <linux/hardirq.h>
 #include <linux/sched.h>
 #include <linux/device.h>
+#include <linux/netdevice.h>
 
 extern struct _ddebug __start___verbose[];
 extern struct _ddebug __stop___verbose[];
@@ -503,6 +504,30 @@ int __dynamic_dev_dbg(struct _ddebug *descriptor,
 }
 EXPORT_SYMBOL(__dynamic_dev_dbg);
 
+int __dynamic_netdev_dbg(struct _ddebug *descriptor,
+		      const struct net_device *dev, const char *fmt, ...)
+{
+	struct va_format vaf;
+	va_list args;
+	int res;
+
+	BUG_ON(!descriptor);
+	BUG_ON(!fmt);
+
+	va_start(args, fmt);
+
+	vaf.fmt = fmt;
+	vaf.va = &args;
+
+	res = dynamic_emit_prefix(descriptor);
+	res += __netdev_printk(KERN_CONT, dev, &vaf);
+
+	va_end(args);
+
+	return res;
+}
+EXPORT_SYMBOL(__dynamic_netdev_dbg);
+
 static __initdata char ddebug_setup_string[1024];
 static __init int ddebug_setup_query(char *str)
 {
diff --git a/net/core/dev.c b/net/core/dev.c
index 9c58c1e..d6d48b2 100644
--- a/net/core/dev.c
+++ b/net/core/dev.c
@@ -6288,7 +6288,7 @@ const char *netdev_drivername(const struct net_device *dev)
 	return empty;
 }
 
-static int __netdev_printk(const char *level, const struct net_device *dev,
+int __netdev_printk(const char *level, const struct net_device *dev,
 			   struct va_format *vaf)
 {
 	int r;
@@ -6303,6 +6303,7 @@ static int __netdev_printk(const char *level, const struct net_device *dev,
 
 	return r;
 }
+EXPORT_SYMBOL(__netdev_printk);
 
 int netdev_printk(const char *level, const struct net_device *dev,
 		  const char *format, ...)
-- 
1.7.5.4

[PATCH 08/11] dynamic_debug: make netif_dbg() call __netdev_printk()

[Jason Baron]

From: Jason Baron <jbaron@redhat.com>

Previously, netif_dbg() was using dynamic_dev_dbg() to perform
the underlying printk. Fix it to use __netdev_printk(), instead.

Cc: David S. Miller <davem@davemloft.net>
Signed-off-by: Jason Baron <jbaron@redhat.com>
---
 include/linux/netdevice.h |    4 +---
 1 files changed, 1 insertions(+), 3 deletions(-)

diff --git a/include/linux/netdevice.h b/include/linux/netdevice.h
index 9b132ef..cb73e77 100644
--- a/include/linux/netdevice.h
+++ b/include/linux/netdevice.h
@@ -2732,9 +2732,7 @@ do {								\
 #define netif_dbg(priv, type, netdev, format, args...)		\
 do {								\
 	if (netif_msg_##type(priv))				\
-		dynamic_dev_dbg((netdev)->dev.parent,		\
-				"%s: " format,			\
-				netdev_name(netdev), ##args);	\
+		dynamic_netdev_dbg(netdev, format, ##args);	\
 } while (0)
 #else
 #define netif_dbg(priv, type, dev, format, args...)			\
-- 
1.7.5.4

[PATCH 09/11] dynamic_debug: consolidate repetitive struct _ddebug descriptor definitions

[Jason Baron]

From: Jason Baron <jbaron@redhat.com>

Replace the repetitive  struct _ddebug descriptor definitions with
a new DYNAMIC_DEBUG_META_DATA(fmt) macro.

Signed-off-by: Jason Baron <jbaron@redhat.com>
---
 include/linux/dynamic_debug.h |   33 ++++++++++++++-------------------
 1 files changed, 14 insertions(+), 19 deletions(-)

diff --git a/include/linux/dynamic_debug.h b/include/linux/dynamic_debug.h
index feaac1e..bc75472 100644
--- a/include/linux/dynamic_debug.h
+++ b/include/linux/dynamic_debug.h
@@ -54,33 +54,28 @@ extern int __dynamic_netdev_dbg(struct _ddebug *descriptor,
 			     const char *fmt, ...)
 	__attribute__ ((format (printf, 3, 4)));
 
+#define DYNAMIC_DEBUG_METADATA(fmt)				\
+	static struct _ddebug descriptor			\
+	__used							\
+	__attribute__((section("__verbose"), aligned(8))) =	\
+	{ KBUILD_MODNAME, __func__, __FILE__, fmt, __LINE__,	\
+		_DPRINTK_FLAGS_DEFAULT };
+
 #define dynamic_pr_debug(fmt, ...) do {					\
-	static struct _ddebug descriptor				\
-	__used								\
-	__attribute__((section("__verbose"), aligned(8))) =		\
-	{ KBUILD_MODNAME, __func__, __FILE__, fmt, __LINE__,		\
-		_DPRINTK_FLAGS_DEFAULT };				\
+	DYNAMIC_DEBUG_METADATA(fmt);					\
 	if (unlikely(descriptor.enabled))				\
-		__dynamic_pr_debug(&descriptor, pr_fmt(fmt), ##__VA_ARGS__); \
+		__dynamic_pr_debug(&descriptor, pr_fmt(fmt), ##__VA_ARGS__);\
 	} while (0)
 
 #define dynamic_dev_dbg(dev, fmt, ...) do {				\
-	static struct _ddebug descriptor				\
-	__used								\
-	__attribute__((section("__verbose"), aligned(8))) =		\
-	{ KBUILD_MODNAME, __func__, __FILE__, fmt, __LINE__,		\
-		_DPRINTK_FLAGS_DEFAULT };				\
+	DYNAMIC_DEBUG_METADATA(fmt);					\
 	if (unlikely(descriptor.enabled))				\
-		__dynamic_dev_dbg(&descriptor, dev, fmt, ##__VA_ARGS__);	\
+		__dynamic_dev_dbg(&descriptor, dev, fmt, ##__VA_ARGS__);\
 	} while (0)
 
-#define dynamic_netdev_dbg(dev, fmt, ...) do {				\
-	static struct _ddebug descriptor				\
-	__used								\
-	__attribute__((section("__verbose"), aligned(8))) =		\
-	{ KBUILD_MODNAME, __func__, __FILE__, fmt, __LINE__,		\
-		_DPRINTK_FLAGS_DEFAULT };				\
-	if (unlikely(descriptor.enabled))				\
+#define dynamic_netdev_dbg(dev, fmt, ...) do {				   \
+	DYNAMIC_DEBUG_METADATA(fmt);					   \
+	if (unlikely(descriptor.enabled))				   \
 		__dynamic_netdev_dbg(&descriptor, dev, fmt, ##__VA_ARGS__);\
 	} while (0)
 
-- 
1.7.5.4

[PATCH 10/11] dynamic_debug: remove num_enabled accounting

[Jason Baron]

From: Jason Baron <jbaron@redhat.com>

The num_enabled accouting aren't actually used anywhere - remove them.

Signed-off-by: Jason Baron <jbaron@redhat.com>
---
 lib/dynamic_debug.c |    7 -------
 1 files changed, 0 insertions(+), 7 deletions(-)

diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
index ee3b9ba..198d2af 100644
--- a/lib/dynamic_debug.c
+++ b/lib/dynamic_debug.c
@@ -42,7 +42,6 @@ struct ddebug_table {
 	struct list_head link;
 	char *mod_name;
 	unsigned int num_ddebugs;
-	unsigned int num_enabled;
 	struct _ddebug *ddebugs;
 };
 
@@ -152,11 +151,6 @@ static void ddebug_change(const struct ddebug_query *query,
 			newflags = (dp->flags & mask) | flags;
 			if (newflags == dp->flags)
 				continue;
-
-			if (!newflags)
-				dt->num_enabled--;
-			else if (!dp->flags)
-				dt->num_enabled++;
 			dp->flags = newflags;
 			if (newflags)
 				dp->enabled = 1;
@@ -764,7 +758,6 @@ int ddebug_add_module(struct _ddebug *tab, unsigned int n,
 	}
 	dt->mod_name = new_name;
 	dt->num_ddebugs = n;
-	dt->num_enabled = 0;
 	dt->ddebugs = tab;
 
 	mutex_lock(&ddebug_lock);
-- 
1.7.5.4

[PATCH 11/11] dynamic_debug: use a single printk() to emit msgs

[Jason Baron]

From: Jason Baron <jbaron@redhat.com>

We were using KERN_CONT to combine msgs with their prefix. However,
KERN_CONT is not smp safe, in the sense that it can interleave messages.
This interleaving can result in printks coming out at the wrong loglevel.
With the high frequency of printks, which dynamic debug can produce, this
is not desirable.

Thus, make dynamic_emit_prefix(), fill a char buf[64], instead
of doing a printk directly. If we enable printing out of
function, module, line, or pid info, they are placed in this
64 byte buffer. In my testing 64 bytes was enough size to fulfill
all requests. Even if its not, we can match up the printk itself
to see where its from, so to me this is no big deal.

Signed-off-by: Jason Baron <jbaron@redhat.com>
---
 lib/dynamic_debug.c |   44 +++++++++++++++++++++++++-------------------
 1 files changed, 25 insertions(+), 19 deletions(-)

diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
index 198d2af..f0f692b 100644
--- a/lib/dynamic_debug.c
+++ b/lib/dynamic_debug.c
@@ -422,7 +422,9 @@ static int ddebug_exec_query(char *query_string)
 	return 0;
 }
 
-static int dynamic_emit_prefix(const struct _ddebug *descriptor)
+#define PREFIX_SIZE 64
+
+static int dynamic_emit_prefix(const struct _ddebug *descriptor, char *buf)
 {
 	char tid[sizeof(int) + sizeof(int)/2 + 4];
 	char lineno[sizeof(int) + sizeof(int)/2];
@@ -442,31 +444,33 @@ static int dynamic_emit_prefix(const struct _ddebug *descriptor)
 	else
 		lineno[0] = 0;
 
-	return printk(KERN_DEBUG "%s%s%s%s%s%s",
-		      tid,
-		      (descriptor->flags & _DPRINTK_FLAGS_INCL_MODNAME) ?
-		      descriptor->modname : "",
-		      (descriptor->flags & _DPRINTK_FLAGS_INCL_MODNAME) ?
-		      ":" : "",
-		      (descriptor->flags & _DPRINTK_FLAGS_INCL_FUNCNAME) ?
-		      descriptor->function : "",
-		      (descriptor->flags & _DPRINTK_FLAGS_INCL_FUNCNAME) ?
-		      ":" : "",
-		      lineno);
+	return snprintf(buf, PREFIX_SIZE, KERN_DEBUG"%s%s%s%s%s%s",
+			tid,
+			(descriptor->flags & _DPRINTK_FLAGS_INCL_MODNAME) ?
+			descriptor->modname : "",
+			(descriptor->flags & _DPRINTK_FLAGS_INCL_MODNAME) ?
+			":" : "",
+			(descriptor->flags & _DPRINTK_FLAGS_INCL_FUNCNAME) ?
+			descriptor->function : "",
+			(descriptor->flags & _DPRINTK_FLAGS_INCL_FUNCNAME) ?
+			":" : "", lineno);
 }
 
 int __dynamic_pr_debug(struct _ddebug *descriptor, const char *fmt, ...)
 {
 	va_list args;
 	int res;
+	struct va_format vaf;
+	char buf[PREFIX_SIZE];
 
 	BUG_ON(!descriptor);
 	BUG_ON(!fmt);
 
 	va_start(args, fmt);
-
-	res = dynamic_emit_prefix(descriptor);
-	res += vprintk(fmt, args);
+	vaf.fmt = fmt;
+	vaf.va = &args;
+	res = dynamic_emit_prefix(descriptor, buf);
+	res += printk("%s %pV", buf, &vaf);
 
 	va_end(args);
 
@@ -480,6 +484,7 @@ int __dynamic_dev_dbg(struct _ddebug *descriptor,
 	struct va_format vaf;
 	va_list args;
 	int res;
+	char buf[PREFIX_SIZE];
 
 	BUG_ON(!descriptor);
 	BUG_ON(!fmt);
@@ -489,8 +494,8 @@ int __dynamic_dev_dbg(struct _ddebug *descriptor,
 	vaf.fmt = fmt;
 	vaf.va = &args;
 
-	res = dynamic_emit_prefix(descriptor);
-	res += __dev_printk(KERN_CONT, dev, &vaf);
+	res = dynamic_emit_prefix(descriptor, buf);
+	res += __dev_printk(buf, dev, &vaf);
 
 	va_end(args);
 
@@ -504,6 +509,7 @@ int __dynamic_netdev_dbg(struct _ddebug *descriptor,
 	struct va_format vaf;
 	va_list args;
 	int res;
+	char buf[PREFIX_SIZE];
 
 	BUG_ON(!descriptor);
 	BUG_ON(!fmt);
@@ -513,8 +519,8 @@ int __dynamic_netdev_dbg(struct _ddebug *descriptor,
 	vaf.fmt = fmt;
 	vaf.va = &args;
 
-	res = dynamic_emit_prefix(descriptor);
-	res += __netdev_printk(KERN_CONT, dev, &vaf);
+	res = dynamic_emit_prefix(descriptor, buf);
+	res += __netdev_printk(buf, dev, &vaf);
 
 	va_end(args);
 
-- 
1.7.5.4

Re: [PATCH 11/11] dynamic_debug: use a single printk() to emit msgs

[Joe Perches]

On Thu, 2011-07-14 at 12:09 -0400, Jason Baron wrote:
> We were using KERN_CONT to combine msgs with their prefix.
[]
> diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c

Perhaps instead:

> +static int dynamic_emit_prefix(const struct _ddebug *descriptor, char *buf)

static char *dynamic_emit_prefix(...)
[]

	snprintf(buf, PREFIX_SIZE, KERN_DEBUG"%s%s%s%s%s%s",

Add a space please after KERN_DEBUG

[]
	return buf;

>  int __dynamic_pr_debug(struct _ddebug *descriptor, const char *fmt, ...)
[]
> +	res = dynamic_emit_prefix(descriptor, buf);
> +	res += printk("%s %pV", buf, &vaf);

This double counts the length of dynamic_emit_prefix.
I think this and the others should be:

	res = printk("%s %pV", dynamic_emit_prefix(descriptor, buf), &vaf);
 

Re: [PATCH 03/11] dynamic_debug: Remove uses of KERN_CONT in dynamic_emit_prefix

[Bart Van Assche]

On Thu, Jul 14, 2011 at 6:09 PM, Jason Baron <jbaron@redhat.com> wrote:
> +       char tid[sizeof(int) + sizeof(int)/2 + 4];
> +       char lineno[sizeof(int) + sizeof(int)/2];

It's not clear to me where the array bounds come from ? Also, why
sizeof(int) + sizeof(int)/2 instead of sizeof(int)*3 + 1 ?

Bart.

Re: [PATCH 11/11] dynamic_debug: use a single printk() to emit msgs

[Bart Van Assche]

On Thu, Jul 14, 2011 at 6:09 PM, Jason Baron <jbaron@redhat.com> wrote:
> +static int dynamic_emit_prefix(const struct _ddebug *descriptor, char *buf)
>  {
>        char tid[sizeof(int) + sizeof(int)/2 + 4];
>        char lineno[sizeof(int) + sizeof(int)/2];
> @@ -442,31 +444,33 @@ static int dynamic_emit_prefix(const struct _ddebug *descriptor)
>        else
>                lineno[0] = 0;
>
> -       return printk(KERN_DEBUG "%s%s%s%s%s%s",
> -                     tid,
> -                     (descriptor->flags & _DPRINTK_FLAGS_INCL_MODNAME) ?
> -                     descriptor->modname : "",
> -                     (descriptor->flags & _DPRINTK_FLAGS_INCL_MODNAME) ?
> -                     ":" : "",
> -                     (descriptor->flags & _DPRINTK_FLAGS_INCL_FUNCNAME) ?
> -                     descriptor->function : "",
> -                     (descriptor->flags & _DPRINTK_FLAGS_INCL_FUNCNAME) ?
> -                     ":" : "",
> -                     lineno);
> +       return snprintf(buf, PREFIX_SIZE, KERN_DEBUG"%s%s%s%s%s%s",
> +                       tid,
> +                       (descriptor->flags & _DPRINTK_FLAGS_INCL_MODNAME) ?
> +                       descriptor->modname : "",
> +                       (descriptor->flags & _DPRINTK_FLAGS_INCL_MODNAME) ?
> +                       ":" : "",
> +                       (descriptor->flags & _DPRINTK_FLAGS_INCL_FUNCNAME) ?
> +                       descriptor->function : "",
> +                       (descriptor->flags & _DPRINTK_FLAGS_INCL_FUNCNAME) ?
> +                       ":" : "", lineno);
>  }

Not that's it important, but this change makes is possible to
eliminate the tid[] and lineno[] arrays again. Has that been
considered ?

Bart.

Re: [PATCH 03/11] dynamic_debug: Remove uses of KERN_CONT in dynamic_emit_prefix

[Jason Baron]

On Fri, Jul 15, 2011 at 12:04:22PM +0200, Bart Van Assche wrote:
> On Thu, Jul 14, 2011 at 6:09 PM, Jason Baron <jbaron@redhat.com> wrote:
> > +       char tid[sizeof(int) + sizeof(int)/2 + 4];
> > +       char lineno[sizeof(int) + sizeof(int)/2];
> 
> It's not clear to me where the array bounds come from ? Also, why
> sizeof(int) + sizeof(int)/2 instead of sizeof(int)*3 + 1 ?
> 
> Bart.

hmmm...for the tid it bounded by PID_MAX_LIMIT, which is 4 million, so
you need 7 characters + 3 for the brackets and space = 10. So that looks
right to me. Although I'm not sure where the sizeof() comes from? Joe?

For the lineno, it is 24 bits, so it can be 2^24 = 16,777,216, or 8
characters, so I think the 6 is incorrect. Although, in practice I don't
think we have any files that are that big. Joe?

Thanks,

-Jason

Re: [PATCH 11/11] dynamic_debug: use a single printk() to emit msgs

[Joe Perches]

On Fri, 2011-07-15 at 12:05 +0200, Bart Van Assche wrote:
> Not that's it important, but this change makes is possible to
> eliminate the tid[] and lineno[] arrays again. Has that been
> considered ?

tid and lineno are decimal.  Not using intermediate
arrays would require awkward contortions to snprintf
them without emitting 0 in the output.

Re: [PATCH 03/11] dynamic_debug: Remove uses of KERN_CONT in dynamic_emit_prefix

[Joe Perches]

On Fri, 2011-07-15 at 11:07 -0400, Jason Baron wrote:
> On Fri, Jul 15, 2011 at 12:04:22PM +0200, Bart Van Assche wrote:
> > On Thu, Jul 14, 2011 at 6:09 PM, Jason Baron <jbaron@redhat.com> wrote:
> > > +       char tid[sizeof(int) + sizeof(int)/2 + 4];
> > > +       char lineno[sizeof(int) + sizeof(int)/2];
> > It's not clear to me where the array bounds come from ? Also, why
> > sizeof(int) + sizeof(int)/2 instead of sizeof(int)*3 + 1 ?
> hmmm...for the tid it bounded by PID_MAX_LIMIT, which is 4 million, so
> you need 7 characters + 3 for the brackets and space = 10. So that looks
> right to me. Although I'm not sure where the sizeof() comes from? Joe?

It's incorrect.

sizeof(int) => # decimal digits + terminating 0
4 => 11
8 => 21

I think I meant to type sizeof(int) * 2 + sizeof(int) / 2 + 1

> For the lineno, it is 24 bits, so it can be 2^24 = 16,777,216, or 8
> characters, so I think the 6 is incorrect. Although, in practice I don't
> think we have any files that are that big.

Then the tid size should be based on PID_MAX_LIMIT.
I don't much care.
I just wanted to minimize stack consumption.

Re: [PATCH 11/11] dynamic_debug: use a single printk() to emit msgs

[Bart Van Assche]

On Fri, Jul 15, 2011 at 5:48 PM, Joe Perches <joe@perches.com> wrote:
> On Fri, 2011-07-15 at 12:05 +0200, Bart Van Assche wrote:
>> Not that's it important, but this change makes is possible to
>> eliminate the tid[] and lineno[] arrays again. Has that been
>> considered ?
>
> tid and lineno are decimal.  Not using intermediate
> arrays would require awkward contortions to snprintf
> them without emitting 0 in the output.

Sorry, but I do not agree with the above. The current implementation
of __dynamic_pr_debug() shows that an implementation without temporary
arrays does not require any awkward constructs. See e.g.
http://git.kernel.org/?p=linux/kernel/git/torvalds/linux-2.6.git;a=blob;f=lib/dynamic_debug.c
for the source code of the current implementation of
__dynamic_pr_debug().

This may be subjective, but my opinion is that following that style
results in shorter and more elegant code than the approach with the
temporary arrays proposed in patch 11/11.

Bart.

Re: [PATCH 11/11] dynamic_debug: use a single printk() to emit msgs

[Jason Baron]

On Fri, Jul 15, 2011 at 05:57:11PM +0200, Bart Van Assche wrote:
> On Fri, Jul 15, 2011 at 5:48 PM, Joe Perches <joe@perches.com> wrote:
> > On Fri, 2011-07-15 at 12:05 +0200, Bart Van Assche wrote:
> >> Not that's it important, but this change makes is possible to
> >> eliminate the tid[] and lineno[] arrays again. Has that been
> >> considered ?
> >
> > tid and lineno are decimal.  Not using intermediate
> > arrays would require awkward contortions to snprintf
> > them without emitting 0 in the output.
> 
> Sorry, but I do not agree with the above. The current implementation
> of __dynamic_pr_debug() shows that an implementation without temporary
> arrays does not require any awkward constructs. See e.g.
> http://git.kernel.org/?p=linux/kernel/git/torvalds/linux-2.6.git;a=blob;f=lib/dynamic_debug.c
> for the source code of the current implementation of
> __dynamic_pr_debug().
> 
> This may be subjective, but my opinion is that following that style
> results in shorter and more elegant code than the approach with the
> temporary arrays proposed in patch 11/11.
> 
> Bart.

yes, but that approach uses 'KERN_CONT'. The point of patch 11/11 is to get rid
of KERN_CONT, which is racy. 

Thanks,

-Jason

Re: [PATCH 11/11] dynamic_debug: use a single printk() to emit msgs

[Joe Perches]

On Fri, 2011-07-15 at 17:57 +0200, Bart Van Assche wrote:
> On Fri, Jul 15, 2011 at 5:48 PM, Joe Perches <joe@perches.com> wrote:
> > On Fri, 2011-07-15 at 12:05 +0200, Bart Van Assche wrote:
> >> Not that's it important, but this change makes is possible to
> >> eliminate the tid[] and lineno[] arrays again. Has that been
> >> considered ?
> > tid and lineno are decimal.  Not using intermediate
> > arrays would require awkward contortions to snprintf
> > them without emitting 0 in the output.
> Sorry, but I do not agree with the above.

Hey Bart.

Then I think you don't understand the goal
of the change.

The goal is to avoid possible interleaving
of multiple printks from different threads.

> The current implementation
> of __dynamic_pr_debug() shows that an implementation without temporary
> arrays does not require any awkward constructs. See e.g.
> http://git.kernel.org/?p=linux/kernel/git/torvalds/linux-2.6.git;a=blob;f=lib/dynamic_debug.c
> for the source code of the current implementation of
> __dynamic_pr_debug().
> This may be subjective, but my opinion is that following that style
> results in shorter and more elegant code than the approach with the
> temporary arrays proposed in patch 11/11.

It requires awkward contortions to emit
a decimal value or "" without multiple
printks or temporaries.

cheers, Joe

Re: [PATCH 11/11] dynamic_debug: use a single printk() to emit msgs

[Joe Perches]

On Fri, 2011-07-15 at 12:04 -0400, Jason Baron wrote:
> but that approach uses 'KERN_CONT'. The point of patch 11/11 is to get rid
> of KERN_CONT, which is racy. 

Not "racy" really, but it can be interleaved
by other threads so using KERN_CONT can make
the output difficult to read.

Re: [PATCH 11/11] dynamic_debug: use a single printk() to emit msgs

[Bart Van Assche]

On Fri, Jul 15, 2011 at 6:04 PM, Jason Baron <jbaron@redhat.com> wrote:
> yes, but that approach uses 'KERN_CONT'. The point of patch 11/11 is to get rid
> of KERN_CONT, which is racy.

I know. What I'm trying to explain is that since patch 11/11 modifies
dynamic_emit_prefix() such that it writes its output to a buffer there
is no longer a need to write into that buffer with a single snprintf()
call. Using multiple snprintf() calls is also fine. Hence it is
possible to eliminate the two temporary arrays (tid[] and lineno[])
from dynamic_emit_prefix() without reintroducing these races.

Bart.

Re: [PATCH 11/11] dynamic_debug: use a single printk() to emit msgs

[Joe Perches]

On Fri, 2011-07-15 at 18:10 +0200, Bart Van Assche wrote:
> On Fri, Jul 15, 2011 at 6:04 PM, Jason Baron <jbaron@redhat.com> wrote:
> > yes, but that approach uses 'KERN_CONT'. The point of patch 11/11 is to get rid
> > of KERN_CONT, which is racy.
> I know. What I'm trying to explain is that since patch 11/11 modifies
> dynamic_emit_prefix() such that it writes its output to a buffer there
> is no longer a need to write into that buffer with a single snprintf()
> call. Using multiple snprintf() calls is also fine. Hence it is
> possible to eliminate the two temporary arrays (tid[] and lineno[])
> from dynamic_emit_prefix() without reintroducing these races.

Ah, just so.  It's so easy to be narrow minded.

Jason, you are going to do this yes?

cheers, Joe

Re: [PATCH 11/11 re-post] dynamic_debug: use a single printk() to emit msgs

[Jason Baron]

On Fri, Jul 15, 2011 at 09:16:20AM -0700, Joe Perches wrote:
> X-Scanned-By: MIMEDefang 2.68 on 10.5.110.19
> 
> On Fri, 2011-07-15 at 18:10 +0200, Bart Van Assche wrote:
> > On Fri, Jul 15, 2011 at 6:04 PM, Jason Baron <jbaron@redhat.com> wrote:
> > > yes, but that approach uses 'KERN_CONT'. The point of patch 11/11 is to get rid
> > > of KERN_CONT, which is racy.
> > I know. What I'm trying to explain is that since patch 11/11 modifies
> > dynamic_emit_prefix() such that it writes its output to a buffer there
> > is no longer a need to write into that buffer with a single snprintf()
> > call. Using multiple snprintf() calls is also fine. Hence it is
> > possible to eliminate the two temporary arrays (tid[] and lineno[])
> > from dynamic_emit_prefix() without reintroducing these races.
> 
> Ah, just so.  It's so easy to be narrow minded.
> 
> Jason, you are going to do this yes?
> 

Yes. ok here's Bart's suggestion as re-post. It looks much cleaner to
me...

thanks,

-Jason


We were using KERN_CONT to combine msgs with their prefix. However,
KERN_CONT is not smp safe, in the sense that it can interleave messages.
This interleaving can result in printks coming out at the wrong loglevel.
With the high frequency of printks, that dynamic debug can produce, this
is not desirable.

Thus, make dynamic_emit_prefix(), fill a char buf[64], instead
of doing a printk directly. If we enable printing out of
function, module, line, or pid info, they are placed in this
64 byte buffer. In my testing 64 bytes was enough size to fulfill
all requests. Even if its not, we can match up the printk itself
to see where its from, so to me this is no big deal.

Signed-off-by: Jason Baron <jbaron@redhat.com>
---
 lib/dynamic_debug.c |   66 +++++++++++++++++++++------------------------------
 1 files changed, 27 insertions(+), 39 deletions(-)

diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
index 198d2af..1f11978 100644
--- a/lib/dynamic_debug.c
+++ b/lib/dynamic_debug.c
@@ -422,52 +422,46 @@ static int ddebug_exec_query(char *query_string)
 	return 0;
 }
 
-static int dynamic_emit_prefix(const struct _ddebug *descriptor)
+#define PREFIX_SIZE 64
+#define LEFT(wrote) ((PREFIX_SIZE - wrote) > 0) ? (PREFIX_SIZE - wrote) : 0
+
+static char *dynamic_emit_prefix(const struct _ddebug *desc, char *buf)
 {
-	char tid[sizeof(int) + sizeof(int)/2 + 4];
-	char lineno[sizeof(int) + sizeof(int)/2];
+	int pos = 0;
 
-	if (descriptor->flags & _DPRINTK_FLAGS_INCL_TID) {
+	pos += snprintf(buf + pos, LEFT(pos), "%s", KERN_DEBUG);
+	if (desc->flags & _DPRINTK_FLAGS_INCL_TID) {
 		if (in_interrupt())
-			snprintf(tid, sizeof(tid), "%s", "<intr> ");
+			pos += snprintf(buf + pos, LEFT(pos), "%s ",
+						"<intr>");
 		else
-			snprintf(tid, sizeof(tid), "[%d] ",
-				 task_pid_vnr(current));
-	} else {
-		tid[0] = 0;
+			pos += snprintf(buf + pos, LEFT(pos), "[%d] ",
+						task_pid_vnr(current));
 	}
+	if (desc->flags & _DPRINTK_FLAGS_INCL_MODNAME)
+		pos += snprintf(buf + pos, LEFT(pos), "%s:", desc->modname);
+	if (desc->flags & _DPRINTK_FLAGS_INCL_FUNCNAME)
+		pos += snprintf(buf + pos, LEFT(pos), "%s:", desc->function);
+	if (desc->flags & _DPRINTK_FLAGS_INCL_LINENO)
+		pos += snprintf(buf + pos, LEFT(pos), "%d ", desc->lineno);
 
-	if (descriptor->flags & _DPRINTK_FLAGS_INCL_LINENO)
-		snprintf(lineno, sizeof(lineno), "%d", descriptor->lineno);
-	else
-		lineno[0] = 0;
-
-	return printk(KERN_DEBUG "%s%s%s%s%s%s",
-		      tid,
-		      (descriptor->flags & _DPRINTK_FLAGS_INCL_MODNAME) ?
-		      descriptor->modname : "",
-		      (descriptor->flags & _DPRINTK_FLAGS_INCL_MODNAME) ?
-		      ":" : "",
-		      (descriptor->flags & _DPRINTK_FLAGS_INCL_FUNCNAME) ?
-		      descriptor->function : "",
-		      (descriptor->flags & _DPRINTK_FLAGS_INCL_FUNCNAME) ?
-		      ":" : "",
-		      lineno);
+	return buf;
 }
 
 int __dynamic_pr_debug(struct _ddebug *descriptor, const char *fmt, ...)
 {
 	va_list args;
 	int res;
+	struct va_format vaf;
+	char buf[PREFIX_SIZE];
 
 	BUG_ON(!descriptor);
 	BUG_ON(!fmt);
 
 	va_start(args, fmt);
-
-	res = dynamic_emit_prefix(descriptor);
-	res += vprintk(fmt, args);
-
+	vaf.fmt = fmt;
+	vaf.va = &args;
+	res = printk("%s%pV", dynamic_emit_prefix(descriptor, buf), &vaf);
 	va_end(args);
 
 	return res;
@@ -480,18 +474,15 @@ int __dynamic_dev_dbg(struct _ddebug *descriptor,
 	struct va_format vaf;
 	va_list args;
 	int res;
+	char buf[PREFIX_SIZE];
 
 	BUG_ON(!descriptor);
 	BUG_ON(!fmt);
 
 	va_start(args, fmt);
-
 	vaf.fmt = fmt;
 	vaf.va = &args;
-
-	res = dynamic_emit_prefix(descriptor);
-	res += __dev_printk(KERN_CONT, dev, &vaf);
-
+	res = __dev_printk(dynamic_emit_prefix(descriptor, buf), dev, &vaf);
 	va_end(args);
 
 	return res;
@@ -504,18 +495,15 @@ int __dynamic_netdev_dbg(struct _ddebug *descriptor,
 	struct va_format vaf;
 	va_list args;
 	int res;
+	char buf[PREFIX_SIZE];
 
 	BUG_ON(!descriptor);
 	BUG_ON(!fmt);
 
 	va_start(args, fmt);
-
 	vaf.fmt = fmt;
 	vaf.va = &args;
-
-	res = dynamic_emit_prefix(descriptor);
-	res += __netdev_printk(KERN_CONT, dev, &vaf);
-
+	res = __netdev_printk(dynamic_emit_prefix(descriptor, buf), dev, &vaf);
 	va_end(args);
 
 	return res;
-- 
1.7.5.4

Re: [PATCH 11/11 re-post] dynamic_debug: use a single printk() to emit msgs

[Joe Perches]

On Fri, 2011-07-15 at 15:59 -0400, Jason Baron wrote:
> here's Bart's suggestion as re-post. It looks much cleaner to
> me...
[]
> diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
[]
> @@ -422,52 +422,46 @@ static int ddebug_exec_query(char *query_string)
>  	return 0;
>  }
>  
> -static int dynamic_emit_prefix(const struct _ddebug *descriptor)
> +#define PREFIX_SIZE 64
> +#define LEFT(wrote) ((PREFIX_SIZE - wrote) > 0) ? (PREFIX_SIZE - wrote) : 0
> +
> +static char *dynamic_emit_prefix(const struct _ddebug *desc, char *buf)
>  {
> -	char tid[sizeof(int) + sizeof(int)/2 + 4];
> -	char lineno[sizeof(int) + sizeof(int)/2];
> +	int pos = 0;
>  
> -	if (descriptor->flags & _DPRINTK_FLAGS_INCL_TID) {
> +	pos += snprintf(buf + pos, LEFT(pos), "%s", KERN_DEBUG);
> +	if (desc->flags & _DPRINTK_FLAGS_INCL_TID) {
>  		if (in_interrupt())
> -			snprintf(tid, sizeof(tid), "%s", "<intr> ");
> +			pos += snprintf(buf + pos, LEFT(pos), "%s ",
> +						"<intr>");

scnprintf works without using LEFT.
snprintf does as well.

http://lkml.org/lkml/2010/7/23/375

Re: [PATCH 11/11 re-post] dynamic_debug: use a single printk() to emit msgs

[Jason Baron]

On Fri, Jul 15, 2011 at 04:46:31PM -0700, Joe Perches wrote:
> On Fri, 2011-07-15 at 15:59 -0400, Jason Baron wrote:
> > here's Bart's suggestion as re-post. It looks much cleaner to
> > me...
> []
> > diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
> []
> > @@ -422,52 +422,46 @@ static int ddebug_exec_query(char *query_string)
> >  	return 0;
> >  }
> >  
> > -static int dynamic_emit_prefix(const struct _ddebug *descriptor)
> > +#define PREFIX_SIZE 64
> > +#define LEFT(wrote) ((PREFIX_SIZE - wrote) > 0) ? (PREFIX_SIZE - wrote) : 0
> > +
> > +static char *dynamic_emit_prefix(const struct _ddebug *desc, char *buf)
> >  {
> > -	char tid[sizeof(int) + sizeof(int)/2 + 4];
> > -	char lineno[sizeof(int) + sizeof(int)/2];
> > +	int pos = 0;
> >  
> > -	if (descriptor->flags & _DPRINTK_FLAGS_INCL_TID) {
> > +	pos += snprintf(buf + pos, LEFT(pos), "%s", KERN_DEBUG);
> > +	if (desc->flags & _DPRINTK_FLAGS_INCL_TID) {
> >  		if (in_interrupt())
> > -			snprintf(tid, sizeof(tid), "%s", "<intr> ");
> > +			pos += snprintf(buf + pos, LEFT(pos), "%s ",
> > +						"<intr>");
> 
> scnprintf works without using LEFT.
> snprintf does as well.
> 
> http://lkml.org/lkml/2010/7/23/375
> 

So you're saying, just pass (PREFIX_SIZE - pos), as the second argument? I see
kernel code written both ways. I think it's fine as written, unless you feel
strongly about this.

thanks,

-Jason

Re: [PATCH 11/11 re-post] dynamic_debug: use a single printk() to emit msgs

[Joe Perches]

On Mon, 2011-07-18 at 10:30 -0400, Jason Baron wrote:
> On Fri, Jul 15, 2011 at 04:46:31PM -0700, Joe Perches wrote:
> > On Fri, 2011-07-15 at 15:59 -0400, Jason Baron wrote:
> > > diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
> > > +#define LEFT(wrote) ((PREFIX_SIZE - wrote) > 0) ? (PREFIX_SIZE - wrote) : 0
[]
> > > +	pos += snprintf(buf + pos, LEFT(pos), "%s", KERN_DEBUG);
> > > +	if (desc->flags & _DPRINTK_FLAGS_INCL_TID) {
> > >  		if (in_interrupt())
> > > -			snprintf(tid, sizeof(tid), "%s", "<intr> ");
> > > +			pos += snprintf(buf + pos, LEFT(pos), "%s ",
> > > +						"<intr>");
> > scnprintf works without using LEFT.
> > snprintf does as well.
> > http://lkml.org/lkml/2010/7/23/375
> So you're saying, just pass (PREFIX_SIZE - pos), as the second argument?

Yes.

> I see kernel code written both ways.

Perhaps one consistently used style is better than two.
 
> I think it's fine as written, unless you feel
> strongly about this.

You're the maintainer, do what you think best.

cheers, Joe

[PATCH 11/11] dynamic_debug: use a single printk() to emit msgs

[Jason Baron]

From: Jason Baron <jbaron@redhat.com>

We were using KERN_CONT to combine msgs with their prefix. However,
KERN_CONT is not smp safe, in the sense that it can interleave messages.
This interleaving can result in printks coming out at the wrong loglevel.
With the high frequency of printks, that dynamic debug can produce, this
is not desirable.

Thus, make dynamic_emit_prefix(), fill a char buf[64], instead
of doing a printk directly. If we enable printing out of
function, module, line, or pid info, they are placed in this
64 byte buffer. In my testing 64 bytes was enough size to fulfill
all requests. Even if its not, we can match up the printk itself
to see where its from, so to me this is no big deal.

Signed-off-by: Jason Baron <jbaron@redhat.com>
---
 lib/dynamic_debug.c |   66 +++++++++++++++++++++------------------------------
 1 files changed, 27 insertions(+), 39 deletions(-)

diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
index 198d2af..1f11978 100644
--- a/lib/dynamic_debug.c
+++ b/lib/dynamic_debug.c
@@ -422,52 +422,46 @@ static int ddebug_exec_query(char *query_string)
 	return 0;
 }
 
-static int dynamic_emit_prefix(const struct _ddebug *descriptor)
+#define PREFIX_SIZE 64
+#define LEFT(wrote) ((PREFIX_SIZE - wrote) > 0) ? (PREFIX_SIZE - wrote) : 0
+
+static char *dynamic_emit_prefix(const struct _ddebug *desc, char *buf)
 {
-	char tid[sizeof(int) + sizeof(int)/2 + 4];
-	char lineno[sizeof(int) + sizeof(int)/2];
+	int pos = 0;
 
-	if (descriptor->flags & _DPRINTK_FLAGS_INCL_TID) {
+	pos += snprintf(buf + pos, LEFT(pos), "%s", KERN_DEBUG);
+	if (desc->flags & _DPRINTK_FLAGS_INCL_TID) {
 		if (in_interrupt())
-			snprintf(tid, sizeof(tid), "%s", "<intr> ");
+			pos += snprintf(buf + pos, LEFT(pos), "%s ",
+						"<intr>");
 		else
-			snprintf(tid, sizeof(tid), "[%d] ",
-				 task_pid_vnr(current));
-	} else {
-		tid[0] = 0;
+			pos += snprintf(buf + pos, LEFT(pos), "[%d] ",
+						task_pid_vnr(current));
 	}
+	if (desc->flags & _DPRINTK_FLAGS_INCL_MODNAME)
+		pos += snprintf(buf + pos, LEFT(pos), "%s:", desc->modname);
+	if (desc->flags & _DPRINTK_FLAGS_INCL_FUNCNAME)
+		pos += snprintf(buf + pos, LEFT(pos), "%s:", desc->function);
+	if (desc->flags & _DPRINTK_FLAGS_INCL_LINENO)
+		pos += snprintf(buf + pos, LEFT(pos), "%d ", desc->lineno);
 
-	if (descriptor->flags & _DPRINTK_FLAGS_INCL_LINENO)
-		snprintf(lineno, sizeof(lineno), "%d", descriptor->lineno);
-	else
-		lineno[0] = 0;
-
-	return printk(KERN_DEBUG "%s%s%s%s%s%s",
-		      tid,
-		      (descriptor->flags & _DPRINTK_FLAGS_INCL_MODNAME) ?
-		      descriptor->modname : "",
-		      (descriptor->flags & _DPRINTK_FLAGS_INCL_MODNAME) ?
-		      ":" : "",
-		      (descriptor->flags & _DPRINTK_FLAGS_INCL_FUNCNAME) ?
-		      descriptor->function : "",
-		      (descriptor->flags & _DPRINTK_FLAGS_INCL_FUNCNAME) ?
-		      ":" : "",
-		      lineno);
+	return buf;
 }
 
 int __dynamic_pr_debug(struct _ddebug *descriptor, const char *fmt, ...)
 {
 	va_list args;
 	int res;
+	struct va_format vaf;
+	char buf[PREFIX_SIZE];
 
 	BUG_ON(!descriptor);
 	BUG_ON(!fmt);
 
 	va_start(args, fmt);
-
-	res = dynamic_emit_prefix(descriptor);
-	res += vprintk(fmt, args);
-
+	vaf.fmt = fmt;
+	vaf.va = &args;
+	res = printk("%s%pV", dynamic_emit_prefix(descriptor, buf), &vaf);
 	va_end(args);
 
 	return res;
@@ -480,18 +474,15 @@ int __dynamic_dev_dbg(struct _ddebug *descriptor,
 	struct va_format vaf;
 	va_list args;
 	int res;
+	char buf[PREFIX_SIZE];
 
 	BUG_ON(!descriptor);
 	BUG_ON(!fmt);
 
 	va_start(args, fmt);
-
 	vaf.fmt = fmt;
 	vaf.va = &args;
-
-	res = dynamic_emit_prefix(descriptor);
-	res += __dev_printk(KERN_CONT, dev, &vaf);
-
+	res = __dev_printk(dynamic_emit_prefix(descriptor, buf), dev, &vaf);
 	va_end(args);
 
 	return res;
@@ -504,18 +495,15 @@ int __dynamic_netdev_dbg(struct _ddebug *descriptor,
 	struct va_format vaf;
 	va_list args;
 	int res;
+	char buf[PREFIX_SIZE];
 
 	BUG_ON(!descriptor);
 	BUG_ON(!fmt);
 
 	va_start(args, fmt);
-
 	vaf.fmt = fmt;
 	vaf.va = &args;
-
-	res = dynamic_emit_prefix(descriptor);
-	res += __netdev_printk(KERN_CONT, dev, &vaf);
-
+	res = __netdev_printk(dynamic_emit_prefix(descriptor, buf), dev, &vaf);
 	va_end(args);
 
 	return res;
-- 
1.7.5.4