[PATCH v3 0/2] Dynamic debug trace support

[PATCH v3 0/2] Dynamic debug trace support

[Vincent Whitchurch]

v3:
 - Split flag rename to a separate patch
 - Rename event to printk:dyndbg

v2:
 - Remove stack buffer and use code similar to __ftrace_trace_stack()
 - Use an event with the same class as printk:console

Vincent Whitchurch (2):
  dynamic debug: split enable and printk flags
  dynamic debug: allow printing to trace event

 .../admin-guide/dynamic-debug-howto.rst       |   1 +
 include/linux/dynamic_debug.h                 |  11 +-
 include/trace/events/printk.h                 |  12 +-
 lib/dynamic_debug.c                           | 161 ++++++++++++++----
 4 files changed, 151 insertions(+), 34 deletions(-)

Range-diff:
-:  ------------ > 1:  2564b3dbbb04 dynamic debug: split enable and printk flags
1:  7bd3fb553503 ! 2:  90291c35d751 dynamic debug: allow printing to trace event
    @@ Commit message
         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().
    +    printk:dyndbg trace event.  The trace event can be emitted instead of or
    +    in addition to the printk().
     
         The print buffer is statically allocated and managed using code borrowed
         from __ftrace_trace_stack() and is limited to 256 bytes (four of these
    @@ Documentation/admin-guide/dynamic-debug-howto.rst: of the characters::
      The flags are::
      
        p    enables the pr_debug() callsite.
    -+  x    enables trace to the printk:dynamic event
    ++  x    enables trace to the printk:dyndbg 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
     
      ## include/linux/dynamic_debug.h ##
     @@ include/linux/dynamic_debug.h: 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_ENABLE		_DPRINTK_FLAGS_PRINTK
     +#define _DPRINTK_FLAGS_TRACE		(1<<5)
    -+#define _DPRINTK_FLAGS_PRINT		(_DPRINTK_FLAGS_PRINTK | \
    ++#define _DPRINTK_FLAGS_ENABLE		(_DPRINTK_FLAGS_PRINTK | \
     +					 _DPRINTK_FLAGS_TRACE)
      #if defined DEBUG
    --#define _DPRINTK_FLAGS_DEFAULT _DPRINTK_FLAGS_PRINT
    -+#define _DPRINTK_FLAGS_DEFAULT _DPRINTK_FLAGS_PRINTK
    + #define _DPRINTK_FLAGS_DEFAULT _DPRINTK_FLAGS_PRINTK
      #else
    - #define _DPRINTK_FLAGS_DEFAULT 0
    - #endif
     
      ## include/trace/events/printk.h ##
     @@
    @@ include/trace/events/printk.h: TRACE_EVENT(console,
     +	TP_ARGS(text, len)
     +);
     +
    -+DEFINE_EVENT(printk, dynamic,
    ++DEFINE_EVENT(printk, dyndbg,
     +	TP_PROTO(const char *text, size_t len),
     +	TP_ARGS(text, len)
     +);
    @@ lib/dynamic_debug.c
      
      #include <rdma/ib_verbs.h>
      
    -@@ lib/dynamic_debug.c: 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' },
    +@@ lib/dynamic_debug.c: static struct { unsigned flag:8; char opt_char; } opt_array[] = {
      	{ _DPRINTK_FLAGS_INCL_FUNCNAME, 'f' },
      	{ _DPRINTK_FLAGS_INCL_LINENO, 'l' },
      	{ _DPRINTK_FLAGS_INCL_TID, 't' },
    @@ lib/dynamic_debug.c: static char *dynamic_emit_prefix(const struct _ddebug *desc
     +	buf = this_cpu_ptr(dynamic_trace_bufs.bufs) + bufidx;
     +
     +	len = vscnprintf(buf->buf, sizeof(buf->buf), fmt, args);
    -+	trace_dynamic(buf->buf, len);
    ++	trace_dyndbg(buf->buf, len);
     +
     +out:
     +	/* As above. */
-- 
2.28.0

[PATCH v3 1/2] dynamic debug: split enable and printk flags

[Vincent Whitchurch]

We're going to add support to allow dynamic debug locations to print to
a trace event, and that will make _DPRINTK_FLAGS_PRINT a bit ambiguous.
Will it mean printk(), or printing to the trace event, or any of the
two?

To make it clearer, split _DPRINTK_FLAGS_PRINT into two:

 (1) _DPRINTK_FLAGS_PRINTK for turning on the printk() and
 (2) _DPRINTK_FLAGS_ENABLE when checking if the dynamic debug location
     is enabled.

_DPRINTK_FLAGS_ENABLE is currently just an alias of
_DPRINTK_FLAGS_PRINTK but will later also include a new flag for
enabling printing to the trace event.

Signed-off-by: Vincent Whitchurch <vincent.whitchurch@axis.com>
---
 include/linux/dynamic_debug.h | 9 +++++----
 lib/dynamic_debug.c           | 8 ++++----
 2 files changed, 9 insertions(+), 8 deletions(-)

diff --git a/include/linux/dynamic_debug.h b/include/linux/dynamic_debug.h
index aa9ff9e1c0b3..738421898aac 100644
--- a/include/linux/dynamic_debug.h
+++ b/include/linux/dynamic_debug.h
@@ -27,13 +27,14 @@ 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_ENABLE		_DPRINTK_FLAGS_PRINTK
 #if defined DEBUG
-#define _DPRINTK_FLAGS_DEFAULT _DPRINTK_FLAGS_PRINT
+#define _DPRINTK_FLAGS_DEFAULT _DPRINTK_FLAGS_PRINTK
 #else
 #define _DPRINTK_FLAGS_DEFAULT 0
 #endif
@@ -111,10 +112,10 @@ void __dynamic_ibdev_dbg(struct _ddebug *descriptor,
 
 #ifdef DEBUG
 #define DYNAMIC_DEBUG_BRANCH(descriptor) \
-	likely(descriptor.flags & _DPRINTK_FLAGS_PRINT)
+	likely(descriptor.flags & _DPRINTK_FLAGS_ENABLE)
 #else
 #define DYNAMIC_DEBUG_BRANCH(descriptor) \
-	unlikely(descriptor.flags & _DPRINTK_FLAGS_PRINT)
+	unlikely(descriptor.flags & _DPRINTK_FLAGS_ENABLE)
 #endif
 
 #endif
diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
index 1d012e597cc3..88af85cb5222 100644
--- a/lib/dynamic_debug.c
+++ b/lib/dynamic_debug.c
@@ -84,7 +84,7 @@ 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' },
@@ -206,10 +206,10 @@ static int ddebug_change(const struct ddebug_query *query,
 			if (newflags == dp->flags)
 				continue;
 #ifdef CONFIG_JUMP_LABEL
-			if (dp->flags & _DPRINTK_FLAGS_PRINT) {
-				if (!(modifiers->flags & _DPRINTK_FLAGS_PRINT))
+			if (dp->flags & _DPRINTK_FLAGS_ENABLE) {
+				if (!(modifiers->flags & _DPRINTK_FLAGS_ENABLE))
 					static_branch_disable(&dp->key.dd_key_true);
-			} else if (modifiers->flags & _DPRINTK_FLAGS_PRINT)
+			} else if (modifiers->flags & _DPRINTK_FLAGS_ENABLE)
 				static_branch_enable(&dp->key.dd_key_true);
 #endif
 			dp->flags = newflags;
-- 
2.28.0

[PATCH v3 2/2] 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:dyndbg trace event.  The trace event can be emitted instead of or
in addition to the printk().

The print buffer is statically allocated and managed using code borrowed
from __ftrace_trace_stack() and is limited to 256 bytes (four of these
are allocated per CPU to handle the various contexts); 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                 |   4 +-
 include/trace/events/printk.h                 |  12 +-
 lib/dynamic_debug.c                           | 153 +++++++++++++++---
 4 files changed, 143 insertions(+), 27 deletions(-)

diff --git a/Documentation/admin-guide/dynamic-debug-howto.rst b/Documentation/admin-guide/dynamic-debug-howto.rst
index e5a8def45f3f..e717054ae142 100644
--- a/Documentation/admin-guide/dynamic-debug-howto.rst
+++ b/Documentation/admin-guide/dynamic-debug-howto.rst
@@ -229,6 +229,7 @@ of the characters::
 The flags are::
 
   p    enables the pr_debug() callsite.
+  x    enables trace to the printk:dyndbg 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 738421898aac..74aee3f922d7 100644
--- a/include/linux/dynamic_debug.h
+++ b/include/linux/dynamic_debug.h
@@ -32,7 +32,9 @@ struct _ddebug {
 #define _DPRINTK_FLAGS_INCL_FUNCNAME	(1<<2)
 #define _DPRINTK_FLAGS_INCL_LINENO	(1<<3)
 #define _DPRINTK_FLAGS_INCL_TID		(1<<4)
-#define _DPRINTK_FLAGS_ENABLE		_DPRINTK_FLAGS_PRINTK
+#define _DPRINTK_FLAGS_TRACE		(1<<5)
+#define _DPRINTK_FLAGS_ENABLE		(_DPRINTK_FLAGS_PRINTK | \
+					 _DPRINTK_FLAGS_TRACE)
 #if defined DEBUG
 #define _DPRINTK_FLAGS_DEFAULT _DPRINTK_FLAGS_PRINTK
 #else
diff --git a/include/trace/events/printk.h b/include/trace/events/printk.h
index 13d405b2fd8b..1f78bd237a91 100644
--- a/include/trace/events/printk.h
+++ b/include/trace/events/printk.h
@@ -7,7 +7,7 @@
 
 #include <linux/tracepoint.h>
 
-TRACE_EVENT(console,
+DECLARE_EVENT_CLASS(printk,
 	TP_PROTO(const char *text, size_t len),
 
 	TP_ARGS(text, len),
@@ -31,6 +31,16 @@ TRACE_EVENT(console,
 
 	TP_printk("%s", __get_str(msg))
 );
+
+DEFINE_EVENT(printk, console,
+	TP_PROTO(const char *text, size_t len),
+	TP_ARGS(text, len)
+);
+
+DEFINE_EVENT(printk, dyndbg,
+	TP_PROTO(const char *text, size_t len),
+	TP_ARGS(text, len)
+);
 #endif /* _TRACE_PRINTK_H */
 
 /* This part must be outside protection */
diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
index 88af85cb5222..3319da2e235c 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>
 
@@ -89,6 +90,7 @@ static struct { unsigned flag:8; char opt_char; } opt_array[] = {
 	{ _DPRINTK_FLAGS_INCL_FUNCNAME, 'f' },
 	{ _DPRINTK_FLAGS_INCL_LINENO, 'l' },
 	{ _DPRINTK_FLAGS_INCL_TID, 't' },
+	{ _DPRINTK_FLAGS_TRACE, 'x' },
 	{ _DPRINTK_FLAGS_NONE, '_' },
 };
 
@@ -600,6 +602,96 @@ static char *dynamic_emit_prefix(const struct _ddebug *desc, char *buf)
 	return buf;
 }
 
+/*
+ * This code is heavily based on __ftrace_trace_stack().
+ *
+ * Allow 4 levels of nesting: normal, softirq, irq, NMI.
+ */
+#define DYNAMIC_TRACE_NESTING	4
+
+struct dynamic_trace_buf {
+	char buf[256];
+};
+
+struct dynamic_trace_bufs {
+	struct dynamic_trace_buf bufs[DYNAMIC_TRACE_NESTING];
+};
+
+static DEFINE_PER_CPU(struct dynamic_trace_bufs, dynamic_trace_bufs);
+static DEFINE_PER_CPU(int, dynamic_trace_reserve);
+
+static void dynamic_trace(const char *fmt, va_list args)
+{
+	struct dynamic_trace_buf *buf;
+	int bufidx;
+	int len;
+
+	preempt_disable_notrace();
+
+	bufidx = __this_cpu_inc_return(dynamic_trace_reserve) - 1;
+
+	if (WARN_ON_ONCE(bufidx > DYNAMIC_TRACE_NESTING))
+		goto out;
+
+	/* For the same reasons as in __ftrace_trace_stack(). */
+	barrier();
+
+	buf = this_cpu_ptr(dynamic_trace_bufs.bufs) + bufidx;
+
+	len = vscnprintf(buf->buf, sizeof(buf->buf), fmt, args);
+	trace_dyndbg(buf->buf, len);
+
+out:
+	/* As above. */
+	barrier();
+	__this_cpu_dec(dynamic_trace_reserve);
+	preempt_enable_notrace();
+}
+
+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;
@@ -614,7 +706,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);
 }
@@ -624,6 +717,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);
@@ -633,16 +727,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);
@@ -655,6 +751,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);
@@ -664,22 +761,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);
@@ -694,27 +793,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.28.0

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

