On Wed, Dec 08, 2021 at 06:16:10AM +0100, jim.cromie@xxxxxxxxx wrote:
> are you planning to dust this patchset off and resubmit it ?
>
> Ive been playing with it and learning ftrace (decade+ late),
> I found your boot-line example very helpful as 1st steps
> (still havent even tried the filtering)
>
>
> with these adjustments (voiced partly to test my understanding)
> I would support it, and rework my patchset to use it.
>
> - change flag to -e, good mnemonics for event/trace-event
> T is good too, but uppercase, no need to go there.
Any flag name works for me.
> - include/trace/events/dyndbg.h - separate file, not mixed with print.h
> dyndbg class, so trace_event=dyndbg:*
>
> - 1 event type per pr_debug, dev_dbg, netdev_dbg ? ibdev_dbg ?
> with the extra args: descriptor that Steven wanted,
> probably also struct <|net|ib>dev
For my use cases I don't see much value in having separate events for
the different debug functions, but since all of them can be easily
enabled (dyndbg:*, as you noted), that works for me too.
> If youre too busy for a while, I'd eventually take a (slow) run at it.
You're welcome to have a go. I think you've already rebased the
patchset, but here's a diff top of v5.16-rc4 for reference. I noticed a
bug inside the CONFIG_JUMP_LABEL handling (also present in the last
version I posted) which should be fixed as part of the diff below (I've
added a comment). Proper tests for this, like the ones you are adding
in your patchset, would certainly be a good idea. Thanks.
8<-------------
diff --git a/Documentation/admin-guide/dynamic-debug-howto.rst b/Documentation/admin-guide/dynamic-debug-howto.rst
index a89cfa083155..b9c4e808befc 100644
--- a/Documentation/admin-guide/dynamic-debug-howto.rst
+++ b/Documentation/admin-guide/dynamic-debug-howto.rst
@@ -228,6 +228,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 dce631e678dd..bc21bfb0fdc6 100644
--- a/include/linux/dynamic_debug.h
+++ b/include/linux/dynamic_debug.h
@@ -27,7 +27,7 @@ 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)
@@ -37,8 +37,11 @@ struct _ddebug {
(_DPRINTK_FLAGS_INCL_MODNAME | _DPRINTK_FLAGS_INCL_FUNCNAME |\
_DPRINTK_FLAGS_INCL_LINENO | _DPRINTK_FLAGS_INCL_TID)
+#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_PRINT
+#define _DPRINTK_FLAGS_DEFAULT _DPRINTK_FLAGS_PRINTK
#else
#define _DPRINTK_FLAGS_DEFAULT 0
#endif
@@ -120,10 +123,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 /* CONFIG_JUMP_LABEL */
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 dd7f56af9aed..161454fa0af8 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>
@@ -86,11 +87,12 @@ static inline const char *trim_prefix(const char *path)
}
static struct { unsigned flag:8; char opt_char; } opt_array[] = {
- { _DPRINTK_FLAGS_PRINT, 'p' },
+ { _DPRINTK_FLAGS_PRINTK, 'p' },
{ _DPRINTK_FLAGS_INCL_MODNAME, 'm' },
{ _DPRINTK_FLAGS_INCL_FUNCNAME, 'f' },
{ _DPRINTK_FLAGS_INCL_LINENO, 'l' },
{ _DPRINTK_FLAGS_INCL_TID, 't' },
+ { _DPRINTK_FLAGS_TRACE, 'x' },
{ _DPRINTK_FLAGS_NONE, '_' },
};
@@ -210,11 +212,23 @@ 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) {
+ /*
+ * The newflags check is to ensure that the
+ * static branch doesn't get disabled in step
+ * 3:
+ *
+ * (1) +pf
+ * (2) +x
+ * (3) -pf
+ */
+ if (!(modifiers->flags & _DPRINTK_FLAGS_ENABLE) &&
+ !(newflags & _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;
v4pr_info("changed %s:%d [%s]%s =%s\n",
@@ -621,6 +635,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);
+ }
+}
+
static inline char *dynamic_emit_prefix(struct _ddebug *desc, char *buf)
{
if (unlikely(desc->flags & _DPRINTK_FLAGS_INCL_ANY))
@@ -642,7 +746,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);
}
@@ -652,6 +757,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);
@@ -661,16 +767,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);
@@ -683,6 +791,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);
@@ -692,22 +801,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);
@@ -722,27 +833,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);
