various fixes v2

PATCH In review Jason Baron 3 participants 28 messages Jul 14, 2011 – Jul 18, 2011

Subsystems (5)

Networking Network drivers Library code Driver core +1 more subsystems

lore

Share & tools

lore

Jason Baron

author

2011-07-14 16:09 UTC #0 lore raw

cover various fixes v2

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(-)

Signature · 1 line

1.7.5.4

Jason Baron

author

2011-07-14 16:09 UTC #1 lore raw

PATCH 1/11 dynamic_debug: Add __dynamic_dev_dbg

From: Joe Perches <[email protected]>

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 <[email protected]>

Noticed-by Aloisio Almeida <[email protected]>

Signed-off-by Joe Perches <[email protected]>

Signed-off-by Jason Baron <[email protected]>

---
 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(-)

drivers/base/core.c +3 -2

index bc8729d..82c8654 100644
@@ -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, ...)

include/linux/device.h +5 -0

index e4f62d8..53711f2 100644
@@ -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)));

include/linux/dynamic_debug.h +8 -2

index e747ecd..bdf1531 100644
@@ -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

lib/dynamic_debug.c +38 -0

index 75ca78f..63b6f95 100644
@@ -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)
 {

Signature · 1 line

1.7.5.4

Jason Baron

author

2011-07-14 16:11 UTC #2 lore raw

PATCH 2/11 dynamic_debug: Consolidate prefix output to single routine

In reply to Jason Baron

From: Joe Perches <[email protected]>

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

Signed-off-by Joe Perches <[email protected]>

Signed-off-by Jason Baron <[email protected]>

---
 lib/dynamic_debug.c |   38 ++++++++++++++++++--------------------
 1 files changed, 18 insertions(+), 20 deletions(-)

lib/dynamic_debug.c +18 ~~-20~~

index 63b6f95..3721709 100644
@@ -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);

Signature · 1 line

1.7.5.4

Jason Baron

author

2011-07-14 16:09 UTC #3 lore raw

PATCH 3/11 dynamic_debug: Remove uses of KERN_CONT in dynamic_emit_prefix

In reply to Jason Baron

From: Joe Perches <[email protected]>

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 <[email protected]>

Signed-off-by Jason Baron <[email protected]>

---
 lib/dynamic_debug.c |   34 +++++++++++++++++++++++-----------
 1 files changed, 23 insertions(+), 11 deletions(-)

lib/dynamic_debug.c +23 ~~-11~~

index 3721709..a3eb6ab 100644
@@ -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, ...)

Signature · 1 line

1.7.5.4

Bart Van Assche

2011-07-15 10:04 UTC #4 lore raw

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

Quoted 2 lines · Jason Baron

+ 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.

Jason Baron

author

2011-07-15 15:07 UTC #5 lore raw

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

Quoted 8 lines · Bart Van Assche

Quoted 2 lines · Jason Baron
+ 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

Joe Perches

2011-07-15 15:54 UTC #6 lore raw

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

Quoted 9 lines · Jason Baron

Quoted 5 lines · Bart Van Assche
lib/dynamic_debug.c static int ddebug_exec_query(char *query_string) · line 434
Quoted 2 lines · Jason Baron
lib/dynamic_debug.c +2 -0
+       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

Quoted 3 lines

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.

Jason Baron

author

2011-07-14 16:09 UTC #7 lore raw

PATCH 4/11 dynamic_debug: Convert printks to pr_<level>

In reply to Jason Baron

From: Joe Perches <[email protected]>

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 <[email protected]>

Signed-off-by Jason Baron <[email protected]>

---
 lib/dynamic_debug.c |   59 ++++++++++++++++++++++----------------------------
 1 files changed, 26 insertions(+), 33 deletions(-)

lib/dynamic_debug.c +26 ~~-33~~

index a3eb6ab..4fc03dd 100644
@@ -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);

Signature · 1 line

1.7.5.4

Jason Baron

author

2011-07-14 16:09 UTC #8 lore raw

PATCH 5/11 dynamic_debug: remove unused control variables

In reply to Jason Baron

From: Jason Baron <[email protected]>

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 <[email protected]>

---
 include/linux/dynamic_debug.h |    7 -------
 1 files changed, 0 insertions(+), 7 deletions(-)

include/linux/dynamic_debug.h +0 -7

index bdf1531..843cb9e 100644
@@ -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,

Signature · 1 line

1.7.5.4

Jason Baron

author

2011-07-14 16:09 UTC #9 lore raw

