* [PATCH v3 0/2] Dynamic debug trace support @ 2020-08-25 15:33 Vincent Whitchurch 2020-08-25 15:33 ` [PATCH v3 1/2] dynamic debug: split enable and printk flags Vincent Whitchurch 2020-08-25 15:33 ` [PATCH v3 2/2] dynamic debug: allow printing to trace event Vincent Whitchurch 0 siblings, 2 replies; 10+ messages in thread From: Vincent Whitchurch @ 2020-08-25 15:33 UTC (permalink / raw) To: jbaron, rostedt, mingo Cc: kernel, corbet, pmladek, sergey.senozhatsky, john.ogness, linux-kernel, 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 ^ permalink raw reply [flat|nested] 10+ messages in thread
* [PATCH v3 1/2] dynamic debug: split enable and printk flags 2020-08-25 15:33 [PATCH v3 0/2] Dynamic debug trace support Vincent Whitchurch @ 2020-08-25 15:33 ` Vincent Whitchurch 2020-08-25 15:33 ` [PATCH v3 2/2] dynamic debug: allow printing to trace event Vincent Whitchurch 1 sibling, 0 replies; 10+ messages in thread From: Vincent Whitchurch @ 2020-08-25 15:33 UTC (permalink / raw) To: jbaron, rostedt, mingo Cc: kernel, corbet, pmladek, sergey.senozhatsky, john.ogness, linux-kernel, 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 ^ permalink raw reply related [flat|nested] 10+ messages in thread
* [PATCH v3 2/2] dynamic debug: allow printing to trace event 2020-08-25 15:33 [PATCH v3 0/2] Dynamic debug trace support Vincent Whitchurch 2020-08-25 15:33 ` [PATCH v3 1/2] dynamic debug: split enable and printk flags Vincent Whitchurch @ 2020-08-25 15:33 ` Vincent Whitchurch 2020-08-25 15:53 ` Joe Perches 1 sibling, 1 reply; 10+ messages in thread From: Vincent Whitchurch @ 2020-08-25 15:33 UTC (permalink / raw) To: jbaron, rostedt, mingo Cc: kernel, corbet, pmladek, sergey.senozhatsky, john.ogness, linux-kernel, 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 ^ permalink raw reply related [flat|nested] 10+ messages in thread
* Re: [PATCH v3 2/2] dynamic debug: allow printing to trace event 2020-08-25 15:33 ` [PATCH v3 2/2] dynamic debug: allow printing to trace event Vincent Whitchurch @ 2020-08-25 15:53 ` Joe Perches 2020-08-26 19:32 ` Steven Rostedt 0 siblings, 1 reply; 10+ messages in thread From: Joe Perches @ 2020-08-25 15:53 UTC (permalink / raw) To: Vincent Whitchurch, jbaron, rostedt, mingo, Nicolas Boichat Cc: kernel, corbet, pmladek, sergey.senozhatsky, john.ogness, linux-kernel 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); ^ permalink raw reply [flat|nested] 10+ messages in thread
* Re: [PATCH v3 2/2] dynamic debug: allow printing to trace event 2020-08-25 15:53 ` Joe Perches @ 2020-08-26 19:32 ` Steven Rostedt 2020-08-26 19:53 ` Joe Perches 0 siblings, 1 reply; 10+ messages in thread From: Steven Rostedt @ 2020-08-26 19:32 UTC (permalink / raw) To: Joe Perches Cc: Vincent Whitchurch, jbaron, mingo, Nicolas Boichat, kernel, corbet, pmladek, sergey.senozhatsky, john.ogness, linux-kernel 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 ^ permalink raw reply [flat|nested] 10+ messages in thread
* Re: [PATCH v3 2/2] dynamic debug: allow printing to trace event 2020-08-26 19:32 ` Steven Rostedt @ 2020-08-26 19:53 ` Joe Perches 2020-09-02 12:17 ` Vincent Whitchurch 2023-12-26 16:57 ` Guilherme G. Piccoli 0 siblings, 2 replies; 10+ messages in thread From: Joe Perches @ 2020-08-26 19:53 UTC (permalink / raw) To: Steven Rostedt Cc: Vincent Whitchurch, jbaron, mingo, Nicolas Boichat, kernel, corbet, pmladek, sergey.senozhatsky, john.ogness, linux-kernel 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? ^ permalink raw reply [flat|nested] 10+ messages in thread
* Re: [PATCH v3 2/2] dynamic debug: allow printing to trace event 2020-08-26 19:53 ` Joe Perches @ 2020-09-02 12:17 ` Vincent Whitchurch 2023-12-26 16:57 ` Guilherme G. Piccoli 1 sibling, 0 replies; 10+ messages in thread From: Vincent Whitchurch @ 2020-09-02 12:17 UTC (permalink / raw) To: Joe Perches Cc: Steven Rostedt, jbaron, mingo, Nicolas Boichat, kernel, corbet, pmladek, sergey.senozhatsky, john.ogness, linux-kernel 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. ^ permalink raw reply [flat|nested] 10+ messages in thread
* Re: Re: [PATCH v3 2/2] dynamic debug: allow printing to trace event 2020-08-26 19:53 ` Joe Perches 2020-09-02 12:17 ` Vincent Whitchurch @ 2023-12-26 16:57 ` Guilherme G. Piccoli 2023-12-27 8:29 ` Vincent Whitchurch 1 sibling, 1 reply; 10+ messages in thread From: Guilherme G. Piccoli @ 2023-12-26 16:57 UTC (permalink / raw) To: Steven Rostedt, joe, vincent.whitchurch Cc: jbaron, Ingo Molnar, drinkcat, kernel, corbet, Petr Mladek, sergey.senozhatsky, john.ogness, linux-kernel, gpiccoli [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 ^ permalink raw reply [flat|nested] 10+ messages in thread
* Re: Re: [PATCH v3 2/2] dynamic debug: allow printing to trace event 2023-12-26 16:57 ` Guilherme G. Piccoli @ 2023-12-27 8:29 ` Vincent Whitchurch 2023-12-27 13:06 ` Guilherme G. Piccoli 0 siblings, 1 reply; 10+ messages in thread From: Vincent Whitchurch @ 2023-12-27 8:29 UTC (permalink / raw) To: joe, rostedt, Vincent Whitchurch, gpiccoli Cc: corbet, sergey.senozhatsky, jbaron, jim.cromie, john.ogness, kernel, mingo, linux-kernel, pmladek, drinkcat, lb 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/ ^ permalink raw reply [flat|nested] 10+ messages in thread
* Re: [PATCH v3 2/2] dynamic debug: allow printing to trace event 2023-12-27 8:29 ` Vincent Whitchurch @ 2023-12-27 13:06 ` Guilherme G. Piccoli 0 siblings, 0 replies; 10+ messages in thread From: Guilherme G. Piccoli @ 2023-12-27 13:06 UTC (permalink / raw) To: Vincent Whitchurch Cc: corbet, rostedt, joe, sergey.senozhatsky, jbaron, jim.cromie, john.ogness, kernel, mingo, linux-kernel, pmladek, drinkcat, lb 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! ^ permalink raw reply [flat|nested] 10+ messages in thread
end of thread, other threads:[~2023-12-27 13:07 UTC | newest] Thread overview: 10+ messages (download: mbox.gz / follow: Atom feed) -- links below jump to the message on this page -- 2020-08-25 15:33 [PATCH v3 0/2] Dynamic debug trace support Vincent Whitchurch 2020-08-25 15:33 ` [PATCH v3 1/2] dynamic debug: split enable and printk flags Vincent Whitchurch 2020-08-25 15:33 ` [PATCH v3 2/2] dynamic debug: allow printing to trace event Vincent Whitchurch 2020-08-25 15:53 ` Joe Perches 2020-08-26 19:32 ` Steven Rostedt 2020-08-26 19:53 ` Joe Perches 2020-09-02 12:17 ` Vincent Whitchurch 2023-12-26 16:57 ` Guilherme G. Piccoli 2023-12-27 8:29 ` Vincent Whitchurch 2023-12-27 13:06 ` Guilherme G. Piccoli
This is a public inbox, see mirroring instructions for how to clone and mirror all data and code used for this inbox; as well as URLs for NNTP newsgroup(s).