[PATCH 0/3] dyndbg: dev_dbg bugfix + 2 trivials

[PATCH 0/3] dyndbg: dev_dbg bugfix + 2 trivials

[Jim Cromie]

3 patches here, 1st is bugfix, others are trivial.

1- fix __dev_printk, which broke dev_dbg() prefix under CONFIG_DYNAMIC_DEBUG.

2- change dyndbg prefix interfield separator from ':' to '.'

for example (output from test-code, not submitted):
r8169 0000:02:00.0: r8169.rtl_init_one: set-drvdata pdev:ffff880223041000 dev:ffff880220d6a000
hwmon hwmon1: k10temp.k10temp_probe.180: set-drvdata pdev:ffff88022303d000 dev:ffff8801dfd2a000

This improves usability of cut -d: <logfile> for pr_debug() messages,
as field position is less volatile with various uses of dyndbg flags.
Its not perfect:
- dev_dbg on net-devices adds several more colons,
  but this doesnt vary with dyndbg flags. 
- dyndbg=+pfmlt still adds a field vs dyndbg==p (ie no prefix)
- pr_fmt() commonly adds another colon (unchanged with this patch)
  
3- trivial var name change in lib/dynamic_debug.c


Please drop or apply 2,3 as you prefer.

[PATCH 1/3] drivers-core: make structured logging play nice with dynamic-debug

[Jim Cromie]

commit c4e00daaa96d3a0786f1f4fe6456281c60ef9a16 changed __dev_printk
in a way that broke dynamic-debug's ability to control the dynamic
prefix of dev_dbg(dev,..), but not dev_dbg(NULL,..) or pr_debug(..),
which is why it wasnt noticed sooner.

When dev==NULL, __dev_printk() just calls printk(), which just works.
But otherwise, it assumed that level was always a string like "<L>"
and just plucked out the 'L', ignoring the rest.  However,
dynamic_emit_prefix() adds "[tid] module:func:line:" to the string,
those additions all got lost.

Signed-off-by: Jim Cromie <jim.cromie@gmail.com>
---
 drivers/base/core.c |    9 +++++++--
 1 file changed, 7 insertions(+), 2 deletions(-)

diff --git a/drivers/base/core.c b/drivers/base/core.c
index 346be8b..ebdb7c5 100644
--- a/drivers/base/core.c
+++ b/drivers/base/core.c
@@ -1848,6 +1848,7 @@ int __dev_printk(const char *level, const struct device *dev,
 		 struct va_format *vaf)
 {
 	char dict[128];
+	const char *level_extra = "";
 	size_t dictlen = 0;
 	const char *subsys;
 
@@ -1894,10 +1895,14 @@ int __dev_printk(const char *level, const struct device *dev,
 				    "DEVICE=+%s:%s", subsys, dev_name(dev));
 	}
 skip:
+	if (level[3])
+		level_extra = &level[3]; /* skip past "<L>" */
+
 	return printk_emit(0, level[1] - '0',
 			   dictlen ? dict : NULL, dictlen,
-			   "%s %s: %pV",
-			   dev_driver_string(dev), dev_name(dev), vaf);
+			   "%s %s: %s%pV", 
+			   dev_driver_string(dev), dev_name(dev),
+			   level_extra, vaf);
 }
 EXPORT_SYMBOL(__dev_printk);
 
-- 
1.7.10.4

[PATCH 1/3] drivers-core: make structured logging play nice with dynamic-debug

[Jim Cromie]

commit c4e00daaa96d3a0786f1f4fe6456281c60ef9a16 changed __dev_printk
in a way that broke dynamic-debug's ability to control the dynamic
prefix of dev_dbg(dev,..), but not dev_dbg(NULL,..) or pr_debug(..),
which is why it wasnt noticed sooner.

When dev==NULL, __dev_printk() just calls printk(), which just works.
But otherwise, it assumed that level was always a string like "<L>"
and just plucked out the 'L', ignoring the rest.  However,
dynamic_emit_prefix() adds "[tid] module:func:line:" to the string,
those additions all got lost.

Signed-off-by: Jim Cromie <jim.cromie@gmail.com>
---
 drivers/base/core.c |    9 +++++++--
 1 file changed, 7 insertions(+), 2 deletions(-)

