Re: [PATCH v1 04/12] dyndbg: add 2 trace-events: pr_debug, dev_dbg

From: jim . cromie
Date: Fri Nov 03 2023 - 23:27:27 EST

Next message: kernel test robot: "arch/powerpc/platforms/pseries/rtas-work-area.c:189: warning: Function parameter or member 'limit' not described in 'rtas_work_area_reserve_arena'"
Previous message: syzbot: "Re: [syzbot] test uaf in hci_conn_drop"
In reply to: Łukasz Bartosik: "[PATCH v1 04/12] dyndbg: add 2 trace-events: pr_debug, dev_dbg"
Next in thread: Steven Rostedt: "Re: [PATCH v1 04/12] dyndbg: add 2 trace-events: pr_debug, dev_dbg"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]

On Fri, Nov 3, 2023 at 7:10 AM Łukasz Bartosik <lb@xxxxxxxxxxxx> wrote:
>
> From: Jim Cromie <jim.cromie@xxxxxxxxx>
>
> ddebug_trace() currently issues a single printk:console event.
> Replace that event by adding include/trace/events/dyndbg.h,
> which defines 2 new trace-events: dyndbg:prdbg & dyndbg:devdbg.
>
> These events get the _ddebug descriptor, so they can access the whole
> callsite record: file, line, function, flags. This allows the
> addition of a dynamic prefix later.
>
> So ddebug_trace() gets 2 new args: the descriptor and the device.
> And its callers: ddebug_printk(), ddebug_dev_printk() upgrade their
> flags param to pass the descriptor itself, and thus also the flags.
>
> Signed-off-by: Jim Cromie <jim.cromie@xxxxxxxxx>

let me add:

I have doubts about adding the descriptor to the trace record.
For loadable modules in particular, those descriptors will go away at rmmod.

I added it thinking it would support filtering by callsite info.
Its not entirely clear whether it adds any utility, now or potentially.

During dev/hacking, I saw UNSAFE_<mumble> while TP_printk-ing the records,
while banging on it with various hammers (modprobe cycling probably)

maybe on rmmod, they could be "cached" (or pointers poisoned)
allowing their use until then (and maybe afterwards)