[Joe Perches]

On Tue, 2020-08-25 at 17:33 +0200, Vincent Whitchurch 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.

This content should be in the 0/3 cover letter.

> 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:dyndbg trace event.  The trace event can be emitted instead of or
> in addition to the printk().
> 
> The print buffer is statically allocated and managed using code borrowed
> from __ftrace_trace_stack() and is limited to 256 bytes (four of these
> are allocated per CPU to handle the various contexts); anything larger
> will be truncated.

There is an effort to avoid using trace_printk and the like
so perhaps this feature should have the same compile time
guard.

> Signed-off-by: Vincent Whitchurch <vincent.whitchurch@axis.com>
> ---
>  .../admin-guide/dynamic-debug-howto.rst       |   1 +
>  include/linux/dynamic_debug.h                 |   4 +-
>  include/trace/events/printk.h                 |  12 +-
>  lib/dynamic_debug.c                           | 153 +++++++++++++++---
>  4 files changed, 143 insertions(+), 27 deletions(-)
> 
> diff --git a/Documentation/admin-guide/dynamic-debug-howto.rst b/Documentation/admin-guide/dynamic-debug-howto.rst
> index e5a8def45f3f..e717054ae142 100644
> --- a/Documentation/admin-guide/dynamic-debug-howto.rst
> +++ b/Documentation/admin-guide/dynamic-debug-howto.rst
> @@ -229,6 +229,7 @@ of the characters::
>  The flags are::
>  
>    p    enables the pr_debug() callsite.
> +  x    enables trace to the printk:dyndbg 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 738421898aac..74aee3f922d7 100644
> --- a/include/linux/dynamic_debug.h
> +++ b/include/linux/dynamic_debug.h
> @@ -32,7 +32,9 @@ struct _ddebug {
>  #define _DPRINTK_FLAGS_INCL_FUNCNAME	(1<<2)
>  #define _DPRINTK_FLAGS_INCL_LINENO	(1<<3)
>  #define _DPRINTK_FLAGS_INCL_TID		(1<<4)
> -#define _DPRINTK_FLAGS_ENABLE		_DPRINTK_FLAGS_PRINTK
> +#define _DPRINTK_FLAGS_TRACE		(1<<5)
> +#define _DPRINTK_FLAGS_ENABLE		(_DPRINTK_FLAGS_PRINTK | \
> +					 _DPRINTK_FLAGS_TRACE)
>  #if defined DEBUG
>  #define _DPRINTK_FLAGS_DEFAULT _DPRINTK_FLAGS_PRINTK
>  #else
> diff --git a/include/trace/events/printk.h b/include/trace/events/printk.h
> index 13d405b2fd8b..1f78bd237a91 100644
> --- a/include/trace/events/printk.h
> +++ b/include/trace/events/printk.h
> @@ -7,7 +7,7 @@
>  
>  #include <linux/tracepoint.h>
>  
> -TRACE_EVENT(console,
> +DECLARE_EVENT_CLASS(printk,
>  	TP_PROTO(const char *text, size_t len),
>  
>  	TP_ARGS(text, len),
> @@ -31,6 +31,16 @@ TRACE_EVENT(console,
>  
>  	TP_printk("%s", __get_str(msg))
>  );
> +
> +DEFINE_EVENT(printk, console,
> +	TP_PROTO(const char *text, size_t len),
> +	TP_ARGS(text, len)
> +);
> +
> +DEFINE_EVENT(printk, dyndbg,
> +	TP_PROTO(const char *text, size_t len),
> +	TP_ARGS(text, len)
> +);
>  #endif /* _TRACE_PRINTK_H */
>  
>  /* This part must be outside protection */
> diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
> index 88af85cb5222..3319da2e235c 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>
>  
> @@ -89,6 +90,7 @@ static struct { unsigned flag:8; char opt_char; } opt_array[] = {
>  	{ _DPRINTK_FLAGS_INCL_FUNCNAME, 'f' },
>  	{ _DPRINTK_FLAGS_INCL_LINENO, 'l' },
>  	{ _DPRINTK_FLAGS_INCL_TID, 't' },
> +	{ _DPRINTK_FLAGS_TRACE, 'x' },
>  	{ _DPRINTK_FLAGS_NONE, '_' },
>  };
>  
> @@ -600,6 +602,96 @@ static char *dynamic_emit_prefix(const struct _ddebug *desc, char *buf)
>  	return buf;
>  }
>  
> +/*
> + * This code is heavily based on __ftrace_trace_stack().
> + *
> + * Allow 4 levels of nesting: normal, softirq, irq, NMI.
> + */
> +#define DYNAMIC_TRACE_NESTING	4
> +
> +struct dynamic_trace_buf {
> +	char buf[256];
> +};
> +
> +struct dynamic_trace_bufs {
> +	struct dynamic_trace_buf bufs[DYNAMIC_TRACE_NESTING];
> +};
> +
> +static DEFINE_PER_CPU(struct dynamic_trace_bufs, dynamic_trace_bufs);
> +static DEFINE_PER_CPU(int, dynamic_trace_reserve);
> +
> +static void dynamic_trace(const char *fmt, va_list args)
> +{
> +	struct dynamic_trace_buf *buf;
> +	int bufidx;
> +	int len;
> +
> +	preempt_disable_notrace();
> +
> +	bufidx = __this_cpu_inc_return(dynamic_trace_reserve) - 1;
> +
> +	if (WARN_ON_ONCE(bufidx > DYNAMIC_TRACE_NESTING))
> +		goto out;
> +
> +	/* For the same reasons as in __ftrace_trace_stack(). */
> +	barrier();
> +
> +	buf = this_cpu_ptr(dynamic_trace_bufs.bufs) + bufidx;
> +
> +	len = vscnprintf(buf->buf, sizeof(buf->buf), fmt, args);
> +	trace_dyndbg(buf->buf, len);
> +
> +out:
> +	/* As above. */
> +	barrier();
> +	__this_cpu_dec(dynamic_trace_reserve);
> +	preempt_enable_notrace();
> +}
> +
> +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;
> @@ -614,7 +706,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);
>  }
> @@ -624,6 +717,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);
> @@ -633,16 +727,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);
> @@ -655,6 +751,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);
> @@ -664,22 +761,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);
> @@ -694,27 +793,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 v3 2/2] dynamic debug: allow printing to trace event

