[PATCH] dynamic debug: allow printing to trace event

[PATCH] dynamic debug: allow printing to trace event

[Vincent Whitchurch]

When debugging device drivers, I've found it very useful to be able to
redirect existing pr_debug()/dev_dbg() prints to the trace buffer
instead of dmesg.  Among the many advantages of the trace buffer is that
it can be dynamically resized, allows these prints to combined with
other trace events, and doesn't fill up system logs.

Since dynamic debug already has hooks in these call sites, getting these
prints into the ftrace buffer is straightforward if we have dynamic
debug do it.

Add an "x" flag to make the dynamic debug call site print to a new
printk:dynamic trace event.  The trace event can be emitted instead of
or in addition to the printk().  The print buffer is placed on the stack
and is limited to a somewhat arbitrarily chosen 256 bytes; anything
larger will be truncated.

Signed-off-by: Vincent Whitchurch <vincent.whitchurch@axis.com>
---
 .../admin-guide/dynamic-debug-howto.rst       |   1 +
 include/linux/dynamic_debug.h                 |   7 +-
 include/trace/events/printk.h                 |  16 +++
 lib/dynamic_debug.c                           | 124 ++++++++++++++----
 4 files changed, 120 insertions(+), 28 deletions(-)

diff --git a/Documentation/admin-guide/dynamic-debug-howto.rst b/Documentation/admin-guide/dynamic-debug-howto.rst
index 1012bd9305e9..b235327fbb53 100644
--- a/Documentation/admin-guide/dynamic-debug-howto.rst
+++ b/Documentation/admin-guide/dynamic-debug-howto.rst
@@ -224,6 +224,7 @@ of the characters::
 The flags are::
 
   p    enables the pr_debug() callsite.
+  x    enables trace to the printk:dynamic event
   f    Include the function name in the printed message
   l    Include line number in the printed message
   m    Include module name in the printed message
diff --git a/include/linux/dynamic_debug.h b/include/linux/dynamic_debug.h
index abcd5fde30eb..9dee405985c4 100644
--- a/include/linux/dynamic_debug.h
+++ b/include/linux/dynamic_debug.h
@@ -27,13 +27,16 @@ struct _ddebug {
 	 * writes commands to <debugfs>/dynamic_debug/control
 	 */
 #define _DPRINTK_FLAGS_NONE	0
-#define _DPRINTK_FLAGS_PRINT	(1<<0) /* printk() a message using the format */
+#define _DPRINTK_FLAGS_PRINTK	(1<<0) /* printk() a message using the format */
 #define _DPRINTK_FLAGS_INCL_MODNAME	(1<<1)
 #define _DPRINTK_FLAGS_INCL_FUNCNAME	(1<<2)
 #define _DPRINTK_FLAGS_INCL_LINENO	(1<<3)
 #define _DPRINTK_FLAGS_INCL_TID		(1<<4)
+#define _DPRINTK_FLAGS_TRACE		(1<<5)
+#define _DPRINTK_FLAGS_PRINT		(_DPRINTK_FLAGS_PRINTK | \
+					 _DPRINTK_FLAGS_TRACE)
 #if defined DEBUG
-#define _DPRINTK_FLAGS_DEFAULT _DPRINTK_FLAGS_PRINT
+#define _DPRINTK_FLAGS_DEFAULT _DPRINTK_FLAGS_PRINTK
 #else
 #define _DPRINTK_FLAGS_DEFAULT 0
 #endif
diff --git a/include/trace/events/printk.h b/include/trace/events/printk.h
index 13d405b2fd8b..696d6e19a9b7 100644
--- a/include/trace/events/printk.h
+++ b/include/trace/events/printk.h
@@ -31,6 +31,22 @@ TRACE_EVENT(console,
 
 	TP_printk("%s", __get_str(msg))
 );
+
+TRACE_EVENT(dynamic,
+	TP_PROTO(const char *message),
+
+	TP_ARGS(message),
+
+	TP_STRUCT__entry(
+		__string(message, message)
+	),
+
+	TP_fast_assign(
+		__assign_str(message, message);
+	),
+
+	TP_printk("%s", __get_str(message))
+);
 #endif /* _TRACE_PRINTK_H */
 
 /* This part must be outside protection */
diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
index 321437bbf87d..9f6d8867af7c 100644
--- a/lib/dynamic_debug.c
+++ b/lib/dynamic_debug.c
@@ -36,6 +36,7 @@
 #include <linux/sched.h>
 #include <linux/device.h>
 #include <linux/netdevice.h>
+#include <trace/events/printk.h>
 
 #include <rdma/ib_verbs.h>
 
@@ -79,11 +80,12 @@ static inline const char *trim_prefix(const char *path)
 }
 
 static struct { unsigned flag:8; char opt_char; } opt_array[] = {
-	{ _DPRINTK_FLAGS_PRINT, 'p' },
+	{ _DPRINTK_FLAGS_PRINTK, 'p' },
 	{ _DPRINTK_FLAGS_INCL_MODNAME, 'm' },
 	{ _DPRINTK_FLAGS_INCL_FUNCNAME, 'f' },
 	{ _DPRINTK_FLAGS_INCL_LINENO, 'l' },
 	{ _DPRINTK_FLAGS_INCL_TID, 't' },
+	{ _DPRINTK_FLAGS_TRACE, 'x' },
 	{ _DPRINTK_FLAGS_NONE, '_' },
 };
 