PATCH 6/11 dynamic_debug: add Jason Baron as maintainer

In reply to Jason Baron

From: Jason Baron <[email protected]>

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

Signed-off-by Jason Baron <[email protected]>

---
 MAINTAINERS |    6 ++++++
 1 files changed, 6 insertions(+), 0 deletions(-)

MAINTAINERS +6 -0

index 187282d..84133a0 100644
@@ -2274,6 +2274,12 @@ L:	[email protected]
 S:	Maintained
 F:	drivers/net/wan/dscc4.c
 
+DYNAMIC DEBUG
+M:	Jason Baron <[email protected]>
+S:	Maintained
+F:	lib/dynamic_debug.c
+F:	include/linux/dynamic_debug.h
+
 DZ DECSTATION DZ11 SERIAL DRIVER
 M:	"Maciej W. Rozycki" <[email protected]>
 S:	Maintained

Signature · 1 line

1.7.5.4

Jason Baron

author

2011-07-14 16:09 UTC #10 lore raw

PATCH 7/11 dynamic_debug: make netdev_dbg() call __netdev_printk()

In reply to Jason Baron

From: Jason Baron <[email protected]>

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 <[email protected]>

Signed-off-by Jason Baron <[email protected]>

---
 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(-)

include/linux/dynamic_debug.h +17 -0

index 843cb9e..feaac1e 100644
@@ -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)

include/linux/netdevice.h +4 -2

index 54b8b4d..9b132ef 100644
@@ -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...)			\

lib/dynamic_debug.c +25 -0

index 4fc03dd..ee3b9ba 100644
@@ -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)
 {

net/core/dev.c +2 -1

index 9c58c1e..d6d48b2 100644
@@ -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, ...)

Signature · 1 line

1.7.5.4

Jason Baron

author

2011-07-14 16:09 UTC #11 lore raw

PATCH 8/11 dynamic_debug: make netif_dbg() call __netdev_printk()

In reply to Jason Baron

From: Jason Baron <[email protected]>

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

Cc David S. Miller <[email protected]>

Signed-off-by Jason Baron <[email protected]>

---
 include/linux/netdevice.h |    4 +---
 1 files changed, 1 insertions(+), 3 deletions(-)

include/linux/netdevice.h +1 -3

index 9b132ef..cb73e77 100644
@@ -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...)			\

Signature · 1 line

1.7.5.4

Jason Baron

author

2011-07-14 16:09 UTC #12 lore raw

PATCH 9/11 dynamic_debug: consolidate repetitive struct _ddebug descriptor definitions

In reply to Jason Baron

From: Jason Baron <[email protected]>

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

Signed-off-by Jason Baron <[email protected]>

---
 include/linux/dynamic_debug.h |   33 ++++++++++++++-------------------
 1 files changed, 14 insertions(+), 19 deletions(-)

include/linux/dynamic_debug.h +14 ~~-19~~

index feaac1e..bc75472 100644
@@ -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)

Signature · 1 line

1.7.5.4

Jason Baron

author

2011-07-14 16:10 UTC #13 lore raw

PATCH 10/11 dynamic_debug: remove num_enabled accounting

In reply to Jason Baron

From: Jason Baron <[email protected]>

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

Signed-off-by Jason Baron <[email protected]>

---
 lib/dynamic_debug.c |    7 -------
 1 files changed, 0 insertions(+), 7 deletions(-)

lib/dynamic_debug.c +0 -7

index ee3b9ba..198d2af 100644
@@ -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);

Signature · 1 line

1.7.5.4

Jason Baron

author

2011-07-14 16:10 UTC #14 lore raw

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

In reply to Jason Baron

From: Jason Baron <[email protected]>

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 <[email protected]>

---
 lib/dynamic_debug.c |   44 +++++++++++++++++++++++++-------------------
 1 files changed, 25 insertions(+), 19 deletions(-)

lib/dynamic_debug.c +25 ~~-19~~

index 198d2af..f0f692b 100644
@@ -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);

Signature · 1 line

1.7.5.4

Joe Perches

2011-07-15 06:41 UTC #15 lore raw

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

Quoted 1 line · Jason Baron

We were using KERN_CONT to combine msgs with their prefix.

[]

lib/dynamic_debug.c

Quoted 1 line

lib/dynamic_debug.c +0 -0

Perhaps instead:

Quoted 1 line

+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;

Quoted 1 line

int __dynamic_pr_debug(struct _ddebug *descriptor, const char *fmt, ...)