[Steven Rostedt]

On Tue, 25 Aug 2020 08:53:25 -0700
Joe Perches <joe@perches.com> wrote:

> > The print buffer is statically allocated and managed using code borrowed
> > from __ftrace_trace_stack() and is limited to 256 bytes (four of these
> > are allocated per CPU to handle the various contexts); anything larger
> > will be truncated.  
> 
> There is an effort to avoid using trace_printk and the like
> so perhaps this feature should have the same compile time
> guard.

No, this is fine for being in a production kernel. Basically, these are
simply debug printk()s that can also be put into the trace buffer. The
key difference to trace_printk() is that they are an event that needs
to be enabled to write into the buffer.

The problem I'm avoiding with not letting people add trace_printk() is
that trace_printk() should be used when a developer is trying to debug
some code. The *only* trace_printk()s should be the ones that developer
adds (because it only shows what they want to find).

trace_printk()s are enabled by default, and they have a special
switch to disable. But it is an all or nothing switch. They either
enable all of them, or disable all of them. No in between.

Now if we allow trace_printk()s to be scattered through the kernel,
when someone wants to use trace_printk() for their own debugging, and
it is turned on, now the trace buffer is filled with a bunch of "noise"
from all these other trace_printk()s that are scattered around, and the
trace_printk()s that the poor developer added are lost among the sea of
other trace_printk()s, making their trace_printk()s useless.