@@ -550,6 +552,65 @@ static char *dynamic_emit_prefix(const struct _ddebug *desc, char *buf)
 	return buf;
 }
 
+static void dynamic_trace(const char *fmt, va_list args)
+{
+	char buf[256];
+	int len;
+
+	len = vscnprintf(buf, sizeof(buf), fmt, args);
+	if (!len)
+		return;
+
+	if (buf[len - 1] == '\n')
+		buf[len - 1] = '\0';
+
+	trace_dynamic(buf);
+}
+
+static void dynamic_printk(unsigned int flags, const char *fmt, ...)
+{
+	if (flags & _DPRINTK_FLAGS_TRACE) {
+		va_list args;
+
+		va_start(args, fmt);
+		/*
+		 * All callers include the KERN_DEBUG prefix to keep the
+		 * vprintk case simple; strip it out for tracing.
+		 */
+		dynamic_trace(fmt + strlen(KERN_DEBUG), args);
+		va_end(args);
+	}
+
+	if (flags & _DPRINTK_FLAGS_PRINTK) {
+		va_list args;
+
+		va_start(args, fmt);
+		vprintk(fmt, args);
+		va_end(args);
+	}
+}
+
+static void dynamic_dev_printk(unsigned int flags, const struct device *dev,
+			       const char *fmt, ...)
+{
+
+	if (flags & _DPRINTK_FLAGS_TRACE) {
+		va_list args;
+
+		va_start(args, fmt);
+		dynamic_trace(fmt, args);
+		va_end(args);
+	}
+
+	if (flags & _DPRINTK_FLAGS_PRINTK) {
+		va_list args;
+
+		va_start(args, fmt);
+		dev_vprintk_emit(LOGLEVEL_DEBUG, dev, fmt, args);
+		va_end(args);
+	}
+}
+
 void __dynamic_pr_debug(struct _ddebug *descriptor, const char *fmt, ...)
 {
 	va_list args;
@@ -564,7 +625,8 @@ void __dynamic_pr_debug(struct _ddebug *descriptor, const char *fmt, ...)
 	vaf.fmt = fmt;
 	vaf.va = &args;
 
-	printk(KERN_DEBUG "%s%pV", dynamic_emit_prefix(descriptor, buf), &vaf);
+	dynamic_printk(descriptor->flags, KERN_DEBUG "%s%pV",
+		       dynamic_emit_prefix(descriptor, buf), &vaf);
 
 	va_end(args);
 }