diff --git a/drivers/base/core.c b/drivers/base/core.c
index 346be8b..ebdb7c5 100644
--- a/drivers/base/core.c
+++ b/drivers/base/core.c
@@ -1848,6 +1848,7 @@ int __dev_printk(const char *level, const struct device *dev,
 		 struct va_format *vaf)
 {
 	char dict[128];
+	const char *level_extra = "";
 	size_t dictlen = 0;
 	const char *subsys;
 
@@ -1894,10 +1895,14 @@ int __dev_printk(const char *level, const struct device *dev,
 				    "DEVICE=+%s:%s", subsys, dev_name(dev));
 	}
 skip:
+	if (level[3])
+		level_extra = &level[3]; /* skip past "<L>" */
+
 	return printk_emit(0, level[1] - '0',
 			   dictlen ? dict : NULL, dictlen,
-			   "%s %s: %pV",
-			   dev_driver_string(dev), dev_name(dev), vaf);
+			   "%s %s: %s%pV", 
+			   dev_driver_string(dev), dev_name(dev),
+			   level_extra, vaf);
 }
 EXPORT_SYMBOL(__dev_printk);
 
-- 
1.7.10.4

[PATCH 2/3] dyndbg: in dynamic_emit_prefix, change inter-field separator

[Jim Cromie]

dynamic_emit_prefix() currently separates modname, funcname, lineno
with ':'.  This is complicates use of cut -d: <logfile>, since the
field positions can change per callsite with dynamic-debug.  So change
inter-field separator to '.' and keep the ':' prefix terminator.

This improves the situation, but doesnt solve it entirely; if
dyndbg==p is used, the callsite is enabled but no prefix is added, so
theres one less ':' in the message.  Changing the terminator to ','
would fix this, and might be warranted.

pr_fmt(fmt) KBUILD_MODNAME ": " fmt, also adds another ':'.

Signed-off-by: Jim Cromie <jim.cromie@gmail.com>
---
 lib/dynamic_debug.c |   12 +++++++-----
 1 file changed, 7 insertions(+), 5 deletions(-)

diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
index 7ca29a0..6bc34aa 100644
--- a/lib/dynamic_debug.c
+++ b/lib/dynamic_debug.c
@@ -532,16 +532,18 @@ static char *dynamic_emit_prefix(const struct _ddebug *desc, char *buf)
 	}
 	pos_after_tid = pos;
 	if (desc->flags & _DPRINTK_FLAGS_INCL_MODNAME)