[]

lib/dynamic_debug.c static int dynamic_emit_prefix(const struct _ddebug *descriptor) · line 473

Quoted 2 lines

lib/dynamic_debug.c +2 -0

+	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);

Bart Van Assche

2011-07-15 10:06 UTC #16 lore raw

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

In reply to Jason Baron

Quoted 22 lines · Jason Baron

+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];
(quoted diff) +0 -0
@@ -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) ?

Quoted 8 lines

+ 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.

Joe Perches

2011-07-15 15:48 UTC #17 lore raw

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

Quoted 3 lines · Bart Van Assche

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.

Bart Van Assche

2011-07-15 15:57 UTC #18 lore raw

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

Quoted 8 lines · Joe Perches

Quoted 3 lines · Bart Van Assche
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.

Jason Baron

author

2011-07-15 16:04 UTC #19 lore raw

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

Quoted 17 lines · Bart Van Assche

Quoted 8 lines · Joe Perches
Quoted 3 lines · Bart Van Assche
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().

Quoted 5 lines

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

Joe Perches

2011-07-15 16:10 UTC #20 lore raw

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

Quoted 2 lines · Jason Baron

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.

Bart Van Assche

2011-07-15 16:10 UTC #21 lore raw

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

In reply to Jason Baron

Quoted 2 lines · Jason Baron

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.

Joe Perches

2011-07-15 16:16 UTC #22 lore raw

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

Quoted 9 lines · Bart Van Assche

Quoted 2 lines · Jason Baron
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

Jason Baron

author

2011-07-15 19:59 UTC #23 lore raw

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

Quoted 13 lines · Joe Perches

X-Scanned-By: MIMEDefang 2.68 on 10.5.110.19
Quoted 9 lines · Bart Van Assche
Quoted 2 lines · Jason Baron
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.

Quoted 4 lines

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.

Signed-off-by Jason Baron <[email protected]>

---
 lib/dynamic_debug.c |   66 +++++++++++++++++++++------------------------------
 1 files changed, 27 insertions(+), 39 deletions(-)

lib/dynamic_debug.c +27 ~~-39~~

index 198d2af..1f11978 100644
@@ -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;

Signature · 1 line

1.7.5.4

Joe Perches

2011-07-15 23:46 UTC #24 lore raw

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

Quoted 2 lines · Jason Baron

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

[]

lib/dynamic_debug.c

Quoted 1 line

lib/dynamic_debug.c +0 -0

[]

Quoted 11 lines

lib/dynamic_debug.c +4 -2

@@ -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];

lib/dynamic_debug.c static int ddebug_exec_query(char *query_string) · line 436

Quoted 10 lines

lib/dynamic_debug.c +5 -3

-	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

Jason Baron

author

2011-07-18 14:30 UTC #25 lore raw

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

Quoted 31 lines · Joe Perches

Quoted 2 lines · Jason Baron

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

[]

lib/dynamic_debug.c

Quoted 1 line

lib/dynamic_debug.c +0 -0

[]

Quoted 11 lines

lib/dynamic_debug.c +4 -2

@@ -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];

lib/dynamic_debug.c static int ddebug_exec_query(char *query_string) · line 436

Quoted 10 lines

lib/dynamic_debug.c +5 -3

-	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.

Quoted 2 lines

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

Joe Perches

2011-07-18 14:50 UTC #26 lore raw

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

Quoted 4 lines · Jason Baron

Quoted 3 lines · Joe Perches
lib/dynamic_debug.c static int ddebug_exec_query(char *query_string) · line 426
Quoted 2 lines · Jason Baron
lib/dynamic_debug.c +1 -0
+#define LEFT(wrote) ((PREFIX_SIZE - wrote) > 0) ? (PREFIX_SIZE - wrote) : 0

[]

Quoted 10 lines

Quoted 9 lines
lib/dynamic_debug.c static int ddebug_exec_query(char *query_string) · line 436
Quoted 6 lines
lib/dynamic_debug.c +4 -1
+	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.

Quoted 1 line

I see kernel code written both ways.

Perhaps one consistently used style is better than two.

Quoted 2 lines

I think it's fine as written, unless you feel
strongly about this.

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

cheers, Joe

Joe Perches

2011-07-15 16:08 UTC #27 lore raw

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

In reply to Bart Van Assche

Quoted 9 lines · Bart Van Assche

Quoted 7 lines · Joe Perches
Quoted 3 lines · Bart Van Assche
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.

Quoted 9 lines

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