@@ -574,6 +636,7 @@ void __dynamic_dev_dbg(struct _ddebug *descriptor,
 		      const struct device *dev, const char *fmt, ...)
 {
 	struct va_format vaf;
+	unsigned int flags;
 	va_list args;
 
 	BUG_ON(!descriptor);
@@ -583,16 +646,18 @@ void __dynamic_dev_dbg(struct _ddebug *descriptor,
 
 	vaf.fmt = fmt;
 	vaf.va = &args;
+	flags = descriptor->flags;
 
 	if (!dev) {
-		printk(KERN_DEBUG "(NULL device *): %pV", &vaf);
+		dynamic_printk(flags, KERN_DEBUG "(NULL device *): %pV",
+			      &vaf);
 	} else {
 		char buf[PREFIX_SIZE];
 
-		dev_printk_emit(LOGLEVEL_DEBUG, dev, "%s%s %s: %pV",
-				dynamic_emit_prefix(descriptor, buf),
-				dev_driver_string(dev), dev_name(dev),
-				&vaf);
+		dynamic_dev_printk(flags, dev, "%s%s %s: %pV",
+				   dynamic_emit_prefix(descriptor, buf),
+				   dev_driver_string(dev), dev_name(dev),
+				   &vaf);
 	}
 
 	va_end(args);
@@ -605,6 +670,7 @@ void __dynamic_netdev_dbg(struct _ddebug *descriptor,
 			  const struct net_device *dev, const char *fmt, ...)
 {
 	struct va_format vaf;
+	unsigned int flags;
 	va_list args;
 
 	BUG_ON(!descriptor);
@@ -614,22 +680,24 @@ void __dynamic_netdev_dbg(struct _ddebug *descriptor,
 
 	vaf.fmt = fmt;
 	vaf.va = &args;
+	flags = descriptor->flags;
 
 	if (dev && dev->dev.parent) {
 		char buf[PREFIX_SIZE];
 
-		dev_printk_emit(LOGLEVEL_DEBUG, dev->dev.parent,
-				"%s%s %s %s%s: %pV",
-				dynamic_emit_prefix(descriptor, buf),
-				dev_driver_string(dev->dev.parent),
-				dev_name(dev->dev.parent),
-				netdev_name(dev), netdev_reg_state(dev),
-				&vaf);
+		dynamic_dev_printk(flags, dev->dev.parent,
+				   "%s%s %s %s%s: %pV",
+				   dynamic_emit_prefix(descriptor, buf),
+				   dev_driver_string(dev->dev.parent),
+				   dev_name(dev->dev.parent),
+				   netdev_name(dev), netdev_reg_state(dev),
+				   &vaf);
 	} else if (dev) {
-		printk(KERN_DEBUG "%s%s: %pV", netdev_name(dev),
-		       netdev_reg_state(dev), &vaf);
+		dynamic_printk(flags, KERN_DEBUG "%s%s: %pV",
+			       netdev_name(dev), netdev_reg_state(dev), &vaf);
 	} else {
-		printk(KERN_DEBUG "(NULL net_device): %pV", &vaf);
+		dynamic_printk(flags, KERN_DEBUG "(NULL net_device): %pV",
+			       &vaf);
 	}
 
 	va_end(args);
@@ -644,27 +712,31 @@ void __dynamic_ibdev_dbg(struct _ddebug *descriptor,
 			 const struct ib_device *ibdev, const char *fmt, ...)
 {
 	struct va_format vaf;
+	unsigned int flags;
 	va_list args;
 
 	va_start(args, fmt);
 
 	vaf.fmt = fmt;
 	vaf.va = &args;
+	flags = descriptor->flags;
 
 	if (ibdev && ibdev->dev.parent) {
 		char buf[PREFIX_SIZE];
 
-		dev_printk_emit(LOGLEVEL_DEBUG, ibdev->dev.parent,
-				"%s%s %s %s: %pV",
-				dynamic_emit_prefix(descriptor, buf),
-				dev_driver_string(ibdev->dev.parent),
-				dev_name(ibdev->dev.parent),
-				dev_name(&ibdev->dev),
-				&vaf);
+		dynamic_dev_printk(flags, ibdev->dev.parent,
+				   "%s%s %s %s: %pV",
+				   dynamic_emit_prefix(descriptor, buf),
+				   dev_driver_string(ibdev->dev.parent),
+				   dev_name(ibdev->dev.parent),
+				   dev_name(&ibdev->dev),
+				   &vaf);
 	} else if (ibdev) {
-		printk(KERN_DEBUG "%s: %pV", dev_name(&ibdev->dev), &vaf);
+		dynamic_printk(flags, KERN_DEBUG "%s: %pV",
+			       dev_name(&ibdev->dev), &vaf);
 	} else {
-		printk(KERN_DEBUG "(NULL ib_device): %pV", &vaf);
+		dynamic_printk(flags, KERN_DEBUG "(NULL ib_device): %pV",
+			       &vaf);
 	}
 
 	va_end(args);
-- 
2.25.1

Re: [PATCH] dynamic debug: allow printing to trace event

[Steven Rostedt]

Added printk maintainers to get their thoughts.


On Tue, 21 Jul 2020 16:11:05 +0200
Vincent Whitchurch <vincent.whitchurch@axis.com> wrote:

> When debugging device drivers, I've found it very useful to be able to
> redirect existing pr_debug()/dev_dbg() prints to the trace buffer
> instead of dmesg.  Among the many advantages of the trace buffer is that
> it can be dynamically resized, allows these prints to combined with
> other trace events, and doesn't fill up system logs.
> 
> Since dynamic debug already has hooks in these call sites, getting these
> prints into the ftrace buffer is straightforward if we have dynamic
> debug do it.
> 
> Add an "x" flag to make the dynamic debug call site print to a new
> printk:dynamic trace event.  The trace event can be emitted instead of
> or in addition to the printk().  The print buffer is placed on the stack
> and is limited to a somewhat arbitrarily chosen 256 bytes; anything
> larger will be truncated.

Is it safe to have a 256 byte string on the stack? That's quite a bit.
How deep is the stack when this is called?

You could run vsnprintf() with a zero length to get the size, and then
just allocate that from the ring buffer. How critical is the performance?

-- Steve


> 
> Signed-off-by: Vincent Whitchurch <vincent.whitchurch@axis.com>
> ---
>  .../admin-guide/dynamic-debug-howto.rst       |   1 +
>  include/linux/dynamic_debug.h                 |   7 +-
>  include/trace/events/printk.h                 |  16 +++
>  lib/dynamic_debug.c                           | 124 ++++++++++++++----
>  4 files changed, 120 insertions(+), 28 deletions(-)
> 
> diff --git a/Documentation/admin-guide/dynamic-debug-howto.rst b/Documentation/admin-guide/dynamic-debug-howto.rst
> index 1012bd9305e9..b235327fbb53 100644
> --- a/Documentation/admin-guide/dynamic-debug-howto.rst
> +++ b/Documentation/admin-guide/dynamic-debug-howto.rst
> @@ -224,6 +224,7 @@ of the characters::
>  The flags are::
>  
>    p    enables the pr_debug() callsite.
> +  x    enables trace to the printk:dynamic event
>    f    Include the function name in the printed message
>    l    Include line number in the printed message
>    m    Include module name in the printed message
> diff --git a/include/linux/dynamic_debug.h b/include/linux/dynamic_debug.h
> index abcd5fde30eb..9dee405985c4 100644
> --- a/include/linux/dynamic_debug.h
> +++ b/include/linux/dynamic_debug.h
> @@ -27,13 +27,16 @@ struct _ddebug {
>  	 * writes commands to <debugfs>/dynamic_debug/control
>  	 */
>  #define _DPRINTK_FLAGS_NONE	0
> -#define _DPRINTK_FLAGS_PRINT	(1<<0) /* printk() a message using the format */
> +#define _DPRINTK_FLAGS_PRINTK	(1<<0) /* printk() a message using the format */
>  #define _DPRINTK_FLAGS_INCL_MODNAME	(1<<1)
>  #define _DPRINTK_FLAGS_INCL_FUNCNAME	(1<<2)
>  #define _DPRINTK_FLAGS_INCL_LINENO	(1<<3)
>  #define _DPRINTK_FLAGS_INCL_TID		(1<<4)
> +#define _DPRINTK_FLAGS_TRACE		(1<<5)
> +#define _DPRINTK_FLAGS_PRINT		(_DPRINTK_FLAGS_PRINTK | \
> +					 _DPRINTK_FLAGS_TRACE)
>  #if defined DEBUG
> -#define _DPRINTK_FLAGS_DEFAULT _DPRINTK_FLAGS_PRINT
> +#define _DPRINTK_FLAGS_DEFAULT _DPRINTK_FLAGS_PRINTK
>  #else
>  #define _DPRINTK_FLAGS_DEFAULT 0
>  #endif
> diff --git a/include/trace/events/printk.h b/include/trace/events/printk.h
> index 13d405b2fd8b..696d6e19a9b7 100644
> --- a/include/trace/events/printk.h
> +++ b/include/trace/events/printk.h
> @@ -31,6 +31,22 @@ TRACE_EVENT(console,
>  
>  	TP_printk("%s", __get_str(msg))
>  );
> +
> +TRACE_EVENT(dynamic,
> +	TP_PROTO(const char *message),
> +
> +	TP_ARGS(message),
> +
> +	TP_STRUCT__entry(
> +		__string(message, message)
> +	),
> +
> +	TP_fast_assign(
> +		__assign_str(message, message);
> +	),
> +
> +	TP_printk("%s", __get_str(message))
> +);
>  #endif /* _TRACE_PRINTK_H */
>  
>  /* This part must be outside protection */
> diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
> index 321437bbf87d..9f6d8867af7c 100644
> --- a/lib/dynamic_debug.c
> +++ b/lib/dynamic_debug.c
> @@ -36,6 +36,7 @@
>  #include <linux/sched.h>
>  #include <linux/device.h>
>  #include <linux/netdevice.h>
> +#include <trace/events/printk.h>
>  
>  #include <rdma/ib_verbs.h>
>  
> @@ -79,11 +80,12 @@ static inline const char *trim_prefix(const char *path)
>  }
>  
>  static struct { unsigned flag:8; char opt_char; } opt_array[] = {
> -	{ _DPRINTK_FLAGS_PRINT, 'p' },
> +	{ _DPRINTK_FLAGS_PRINTK, 'p' },
>  	{ _DPRINTK_FLAGS_INCL_MODNAME, 'm' },
>  	{ _DPRINTK_FLAGS_INCL_FUNCNAME, 'f' },
>  	{ _DPRINTK_FLAGS_INCL_LINENO, 'l' },
>  	{ _DPRINTK_FLAGS_INCL_TID, 't' },
> +	{ _DPRINTK_FLAGS_TRACE, 'x' },
>  	{ _DPRINTK_FLAGS_NONE, '_' },
>  };
>  
> @@ -550,6 +552,65 @@ static char *dynamic_emit_prefix(const struct _ddebug *desc, char *buf)
>  	return buf;
>  }
>  
> +static void dynamic_trace(const char *fmt, va_list args)
> +{
> +	char buf[256];
> +	int len;
> +
> +	len = vscnprintf(buf, sizeof(buf), fmt, args);
> +	if (!len)
> +		return;
> +
> +	if (buf[len - 1] == '\n')
> +		buf[len - 1] = '\0';
> +
> +	trace_dynamic(buf);
> +}
> +
> +static void dynamic_printk(unsigned int flags, const char *fmt, ...)
> +{
> +	if (flags & _DPRINTK_FLAGS_TRACE) {
> +		va_list args;
> +
> +		va_start(args, fmt);
> +		/*
> +		 * All callers include the KERN_DEBUG prefix to keep the
> +		 * vprintk case simple; strip it out for tracing.
> +		 */
> +		dynamic_trace(fmt + strlen(KERN_DEBUG), args);
> +		va_end(args);
> +	}
> +
> +	if (flags & _DPRINTK_FLAGS_PRINTK) {
> +		va_list args;
> +
> +		va_start(args, fmt);
> +		vprintk(fmt, args);
> +		va_end(args);
> +	}
> +}
> +
> +static void dynamic_dev_printk(unsigned int flags, const struct device *dev,
> +			       const char *fmt, ...)
> +{
> +
> +	if (flags & _DPRINTK_FLAGS_TRACE) {
> +		va_list args;
> +
> +		va_start(args, fmt);
> +		dynamic_trace(fmt, args);
> +		va_end(args);
> +	}
> +
> +	if (flags & _DPRINTK_FLAGS_PRINTK) {
> +		va_list args;
> +
> +		va_start(args, fmt);
> +		dev_vprintk_emit(LOGLEVEL_DEBUG, dev, fmt, args);
> +		va_end(args);
> +	}
> +}
> +
>  void __dynamic_pr_debug(struct _ddebug *descriptor, const char *fmt, ...)
>  {
>  	va_list args;
> @@ -564,7 +625,8 @@ void __dynamic_pr_debug(struct _ddebug *descriptor, const char *fmt, ...)
>  	vaf.fmt = fmt;
>  	vaf.va = &args;
>  
> -	printk(KERN_DEBUG "%s%pV", dynamic_emit_prefix(descriptor, buf), &vaf);
> +	dynamic_printk(descriptor->flags, KERN_DEBUG "%s%pV",
> +		       dynamic_emit_prefix(descriptor, buf), &vaf);
>  
>  	va_end(args);
>  }
> @@ -574,6 +636,7 @@ void __dynamic_dev_dbg(struct _ddebug *descriptor,
>  		      const struct device *dev, const char *fmt, ...)
>  {
>  	struct va_format vaf;
> +	unsigned int flags;
>  	va_list args;
>  
>  	BUG_ON(!descriptor);
> @@ -583,16 +646,18 @@ void __dynamic_dev_dbg(struct _ddebug *descriptor,
>  
>  	vaf.fmt = fmt;
>  	vaf.va = &args;
> +	flags = descriptor->flags;
>  
>  	if (!dev) {
> -		printk(KERN_DEBUG "(NULL device *): %pV", &vaf);
> +		dynamic_printk(flags, KERN_DEBUG "(NULL device *): %pV",
> +			      &vaf);
>  	} else {
>  		char buf[PREFIX_SIZE];
>  
> -		dev_printk_emit(LOGLEVEL_DEBUG, dev, "%s%s %s: %pV",
> -				dynamic_emit_prefix(descriptor, buf),
> -				dev_driver_string(dev), dev_name(dev),
> -				&vaf);
> +		dynamic_dev_printk(flags, dev, "%s%s %s: %pV",
> +				   dynamic_emit_prefix(descriptor, buf),
> +				   dev_driver_string(dev), dev_name(dev),
> +				   &vaf);
>  	}
>  
>  	va_end(args);
> @@ -605,6 +670,7 @@ void __dynamic_netdev_dbg(struct _ddebug *descriptor,
>  			  const struct net_device *dev, const char *fmt, ...)
>  {
>  	struct va_format vaf;
> +	unsigned int flags;
>  	va_list args;
>  
>  	BUG_ON(!descriptor);
> @@ -614,22 +680,24 @@ void __dynamic_netdev_dbg(struct _ddebug *descriptor,
>  
>  	vaf.fmt = fmt;
>  	vaf.va = &args;
> +	flags = descriptor->flags;
>  
>  	if (dev && dev->dev.parent) {
>  		char buf[PREFIX_SIZE];
>  
> -		dev_printk_emit(LOGLEVEL_DEBUG, dev->dev.parent,
> -				"%s%s %s %s%s: %pV",
> -				dynamic_emit_prefix(descriptor, buf),
> -				dev_driver_string(dev->dev.parent),
> -				dev_name(dev->dev.parent),
> -				netdev_name(dev), netdev_reg_state(dev),
> -				&vaf);
> +		dynamic_dev_printk(flags, dev->dev.parent,
> +				   "%s%s %s %s%s: %pV",
> +				   dynamic_emit_prefix(descriptor, buf),
> +				   dev_driver_string(dev->dev.parent),
> +				   dev_name(dev->dev.parent),
> +				   netdev_name(dev), netdev_reg_state(dev),
> +				   &vaf);
>  	} else if (dev) {
> -		printk(KERN_DEBUG "%s%s: %pV", netdev_name(dev),
> -		       netdev_reg_state(dev), &vaf);
> +		dynamic_printk(flags, KERN_DEBUG "%s%s: %pV",
> +			       netdev_name(dev), netdev_reg_state(dev), &vaf);
>  	} else {
> -		printk(KERN_DEBUG "(NULL net_device): %pV", &vaf);
> +		dynamic_printk(flags, KERN_DEBUG "(NULL net_device): %pV",
> +			       &vaf);
>  	}
>  
>  	va_end(args);
> @@ -644,27 +712,31 @@ void __dynamic_ibdev_dbg(struct _ddebug *descriptor,
>  			 const struct ib_device *ibdev, const char *fmt, ...)
>  {
>  	struct va_format vaf;
> +	unsigned int flags;
>  	va_list args;
>  
>  	va_start(args, fmt);
>  
>  	vaf.fmt = fmt;
>  	vaf.va = &args;
> +	flags = descriptor->flags;
>  
>  	if (ibdev && ibdev->dev.parent) {
>  		char buf[PREFIX_SIZE];
>  
> -		dev_printk_emit(LOGLEVEL_DEBUG, ibdev->dev.parent,
> -				"%s%s %s %s: %pV",
> -				dynamic_emit_prefix(descriptor, buf),
> -				dev_driver_string(ibdev->dev.parent),
> -				dev_name(ibdev->dev.parent),
> -				dev_name(&ibdev->dev),
> -				&vaf);
> +		dynamic_dev_printk(flags, ibdev->dev.parent,
> +				   "%s%s %s %s: %pV",
> +				   dynamic_emit_prefix(descriptor, buf),
> +				   dev_driver_string(ibdev->dev.parent),
> +				   dev_name(ibdev->dev.parent),
> +				   dev_name(&ibdev->dev),
> +				   &vaf);
>  	} else if (ibdev) {
> -		printk(KERN_DEBUG "%s: %pV", dev_name(&ibdev->dev), &vaf);
> +		dynamic_printk(flags, KERN_DEBUG "%s: %pV",
> +			       dev_name(&ibdev->dev), &vaf);
>  	} else {
> -		printk(KERN_DEBUG "(NULL ib_device): %pV", &vaf);
> +		dynamic_printk(flags, KERN_DEBUG "(NULL ib_device): %pV",
> +			       &vaf);
>  	}
>  
>  	va_end(args);

Re: [PATCH] dynamic debug: allow printing to trace event

[Sergey Senozhatsky]

On (20/07/21 17:30), Steven Rostedt wrote:
> On Tue, 21 Jul 2020 16:11:05 +0200
> Vincent Whitchurch <vincent.whitchurch@axis.com> wrote:
> 
> > When debugging device drivers, I've found it very useful to be able to
> > redirect existing pr_debug()/dev_dbg() prints to the trace buffer
> > instead of dmesg.  Among the many advantages of the trace buffer is that
> > it can be dynamically resized, allows these prints to combined with
> > other trace events, and doesn't fill up system logs.
> > 
> > Since dynamic debug already has hooks in these call sites, getting these
> > prints into the ftrace buffer is straightforward if we have dynamic
> > debug do it.
> > 
> > Add an "x" flag to make the dynamic debug call site print to a new
> > printk:dynamic trace event.  The trace event can be emitted instead of
> > or in addition to the printk().  The print buffer is placed on the stack
> > and is limited to a somewhat arbitrarily chosen 256 bytes; anything
> > larger will be truncated.
> 
> Is it safe to have a 256 byte string on the stack? That's quite a bit.
> How deep is the stack when this is called?
> 
> You could run vsnprintf() with a zero length to get the size, and then
> just allocate that from the ring buffer. How critical is the performance?

Hmm.
Can trace event contain a fixed size buffer or a dynamic array; then
we'll pass fmt and va_list to trace event so it can vscnprintf() into
its buffer in assign function?

	-ss

Re: [PATCH] dynamic debug: allow printing to trace event

[John Ogness]

On 2020-07-21, Steven Rostedt <rostedt@goodmis.org> wrote:
>> diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
>> index 321437bbf87d..9f6d8867af7c 100644
>> --- a/lib/dynamic_debug.c
>> +++ b/lib/dynamic_debug.c
[..]
>> +static void dynamic_printk(unsigned int flags, const char *fmt, ...)
>> +{
>> +	if (flags & _DPRINTK_FLAGS_TRACE) {
>> +		va_list args;
>> +
>> +		va_start(args, fmt);
>> +		/*
>> +		 * All callers include the KERN_DEBUG prefix to keep the
>> +		 * vprintk case simple; strip it out for tracing.
>> +		 */
>> +		dynamic_trace(fmt + strlen(KERN_DEBUG), args);

Do we really need a separate tracing event for this? Why not just:

                ftrace_vprintk(fmt + strlen(KERN_DEBUG), args);

John Ogness

Re: [PATCH] dynamic debug: allow printing to trace event

[Vincent Whitchurch]

On Wed, Jul 22, 2020 at 03:52:22PM +0200, John Ogness wrote:
> On 2020-07-21, Steven Rostedt <rostedt@goodmis.org> wrote:
> >> diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
> >> index 321437bbf87d..9f6d8867af7c 100644
> >> --- a/lib/dynamic_debug.c
> >> +++ b/lib/dynamic_debug.c
> [..]
> >> +static void dynamic_printk(unsigned int flags, const char *fmt, ...)
> >> +{
> >> +	if (flags & _DPRINTK_FLAGS_TRACE) {
> >> +		va_list args;
> >> +
> >> +		va_start(args, fmt);
> >> +		/*
> >> +		 * All callers include the KERN_DEBUG prefix to keep the
> >> +		 * vprintk case simple; strip it out for tracing.
> >> +		 */
> >> +		dynamic_trace(fmt + strlen(KERN_DEBUG), args);
> 
> Do we really need a separate tracing event for this? Why not just:
> 
>                 ftrace_vprintk(fmt + strlen(KERN_DEBUG), args);

Thanks, I tried that out now and it seems to work, but it results in the
trace_printk() splat (even if the feature is not used), though:

 **********************************************************
 **   NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE   **
 **                                                      **
 ** trace_printk() being used. Allocating extra memory.  **
 **                                                      **
 ** This means that this is a DEBUG kernel and it is     **
 ** unsafe for production use.                           **
 **                                                      **
 ** If you see this message and you are not debugging    **
 ** the kernel, report this immediately to your vendor!  **
 **                                                      **
 **   NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE   **
 **********************************************************

Re: [PATCH] dynamic debug: allow printing to trace event

[Steven Rostedt]

On Wed, 22 Jul 2020 15:58:22 +0206
John Ogness <john.ogness@linutronix.de> wrote:

> >> +static void dynamic_printk(unsigned int flags, const char *fmt, ...)
> >> +{
> >> +	if (flags & _DPRINTK_FLAGS_TRACE) {
> >> +		va_list args;
> >> +
> >> +		va_start(args, fmt);
> >> +		/*
> >> +		 * All callers include the KERN_DEBUG prefix to keep the
> >> +		 * vprintk case simple; strip it out for tracing.
> >> +		 */
> >> +		dynamic_trace(fmt + strlen(KERN_DEBUG), args);  
> 
> Do we really need a separate tracing event for this? Why not just:
> 
>                 ftrace_vprintk(fmt + strlen(KERN_DEBUG), args);

It must be an event, one that can be enabled or disabled separately
from trace_printk().

If you are asking if this could be something like trace_printk(), which
ftrace_vprintk() is. The reason for that nasty banner when people use
trace_printk() is to keep developers from using it as their personal
debugging tool in production.

A trace_printk() can not be discretely disabled. It's either totally
on, or totally off. And since it is used for debugging, if there's
trace_printk()s all over the kernel, you will have to deal with the
noise of everyone else's trace_printk(), making trace_printk() useless.

Thus, NAK on using ftrace_vprintk() here.

-- Steve

Re: [PATCH] dynamic debug: allow printing to trace event

[Steven Rostedt]

On Wed, 22 Jul 2020 16:49:52 +0200
Vincent Whitchurch <vincent.whitchurch@axis.com> wrote:

>  Do we really need a separate tracing event for this? Why not just:
> > 
> >                 ftrace_vprintk(fmt + strlen(KERN_DEBUG), args);  
> 
> Thanks, I tried that out now and it seems to work, but it results in the
> trace_printk() splat (even if the feature is not used), though:
> 
>  **********************************************************
>  **   NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE   **
>  **                                                      **
>  ** trace_printk() being used. Allocating extra memory.  **
>  **                                                      **
>  ** This means that this is a DEBUG kernel and it is     **
>  ** unsafe for production use.                           **
>  **                                                      **
>  ** If you see this message and you are not debugging    **
>  ** the kernel, report this immediately to your vendor!  **
>  **                                                      **
>  **   NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE   **
>  **********************************************************

And that is done purposely. No DO NOT USE ftrace_vprintk()!!!

I explained why to John.

For you, I made this quick patch. If this works for you, I can make it
into a formal patch. It includes a test use case in do_sys_openat2() to
show the file name and file descriptor. Obviously, that wont be part of
the final patch.

Thoughts?

-- Steve

diff --git a/fs/open.c b/fs/open.c
index b69d6eed67e6..ea19478a2220 100644
--- a/fs/open.c
+++ b/fs/open.c
@@ -32,6 +32,7 @@
 #include <linux/ima.h>
 #include <linux/dnotify.h>
 #include <linux/compat.h>
+#include <trace/events/printk.h>
 
 #include "internal.h"
 
@@ -1127,6 +1128,15 @@ struct file *file_open_root(struct dentry *dentry, struct vfsmount *mnt,
 }
 EXPORT_SYMBOL(file_open_root);
 
+static void do_trace_vprintk(const char *fmt, ...)
+{
+	va_list ap;
+
+	va_start(ap, fmt);
+	trace_vprintk(fmt, ap);
+	va_end(ap);
+}
+
 static long do_sys_openat2(int dfd, const char __user *filename,
 			   struct open_how *how)
 {
@@ -1141,6 +1151,8 @@ static long do_sys_openat2(int dfd, const char __user *filename,
 	if (IS_ERR(tmp))
 		return PTR_ERR(tmp);
 
+	do_trace_vprintk("file=%s fd=%d\n", tmp->name, fd);
+
 	fd = get_unused_fd_flags(how->flags);
 	if (fd >= 0) {
 		struct file *f = do_filp_open(dfd, tmp, &op);
diff --git a/include/trace/events/printk.h b/include/trace/events/printk.h
index 13d405b2fd8b..60d9ca21acf9 100644
--- a/include/trace/events/printk.h
+++ b/include/trace/events/printk.h
@@ -31,6 +31,53 @@ TRACE_EVENT(console,
 
 	TP_printk("%s", __get_str(msg))
 );
+
+#ifndef __FIND_VPRINTK_LEN_H
+#define __FIND_VPRINTK_LEN_H
+/* The header is called multiple times, but this should not be */
+static inline int find_vprintk_len(const char *fmt, va_list args)
+{
+	va_list va;
+	int len;
+
+	va_copy(va, args);
+	len = vsnprintf(NULL, 0, fmt, va);
+	va_end(va);
+	return len + 1;
+}
+#endif
+
+TRACE_EVENT(vprintk,
+	TP_PROTO(const char *fmt, va_list args),
+
+	TP_ARGS(fmt, args),
+
+	TP_STRUCT__entry(
+		__dynamic_array(char, msg, find_vprintk_len(fmt, args))
+	),
+
+	TP_fast_assign(
+		va_list ap;
+		int len = find_vprintk_len(fmt, args);
+
+		va_copy(ap, args);
+		len = vsnprintf(__get_str(msg), len, fmt, ap);
+		va_end(ap);
+		/*
+		 * Each trace entry is printed in a new line.
+		 * If the msg finishes with '\n', cut it off
+		 * to avoid blank lines in the trace.
+		 */
+		if ((len > 0) && (__get_str(msg)[len-1] == '\n'))
+			len -= 1;
+
+		__get_str(msg)[len] = 0;
+	),
+
+	TP_printk("%s", __get_str(msg))
+);
+
+
 #endif /* _TRACE_PRINTK_H */
 
 /* This part must be outside protection */

Re: [PATCH] dynamic debug: allow printing to trace event

[Vincent Whitchurch]

On Wed, Jul 22, 2020 at 05:28:23PM +0200, Steven Rostedt wrote:
> For you, I made this quick patch. If this works for you, I can make it
> into a formal patch. It includes a test use case in do_sys_openat2() to
> show the file name and file descriptor. Obviously, that wont be part of
> the final patch.

Thank you.  I had to replace the inline with an __attribute__((unused))
because otherwise my GCC errors out with "error: function
'find_vprintk_len' can never be inlined because it uses variable
argument lists".

Apart from that it works fine, but the several calls to vsnprintf() take
their toll and this method is twice as slow as the buffer-on-stack
implementation (and ftrace_vprintk()).  If I pass in a fixed size for
the __dynamic_array I get the same performance as the buffer-on-stack
method, but that's probably not surprising.

I know a dedicated trace event or a binary trace_printk() at the call
site of pr_debug() is always going to be more performant, but it would
be nice to avoid the extra slowdown if possible.

It's hard to guarantee that 256 bytes on the stack is safe on all
systems since these functions are called from lots of places.  

Would it be acceptable to just use a fixed size for the event?  At least
for my own debugging use cases it's preferable to just have to increase
the trace buffer size in case it's insufficient, rather than to have to
restort to one-off debugging code.

Re: [PATCH] dynamic debug: allow printing to trace event

[John Ogness]

On 2020-07-22, Steven Rostedt <rostedt@goodmis.org> wrote:
>>> +static void dynamic_printk(unsigned int flags, const char *fmt, ...)
>>> +{
>>> +	if (flags & _DPRINTK_FLAGS_TRACE) {
>>> +		va_list args;
>>> +
>>> +		va_start(args, fmt);
>>> +		/*
>>> +		 * All callers include the KERN_DEBUG prefix to keep the
>>> +		 * vprintk case simple; strip it out for tracing.
>>> +		 */
>>> +		dynamic_trace(fmt + strlen(KERN_DEBUG), args);  
>> 
>> Do we really need a separate tracing event for this? Why not just:
>> 
>>                 ftrace_vprintk(fmt + strlen(KERN_DEBUG), args);
>
> It must be an event, one that can be enabled or disabled separately
> from trace_printk().
>
> If you are asking if this could be something like trace_printk(),
> which ftrace_vprintk() is. The reason for that nasty banner when
> people use trace_printk() is to keep developers from using it as their
> personal debugging tool in production.
>
> A trace_printk() can not be discretely disabled. It's either totally
> on, or totally off. And since it is used for debugging, if there's
> trace_printk()s all over the kernel, you will have to deal with the
> noise of everyone else's trace_printk(), making trace_printk()
> useless.

I understand and agree with your concern about trace_printk(). But it
seems to me that trace_printk() via pr_debug() should be OK because
there is discrete control per message implemented. Yes, more code is
necessary to distinguish between the two, such as letting dynamic_printk
use an internal function that does not trigger a splat. But I think that
is reasonable.

For me a trace event represents a specific point in the kernel code. But
this new printk trace event, instead, represents general log
redirection. I do not oppose it, but it feels like a hack to me. In
contrast, simply setting a dynamic printk flag to write the message
string to the trace buffer (without also activating some pseudo trace
event) feels more natural.

Just sharing my thoughts, as requested.

John Ogness

Re: [PATCH] dynamic debug: allow printing to trace event

[John Ogness]

On 2020-07-23, John Ogness <john.ogness@linutronix.de> wrote:
> For me a trace event represents a specific point in the kernel
> code.

Actually, after revisiting Vincent's original patch (adding a "dynamic"
event in the "printk" group and placing the event within the
dynamic_printk printing path), I would fully support the new event. It
_is_ appropriately a printk/dynamic event.

John Ogness

Re: [PATCH] dynamic debug: allow printing to trace event

[Steven Rostedt]

On Thu, 23 Jul 2020 12:57:35 +0200
Vincent Whitchurch <vincent.whitchurch@axis.com> wrote:

> Would it be acceptable to just use a fixed size for the event?  At least
> for my own debugging use cases it's preferable to just have to increase
> the trace buffer size in case it's insufficient, rather than to have to
> restort to one-off debugging code.

There's two other options.

Option 1, is to allocate 256 bytes times 4 (in case of interruption,
where you have a separate buffer for every context - normal, softirq,
irq, nmi), and use it like I do for stack traces in the latest kernel
(see __ftrace_stack_trace() in kernel/trace/trace.c)

Option 2, would be to use trace_array_vprintk(), but you need to create
your own instance to do so to keep from messing with the top level buffer.

-- Steve

Re: [PATCH] dynamic debug: allow printing to trace event

[Steven Rostedt]

On Thu, 23 Jul 2020 16:08:44 +0206
John Ogness <john.ogness@linutronix.de> wrote:

> For me a trace event represents a specific point in the kernel code. But
> this new printk trace event, instead, represents general log
> redirection. I do not oppose it, but it feels like a hack to me. In
> contrast, simply setting a dynamic printk flag to write the message
> string to the trace buffer (without also activating some pseudo trace
> event) feels more natural.

I agree with your sentiment. But my experience with the kernel is, if
you create an API for one subsystem, other subsystems are destined to
(ab)use it.

Now, trace_array_vprintk() is available too, which acts just like
trace_printk(), but requires creating a separate trace buffer to write
to. I'm fine with this because it wont cause noise in the top level
buffer.


> 
> Just sharing my thoughts, as requested.

Appreciated ;-)

-- Steve

Re: [PATCH] dynamic debug: allow printing to trace event

[Vincent Whitchurch]

On Thu, Jul 23, 2020 at 05:26:44PM +0200, Steven Rostedt wrote:
> On Thu, 23 Jul 2020 12:57:35 +0200
> Vincent Whitchurch <vincent.whitchurch@axis.com> wrote:
> 
> > Would it be acceptable to just use a fixed size for the event?  At least
> > for my own debugging use cases it's preferable to just have to increase
> > the trace buffer size in case it's insufficient, rather than to have to
> > restort to one-off debugging code.
> 
> There's two other options.
> 
> Option 1, is to allocate 256 bytes times 4 (in case of interruption,
> where you have a separate buffer for every context - normal, softirq,
> irq, nmi), and use it like I do for stack traces in the latest kernel
> (see __ftrace_stack_trace() in kernel/trace/trace.c)
> 
> Option 2, would be to use trace_array_vprintk(), but you need to create
> your own instance to do so to keep from messing with the top level buffer.

Thanks for the suggestions, I've sent out a v2 implementing option 1:

https://lore.kernel.org/lkml/20200814133151.7759-1-vincent.whitchurch@axis.com/