-		pos += snprintf(buf + pos, remaining(pos), "%s:",
+		pos += snprintf(buf + pos, remaining(pos), "%s.",
 					desc->modname);
 	if (desc->flags & _DPRINTK_FLAGS_INCL_FUNCNAME)
-		pos += snprintf(buf + pos, remaining(pos), "%s:",
+		pos += snprintf(buf + pos, remaining(pos), "%s.",
 					desc->function);
 	if (desc->flags & _DPRINTK_FLAGS_INCL_LINENO)
-		pos += snprintf(buf + pos, remaining(pos), "%d:",
+		pos += snprintf(buf + pos, remaining(pos), "%d.",
 					desc->lineno);
-	if (pos - pos_after_tid)
-		pos += snprintf(buf + pos, remaining(pos), " ");
+	if (pos - pos_after_tid) {
+		pos--;
+		pos += snprintf(buf + pos, remaining(pos), ": ");
+	}
 	if (pos >= PREFIX_SIZE)
 		buf[PREFIX_SIZE - 1] = '\0';
 
-- 
1.7.10.4

[PATCH 3/3] dyndbg: change varname verbose_bytes to sz_used

[Jim Cromie]

New name reflects purpose (count mem used), verbose is just print
condition, and bytes is too generic.

Signed-off-by: Jim Cromie <jim.cromie@gmail.com>
---
 lib/dynamic_debug.c |    6 +++---
 1 file changed, 3 insertions(+), 3 deletions(-)

diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
index 6bc34aa..0cc715c 100644
--- a/lib/dynamic_debug.c
+++ b/lib/dynamic_debug.c
@@ -978,7 +978,7 @@ static int __init dynamic_debug_init(void)
 	char *cmdline;
 	int ret = 0;
 	int n = 0, entries = 0, modct = 0;
-	int verbose_bytes = 0;
+	int sz_used = 0;
 
 	if (__start___verbose == __stop___verbose) {
 		pr_warn("_ddebug table is empty in a "
@@ -990,7 +990,7 @@ static int __init dynamic_debug_init(void)
 	iter_start = iter;
 	for (; iter < __stop___verbose; iter++) {
 		entries++;
-		verbose_bytes += strlen(iter->modname) + strlen(iter->function)
+		sz_used += strlen(iter->modname) + strlen(iter->function)
 			+ strlen(iter->filename) + strlen(iter->format);
 
 		if (strcmp(modname, iter->modname)) {
@@ -1012,7 +1012,7 @@ static int __init dynamic_debug_init(void)
 	vpr_info("%d modules, %d entries and %d bytes in ddebug tables,"
 		" %d bytes in (readonly) verbose section\n",
 		modct, entries, (int)( modct * sizeof(struct ddebug_table)),
-		verbose_bytes + (int)(__stop___verbose - __start___verbose));
+		sz_used + (int)(__stop___verbose - __start___verbose));
 
 	/* apply ddebug_query boot param, dont unload tables on err */
 	if (ddebug_setup_string[0] != '\0') {
-- 
1.7.10.4

Re: [PATCH 0/3] dyndbg: dev_dbg bugfix + 2 trivials

[Jason Baron]

On Thu, Jul 19, 2012 at 01:46:19PM -0600, Jim Cromie wrote:
> 3 patches here, 1st is bugfix, others are trivial.
> 
> 1- fix __dev_printk, which broke dev_dbg() prefix under CONFIG_DYNAMIC_DEBUG.
> 

Patch looks good, and would be really nice to get into 3.5. Kay, are you
ok with this patch? 

> 2- change dyndbg prefix interfield separator from ':' to '.'
> 
> for example (output from test-code, not submitted):
> r8169 0000:02:00.0: r8169.rtl_init_one: set-drvdata pdev:ffff880223041000 dev:ffff880220d6a000
> hwmon hwmon1: k10temp.k10temp_probe.180: set-drvdata pdev:ffff88022303d000 dev:ffff8801dfd2a000
> 
> This improves usability of cut -d: <logfile> for pr_debug() messages,
> as field position is less volatile with various uses of dyndbg flags.
> Its not perfect:
> - dev_dbg on net-devices adds several more colons,
>   but this doesnt vary with dyndbg flags. 
> - dyndbg=+pfmlt still adds a field vs dyndbg==p (ie no prefix)
> - pr_fmt() commonly adds another colon (unchanged with this patch)

As you suggest in the patch, changing the delimiter to a non-colon
character such as ',' would resolve these cases? 

>   
> 3- trivial var name change in lib/dynamic_debug.c
> 
> 
> Please drop or apply 2,3 as you prefer.

2,3 are nice, but as you suggest I think we want to separate them from
patch 1, which is a bugfix for 3.5.

Thanks,

-Jason

Re: [PATCH 0/3] dyndbg: dev_dbg bugfix + 2 trivials

[Greg KH]

On Fri, Jul 20, 2012 at 04:38:58PM -0400, Jason Baron wrote:
> On Thu, Jul 19, 2012 at 01:46:19PM -0600, Jim Cromie wrote:
> > 3 patches here, 1st is bugfix, others are trivial.
> > 
> > 1- fix __dev_printk, which broke dev_dbg() prefix under CONFIG_DYNAMIC_DEBUG.
> > 
> 
> Patch looks good, and would be really nice to get into 3.5. Kay, are you
> ok with this patch? 

It's too late for 3.5, but I can take it for 3.6-rc1 and backport it to
3.5.1 if needed.

I just need you ack :)

> > 2- change dyndbg prefix interfield separator from ':' to '.'
> > 
> > for example (output from test-code, not submitted):
> > r8169 0000:02:00.0: r8169.rtl_init_one: set-drvdata pdev:ffff880223041000 dev:ffff880220d6a000
> > hwmon hwmon1: k10temp.k10temp_probe.180: set-drvdata pdev:ffff88022303d000 dev:ffff8801dfd2a000
> > 
> > This improves usability of cut -d: <logfile> for pr_debug() messages,
> > as field position is less volatile with various uses of dyndbg flags.
> > Its not perfect:
> > - dev_dbg on net-devices adds several more colons,
> >   but this doesnt vary with dyndbg flags. 
> > - dyndbg=+pfmlt still adds a field vs dyndbg==p (ie no prefix)
> > - pr_fmt() commonly adds another colon (unchanged with this patch)
> 
> As you suggest in the patch, changing the delimiter to a non-colon
> character such as ',' would resolve these cases? 
> 
> >   
> > 3- trivial var name change in lib/dynamic_debug.c
> > 
> > 
> > Please drop or apply 2,3 as you prefer.
> 
> 2,3 are nice, but as you suggest I think we want to separate them from
> patch 1, which is a bugfix for 3.5.

I agree.

thanks,

greg k-h

Re: [PATCH 1/3] drivers-core: make structured logging play nice with dynamic-debug

[Jason Baron]

On Thu, Jul 19, 2012 at 01:46:20PM -0600, Jim Cromie wrote:
> commit c4e00daaa96d3a0786f1f4fe6456281c60ef9a16 changed __dev_printk
> in a way that broke dynamic-debug's ability to control the dynamic
> prefix of dev_dbg(dev,..), but not dev_dbg(NULL,..) or pr_debug(..),
> which is why it wasnt noticed sooner.
> 
> When dev==NULL, __dev_printk() just calls printk(), which just works.
> But otherwise, it assumed that level was always a string like "<L>"
> and just plucked out the 'L', ignoring the rest.  However,
> dynamic_emit_prefix() adds "[tid] module:func:line:" to the string,
> those additions all got lost.
> 
> Signed-off-by: Jim Cromie <jim.cromie@gmail.com>
> ---
>  drivers/base/core.c |    9 +++++++--
>  1 file changed, 7 insertions(+), 2 deletions(-)
> 

Acked-by: Jason Baron <jbaron@redhat.com>


> diff --git a/drivers/base/core.c b/drivers/base/core.c
> index 346be8b..ebdb7c5 100644
> --- a/drivers/base/core.c
> +++ b/drivers/base/core.c
> @@ -1848,6 +1848,7 @@ int __dev_printk(const char *level, const struct device *dev,
>  		 struct va_format *vaf)
>  {
>  	char dict[128];
> +	const char *level_extra = "";
>  	size_t dictlen = 0;
>  	const char *subsys;
>  
> @@ -1894,10 +1895,14 @@ int __dev_printk(const char *level, const struct device *dev,
>  				    "DEVICE=+%s:%s", subsys, dev_name(dev));
>  	}
>  skip:
> +	if (level[3])
> +		level_extra = &level[3]; /* skip past "<L>" */
> +
>  	return printk_emit(0, level[1] - '0',
>  			   dictlen ? dict : NULL, dictlen,
> -			   "%s %s: %pV",
> -			   dev_driver_string(dev), dev_name(dev), vaf);
> +			   "%s %s: %s%pV", 
> +			   dev_driver_string(dev), dev_name(dev),
> +			   level_extra, vaf);
>  }
>  EXPORT_SYMBOL(__dev_printk);
>  
> -- 
> 1.7.10.4
> 

Re: [PATCH 1/3] drivers-core: make structured logging play nice with dynamic-debug

[Joe Perches]

On Mon, 2012-07-23 at 09:07 -0400, Jason Baron wrote:
> On Thu, Jul 19, 2012 at 01:46:20PM -0600, Jim Cromie wrote:
> > commit c4e00daaa96d3a0786f1f4fe6456281c60ef9a16 changed __dev_printk
> > in a way that broke dynamic-debug's ability to control the dynamic
> > prefix of dev_dbg(dev,..), but not dev_dbg(NULL,..) or pr_debug(..),
> > which is why it wasnt noticed sooner.
> > 
> > When dev==NULL, __dev_printk() just calls printk(), which just works.
> > But otherwise, it assumed that level was always a string like "<L>"
> > and just plucked out the 'L', ignoring the rest.  However,
> > dynamic_emit_prefix() adds "[tid] module:func:line:" to the string,
> > those additions all got lost.
> >

I think this is not a really good approach.

3 depths of %pV can consume quite a lot of stack
and avoiding this is useful.

I'd much rather improve/centralize the mechanism
in dynamic_debug.c so that the extra recursion
depth is avoided.

Something like this:

o Remove KERN_DEBUG from dynamic_emit_prefix
o Make a function of create_syslog_header to format
  the header for printk_emit.
o Call printk_emit in dynamic_dev_dbg and dynamic_netdev_dbg
o Call printk_emit in __dev_printk
o Remove now unused EXPORT_SYMBOL(__netdev_printk)
o Neatening

Thoughts?

---

 drivers/base/core.c    |   55 +++++++++++++++++++++++++----------------
 include/linux/device.h |    6 +++-
 lib/dynamic_debug.c    |   63 ++++++++++++++++++++++++++++++++++++++---------
 net/core/dev.c         |    5 ++-
 4 files changed, 91 insertions(+), 38 deletions(-)

diff --git a/drivers/base/core.c b/drivers/base/core.c
index 346be8b..94f3803 100644
--- a/drivers/base/core.c
+++ b/drivers/base/core.c
@@ -1844,25 +1844,19 @@ void device_shutdown(void)
  */
 
 #ifdef CONFIG_PRINTK
-int __dev_printk(const char *level, const struct device *dev,
-		 struct va_format *vaf)
+int create_syslog_header(const struct device *dev, char *hdr, size_t hdrlen)
 {
-	char dict[128];
-	size_t dictlen = 0;
 	const char *subsys;
-
-	if (!dev)
-		return printk("%s(NULL device *): %pV", level, vaf);
+	size_t pos = 0;
 
 	if (dev->class)
 		subsys = dev->class->name;
 	else if (dev->bus)
 		subsys = dev->bus->name;
 	else
-		goto skip;
+		return 0;
 
-	dictlen += snprintf(dict + dictlen, sizeof(dict) - dictlen,
-			    "SUBSYSTEM=%s", subsys);
+	pos += snprintf(hdr + pos, hdrlen - pos, "SUBSYSTEM=%s", subsys);
 
 	/*
 	 * Add device identifier DEVICE=:
@@ -1878,24 +1872,39 @@ int __dev_printk(const char *level, const struct device *dev,
 			c = 'b';
 		else
 			c = 'c';
-		dictlen++;
-		dictlen += snprintf(dict + dictlen, sizeof(dict) - dictlen,
-				   "DEVICE=%c%u:%u",
-				   c, MAJOR(dev->devt), MINOR(dev->devt));
+		pos++;
+		pos += snprintf(hdr + pos, hdrlen - pos,
+				"DEVICE=%c%u:%u",
+				c, MAJOR(dev->devt), MINOR(dev->devt));
 	} else if (strcmp(subsys, "net") == 0) {
 		struct net_device *net = to_net_dev(dev);
 
-		dictlen++;
-		dictlen += snprintf(dict + dictlen, sizeof(dict) - dictlen,
-				    "DEVICE=n%u", net->ifindex);
+		pos++;
+		pos += snprintf(hdr + pos, hdrlen - pos,
+				"DEVICE=n%u", net->ifindex);
 	} else {
-		dictlen++;
-		dictlen += snprintf(dict + dictlen, sizeof(dict) - dictlen,
-				    "DEVICE=+%s:%s", subsys, dev_name(dev));
+		pos++;
+		pos += snprintf(hdr + pos, hdrlen - pos,
+				"DEVICE=+%s:%s", subsys, dev_name(dev));
 	}
-skip:
+
+	return pos;
+}
+EXPORT_SYMBOL(create_syslog_header);
+
+int __dev_printk(const char *level, const struct device *dev,
+		 struct va_format *vaf)
+{
+	char hdr[128];
+	size_t hdrlen;
+
+	if (!dev)
+		return printk("%s(NULL device *): %pV", level, vaf);
+
+	hdrlen = create_syslog_header(dev, hdr, sizeof(hdr));
+
 	return printk_emit(0, level[1] - '0',
-			   dictlen ? dict : NULL, dictlen,
+			   hdrlen ? hdr : NULL, hdrlen,
 			   "%s %s: %pV",
 			   dev_driver_string(dev), dev_name(dev), vaf);
 }
@@ -1914,6 +1923,7 @@ int dev_printk(const char *level, const struct device *dev,
 	vaf.va = &args;
 
 	r = __dev_printk(level, dev, &vaf);
+
 	va_end(args);
 
 	return r;
@@ -1933,6 +1943,7 @@ int func(const struct device *dev, const char *fmt, ...)	\
 	vaf.va = &args;						\
 								\
 	r = __dev_printk(kern_level, dev, &vaf);		\
+								\
 	va_end(args);						\
 								\
 	return r;						\
diff --git a/include/linux/device.h b/include/linux/device.h
index 6de9415..74863f0 100644
--- a/include/linux/device.h
+++ b/include/linux/device.h
@@ -884,12 +884,14 @@ extern const char *dev_driver_string(const struct device *dev);
 
 #ifdef CONFIG_PRINTK
 
+extern int create_syslog_header(const struct device *dev,
+				char *hdr, size_t hdrlen);
+
 extern int __dev_printk(const char *level, const struct device *dev,
 			struct va_format *vaf);
 extern __printf(3, 4)
 int dev_printk(const char *level, const struct device *dev,
-	       const char *fmt, ...)
-	;
+	       const char *fmt, ...);
 extern __printf(2, 3)
 int dev_emerg(const struct device *dev, const char *fmt, ...);
 extern __printf(2, 3)
diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
index 7ca29a0..08442e7 100644
--- a/lib/dynamic_debug.c
+++ b/lib/dynamic_debug.c
@@ -521,25 +521,23 @@ static char *dynamic_emit_prefix(const struct _ddebug *desc, char *buf)
 	int pos_after_tid;
 	int pos = 0;
 
-	pos += snprintf(buf + pos, remaining(pos), "%s", KERN_DEBUG);
 	if (desc->flags & _DPRINTK_FLAGS_INCL_TID) {
 		if (in_interrupt())
-			pos += snprintf(buf + pos, remaining(pos), "%s ",
-						"<intr>");
+			pos += snprintf(buf + pos, remaining(pos), "<intr> ");
 		else
 			pos += snprintf(buf + pos, remaining(pos), "[%d] ",
-						task_pid_vnr(current));
+					task_pid_vnr(current));
 	}
 	pos_after_tid = pos;
 	if (desc->flags & _DPRINTK_FLAGS_INCL_MODNAME)
 		pos += snprintf(buf + pos, remaining(pos), "%s:",
-					desc->modname);
+				desc->modname);
 	if (desc->flags & _DPRINTK_FLAGS_INCL_FUNCNAME)
 		pos += snprintf(buf + pos, remaining(pos), "%s:",
-					desc->function);
+				desc->function);
 	if (desc->flags & _DPRINTK_FLAGS_INCL_LINENO)
 		pos += snprintf(buf + pos, remaining(pos), "%d:",
-					desc->lineno);
+				desc->lineno);
 	if (pos - pos_after_tid)
 		pos += snprintf(buf + pos, remaining(pos), " ");
 	if (pos >= PREFIX_SIZE)
@@ -559,9 +557,13 @@ int __dynamic_pr_debug(struct _ddebug *descriptor, const char *fmt, ...)
 	BUG_ON(!fmt);
 
 	va_start(args, fmt);
+
 	vaf.fmt = fmt;
 	vaf.va = &args;
-	res = printk("%s%pV", dynamic_emit_prefix(descriptor, buf), &vaf);
+
+	res = printk(KERN_DEBUG "%s%pV",
+		     dynamic_emit_prefix(descriptor, buf), &vaf);
+
 	va_end(args);
 
 	return res;
@@ -580,9 +582,25 @@ int __dynamic_dev_dbg(struct _ddebug *descriptor,
 	BUG_ON(!fmt);
 
 	va_start(args, fmt);
+
 	vaf.fmt = fmt;
 	vaf.va = &args;
-	res = __dev_printk(dynamic_emit_prefix(descriptor, buf), dev, &vaf);
+
+	if (!dev) {
+		res = printk(KERN_DEBUG "(NULL device *): %pV", &vaf);
+	} else {
+		char dict[128];
+		size_t dictlen;
+
+		dictlen = create_syslog_header(dev, dict, sizeof(dict));
+
+		res = printk_emit(0, 7,
+				  dictlen ? dict : NULL, dictlen,
+				  "%s%s %s: %pV",
+				  dynamic_emit_prefix(descriptor, buf),
+				  dev_driver_string(dev), dev_name(dev), &vaf);
+	}
+
 	va_end(args);
 
 	return res;
@@ -592,20 +610,41 @@ EXPORT_SYMBOL(__dynamic_dev_dbg);
 #ifdef CONFIG_NET
 
 int __dynamic_netdev_dbg(struct _ddebug *descriptor,
-		      const struct net_device *dev, const char *fmt, ...)
+			 const struct net_device *dev, const char *fmt, ...)
 {
 	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 = __netdev_printk(dynamic_emit_prefix(descriptor, buf), dev, &vaf);
+
+	if (dev && dev->dev.parent) {
+		char buf[PREFIX_SIZE];
+		char dict[128];
+		size_t dictlen;
+
+		dictlen = create_syslog_header(dev->dev.parent,
+					       dict, sizeof(dict));
+
+		res = printk_emit(0, 7,
+				  dictlen ? dict : NULL, dictlen,
+				  "%s%s %s: %pV",
+				  dynamic_emit_prefix(descriptor, buf),
+				  dev_driver_string(dev->dev.parent),
+				  netdev_name(dev), &vaf);
+
+	} else if (dev) {
+		res = printk(KERN_DEBUG "%s: %pV", netdev_name(dev), &vaf);
+	} else {
+		res = printk(KERN_DEBUG "(NULL net_device): %pV", &vaf);
+	}
+
 	va_end(args);
 
 	return res;
diff --git a/net/core/dev.c b/net/core/dev.c
index 1cb0d8a..1651065 100644
--- a/net/core/dev.c
+++ b/net/core/dev.c
@@ -6324,7 +6324,7 @@ const char *netdev_drivername(const struct net_device *dev)
 	return empty;
 }
 
-int __netdev_printk(const char *level, const struct net_device *dev,
+static int __netdev_printk(const char *level, const struct net_device *dev,
 			   struct va_format *vaf)
 {
 	int r;
@@ -6339,7 +6339,6 @@ 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, ...)
@@ -6354,6 +6353,7 @@ int netdev_printk(const char *level, const struct net_device *dev,
 	vaf.va = &args;
 
 	r = __netdev_printk(level, dev, &vaf);
+
 	va_end(args);
 
 	return r;
@@ -6373,6 +6373,7 @@ int func(const struct net_device *dev, const char *fmt, ...)	\
 	vaf.va = &args;						\
 								\
 	r = __netdev_printk(level, dev, &vaf);			\
+								\
 	va_end(args);						\
 								\
 	return r;						\

Re: [PATCH 1/3] drivers-core: make structured logging play nice with dynamic-debug

[Jim Cromie]

On Mon, Jul 23, 2012 at 11:09 AM, Joe Perches <joe@perches.com> wrote:
> On Mon, 2012-07-23 at 09:07 -0400, Jason Baron wrote:
>> On Thu, Jul 19, 2012 at 01:46:20PM -0600, Jim Cromie wrote:
>> > commit c4e00daaa96d3a0786f1f4fe6456281c60ef9a16 changed __dev_printk
>> > in a way that broke dynamic-debug's ability to control the dynamic
>> > prefix of dev_dbg(dev,..), but not dev_dbg(NULL,..) or pr_debug(..),
>> > which is why it wasnt noticed sooner.
>> >
>> > When dev==NULL, __dev_printk() just calls printk(), which just works.
>> > But otherwise, it assumed that level was always a string like "<L>"
>> > and just plucked out the 'L', ignoring the rest.  However,
>> > dynamic_emit_prefix() adds "[tid] module:func:line:" to the string,
>> > those additions all got lost.
>> >
>
> I think this is not a really good approach.
>
> 3 depths of %pV can consume quite a lot of stack
> and avoiding this is useful.
>
> I'd much rather improve/centralize the mechanism
> in dynamic_debug.c so that the extra recursion
> depth is avoided.
>
> Something like this:
>
> o Remove KERN_DEBUG from dynamic_emit_prefix
> o Make a function of create_syslog_header to format
>   the header for printk_emit.
> o Call printk_emit in dynamic_dev_dbg and dynamic_netdev_dbg
> o Call printk_emit in __dev_printk
> o Remove now unused EXPORT_SYMBOL(__netdev_printk)
> o Neatening
>
> Thoughts?
>

My patch was a minimal bug-fix aimed at rc-late, but it missed the window.
We now have room for a more comprehensive fix, such as yours.

OTOH, my patch does fix a bug, while yours is a bigger "optimization" patch.
Your commit message could identify the lost prefix as its impetus,
but I think it stands nicely on its own as a refactoring for less stack usage.

I'll try the patch soon

thanks
Jim

Re: [PATCH 0/3] dyndbg: dev_dbg bugfix + 2 trivials

[Jim Cromie]

hi Jason

( Kay, I previously mis-addressed you at vrfy.com, so you havent received the
thread directly until now. sorry about that)

On Fri, Jul 20, 2012 at 2:38 PM, Jason Baron <jbaron@redhat.com> wrote:
> On Thu, Jul 19, 2012 at 01:46:19PM -0600, Jim Cromie wrote:
>> 3 patches here, 1st is bugfix, others are trivial.
>>
>> 1- fix __dev_printk, which broke dev_dbg() prefix under CONFIG_DYNAMIC_DEBUG.
>>
>
> Patch looks good, and would be really nice to get into 3.5. Kay, are you
> ok with this patch?
>
>> 2- change dyndbg prefix interfield separator from ':' to '.'
>>
>> for example (output from test-code, not submitted):
>> r8169 0000:02:00.0: r8169.rtl_init_one: set-drvdata pdev:ffff880223041000 dev:ffff880220d6a000
>> hwmon hwmon1: k10temp.k10temp_probe.180: set-drvdata pdev:ffff88022303d000 dev:ffff8801dfd2a000
>>
>> This improves usability of cut -d: <logfile> for pr_debug() messages,
>> as field position is less volatile with various uses of dyndbg flags.
>> Its not perfect:
>> - dev_dbg on net-devices adds several more colons,
>>   but this doesnt vary with dyndbg flags.
>> - dyndbg=+pfmlt still adds a field vs dyndbg==p (ie no prefix)
>> - pr_fmt() commonly adds another colon (unchanged with this patch)
>
> As you suggest in the patch, changing the delimiter to a non-colon
> character such as ',' would resolve these cases?

yes mostly - depending upon what "these" are.

Changing the prefix delimiter (I chose dot since its used in nested
names everywhere)
definitely improves the situation, with this patch the field-count variation is
0 or 1 for dyndbg==p or dyndbg==p[fmlt]+ respectively

It obviously doesnt address colons which may be added elsewhere;
pr_fmt() KBUILD_MODNAME ":" __func__  adds another,
and dev_printk adds several, depending on the device type

Its reasonable to change all the pr_fmt() delimiters to dot also,
but thats a lot of touches to a lot of modules (ie churn), and
probably isnt worth doing
unless its done fully, which would need a solid consensus that its
worth the trouble.

changing delimiters inside dev_printk() / dev_driver_string() is harder;
it means changing values in low level fields
                        (dev->bus ? dev->bus->name :
                        (dev->class ? dev->class->name : ""));

which are also exposed to user-space, forex by lspci etc

]$ lspci | cut -c 1-20
00:00.0 Host bridge:
00:07.0 PCI bridge:
00:11.0 SATA control
00:12.0 USB Controll
00:14.0 SMBus: ATI T
00:14.1 IDE interfac
00:14.2 Audio device
00:14.3 ISA bridge:
00:14.4 PCI bridge:

That looks like a can of worms best left closed.


So this patch only addresses dyndbg prefix, and is 95% resolved.
the remaining 0-1 variation isnt really important - almost all dyndbg users
will want some prefix - at least module, so the missing field in dyndbg==p
is pretty inconsequential, and its typically provided by pr_fmt() anyway.


In any case, I think ths patch does what is practical now, and no more.
If you agree, the patch needs your Ackd-by before Greg will take it.


Going forward, the proper priorities for dyndbg are IMO (CMIIW)

- get jumplabels working

  Ive coded this, and it looks ok, but Im stuck on the circular
include problem seen
  when I add #include <linux/jumplabel.h> needed for the ddebug.key field.
  Ive tried a few permutations, but I dont think thats gonna
illuminate a working fix.
  I think I'll post a minimal RF-Help patch to demonstrate the problem ..

- propose a pr_debug_flags("flagchars", "fmt", ...)

  "flagchars" would be uppercase chars defined for each module
  DBG_DEFINE_FLAG( mod_debug_str, "A", "alpha flag controls .. blah blah..");

  I think this could be made to work for both dyndbg and non-dyndbg:
  $ echo A > /sys/module/modname/parameters/dbg_str
  $ echo module modname +pA > /dbg/dynamic_debug/control

This needs more thought, and perhaps simplification,
but it seems appropriate to see if dyndbg and non-dyndbg can be made
to fit together cogently from a user perspective.

Re: [PATCH 0/3] dyndbg: dev_dbg bugfix + 2 trivials

[Joe Perches]

On Tue, 2012-07-24 at 15:40 -0600, Jim Cromie wrote:
> On Fri, Jul 20, 2012 at 2:38 PM, Jason Baron <jbaron@redhat.com> wrote:
> > On Thu, Jul 19, 2012 at 01:46:19PM -0600, Jim Cromie wrote:
> >> 3 patches here, 1st is bugfix, others are trivial.
> >>
> >> 1- fix __dev_printk, which broke dev_dbg() prefix under CONFIG_DYNAMIC_DEBUG.

I'd rather what I posted be tested/implemented instead.
It works with the printk changes already in -next via mm.

Try your patch against -next and see it doesn't work.
It requires additional changes for SOH handling.

> >> 2- change dyndbg prefix interfield separator from ':' to '.'

I think this part of the patch completely unnecessary.
What value does changing the prefix from one char to another really add?
Trying to parse  logfiles via cut will always be imperfect.

dmesg -r|grep "^<7>" seems to work well enough for debug messages

> Going forward, the proper priorities for dyndbg are IMO (CMIIW)
> 
> - get jumplabels working
> 
>   Ive coded this, and it looks ok, but Im stuck on the circular
> include problem seen
>   when I add #include <linux/jumplabel.h> needed for the ddebug.key field.
>   Ive tried a few permutations, but I dont think thats gonna
> illuminate a working fix.
>   I think I'll post a minimal RF-Help patch to demonstrate the problem ..

Seems reasonable.

> - propose a pr_debug_flags("flagchars", "fmt", ...)
> 
>   "flagchars" would be uppercase chars defined for each module
>   DBG_DEFINE_FLAG( mod_debug_str, "A", "alpha flag controls .. blah blah..");

what's the fmt,... for?
Why not just a per-module set of flags?