That is the reason I try hard not letting trace_printk() enter into the
kernel.

-- Steve

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

[Joe Perches]

On Wed, 2020-08-26 at 15:32 -0400, Steven Rostedt wrote:
> On Tue, 25 Aug 2020 08:53:25 -0700
> Joe Perches <joe@perches.com> wrote:
> 
> > > The print buffer is statically allocated and managed using code borrowed
> > > from __ftrace_trace_stack() and is limited to 256 bytes (four of these
> > > are allocated per CPU to handle the various contexts); anything larger
> > > will be truncated.  
> > 
> > There is an effort to avoid using trace_printk and the like
> > so perhaps this feature should have the same compile time
> > guard.
> 
> No, this is fine for being in a production kernel. Basically, these are
> simply debug printk()s that can also be put into the trace buffer. The
> key difference to trace_printk() is that they are an event that needs
> to be enabled to write into the buffer.

It just seems like a backdoor way to convert various pr_debug functions
(dev_dbg/netdev_dbg, et al) into tracing.

What's the real value?  Timing data?  Something else?

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

[Vincent Whitchurch]

On Wed, Aug 26, 2020 at 09:53:57PM +0200, Joe Perches wrote:
> On Wed, 2020-08-26 at 15:32 -0400, Steven Rostedt wrote:
> > On Tue, 25 Aug 2020 08:53:25 -0700
> > Joe Perches <joe@perches.com> wrote:
> > 
> > > > The print buffer is statically allocated and managed using code borrowed
> > > > from __ftrace_trace_stack() and is limited to 256 bytes (four of these
> > > > are allocated per CPU to handle the various contexts); anything larger
> > > > will be truncated.  
> > > 
> > > There is an effort to avoid using trace_printk and the like
> > > so perhaps this feature should have the same compile time
> > > guard.
> > 
> > No, this is fine for being in a production kernel. Basically, these are
> > simply debug printk()s that can also be put into the trace buffer. The
> > key difference to trace_printk() is that they are an event that needs
> > to be enabled to write into the buffer.
> 
> It just seems like a backdoor way to convert various pr_debug functions
> (dev_dbg/netdev_dbg, et al) into tracing.
> 
> What's the real value?  Timing data?  Something else?