> ---
> MAINTAINERS | 1 +
> include/trace/events/dyndbg.h | 74 +++++++++++++++++++++++++++++++++++
> lib/dynamic_debug.c | 73 +++++++++++++++++-----------------
> 3 files changed, 112 insertions(+), 36 deletions(-)
> create mode 100644 include/trace/events/dyndbg.h
>
> diff --git a/MAINTAINERS b/MAINTAINERS
> index dd5de540ec0b..fd02dc86f1fd 100644
> --- a/MAINTAINERS
> +++ b/MAINTAINERS
> @@ -7320,6 +7320,7 @@ M: Jason Baron <jbaron@xxxxxxxxxx>
> M: Jim Cromie <jim.cromie@xxxxxxxxx>
> S: Maintained
> F: include/linux/dynamic_debug.h
> +F: include/trace/events/dyndbg.h
> F: lib/dynamic_debug.c
> F: lib/test_dynamic_debug.c
>
> diff --git a/include/trace/events/dyndbg.h b/include/trace/events/dyndbg.h
> new file mode 100644
> index 000000000000..ccc5bcb070f9
> --- /dev/null
> +++ b/include/trace/events/dyndbg.h
> @@ -0,0 +1,74 @@
> +/* SPDX-License-Identifier: GPL-2.0 */
> +#undef TRACE_SYSTEM
> +#define TRACE_SYSTEM dyndbg
> +
> +#if !defined(_TRACE_DYNDBG_H) || defined(TRACE_HEADER_MULTI_READ)
> +#define _TRACE_DYNDBG_H
> +
> +#include <linux/tracepoint.h>
> +
> +/* capture pr_debug() callsite descriptor and message */
> +TRACE_EVENT(prdbg,
> + TP_PROTO(const struct _ddebug *desc, const char *text, size_t len),
> +
> + TP_ARGS(desc, text, len),
> +
> + TP_STRUCT__entry(
> + __field(const struct _ddebug *, desc)
> + __dynamic_array(char, msg, len + 1)
> + ),
> +
> + TP_fast_assign(
> + __entry->desc = desc;
> + /*
> + * Each trace entry is printed in a new line.
> + * If the msg finishes with '\n', cut it off
> + * to avoid blank lines in the trace.
> + */
> + if (len > 0 && (text[len - 1] == '\n'))
> + len -= 1;
> +
> + memcpy(__get_str(msg), text, len);
> + __get_str(msg)[len] = 0;
> + ),
> +
> + TP_printk("%s.%s %s", __entry->desc->modname,
> + __entry->desc->function, __get_str(msg))
> +);
> +
> +/* capture dev_dbg() callsite descriptor, device, and message */
> +TRACE_EVENT(devdbg,
> + TP_PROTO(const struct _ddebug *desc, const struct device *dev,
> + const char *text, size_t len),
> +
> + TP_ARGS(desc, dev, text, len),
> +
> + TP_STRUCT__entry(
> + __field(const struct _ddebug *, desc)
> + __field(const struct device *, dev)
> + __dynamic_array(char, msg, len + 1)
> + ),
> +
> + TP_fast_assign(
> + __entry->desc = desc;
> + __entry->dev = (struct device *) dev;
> + /*
> + * Each trace entry is printed in a new line.
> + * If the msg finishes with '\n', cut it off
> + * to avoid blank lines in the trace.
> + */
> + if (len > 0 && (text[len - 1] == '\n'))
> + len -= 1;
> +
> + memcpy(__get_str(msg), text, len);
> + __get_str(msg)[len] = 0;
> + ),
> +
> + TP_printk("%s.%s %s", __entry->desc->modname,
> + __entry->desc->function, __get_str(msg))
> +);
> +
> +#endif /* _TRACE_DYNDBG_H */
> +
> +/* This part must be outside protection */
> +#include <trace/define_trace.h>
> diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
> index 016f33c20251..1ed3c4f16f69 100644
> --- a/lib/dynamic_debug.c
> +++ b/lib/dynamic_debug.c
> @@ -36,7 +36,9 @@
> #include <linux/sched.h>
> #include <linux/device.h>
> #include <linux/netdevice.h>
> -#include <trace/events/printk.h>
> +
> +#define CREATE_TRACE_POINTS
> +#include <trace/events/dyndbg.h>
>
> #include <rdma/ib_verbs.h>
>
> @@ -878,7 +880,9 @@ struct ddebug_trace_bufs {
> static DEFINE_PER_CPU(struct ddebug_trace_bufs, ddebug_trace_bufs);
> static DEFINE_PER_CPU(int, ddebug_trace_reserve);
>
> -static void ddebug_trace(const char *fmt, va_list args)
> +__printf(3, 0)
> +static void ddebug_trace(struct _ddebug *desc, const struct device *dev,
> + const char *fmt, va_list args)
> {
> struct ddebug_trace_buf *buf;
> int bufidx;
> @@ -897,7 +901,11 @@ static void ddebug_trace(const char *fmt, va_list args)
> buf = this_cpu_ptr(ddebug_trace_bufs.bufs) + bufidx;
>
> len = vscnprintf(buf->buf, sizeof(buf->buf), fmt, args);
> - trace_console(buf->buf, len);
> +
> + if (!dev)
> + trace_prdbg(desc, buf->buf, len);
> + else
> + trace_devdbg(desc, dev, buf->buf, len);
>
> out:
> /* As above. */
> @@ -907,9 +915,9 @@ static void ddebug_trace(const char *fmt, va_list args)
> }
>
> __printf(2, 3)
> -static void ddebug_printk(unsigned int flags, const char *fmt, ...)
> +static void ddebug_printk(struct _ddebug *desc, const char *fmt, ...)
> {
> - if (flags & _DPRINTK_FLAGS_TRACE) {
> + if (desc->flags & _DPRINTK_FLAGS_TRACE) {
> va_list args;
>
> va_start(args, fmt);
> @@ -917,11 +925,11 @@ static void ddebug_printk(unsigned int flags, const char *fmt, ...)
> * All callers include the KERN_DEBUG prefix to keep the
> * vprintk case simple; strip it out for tracing.
> */
> - ddebug_trace(fmt + strlen(KERN_DEBUG), args);
> + ddebug_trace(desc, NULL, fmt + strlen(KERN_DEBUG), args);
> va_end(args);
> }
>
> - if (flags & _DPRINTK_FLAGS_PRINTK) {
> + if (desc->flags & _DPRINTK_FLAGS_PRINTK) {
> va_list args;
>
> va_start(args, fmt);
> @@ -931,19 +939,19 @@ static void ddebug_printk(unsigned int flags, const char *fmt, ...)
> }
>
> __printf(3, 4)
> -static void ddebug_dev_printk(unsigned int flags, const struct device *dev,
> +static void ddebug_dev_printk(struct _ddebug *desc, const struct device *dev,
> const char *fmt, ...)
> {
>
> - if (flags & _DPRINTK_FLAGS_TRACE) {
> + if (desc->flags & _DPRINTK_FLAGS_TRACE) {
> va_list args;
>
> va_start(args, fmt);
> - ddebug_trace(fmt, args);
> + ddebug_trace(desc, dev, fmt, args);
> va_end(args);
> }
>
> - if (flags & _DPRINTK_FLAGS_PRINTK) {
> + if (desc->flags & _DPRINTK_FLAGS_PRINTK) {
> va_list args;
>
> va_start(args, fmt);
> @@ -966,7 +974,7 @@ void __dynamic_pr_debug(struct _ddebug *descriptor, const char *fmt, ...)
> vaf.fmt = fmt;
> vaf.va = &args;
>
> - ddebug_printk(descriptor->flags, KERN_DEBUG "%s%pV",
> + ddebug_printk(descriptor, KERN_DEBUG "%s%pV",
> dynamic_emit_prefix(descriptor, buf), &vaf);
>
> va_end(args);
> @@ -977,7 +985,6 @@ 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);
> @@ -987,15 +994,14 @@ void __dynamic_dev_dbg(struct _ddebug *descriptor,
>
> vaf.fmt = fmt;
> vaf.va = &args;
> - flags = descriptor->flags;
>
> if (!dev) {
> - ddebug_printk(flags, KERN_DEBUG "(NULL device *): %pV",
> - &vaf);
> + ddebug_printk(descriptor, KERN_DEBUG "(NULL device *): %pV",
> + &vaf);
> } else {
> char buf[PREFIX_SIZE] = "";
>
> - ddebug_dev_printk(flags, dev, "%s%s %s: %pV",
> + ddebug_dev_printk(descriptor, dev, "%s%s %s: %pV",
> dynamic_emit_prefix(descriptor, buf),
> dev_driver_string(dev), dev_name(dev),
> &vaf);
> @@ -1011,7 +1017,6 @@ 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);
> @@ -1021,24 +1026,22 @@ 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] = "";
>
> - ddebug_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);
> + ddebug_dev_printk(descriptor, 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) {
> - ddebug_printk(flags, KERN_DEBUG "%s%s: %pV",
> - netdev_name(dev), netdev_reg_state(dev), &vaf);
> + ddebug_dev_printk(descriptor, &dev->dev, KERN_DEBUG "%s%s: %pV",
> + netdev_name(dev), netdev_reg_state(dev), &vaf);
> } else {
> - ddebug_printk(flags, KERN_DEBUG "(NULL net_device): %pV",
> - &vaf);
> + ddebug_printk(descriptor, KERN_DEBUG "(NULL net_device): %pV", &vaf);
> }
>
> va_end(args);
> @@ -1054,18 +1057,16 @@ void __dynamic_ibdev_dbg(struct _ddebug *descriptor,
> {
> struct va_format vaf;
> va_list args;
> - unsigned int flags;
>
> va_start(args, fmt);
>
> vaf.fmt = fmt;
> vaf.va = &args;
> - flags = descriptor->flags;
>
> if (ibdev && ibdev->dev.parent) {
> char buf[PREFIX_SIZE] = "";
>
> - ddebug_dev_printk(flags, ibdev->dev.parent,
> + ddebug_dev_printk(descriptor, ibdev->dev.parent,
> "%s%s %s %s: %pV",
> dynamic_emit_prefix(descriptor, buf),
> dev_driver_string(ibdev->dev.parent),
> @@ -1073,10 +1074,10 @@ void __dynamic_ibdev_dbg(struct _ddebug *descriptor,
> dev_name(&ibdev->dev),
> &vaf);
> } else if (ibdev) {
> - ddebug_printk(flags, KERN_DEBUG "%s: %pV",
> - dev_name(&ibdev->dev), &vaf);
> + ddebug_dev_printk(descriptor, &ibdev->dev, KERN_DEBUG "%s: %pV",
> + dev_name(&ibdev->dev), &vaf);
> } else {
> - ddebug_printk(flags, KERN_DEBUG "(NULL ip_device): %pV", &vaf);
> + ddebug_printk(descriptor, KERN_DEBUG "(NULL ip_device): %pV", &vaf);
> }
>
> va_end(args);
> --
> 2.42.0.869.gea05f2083d-goog
>

Next message: kernel test robot: "arch/powerpc/platforms/pseries/rtas-work-area.c:189: warning: Function parameter or member 'limit' not described in 'rtas_work_area_reserve_arena'"
Previous message: syzbot: "Re: [syzbot] test uaf in hci_conn_drop"
In reply to: Łukasz Bartosik: "[PATCH v1 04/12] dyndbg: add 2 trace-events: pr_debug, dev_dbg"
Next in thread: Steven Rostedt: "Re: [PATCH v1 04/12] dyndbg: add 2 trace-events: pr_debug, dev_dbg"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]