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 <[email protected]>
---
.../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
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 <[email protected]>
> ---
> .../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);
On Tue, 25 Aug 2020 08:53:25 -0700
Joe Perches <[email protected]> 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
On Wed, 2020-08-26 at 15:32 -0400, Steven Rostedt wrote:
> On Tue, 25 Aug 2020 08:53:25 -0700
> Joe Perches <[email protected]> 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?
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 <[email protected]> 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.
[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/[email protected]/]
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
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/[email protected]/]
>
> 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/[email protected]/
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/[email protected]/]
>>
>> 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/[email protected]/
This is great, thank you!