I mentioned my use case for this in the commit message and why it works
much better than printk() for that, please let me know if it is unclear:

 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.

This is my only use case for this, and I've used it very very often
during the years I've been carrying this patch locally.

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

[Guilherme G. Piccoli]

[First of all, apologies for necro'ing this thread - for those that
somehow deleted the full thread of their clients, here is the link:
https://lore.kernel.org/lkml/20200825153338.17061-1-vincent.whitchurch@axis.com/]

So, I would like to reopen this discussion. Is there any reason this
feature wasn't merged Joe? Can we improve something in order to get it
into mainline?

I'm saying that 'cause I almost implemented this myself here, I have the
same use case as Vicent's - but thankfully, I searched before and he
already implemented that. As per my understanding, there was no
objection from Steven, right?

Thanks in advance! And happy holidays =)
Cheers,


Guilherme

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

[Vincent Whitchurch]

On Tue, 2023-12-26 at 13:57 -0300, Guilherme G. Piccoli wrote:
> [First of all, apologies for necro'ing this thread - for those that
> somehow deleted the full thread of their clients, here is the link:
> https://lore.kernel.org/lkml/20200825153338.17061-1-vincent.whitchurch@axis.com/]
> 
> So, I would like to reopen this discussion. Is there any reason this
> feature wasn't merged Joe? Can we improve something in order to get it
> into mainline?
> 
> I'm saying that 'cause I almost implemented this myself here, I have the
> same use case as Vicent's - but thankfully, I searched before and he
> already implemented that. As per my understanding, there was no
> objection from Steven, right?

Jim and Łukasz (CC'd) are actively working on getting this feature
merged:

 https://lore.kernel.org/lkml/20231223015131.2836090-1-lb@semihalf.com/

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

[Guilherme G. Piccoli]

On 27/12/2023 05:29, Vincent Whitchurch wrote:
> On Tue, 2023-12-26 at 13:57 -0300, Guilherme G. Piccoli wrote:
>> [First of all, apologies for necro'ing this thread - for those that
>> somehow deleted the full thread of their clients, here is the link:
>> https://lore.kernel.org/lkml/20200825153338.17061-1-vincent.whitchurch@axis.com/]
>>
>> So, I would like to reopen this discussion. Is there any reason this
>> feature wasn't merged Joe? Can we improve something in order to get it
>> into mainline?
>>
>> I'm saying that 'cause I almost implemented this myself here, I have the
>> same use case as Vicent's - but thankfully, I searched before and he
>> already implemented that. As per my understanding, there was no
>> objection from Steven, right?
> 
> Jim and Łukasz (CC'd) are actively working on getting this feature
> merged:
> 
>  https://lore.kernel.org/lkml/20231223015131.2836090-1-lb@semihalf.com/

This is great, thank you!