Add support for writing debug logs to trace events and trace instances.
The rationale behing this feature is to be able to redirect debug logs
(per each callsite individually) to trace to aid in debugging. The debug
logs output to trace can be enabled with T flag. Additionally the T flag
accepts trace destination which can be provided to the T flag after ":".
The trace destination field is used to determine where debug logs will be
written.
In order to redirect callsite debug log to a trace instance it has to be
initialized first with a newly introduced "open" command. For example,
"usb" trace instance in <debugfs>/tracing/instances/ can be initialized
by issuing the command:
localhost ~ # echo "open usb" >
<debugfs>/dynamic_debug/control
If the trace instance <debugfs>/tracing/instances/usb already exists
then it will be reused otherwise new usbcore instance will be created.
Maximum 63 trace instances can be "opened". The trace instance name can
include any of ^\w+ and underscore characters. There is also a special
name "0" reserved for writing debug logs to trace prdbg and devdbg events.
The reserved name "0" does not require to be "opened" before use.
To enable writing usbcore module debug logs to the "usb" trace instance
opened above a user can issue the command:
localhost ~ # echo "module usbcore =pT:usb" >
<debugfs>/dynamic_debug/control
Please note that output of debug logs to syslog (p flag) and trace (T flag)
can be independently enabled/disabled for each callsite. Therefore the
above command will enable writing of debug logs not only to the trace
instance "usb" but also to syslog.
When trace destination is followed by another flag the next flag has to
be preeceded with ".", for example
localhost ~ # echo "module usbcore =pT:usb.l" >
<debugfs>/dynamic_debug/control
To simplify processing trace destination can be omitted when default
trace destination is set, for example the command
localhost ~ # echo "module usbcore =pTl" >
<debugfs>/dynamic_debug/control
will use default trace destination. If default trace destination is not
set the above command will fail. The default trace destination is set
when a command with any of the flags [-+=] and explicitly provided trace
destination matches at least one callsite, for example the command
localhost ~ # echo "module usbcore -T:usb" >
<debugfs>/dynamic_debug/control
will disable trace for all usbcore module callsites (if any was enabled)
and will set "usb" instance as default trace destination. To enable writing
thunderbolt module debug logs to the "usb" trace instance as well a user
can issue the command:
localhost ~ # echo "module thunderbolt =T" >
<debugfs>/dynamic_debug/control
Since default trace destination was previously set therefore "usb" instance
name does not have to be explicitly provided.
When no callsite writes debug logs to a trace instance then it can be
released (its reference counter decrased) with the "close" command.
Closing a trace instance make it unavailable for dynamic debug and also
allows a user to delete such a trace instance at convenient time later
with rmdir command. For example when "usb" instance is not used anymore
a user can issue the command:
localhost ~ # echo "close usb" >
<debugfs>/dynamic_debug/control
and then to delete it with:
localhost ~ # rmdir <debugfs>/tracing/instances/
To enable writing usbcore module debug logs to trace dyndbg:prdbg and
dyndbg:devdbg events user can issue the command:
localhost ~ # echo "module usbcore =T:0" >
<debugfs>/dynamic_debug/control
Then dyndbg trace events can be for example captured with the command:
localhost ~ # trace-cmd start -e dyndbg
And displayed with the command:
localhost ~ # trace-cmd show
Jim, I made a few changes to the test script dd-selftest.rc you created
and I also added new test scenarios. You can find the entire patchset
with the test script changes on top here
https://chromium.googlesource.com/chromiumos/third_party/kernel/+log/refs/sandbox/ukaszb/dyndbg_trace_v3
I wonder where would be the proper place to store the test script
(upstream, your github.com:jimc/linux.git)
Do you have a suggestion for that ?
TODOs:
- update dynamic debug documentation,
- finalize discussion related to default trace destination
(whether we want it at all, if yes then conclude on the details)
Changes:
V3 -> V2
- squash "dyndbg: export _print_hex_dump" with "dyndbg: add support for hex_dump output to trace",
- squash "dyndbg: tweak pr_info format s/trace dest/trace_dest/" with "dyndbg: add processing of T(race) flag argument",
- squash "dyndbg: change +T:name_terminator to dot" with "dyndbg: add processing of T(race) flag argument",
- fix setting default trace destination,
- decrease use count when callsite is being disabled as a part of module removal,
- fix parsing of T flag argument,
- update __get_str_strip_nl macro per Steve's comment,
- drop commit "dyndbg: move lock,unlock into ddebug_change, drop goto" and add comment explaining why ddebug_parse_flags
and ddebug_change have to be run in critical section,
- add "depends on TRACING" for "DYNAMIC_DEBUG",
- update DYNAMIC_DEBUG_BRANCH macro which is used when CONFIG_JUMP_LABEL is not set,
- change structure name ddebug_trace_inst to dd_private_tracebuf,
- change structure name ddebug_trace to dd_tracebuf_tbl_info,
- rename is_ddebug_cmd to is_dd_trace_cmd,
- rename validate_tr_name to dd_good_trace_name,
- rename handle_tr_opend_cmd to handle_trace_opend_cmd and handle_tr_close_cmd to handle_trace_close_cmd,
- refactor ddebug_parse_cmd,
- add pr_err when trace_array_get_by_name or trace_array_init_printk fails in trace_array_init_printk,
- add static prefix to show_T_args,
- rename TRACE_DST_MAX to TRACE_DST_LAST and change its value to 64, reserve index 0 for trace events in dd_tracebuf_tbl_info (index 0 will be wasted),
- add "#: " prefix to "Default trace destination" and "Opened trace instances" and print all opened trace instances on the same line,
V2->V1
Major rework after receiving feedback in
https://lore.kernel.org/all/[email protected]/
This includes among other things:
- addittion of open/close commands,
- use names instead of numbers for trace destinations,
- change prdbg and devdbg trace events to strip newline
on the slow path (read side),
- change prdbg and devdbg trace events to stores actual values
instead of pointers because if a pointer becomes invalid then
the TP_printk call will cause a crash,
- add support for default trace destination.
V1
Major rework after receiving feedback in
https://lore.kernel.org/all/[email protected]/
Jim Cromie (14):
dyndbg: add _DPRINTK_FLAGS_ENABLED
dyndbg: add _DPRINTK_FLAGS_TRACE
dyndbg: add write events to tracefs code
dyndbg: add 2 trace-events: prdbg, devdbg
tracefs: add __get_str_strip_nl - RFC
dyndbg: use __get_str_strip_nl in prdbg and devdbg
dyndbg: repack _ddebug structure
dyndbg: disambiguate quoting in a debug msg
dyndbg: fix old BUG_ON in >control parser
dyndbg: treat comma as a token separator
dyndbg: add skip_spaces_and_coma()
dyndbg: split multi-query strings with %
dyndbg: reduce verbose/debug clutter
dyndbg: id the bad word in parse-flags err msg
Łukasz Bartosik (8):
dyndbg: move flags field to a new structure
dyndbg: add trace destination field to _ddebug
dyndbg: add open and close commands for trace
dyndbg: don't close trace instance when in use
dyndbg: add processing of T(race) flag argument
dyndbg: add support for default trace destination
dyndbg: write debug logs to trace instance
dyndbg: add support for hex_dump output to trace
.../admin-guide/dynamic-debug-howto.rst | 5 +-
MAINTAINERS | 1 +
include/linux/dynamic_debug.h | 57 +-
include/trace/events/dyndbg.h | 54 ++
include/trace/stages/stage3_trace_output.h | 13 +
lib/Kconfig.debug | 2 +
lib/dynamic_debug.c | 736 ++++++++++++++++--
7 files changed, 775 insertions(+), 93 deletions(-)
create mode 100644 include/trace/events/dyndbg.h
--
2.43.0.472.g3155946c3a-goog
From: Jim Cromie <[email protected]>
Add new flag, and OR it into _DPRINTK_FLAGS_ENABLED definition
CC: [email protected]
Signed-off-by: Jim Cromie <[email protected]>
---
include/linux/dynamic_debug.h | 5 +++--
1 file changed, 3 insertions(+), 2 deletions(-)
diff --git a/include/linux/dynamic_debug.h b/include/linux/dynamic_debug.h
index 7be791af7cf1..497130816e9c 100644
--- a/include/linux/dynamic_debug.h
+++ b/include/linux/dynamic_debug.h
@@ -33,6 +33,9 @@ struct _ddebug {
*/
#define _DPRINTK_FLAGS_NONE 0
#define _DPRINTK_FLAGS_PRINTK (1 << 0) /* printk() a message using the format */
+#define _DPRINTK_FLAGS_TRACE (1 << 6)
+#define _DPRINTK_FLAGS_ENABLED (_DPRINTK_FLAGS_PRINTK | _DPRINTK_FLAGS_TRACE)
+
#define _DPRINTK_FLAGS_INCL_MODNAME (1<<1)
#define _DPRINTK_FLAGS_INCL_FUNCNAME (1<<2)
#define _DPRINTK_FLAGS_INCL_LINENO (1<<3)
@@ -44,8 +47,6 @@ struct _ddebug {
_DPRINTK_FLAGS_INCL_LINENO | _DPRINTK_FLAGS_INCL_TID |\
_DPRINTK_FLAGS_INCL_SOURCENAME)
-#define _DPRINTK_FLAGS_ENABLED _DPRINTK_FLAGS_PRINTK
-
#if defined DEBUG
#define _DPRINTK_FLAGS_DEFAULT _DPRINTK_FLAGS_PRINTK
#else
--
2.43.0.472.g3155946c3a-goog
From: Jim Cromie <[email protected]>
adds: ddebug_trace()
uses trace_console() temporarily to issue printk:console event
uses internal-ish __ftrace_trace_stack code:
4-context buffer stack, barriers per Steve Rostedt
call it from new funcs:
ddebug_printk() - print to both syslog/tracefs
ddebug_dev_printk() - dev-print to both syslog/tracefs
These handle both _DPRINTK_FLAGS_PRINTK and _DPRINTK_FLAGS_TRACE
cases, allowing to vsnprintf the message once and use it for both,
skipping past the KERN_DEBUG character for tracing.
Finally, adjust the callers: __ddebug_{pr_debug,{,net,ib}dev_dbg},
replacing printk and dev_printk with the new funcs above.
The _DPRINTK_FLAGS_TRACE flag character is 'T', so the following finds
all callsites enabled for tracing:
grep -P =p?T /proc/dynamic_debug/control
This patch,~1,~2 are basically copies of [1] with a few differences:
- s/dynamic_/ddebug_/ on Vincent's additions
- __printf attrs on the _printk funcs
- reuses trace_console() event, not adding a new "printk:dyndbg" event.
next patch replaces this with 2 new events
[1] https://lore.kernel.org/lkml/[email protected]
CC: [email protected]
Signed-off-by: Jim Cromie <[email protected]>
---
.../admin-guide/dynamic-debug-howto.rst | 5 +-
lib/dynamic_debug.c | 156 +++++++++++++++---
2 files changed, 133 insertions(+), 28 deletions(-)
diff --git a/Documentation/admin-guide/dynamic-debug-howto.rst b/Documentation/admin-guide/dynamic-debug-howto.rst
index 0c526dac8428..19732b510cfc 100644
--- a/Documentation/admin-guide/dynamic-debug-howto.rst
+++ b/Documentation/admin-guide/dynamic-debug-howto.rst
@@ -209,8 +209,9 @@ of the characters::
The flags are::
- p enables the pr_debug() callsite.
- _ enables no flags.
+ p callsite prints to syslog
+ T callsite issues a dyndbg:* trace-event
+ _ enables no flags
Decorator flags add to the message-prefix, in order:
t Include thread ID, or <intr>
diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
index ee0cb37153ef..016f33c20251 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>
@@ -90,6 +91,7 @@ static inline const char *trim_prefix(const char *path)
static const struct { unsigned flag:8; char opt_char; } opt_array[] = {
{ _DPRINTK_FLAGS_PRINTK, 'p' },
+ { _DPRINTK_FLAGS_TRACE, 'T' },
{ _DPRINTK_FLAGS_INCL_MODNAME, 'm' },
{ _DPRINTK_FLAGS_INCL_FUNCNAME, 'f' },
{ _DPRINTK_FLAGS_INCL_SOURCENAME, 's' },
@@ -858,6 +860,98 @@ static inline char *dynamic_emit_prefix(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 ddebug_trace_buf {
+ char buf[256];
+};
+
+struct ddebug_trace_bufs {
+ struct ddebug_trace_buf bufs[DYNAMIC_TRACE_NESTING];
+};
+
+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)
+{
+ struct ddebug_trace_buf *buf;
+ int bufidx;
+ int len;
+
+ preempt_disable_notrace();
+
+ bufidx = __this_cpu_inc_return(ddebug_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(ddebug_trace_bufs.bufs) + bufidx;
+
+ len = vscnprintf(buf->buf, sizeof(buf->buf), fmt, args);
+ trace_console(buf->buf, len);
+
+out:
+ /* As above. */
+ barrier();
+ __this_cpu_dec(ddebug_trace_reserve);
+ preempt_enable_notrace();
+}
+
+__printf(2, 3)
+static void ddebug_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.
+ */
+ ddebug_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);
+ }
+}
+
+__printf(3, 4)
+static void ddebug_dev_printk(unsigned int flags, const struct device *dev,
+ const char *fmt, ...)
+{
+
+ if (flags & _DPRINTK_FLAGS_TRACE) {
+ va_list args;
+
+ va_start(args, fmt);
+ ddebug_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;
@@ -872,16 +966,18 @@ 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);
+ ddebug_printk(descriptor->flags, KERN_DEBUG "%s%pV",
+ dynamic_emit_prefix(descriptor, buf), &vaf);
va_end(args);
}
EXPORT_SYMBOL(__dynamic_pr_debug);
void __dynamic_dev_dbg(struct _ddebug *descriptor,
- const struct device *dev, const char *fmt, ...)
+ const struct device *dev, const char *fmt, ...)
{
struct va_format vaf;
+ unsigned int flags;
va_list args;
BUG_ON(!descriptor);
@@ -891,16 +987,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);
+ ddebug_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);
+ ddebug_dev_printk(flags, dev, "%s%s %s: %pV",
+ dynamic_emit_prefix(descriptor, buf),
+ dev_driver_string(dev), dev_name(dev),
+ &vaf);
}
va_end(args);
@@ -913,6 +1011,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);
@@ -922,22 +1021,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);
+ 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);
} else if (dev) {
- printk(KERN_DEBUG "%s%s: %pV", netdev_name(dev),
- netdev_reg_state(dev), &vaf);
+ ddebug_printk(flags, KERN_DEBUG "%s%s: %pV",
+ netdev_name(dev), netdev_reg_state(dev), &vaf);
} else {
- printk(KERN_DEBUG "(NULL net_device): %pV", &vaf);
+ ddebug_printk(flags, KERN_DEBUG "(NULL net_device): %pV",
+ &vaf);
}
va_end(args);
@@ -953,26 +1054,29 @@ 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] = "";
- 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);
+ ddebug_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);
+ ddebug_printk(flags, KERN_DEBUG "%s: %pV",
+ dev_name(&ibdev->dev), &vaf);
} else {
- printk(KERN_DEBUG "(NULL ib_device): %pV", &vaf);
+ ddebug_printk(flags, KERN_DEBUG "(NULL ip_device): %pV", &vaf);
}
va_end(args);
--
2.43.0.472.g3155946c3a-goog
From: Jim Cromie <[email protected]>
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 save a debug message and use its length for
processing. They also accept the _ddebug descriptor and dev
structure so they can be used to access the whole callsite
record in the future: 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 <[email protected]>
Signed-off-by: Łukasz Bartosik <[email protected]>
---
MAINTAINERS | 1 +
include/trace/events/dyndbg.h | 63 ++++++++++++++++++++++++++++++
lib/dynamic_debug.c | 73 ++++++++++++++++++-----------------
3 files changed, 101 insertions(+), 36 deletions(-)
create mode 100644 include/trace/events/dyndbg.h
diff --git a/MAINTAINERS b/MAINTAINERS
index 9104430e148e..e5bef24d6134 100644
--- a/MAINTAINERS
+++ b/MAINTAINERS
@@ -7391,6 +7391,7 @@ M: Jason Baron <[email protected]>
M: Jim Cromie <[email protected]>
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..647c30206a7d
--- /dev/null
+++ b/include/trace/events/dyndbg.h
@@ -0,0 +1,63 @@
+/* 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>
+
+/*
+ * template for dynamic debug events
+ * captures debug log message and uses its length, it also
+ * accepts _ddebug and dev structures for future extensions
+ */
+DECLARE_EVENT_CLASS(dyndbg_template,
+
+ TP_PROTO(const struct _ddebug *desc, const struct device *dev,
+ const char *msg, size_t len),
+
+ TP_ARGS(desc, dev, msg, len),
+
+ TP_STRUCT__entry(
+ __dynamic_array(char, s, len+1)
+ ),
+
+ TP_fast_assign(
+ /*
+ * 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 && (msg[len-1] == '\n'))
+ len -= 1;
+
+ memcpy(__get_str(s), msg, len);
+ __get_str(s)[len] = 0;
+ ),
+
+ TP_printk("%s", __get_str(s))
+);
+
+/* captures pr_debug() callsites */
+DEFINE_EVENT(dyndbg_template, prdbg,
+
+ TP_PROTO(const struct _ddebug *desc, const struct device *dev,
+ const char *msg, size_t len),
+
+ TP_ARGS(desc, dev, msg, len)
+);
+
+/* captures dev_dbg() callsites */
+DEFINE_EVENT(dyndbg_template, devdbg,
+
+ TP_PROTO(const struct _ddebug *desc, const struct device *dev,
+ const char *msg, size_t len),
+
+ TP_ARGS(desc, dev, msg, len)
+);
+
+#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..fcc7c5631b53 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, NULL, 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.43.0.472.g3155946c3a-goog
From: Jim Cromie <[email protected]>
This variant of __get_str() removes the trailing newline. It is for
use by printk/debug-ish events which already have a trailing newline.
It is here to support [1] which taught dyndbg to send pr_debug() msgs
to tracefs, via -x/T flag. It "reused" the include/trace/events/printk.h
console event, which does the following:
TP_fast_assign(
/*
* 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 && (msg[len-1] == '\n'))
len -= 1;
memcpy(__get_str(s), msg, len);
__get_str(s)[len] = 0;
),
That trim work could be avoided, *if* all pr_debug() callers are
known to have no '\n' to strip. While that's not true for *all*
callsites, it is 99+% true for DRM.debug callsites, and can be made
true for some subsets of prdbg/dyndbg callsites.
WANTED: macros to validate that a literal format-str has or doesn't
have a trailing newline, or to provide or trim trailing newline(s?).
Should be usable in TP_printk* defns, for use in new event defns.
[1] https://lore.kernel.org/lkml/[email protected]
Cc: <[email protected]>
Cc: Vincent Whitchurch <[email protected]>
Cc: <[email protected]>
Cc: <[email protected]>
Cc: <[email protected]>
Cc: <[email protected]>
Cc: Simon Ser <[email protected]>
Cc: Sean Paul <[email protected]>
Signed-off-by: Jim Cromie <[email protected]>
Signed-off-by: Łukasz Bartosik <[email protected]>
---
include/trace/stages/stage3_trace_output.h | 13 +++++++++++++
1 file changed, 13 insertions(+)
diff --git a/include/trace/stages/stage3_trace_output.h b/include/trace/stages/stage3_trace_output.h
index c1fb1355d309..283533a17e62 100644
--- a/include/trace/stages/stage3_trace_output.h
+++ b/include/trace/stages/stage3_trace_output.h
@@ -19,6 +19,19 @@
#undef __get_str
#define __get_str(field) ((char *)__get_dynamic_array(field))
+#undef __get_str_strip_nl
+#define __get_str_strip_nl(field) \
+ ({ \
+ char *s = trace_seq_buffer_ptr(p); \
+ size_t len; \
+ trace_seq_printf(p, "%s", __get_str(field)); \
+ trace_seq_putc(p, '\0'); \
+ len = strlen(s); \
+ if (len && s[len-1] == '\n') \
+ s[len-1] = '\0'; \
+ s; \
+ })
+
#undef __get_rel_dynamic_array
#define __get_rel_dynamic_array(field) \
((void *)__entry + \
--
2.43.0.472.g3155946c3a-goog
From: Jim Cromie <[email protected]>
Recently added dyndbg events: prdbg, devdbg have code to strip the
trailing newline, if it's there. Instead of removing the newline
in TP_fast_assign use __get_str_strip_nl macro in TP_printk. Advantage
of such an approach is that the removal is done on the read side (slow
path). The change removes also passing of debug message length to prdbg
and devdbg events.
This use is slightly premature/overkill, since some pr_debugs do not
have the expected trailing newline. While those lacks are arguably
bugs, this doesn't fix them.
Signed-off-by: Jim Cromie <[email protected]>
Signed-off-by: Łukasz Bartosik <[email protected]>
---
include/trace/events/dyndbg.h | 27 +++++++++------------------
lib/dynamic_debug.c | 7 +++----
2 files changed, 12 insertions(+), 22 deletions(-)
diff --git a/include/trace/events/dyndbg.h b/include/trace/events/dyndbg.h
index 647c30206a7d..ffd21480cd9d 100644
--- a/include/trace/events/dyndbg.h
+++ b/include/trace/events/dyndbg.h
@@ -15,46 +15,37 @@
DECLARE_EVENT_CLASS(dyndbg_template,
TP_PROTO(const struct _ddebug *desc, const struct device *dev,
- const char *msg, size_t len),
+ const char *msg),
- TP_ARGS(desc, dev, msg, len),
+ TP_ARGS(desc, dev, msg),
TP_STRUCT__entry(
- __dynamic_array(char, s, len+1)
+ __string(s, msg)
),
TP_fast_assign(
- /*
- * 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 && (msg[len-1] == '\n'))
- len -= 1;
-
- memcpy(__get_str(s), msg, len);
- __get_str(s)[len] = 0;
+ __assign_str(s, msg);
),
- TP_printk("%s", __get_str(s))
+ TP_printk("%s", __get_str_strip_nl(s))
);
/* captures pr_debug() callsites */
DEFINE_EVENT(dyndbg_template, prdbg,
TP_PROTO(const struct _ddebug *desc, const struct device *dev,
- const char *msg, size_t len),
+ const char *msg),
- TP_ARGS(desc, dev, msg, len)
+ TP_ARGS(desc, dev, msg)
);
/* captures dev_dbg() callsites */
DEFINE_EVENT(dyndbg_template, devdbg,
TP_PROTO(const struct _ddebug *desc, const struct device *dev,
- const char *msg, size_t len),
+ const char *msg),
- TP_ARGS(desc, dev, msg, len)
+ TP_ARGS(desc, dev, msg)
);
#endif /* _TRACE_DYNDBG_H */
diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
index fcc7c5631b53..9682277f3909 100644
--- a/lib/dynamic_debug.c
+++ b/lib/dynamic_debug.c
@@ -886,7 +886,6 @@ static void ddebug_trace(struct _ddebug *desc, const struct device *dev,
{
struct ddebug_trace_buf *buf;
int bufidx;
- int len;
preempt_disable_notrace();
@@ -900,12 +899,12 @@ static void ddebug_trace(struct _ddebug *desc, const struct device *dev,
buf = this_cpu_ptr(ddebug_trace_bufs.bufs) + bufidx;
- len = vscnprintf(buf->buf, sizeof(buf->buf), fmt, args);
+ vscnprintf(buf->buf, sizeof(buf->buf), fmt, args);
if (!dev)
- trace_prdbg(desc, NULL, buf->buf, len);
+ trace_prdbg(desc, NULL, buf->buf);
else
- trace_devdbg(desc, dev, buf->buf, len);
+ trace_devdbg(desc, dev, buf->buf);
out:
/* As above. */
--
2.43.0.472.g3155946c3a-goog
From: Jim Cromie <[email protected]>
Move the JUMP_LABEL to the top of the struct, since they're both
align(8) and this closes a pahole (unfortunately trading for padding,
but still).
Signed-off-by: Jim Cromie <[email protected]>
---
include/linux/dynamic_debug.h | 12 ++++++------
1 file changed, 6 insertions(+), 6 deletions(-)
diff --git a/include/linux/dynamic_debug.h b/include/linux/dynamic_debug.h
index 497130816e9c..b9237e4ecd1b 100644
--- a/include/linux/dynamic_debug.h
+++ b/include/linux/dynamic_debug.h
@@ -14,6 +14,12 @@
* the special section is treated as an array of these.
*/
struct _ddebug {
+#ifdef CONFIG_JUMP_LABEL
+ union {
+ struct static_key_true dd_key_true;
+ struct static_key_false dd_key_false;
+ } key;
+#endif
/*
* These fields are used to drive the user interface
* for selecting and displaying debug callsites.
@@ -53,12 +59,6 @@ struct _ddebug {
#define _DPRINTK_FLAGS_DEFAULT 0
#endif
unsigned int flags:8;
-#ifdef CONFIG_JUMP_LABEL
- union {
- struct static_key_true dd_key_true;
- struct static_key_false dd_key_false;
- } key;
-#endif
} __attribute__((aligned(8)));
enum class_map_type {
--
2.43.0.472.g3155946c3a-goog
The trace destination field is used to determine output of debug
logs when +T is set. Setting trace_dst value to 0 enables output
to prdbg and devdbg trace events. Setting trace_dst value to a
value in range of [1..63] enables output to trace instance.
Signed-off-by: Łukasz Bartosik <[email protected]>
---
include/linux/dynamic_debug.h | 13 +++++++++++--
lib/dynamic_debug.c | 28 +++++++++++++++++++---------
2 files changed, 30 insertions(+), 11 deletions(-)
diff --git a/include/linux/dynamic_debug.h b/include/linux/dynamic_debug.h
index a551b2967cb8..dc10c7535f13 100644
--- a/include/linux/dynamic_debug.h
+++ b/include/linux/dynamic_debug.h
@@ -60,9 +60,18 @@ struct _ddebug {
#else
#define _DPRINTK_FLAGS_DEFAULT 0
#endif
- struct {
+ struct dd_ctrl {
unsigned int flags:8;
- unsigned unused:24;
+ /*
+ * The trace destination field is used to determine output of debug
+ * logs when +T is set. Setting trace_dst value to 0 enables output
+ * to prdbg and devdbg trace events. Setting trace_dst value to a
+ * value in range of [1..63] enables output to trace instance.
+ */
+#define TRACE_DST_BITS 6
+ unsigned int trace_dst:TRACE_DST_BITS;
+#define TRACE_DST_LAST (1 << TRACE_DST_BITS)
+ unsigned unused:18;
} ctrl;
} __attribute__((aligned(8)));
diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
index f47cb76e0e3d..0dc9ec76b867 100644
--- a/lib/dynamic_debug.c
+++ b/lib/dynamic_debug.c
@@ -80,14 +80,24 @@ module_param(verbose, int, 0644);
MODULE_PARM_DESC(verbose, " dynamic_debug/control processing "
"( 0 = off (default), 1 = module add/rm, 2 = >control summary, 3 = parsing, 4 = per-site changes)");
+static inline struct dd_ctrl *get_ctrl(struct _ddebug *desc)
+{
+ return &desc->ctrl;
+}
+
+static inline void set_ctrl(struct _ddebug *desc, struct dd_ctrl *ctrl)
+{
+ desc->ctrl = *ctrl;
+}
+
static inline unsigned int get_flags(const struct _ddebug *desc)
{
return desc->ctrl.flags;
}
-static inline void set_flags(struct _ddebug *desc, unsigned int val)
+static inline unsigned int get_trace_dst(const struct _ddebug *desc)
{
- desc->ctrl.flags = val;
+ return desc->ctrl.trace_dst;
}
/* Return the path relative to source root */
@@ -190,8 +200,8 @@ static int ddebug_change(const struct ddebug_query *query,
{
int i;
struct ddebug_table *dt;
- unsigned int newflags;
unsigned int nfound = 0;
+ struct dd_ctrl nctrl = {0};
struct flagsbuf fbuf, nbuf;
struct ddebug_class_map *map = NULL;
int __outvar valid_class;
@@ -257,14 +267,14 @@ static int ddebug_change(const struct ddebug_query *query,
nfound++;
- newflags = (get_flags(dp) & modifiers->mask) | modifiers->flags;
- if (newflags == get_flags(dp))
+ nctrl.flags = (get_flags(dp) & modifiers->mask) | modifiers->flags;
+ if (!memcmp(&nctrl, get_ctrl(dp), sizeof(struct dd_ctrl)))
continue;
#ifdef CONFIG_JUMP_LABEL
if (get_flags(dp) & _DPRINTK_FLAGS_ENABLED) {
- if (!(newflags & _DPRINTK_FLAGS_ENABLED))
+ if (!(nctrl.flags & _DPRINTK_FLAGS_ENABLED))
static_branch_disable(&dp->key.dd_key_true);
- } else if (newflags & _DPRINTK_FLAGS_ENABLED) {
+ } else if (nctrl.flags & _DPRINTK_FLAGS_ENABLED) {
static_branch_enable(&dp->key.dd_key_true);
}
#endif
@@ -272,8 +282,8 @@ static int ddebug_change(const struct ddebug_query *query,
trim_prefix(dp->filename), dp->lineno,
dt->mod_name, dp->function,
ddebug_describe_flags(get_flags(dp), &fbuf),
- ddebug_describe_flags(newflags, &nbuf));
- set_flags(dp, newflags);
+ ddebug_describe_flags(nctrl.flags, &nbuf));
+ set_ctrl(dp, &nctrl);
}
}
mutex_unlock(&ddebug_lock);
--
2.43.0.472.g3155946c3a-goog
Add open and close commands for opening and closing trace instances.
The open command has to be mandatory followed by a trace instance name.
If a trace instance already exists in <debugfs>/tracing/instances
directory then the open command will reuse it otherwise a new trace
instance with a name provided to the open will be created. Close
command closes previously opened trace instance. The close will
fail if a user tries to close non-existent trace instances or an
instance which was not previously opened.
For example the following command will open (create or reuse existing)
trace instance located in <debugfs>/tracing/instances/usbcore:
echo "open usbcore" > <debugfs>/dynamic_debug/control
Signed-off-by: Łukasz Bartosik <[email protected]>
---
lib/Kconfig.debug | 2 +
lib/dynamic_debug.c | 194 ++++++++++++++++++++++++++++++++++++++++++++
2 files changed, 196 insertions(+)
diff --git a/lib/Kconfig.debug b/lib/Kconfig.debug
index 4405f81248fb..233132a05299 100644
--- a/lib/Kconfig.debug
+++ b/lib/Kconfig.debug
@@ -110,6 +110,7 @@ config DYNAMIC_DEBUG
default n
depends on PRINTK
depends on (DEBUG_FS || PROC_FS)
+ depends on TRACING
select DYNAMIC_DEBUG_CORE
help
@@ -181,6 +182,7 @@ config DYNAMIC_DEBUG_CORE
bool "Enable core function of dynamic debug support"
depends on PRINTK
depends on (DEBUG_FS || PROC_FS)
+ depends on TRACING
help
Enable core functional support of dynamic debug. It is useful
when you want to tie dynamic debug to your kernel modules with
diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
index 0dc9ec76b867..dd4510ad124e 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 <linux/trace.h>
#define CREATE_TRACE_POINTS
#include <trace/events/dyndbg.h>
@@ -73,6 +74,27 @@ struct flag_settings {
unsigned int mask;
};
+#define DD_OPEN_CMD "open"
+#define DD_CLOSE_CMD "close"
+#define DD_TR_EVENT "0"
+
+struct dd_private_tracebuf {
+ const char *name;
+ struct trace_array *arr;
+};
+
+/*
+ * Trace destination value 0 is reserved for writing
+ * debug logs to trace events (prdbg, devdbg), that
+ * is why buf[0] is not used and we traverse bitmap
+ * starting from bit 1 (bit 0 is also not used).
+ */
+struct dd_tracebuf_tbl_info {
+ struct dd_private_tracebuf buf[TRACE_DST_LAST];
+ DECLARE_BITMAP(bmap, TRACE_DST_LAST);
+ int bmap_size;
+};
+
static DEFINE_MUTEX(ddebug_lock);
static LIST_HEAD(ddebug_tables);
static int verbose;
@@ -80,6 +102,9 @@ module_param(verbose, int, 0644);
MODULE_PARM_DESC(verbose, " dynamic_debug/control processing "
"( 0 = off (default), 1 = module add/rm, 2 = >control summary, 3 = parsing, 4 = per-site changes)");
+static struct
+dd_tracebuf_tbl_info trc_tbl = { .bmap_size = TRACE_DST_LAST };
+
static inline struct dd_ctrl *get_ctrl(struct _ddebug *desc)
{
return &desc->ctrl;
@@ -171,6 +196,145 @@ static void vpr_info_dq(const struct ddebug_query *query, const char *msg)
query->first_lineno, query->last_lineno, query->class_string);
}
+static bool is_dd_trace_cmd(const char *str)
+{
+ if (!strcmp(str, DD_OPEN_CMD) || !strcmp(str, DD_CLOSE_CMD))
+ return true;
+
+ return false;
+}
+
+static bool dd_good_trace_name(const char *str)
+{
+ /* "0" is reserved for writing debug logs to trace events (prdbg, devdbg) */
+ if (!strcmp(str, DD_TR_EVENT))
+ return false;
+
+ /* we allow trace instance names to include ^\w+ and underscore */
+ while (*str != '\0') {
+ if (!isalnum(*str) && *str != '_')
+ return false;
+ str++;
+ }
+
+ return true;
+}
+
+static int find_tr_instance(const char *name)
+{
+ int idx = 1;
+
+ for_each_set_bit_from(idx, trc_tbl.bmap, trc_tbl.bmap_size)
+ if (!strcmp(trc_tbl.buf[idx].name, name))
+ return idx;
+
+ return -ENOENT;
+}
+
+static int handle_trace_open_cmd(const char *arg)
+{
+ struct dd_private_tracebuf *buf;
+ int idx, ret = 0;
+
+ mutex_lock(&ddebug_lock);
+
+ /* bit 0 is not used, reserved for trace prdbg and devdbg events */
+ idx = find_next_zero_bit(trc_tbl.bmap, trc_tbl.bmap_size, 1);
+ if (idx == trc_tbl.bmap_size) {
+ ret = -ENOSPC;
+ goto end;
+ }
+
+ if (!dd_good_trace_name(arg)) {
+ pr_err("invalid instance name:%s\n", arg);
+ ret = -EINVAL;
+ goto end;
+ }
+
+ if (find_tr_instance(arg) >= 0) {
+ pr_err("instance is already opened name:%s\n", arg);
+ ret = -EEXIST;
+ goto end;
+ }
+
+ buf = &trc_tbl.buf[idx];
+ buf->name = kstrdup(arg, GFP_KERNEL);
+ if (!buf->name) {
+ ret = -ENOMEM;
+ goto end;
+ }
+
+ buf->arr = trace_array_get_by_name(buf->name);
+ if (!buf->arr) {
+ pr_err("failed to get trace array name:%s", buf->name);
+ ret = -EINVAL;
+ goto end;
+ }
+
+ ret = trace_array_init_printk(buf->arr);
+ if (ret) {
+ pr_err("failed to init trace array name:%s", buf->name);
+ trace_array_put(buf->arr);
+ trace_array_destroy(buf->arr);
+ goto end;
+ }
+
+ set_bit(idx, trc_tbl.bmap);
+ v3pr_info("opened trace instance idx=%d, name=%s\n", idx, arg);
+end:
+ mutex_unlock(&ddebug_lock);
+ return ret;
+}
+
+static int handle_trace_close_cmd(const char *arg)
+{
+ struct dd_private_tracebuf *buf;
+ int idx, ret = 0;
+
+ mutex_lock(&ddebug_lock);
+
+ idx = find_tr_instance(arg);
+ if (idx < 0) {
+ ret = idx;
+ goto end;
+ }
+
+ buf = &trc_tbl.buf[idx];
+
+ trace_array_put(buf->arr);
+ /*
+ * don't destroy trace instance but let user do it manually
+ * with rmdir command at a convenient time later, if it is
+ * destroyed here all debug logs will be lost
+ *
+ * trace_array_destroy(inst->arr);
+ */
+ buf->arr = NULL;
+
+ kfree(buf->name);
+ buf->name = NULL;
+
+ clear_bit(idx, trc_tbl.bmap);
+ v3pr_info("closed trace instance idx=%d, name=%s\n", idx, arg);
+end:
+ mutex_unlock(&ddebug_lock);
+ return ret;
+}
+
+static int ddebug_parse_cmd(char *words[], int nwords)
+{
+ if (nwords != 1)
+ return -EINVAL;
+
+ if (!strcmp(words[0], DD_OPEN_CMD))
+ return handle_trace_open_cmd(words[1]);
+ if (!strcmp(words[0], DD_CLOSE_CMD))
+ return handle_trace_close_cmd(words[1]);
+
+ pr_err("invalid command %s\n", words[0]);
+ return -EINVAL;
+}
+
static struct ddebug_class_map *ddebug_find_valid_class(struct ddebug_table const *dt,
const char *class_string, int *class_id)
{
@@ -567,6 +731,11 @@ static int ddebug_exec_query(char *query_string, const char *modname)
pr_err("tokenize failed\n");
return -EINVAL;
}
+
+ /* check for open, close commands */
+ if (is_dd_trace_cmd(words[0]))
+ return ddebug_parse_cmd(words, nwords-1);
+
/* check flags 1st (last arg) so query is pairs of spec,val */
if (ddebug_parse_flags(words[nwords-1], &modifiers)) {
pr_err("flags parse failed\n");
@@ -1191,6 +1360,20 @@ static struct _ddebug *ddebug_iter_next(struct ddebug_iter *iter)
return &iter->table->ddebugs[iter->idx];
}
+/*
+ * Check if the iterator points to the last _ddebug object
+ * to traverse.
+ */
+static bool ddebug_iter_is_last(struct ddebug_iter *iter)
+{
+ if (iter->table == NULL)
+ return false;
+ if (iter->idx-1 < 0 &&
+ list_is_last(&iter->table->link, &ddebug_tables))
+ return true;
+ return false;
+}
+
/*
* Seq_ops start method. Called at the start of every
* read() call from userspace. Takes the ddebug_lock and
@@ -1281,6 +1464,17 @@ static int ddebug_proc_show(struct seq_file *m, void *p)
}
seq_puts(m, "\n");
+ if (ddebug_iter_is_last(iter) &&
+ !bitmap_empty(trc_tbl.bmap, trc_tbl.bmap_size)) {
+ int idx = 1;
+
+ seq_puts(m, "\n");
+ seq_puts(m, "#: Opened trace instances:");
+ for_each_set_bit_from(idx, trc_tbl.bmap, trc_tbl.bmap_size)
+ seq_printf(m, " %s", trc_tbl.buf[idx].name);
+ seq_puts(m, "\n");
+ }
+
return 0;
}
--
2.43.0.472.g3155946c3a-goog
Don't allow trace instance to be closed when it
is still being used by at least one callsite.
Signed-off-by: Łukasz Bartosik <[email protected]>
---
lib/dynamic_debug.c | 38 ++++++++++++++++++++++++++++++++++++++
1 file changed, 38 insertions(+)
diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
index dd4510ad124e..59682729ed3a 100644
--- a/lib/dynamic_debug.c
+++ b/lib/dynamic_debug.c
@@ -81,6 +81,7 @@ struct flag_settings {
struct dd_private_tracebuf {
const char *name;
struct trace_array *arr;
+ int use_cnt;
};
/*
@@ -279,6 +280,7 @@ static int handle_trace_open_cmd(const char *arg)
goto end;
}
+ buf->use_cnt = 0;
set_bit(idx, trc_tbl.bmap);
v3pr_info("opened trace instance idx=%d, name=%s\n", idx, arg);
end:
@@ -301,6 +303,14 @@ static int handle_trace_close_cmd(const char *arg)
buf = &trc_tbl.buf[idx];
+ WARN_ON(buf->use_cnt < 0);
+ if (buf->use_cnt) {
+ pr_err("trace instance is being used name=%s, use_cnt=%d\n",
+ buf->name, buf->use_cnt);
+ ret = -EBUSY;
+ goto end;
+ }
+
trace_array_put(buf->arr);
/*
* don't destroy trace instance but let user do it manually
@@ -321,6 +331,24 @@ static int handle_trace_close_cmd(const char *arg)
return ret;
}
+static
+void update_tr_dst(const struct _ddebug *desc, const struct dd_ctrl *nctrl)
+{
+ int oflags = get_flags(desc), odst = get_trace_dst(desc);
+ int nflags = nctrl->flags, ndst = nctrl->trace_dst;
+
+ if (oflags & _DPRINTK_FLAGS_TRACE &&
+ nflags & _DPRINTK_FLAGS_TRACE &&
+ odst == ndst)
+ return;
+
+ if (odst && (oflags & _DPRINTK_FLAGS_TRACE))
+ trc_tbl.buf[odst].use_cnt--;
+
+ if (ndst && (nflags & _DPRINTK_FLAGS_TRACE))
+ trc_tbl.buf[ndst].use_cnt++;
+}
+
static int ddebug_parse_cmd(char *words[], int nwords)
{
if (nwords != 1)
@@ -447,6 +475,7 @@ static int ddebug_change(const struct ddebug_query *query,
dt->mod_name, dp->function,
ddebug_describe_flags(get_flags(dp), &fbuf),
ddebug_describe_flags(nctrl.flags, &nbuf));
+ update_tr_dst(dp, &nctrl);
set_ctrl(dp, &nctrl);
}
}
@@ -1628,6 +1657,15 @@ int ddebug_dyndbg_module_param_cb(char *param, char *val, const char *module)
static void ddebug_table_free(struct ddebug_table *dt)
{
+
+ int dst, i;
+
+ for (i = 0; i < dt->num_ddebugs; i++) {
+ dst = get_trace_dst(&dt->ddebugs[i]);
+ if (dst && (get_flags(&dt->ddebugs[i]) & _DPRINTK_FLAGS_TRACE))
+ trc_tbl.buf[dst].use_cnt--;
+ }
+
list_del_init(&dt->link);
kfree(dt);
}
--
2.43.0.472.g3155946c3a-goog
Add a new structure ctrl and place it in 4 padding bytes
of _ddebug struct. Move flags field to the ctrl struct
and create setter and getter for the flags field. Add unused
fields to explicitly emphasise size of each bitfield.
This step prepares for addition of a trace_dst field.
Layout of _ddebug struct after addition of ctrl is:
struct _ddebug {
union {
struct static_key_true dd_key_true; /* 0 16 */
struct static_key_false dd_key_false; /* 0 16 */
} key; /* 0 16 */
union {
struct static_key_true dd_key_true; /* 0 16 */
struct static_key_false dd_key_false; /* 0 16 */
};
const char * modname; /* 16 8 */
const char * function; /* 24 8 */
const char * filename; /* 32 8 */
const char * format; /* 40 8 */
unsigned int lineno:18; /* 48: 0 4 */
unsigned int class_id:6; /* 48:18 4 */
unsigned int unused:8; /* 48:24 4 */
struct dd_ctrl ctrl; /* 52 4 */
/* size: 56, cachelines: 1, members: 9 */
/* last cacheline: 56 bytes */
} __attribute__((__aligned__(8)));
Signed-off-by: Łukasz Bartosik <[email protected]>
---
include/linux/dynamic_debug.h | 13 +++++++----
lib/dynamic_debug.c | 44 ++++++++++++++++++++++-------------
2 files changed, 37 insertions(+), 20 deletions(-)
diff --git a/include/linux/dynamic_debug.h b/include/linux/dynamic_debug.h
index b9237e4ecd1b..a551b2967cb8 100644
--- a/include/linux/dynamic_debug.h
+++ b/include/linux/dynamic_debug.h
@@ -32,6 +32,8 @@ struct _ddebug {
#define CLS_BITS 6
unsigned int class_id:CLS_BITS;
#define _DPRINTK_CLASS_DFLT ((1 << CLS_BITS) - 1)
+ unsigned int unused:8;
+
/*
* The flags field controls the behaviour at the callsite.
* The bits here are changed dynamically when the user
@@ -58,7 +60,10 @@ struct _ddebug {
#else
#define _DPRINTK_FLAGS_DEFAULT 0
#endif
- unsigned int flags:8;
+ struct {
+ unsigned int flags:8;
+ unsigned unused:24;
+ } ctrl;
} __attribute__((aligned(8)));
enum class_map_type {
@@ -171,7 +176,7 @@ void __dynamic_ibdev_dbg(struct _ddebug *descriptor,
.filename = __FILE__, \
.format = (fmt), \
.lineno = __LINE__, \
- .flags = _DPRINTK_FLAGS_DEFAULT, \
+ .ctrl = { .flags = _DPRINTK_FLAGS_DEFAULT }, \
.class_id = cls, \
_DPRINTK_KEY_INIT \
}; \
@@ -202,10 +207,10 @@ void __dynamic_ibdev_dbg(struct _ddebug *descriptor,
#ifdef DEBUG
#define DYNAMIC_DEBUG_BRANCH(descriptor) \
- likely(descriptor.flags & _DPRINTK_FLAGS_ENABLED)
+ likely(descriptor.ctrl.flags & _DPRINTK_FLAGS_ENABLED)
#else
#define DYNAMIC_DEBUG_BRANCH(descriptor) \
- unlikely(descriptor.flags & _DPRINTK_FLAGS_ENABLED)
+ unlikely(descriptor.ctrl.flags & _DPRINTK_FLAGS_ENABLED)
#endif
#endif /* CONFIG_JUMP_LABEL */
diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
index 9682277f3909..f47cb76e0e3d 100644
--- a/lib/dynamic_debug.c
+++ b/lib/dynamic_debug.c
@@ -80,6 +80,16 @@ module_param(verbose, int, 0644);
MODULE_PARM_DESC(verbose, " dynamic_debug/control processing "
"( 0 = off (default), 1 = module add/rm, 2 = >control summary, 3 = parsing, 4 = per-site changes)");
+static inline unsigned int get_flags(const struct _ddebug *desc)
+{
+ return desc->ctrl.flags;
+}
+
+static inline void set_flags(struct _ddebug *desc, unsigned int val)
+{
+ desc->ctrl.flags = val;
+}
+
/* Return the path relative to source root */
static inline const char *trim_prefix(const char *path)
{
@@ -247,11 +257,11 @@ static int ddebug_change(const struct ddebug_query *query,
nfound++;
- newflags = (dp->flags & modifiers->mask) | modifiers->flags;
- if (newflags == dp->flags)
+ newflags = (get_flags(dp) & modifiers->mask) | modifiers->flags;
+ if (newflags == get_flags(dp))
continue;
#ifdef CONFIG_JUMP_LABEL
- if (dp->flags & _DPRINTK_FLAGS_ENABLED) {
+ if (get_flags(dp) & _DPRINTK_FLAGS_ENABLED) {
if (!(newflags & _DPRINTK_FLAGS_ENABLED))
static_branch_disable(&dp->key.dd_key_true);
} else if (newflags & _DPRINTK_FLAGS_ENABLED) {
@@ -261,9 +271,9 @@ static int ddebug_change(const struct ddebug_query *query,
v4pr_info("changed %s:%d [%s]%s %s => %s\n",
trim_prefix(dp->filename), dp->lineno,
dt->mod_name, dp->function,
- ddebug_describe_flags(dp->flags, &fbuf),
+ ddebug_describe_flags(get_flags(dp), &fbuf),
ddebug_describe_flags(newflags, &nbuf));
- dp->flags = newflags;
+ set_flags(dp, newflags);
}
}
mutex_unlock(&ddebug_lock);
@@ -824,10 +834,11 @@ static int remaining(int wrote)
static char *__dynamic_emit_prefix(const struct _ddebug *desc, char *buf)
{
+ unsigned int flags = get_flags(desc);
int pos_after_tid;
int pos = 0;
- if (desc->flags & _DPRINTK_FLAGS_INCL_TID) {
+ if (flags & _DPRINTK_FLAGS_INCL_TID) {
if (in_interrupt())
pos += snprintf(buf + pos, remaining(pos), "<intr> ");
else
@@ -835,16 +846,16 @@ static char *__dynamic_emit_prefix(const struct _ddebug *desc, char *buf)
task_pid_vnr(current));
}
pos_after_tid = pos;
- if (desc->flags & _DPRINTK_FLAGS_INCL_MODNAME)
+ if (flags & _DPRINTK_FLAGS_INCL_MODNAME)
pos += snprintf(buf + pos, remaining(pos), "%s:",
desc->modname);
- if (desc->flags & _DPRINTK_FLAGS_INCL_FUNCNAME)
+ if (flags & _DPRINTK_FLAGS_INCL_FUNCNAME)
pos += snprintf(buf + pos, remaining(pos), "%s:",
desc->function);
- if (desc->flags & _DPRINTK_FLAGS_INCL_SOURCENAME)
+ if (flags & _DPRINTK_FLAGS_INCL_SOURCENAME)
pos += snprintf(buf + pos, remaining(pos), "%s:",
trim_prefix(desc->filename));
- if (desc->flags & _DPRINTK_FLAGS_INCL_LINENO)
+ if (flags & _DPRINTK_FLAGS_INCL_LINENO)
pos += snprintf(buf + pos, remaining(pos), "%d:",
desc->lineno);
if (pos - pos_after_tid)
@@ -857,7 +868,7 @@ static char *__dynamic_emit_prefix(const struct _ddebug *desc, char *buf)
static inline char *dynamic_emit_prefix(struct _ddebug *desc, char *buf)
{
- if (unlikely(desc->flags & _DPRINTK_FLAGS_INCL_ANY))
+ if (unlikely(get_flags(desc) & _DPRINTK_FLAGS_INCL_ANY))
return __dynamic_emit_prefix(desc, buf);
return buf;
}
@@ -916,7 +927,8 @@ static void ddebug_trace(struct _ddebug *desc, const struct device *dev,
__printf(2, 3)
static void ddebug_printk(struct _ddebug *desc, const char *fmt, ...)
{
- if (desc->flags & _DPRINTK_FLAGS_TRACE) {
+
+ if (get_flags(desc) & _DPRINTK_FLAGS_TRACE) {
va_list args;
va_start(args, fmt);
@@ -928,7 +940,7 @@ static void ddebug_printk(struct _ddebug *desc, const char *fmt, ...)
va_end(args);
}
- if (desc->flags & _DPRINTK_FLAGS_PRINTK) {
+ if (get_flags(desc) & _DPRINTK_FLAGS_PRINTK) {
va_list args;
va_start(args, fmt);
@@ -942,7 +954,7 @@ static void ddebug_dev_printk(struct _ddebug *desc, const struct device *dev,
const char *fmt, ...)
{
- if (desc->flags & _DPRINTK_FLAGS_TRACE) {
+ if (get_flags(desc) & _DPRINTK_FLAGS_TRACE) {
va_list args;
va_start(args, fmt);
@@ -950,7 +962,7 @@ static void ddebug_dev_printk(struct _ddebug *desc, const struct device *dev,
va_end(args);
}
- if (desc->flags & _DPRINTK_FLAGS_PRINTK) {
+ if (get_flags(desc) & _DPRINTK_FLAGS_PRINTK) {
va_list args;
va_start(args, fmt);
@@ -1246,7 +1258,7 @@ static int ddebug_proc_show(struct seq_file *m, void *p)
seq_printf(m, "%s:%u [%s]%s =%s \"",
trim_prefix(dp->filename), dp->lineno,
iter->table->mod_name, dp->function,
- ddebug_describe_flags(dp->flags, &flags));
+ ddebug_describe_flags(get_flags(dp), &flags));
seq_escape_str(m, dp->format, ESCAPE_SPACE, "\t\r\n\"");
seq_puts(m, "\"");
--
2.43.0.472.g3155946c3a-goog
Add processing of argument provided to T(race) flag.
The string argument determines destination of debug logs:
"0" - debug logs will be written to prdbg and devdbg trace events
name - debug logs will be written to trace instance pointed by name,
trace instance name has to be previously opened with open
command
A user can provide trace destination name by following T flag with
":" and trace destination name, for example:
echo "module thunderbolt =pT:tbt" > <debugfs>/dynamic_debug/control
echo "module thunderbolt =lT:tbt.p" > <debugfs>/dynamic_debug/control
When T flag with argument is followed by other flag then the next
flag has to be preceded with ".". Use of "." as a separator between
flags allows a later patch to treat ',' as a space, which mostly
eliminates the need to quote query/rules. And this in turn avoids
quoting hassles:
modprobe test_dynamic_debug dyndbg=class,D2_CORE,+p
It is particularly good for passing boot-args into test-scripts.
vng -p 4 -v \
-a test_dynamic_debug.dyndbg=class,D2_CORE,+p
Signed-off-by: Łukasz Bartosik <[email protected]>
Signed-off-by: Jim Cromie <[email protected]>
---
lib/dynamic_debug.c | 180 ++++++++++++++++++++++++++++++++++----------
1 file changed, 141 insertions(+), 39 deletions(-)
diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
index 59682729ed3a..6c3b83bce18d 100644
--- a/lib/dynamic_debug.c
+++ b/lib/dynamic_debug.c
@@ -72,6 +72,7 @@ struct ddebug_iter {
struct flag_settings {
unsigned int flags;
unsigned int mask;
+ unsigned int trace_dst;
};
#define DD_OPEN_CMD "open"
@@ -85,10 +86,14 @@ struct dd_private_tracebuf {
};
/*
- * Trace destination value 0 is reserved for writing
- * debug logs to trace events (prdbg, devdbg), that
- * is why buf[0] is not used and we traverse bitmap
- * starting from bit 1 (bit 0 is also not used).
+ * When trace is enabled (T flag is set) and trace destination field
+ * value is in range [1..63] then debug logs will be written to trace
+ * instance whose name is stored in buf[trace destination].name, e.g.
+ * when trace destination value is 2 and buf[2].name is set to tbt then
+ * debug logs will be written to <debugfs>/tracing/instances/tbt.
+ * On the other hand trace destination value 0 is reserved for writing
+ * debug logs to trace events (prdbg, devdbg), that is why buf[0] is not
+ * used and we traverse bitmap starting from bit 1 (bit 0 is also not used).
*/
struct dd_tracebuf_tbl_info {
struct dd_private_tracebuf buf[TRACE_DST_LAST];
@@ -126,6 +131,73 @@ static inline unsigned int get_trace_dst(const struct _ddebug *desc)
return desc->ctrl.trace_dst;
}
+static int find_tr_instance(const char *name)
+{
+ int idx = 1;
+
+ for_each_set_bit_from(idx, trc_tbl.bmap, trc_tbl.bmap_size)
+ if (!strcmp(trc_tbl.buf[idx].name, name))
+ return idx;
+
+ return -ENOENT;
+}
+
+static const
+char *read_T_args(const char *str, struct flag_settings *modifiers)
+{
+ int len, idx = 0;
+ char *end;
+
+ if (*(str+1) != ':')
+ return str;
+
+ str += 2;
+ end = strchr(str, '.');
+ if (end && *(end + 1) == '\0')
+ return NULL;
+
+ if (end) {
+ len = end - str;
+ *end = '\0';
+ } else
+ len = strlen(str);
+ len -= 1;
+
+ /* destination trace events */
+ if (!strcmp(str, DD_TR_EVENT))
+ goto end;
+
+ idx = find_tr_instance(str);
+ if (idx < 0)
+ return NULL;
+end:
+ modifiers->trace_dst = idx;
+ return end ? end : str + len;
+}
+
+/*
+ * Maximum number of characters which are being displayed when
+ * printing trace instance name, longer names are truncated
+ */
+#define FLAG_T_ARG_LEN 24
+
+static char *show_T_args(struct dd_ctrl *ctrl, char *p)
+{
+ const char *str;
+ int n;
+
+ str = !ctrl->trace_dst ? DD_TR_EVENT :
+ trc_tbl.buf[ctrl->trace_dst].name;
+
+ n = snprintf(p, FLAG_T_ARG_LEN, ":%s", str);
+ if (n >= FLAG_T_ARG_LEN) {
+ strscpy(&p[FLAG_T_ARG_LEN-4], "...", 4);
+ n = FLAG_T_ARG_LEN - 1;
+ }
+
+ return n < 0 ? p : p + n;
+}
+
/* Return the path relative to source root */
static inline const char *trim_prefix(const char *path)
{
@@ -137,9 +209,18 @@ static inline const char *trim_prefix(const char *path)
return path + skip;
}
-static const struct { unsigned flag:8; char opt_char; } opt_array[] = {
+typedef const char* (*read_flag_args_f)(const char *, struct flag_settings *);
+typedef char* (*show_flag_args_f)(struct dd_ctrl *, char *);
+
+static const struct
+{
+ unsigned flag:8;
+ char opt_char;
+ read_flag_args_f read_args;
+ show_flag_args_f show_args;
+} opt_array[] = {
{ _DPRINTK_FLAGS_PRINTK, 'p' },
- { _DPRINTK_FLAGS_TRACE, 'T' },
+ { _DPRINTK_FLAGS_TRACE, 'T', read_T_args, show_T_args},
{ _DPRINTK_FLAGS_INCL_MODNAME, 'm' },
{ _DPRINTK_FLAGS_INCL_FUNCNAME, 'f' },
{ _DPRINTK_FLAGS_INCL_SOURCENAME, 's' },
@@ -148,22 +229,30 @@ static const struct { unsigned flag:8; char opt_char; } opt_array[] = {
{ _DPRINTK_FLAGS_NONE, '_' },
};
-struct flagsbuf { char buf[ARRAY_SIZE(opt_array)+1]; };
+struct ctrlbuf { char buf[ARRAY_SIZE(opt_array)+FLAG_T_ARG_LEN+1]; };
/* format a string into buf[] which describes the _ddebug's flags */
-static char *ddebug_describe_flags(unsigned int flags, struct flagsbuf *fb)
+static char *ddebug_describe_ctrl(struct dd_ctrl *ctrl, struct ctrlbuf *cb)
{
- char *p = fb->buf;
+ show_flag_args_f show_args = NULL;
+ char *p = cb->buf;
int i;
for (i = 0; i < ARRAY_SIZE(opt_array); ++i)
- if (flags & opt_array[i].flag)
+ if (ctrl->flags & opt_array[i].flag) {
+ if (show_args)
+ *p++ = '.';
*p++ = opt_array[i].opt_char;
- if (p == fb->buf)
+ show_args = opt_array[i].show_args;
+ if (show_args)
+ p = show_args(ctrl, p);
+ }
+
+ if (p == cb->buf)
*p++ = '_';
*p = '\0';
- return fb->buf;
+ return cb->buf;
}
#define vnpr_info(lvl, fmt, ...) \
@@ -221,17 +310,6 @@ static bool dd_good_trace_name(const char *str)
return true;
}
-static int find_tr_instance(const char *name)
-{
- int idx = 1;
-
- for_each_set_bit_from(idx, trc_tbl.bmap, trc_tbl.bmap_size)
- if (!strcmp(trc_tbl.buf[idx].name, name))
- return idx;
-
- return -ENOENT;
-}
-
static int handle_trace_open_cmd(const char *arg)
{
struct dd_private_tracebuf *buf;
@@ -385,7 +463,7 @@ static struct ddebug_class_map *ddebug_find_valid_class(struct ddebug_table cons
* Search the tables for _ddebug's which match the given `query' and
* apply the `flags' and `mask' to them. Returns number of matching
* callsites, normally the same as number of changes. If verbose,
- * logs the changes. Takes ddebug_lock.
+ * logs the changes.
*/
static int ddebug_change(const struct ddebug_query *query,
struct flag_settings *modifiers)
@@ -393,13 +471,12 @@ static int ddebug_change(const struct ddebug_query *query,
int i;
struct ddebug_table *dt;
unsigned int nfound = 0;
+ struct ctrlbuf cbuf, nbuf;
struct dd_ctrl nctrl = {0};
- struct flagsbuf fbuf, nbuf;
struct ddebug_class_map *map = NULL;
int __outvar valid_class;
/* search for matching ddebugs */
- mutex_lock(&ddebug_lock);
list_for_each_entry(dt, &ddebug_tables, link) {
/* match against the module name */
@@ -460,7 +537,8 @@ static int ddebug_change(const struct ddebug_query *query,
nfound++;
nctrl.flags = (get_flags(dp) & modifiers->mask) | modifiers->flags;
- if (!memcmp(&nctrl, get_ctrl(dp), sizeof(struct dd_ctrl)))
+ nctrl.trace_dst = modifiers->trace_dst;
+ if (!memcmp(&nctrl, get_ctrl(dp), sizeof(nctrl)))
continue;
#ifdef CONFIG_JUMP_LABEL
if (get_flags(dp) & _DPRINTK_FLAGS_ENABLED) {
@@ -473,13 +551,12 @@ static int ddebug_change(const struct ddebug_query *query,
v4pr_info("changed %s:%d [%s]%s %s => %s\n",
trim_prefix(dp->filename), dp->lineno,
dt->mod_name, dp->function,
- ddebug_describe_flags(get_flags(dp), &fbuf),
- ddebug_describe_flags(nctrl.flags, &nbuf));
+ ddebug_describe_ctrl(&dp->ctrl, &cbuf),
+ ddebug_describe_ctrl(&nctrl, &nbuf));
update_tr_dst(dp, &nctrl);
set_ctrl(dp, &nctrl);
}
}
- mutex_unlock(&ddebug_lock);
if (!nfound && verbose)
pr_info("no matches for query\n");
@@ -700,6 +777,7 @@ static int ddebug_parse_query(char *words[], int nwords,
*/
static int ddebug_parse_flags(const char *str, struct flag_settings *modifiers)
{
+ read_flag_args_f read_args;
int op, i;
switch (*str) {
@@ -718,6 +796,12 @@ static int ddebug_parse_flags(const char *str, struct flag_settings *modifiers)
for (i = ARRAY_SIZE(opt_array) - 1; i >= 0; i--) {
if (*str == opt_array[i].opt_char) {
modifiers->flags |= opt_array[i].flag;
+ read_args = opt_array[i].read_args;
+ if (read_args) {
+ str = read_args(str, modifiers);
+ if (!str)
+ return -EINVAL;
+ }
break;
}
}
@@ -726,7 +810,7 @@ static int ddebug_parse_flags(const char *str, struct flag_settings *modifiers)
return -EINVAL;
}
}
- v3pr_info("flags=0x%x\n", modifiers->flags);
+ v3pr_info("flags=0x%x, trace_dest=0x%x\n", modifiers->flags, modifiers->trace_dst);
/* calculate final flags, mask based upon op */
switch (op) {
@@ -765,20 +849,38 @@ static int ddebug_exec_query(char *query_string, const char *modname)
if (is_dd_trace_cmd(words[0]))
return ddebug_parse_cmd(words, nwords-1);
- /* check flags 1st (last arg) so query is pairs of spec,val */
- if (ddebug_parse_flags(words[nwords-1], &modifiers)) {
- pr_err("flags parse failed\n");
- return -EINVAL;
- }
if (ddebug_parse_query(words, nwords-1, &query, modname)) {
pr_err("query parse failed\n");
return -EINVAL;
}
+
+ /*
+ * Both ddebug_parse_flags and ddebug_change have to be run
+ * with locking because ddebug_parse_flags->read_T_args verifies
+ * if a requested trace instance is opened. Next ddebug_change
+ * sets the requested trace instance as output for debug logs of
+ * callsite(s) which matched a query. Because ddebug_proc_write
+ * function can be called concurrently then without locking we
+ * could for example run into a scenario where ddebug_change uses
+ * a trace instance which is already closed.
+ */
+ mutex_lock(&ddebug_lock);
+
+ /* check flags 1st (last arg) so query is pairs of spec,val */
+ if (ddebug_parse_flags(words[nwords-1], &modifiers)) {
+ pr_err("flags parse failed\n");
+ goto err;
+ }
+
/* actually go and implement the change */
nfound = ddebug_change(&query, &modifiers);
- vpr_info_dq(&query, nfound ? "applied" : "no-match");
+ mutex_unlock(&ddebug_lock);
+ vpr_info_dq(&query, nfound ? "applied" : "no-match");
return nfound;
+err:
+ mutex_unlock(&ddebug_lock);
+ return -EINVAL;
}
/* handle multiple queries in query string, continue on error, return
@@ -1468,7 +1570,7 @@ static int ddebug_proc_show(struct seq_file *m, void *p)
{
struct ddebug_iter *iter = m->private;
struct _ddebug *dp = p;
- struct flagsbuf flags;
+ struct ctrlbuf cbuf;
char const *class;
if (p == SEQ_START_TOKEN) {
@@ -1480,7 +1582,7 @@ static int ddebug_proc_show(struct seq_file *m, void *p)
seq_printf(m, "%s:%u [%s]%s =%s \"",
trim_prefix(dp->filename), dp->lineno,
iter->table->mod_name, dp->function,
- ddebug_describe_flags(get_flags(dp), &flags));
+ ddebug_describe_ctrl(&dp->ctrl, &cbuf));
seq_escape_str(m, dp->format, ESCAPE_SPACE, "\t\r\n\"");
seq_puts(m, "\"");
--
2.43.0.472.g3155946c3a-goog
Instead of repeating trace destination name explicitly for each
command (e.g. +T:thunderbolt), this change saves previously used
trace destination provided to [=+-]T as default and consecutive
commands which don't provide trace destination explicitly will
usa the saved trace destination.
Signed-off-by: Łukasz Bartosik <[email protected]>
---
lib/dynamic_debug.c | 94 +++++++++++++++++++++++++++++++++++++--------
1 file changed, 77 insertions(+), 17 deletions(-)
diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
index 6c3b83bce18d..99ab5756f0ed 100644
--- a/lib/dynamic_debug.c
+++ b/lib/dynamic_debug.c
@@ -72,7 +72,7 @@ struct ddebug_iter {
struct flag_settings {
unsigned int flags;
unsigned int mask;
- unsigned int trace_dst;
+ int trace_dst;
};
#define DD_OPEN_CMD "open"
@@ -99,6 +99,10 @@ struct dd_tracebuf_tbl_info {
struct dd_private_tracebuf buf[TRACE_DST_LAST];
DECLARE_BITMAP(bmap, TRACE_DST_LAST);
int bmap_size;
+#define DST_NOT_SET (-1)
+#define DST_TR_EVENT 0
+#define DST_NOT_SET_STR "not set"
+ int default_dst;
};
static DEFINE_MUTEX(ddebug_lock);
@@ -109,7 +113,8 @@ MODULE_PARM_DESC(verbose, " dynamic_debug/control processing "
"( 0 = off (default), 1 = module add/rm, 2 = >control summary, 3 = parsing, 4 = per-site changes)");
static struct
-dd_tracebuf_tbl_info trc_tbl = { .bmap_size = TRACE_DST_LAST };
+dd_tracebuf_tbl_info trc_tbl = { .bmap_size = TRACE_DST_LAST,
+ .default_dst = DST_NOT_SET, };
static inline struct dd_ctrl *get_ctrl(struct _ddebug *desc)
{
@@ -131,6 +136,11 @@ static inline unsigned int get_trace_dst(const struct _ddebug *desc)
return desc->ctrl.trace_dst;
}
+static inline bool has_tr_default_dst(void)
+{
+ return trc_tbl.default_dst != DST_NOT_SET;
+}
+
static int find_tr_instance(const char *name)
{
int idx = 1;
@@ -145,11 +155,16 @@ static int find_tr_instance(const char *name)
static const
char *read_T_args(const char *str, struct flag_settings *modifiers)
{
- int len, idx = 0;
- char *end;
+ bool has_colon = *(str+1) == ':' ? true : false;
+ int len = 0, idx = DST_TR_EVENT;
+ char *end = NULL;
- if (*(str+1) != ':')
- return str;
+ if (!has_colon) {
+ if (!has_tr_default_dst())
+ return NULL;
+ idx = trc_tbl.default_dst;
+ goto end;
+ }
str += 2;
end = strchr(str, '.');
@@ -168,8 +183,12 @@ char *read_T_args(const char *str, struct flag_settings *modifiers)
goto end;
idx = find_tr_instance(str);
- if (idx < 0)
- return NULL;
+ if (idx < 0) {
+ if (!has_tr_default_dst() ||
+ has_colon)
+ return NULL;
+ idx = trc_tbl.default_dst;
+ }
end:
modifiers->trace_dst = idx;
return end ? end : str + len;
@@ -389,6 +408,13 @@ static int handle_trace_close_cmd(const char *arg)
goto end;
}
+ /*
+ * check if default trace instance is being closed,
+ * if yes then clear default destination
+ */
+ if (trc_tbl.default_dst == idx)
+ trc_tbl.default_dst = DST_NOT_SET;
+
trace_array_put(buf->arr);
/*
* don't destroy trace instance but let user do it manually
@@ -427,6 +453,30 @@ void update_tr_dst(const struct _ddebug *desc, const struct dd_ctrl *nctrl)
trc_tbl.buf[ndst].use_cnt++;
}
+static const char *get_tr_default_dst_str(void)
+{
+ switch (trc_tbl.default_dst) {
+ case DST_NOT_SET:
+ return DST_NOT_SET_STR;
+ case DST_TR_EVENT:
+ return DD_TR_EVENT;
+ default:
+ return trc_tbl.buf[trc_tbl.default_dst].name;
+ }
+}
+
+static void update_tr_default_dst(const struct flag_settings *modifiers)
+{
+ int dst = modifiers->trace_dst;
+
+ if (dst == DST_NOT_SET || dst == trc_tbl.default_dst)
+ return;
+
+ trc_tbl.default_dst = dst;
+ v3pr_info("set default trace dst to idx=%d, name=%s\n", dst,
+ get_tr_default_dst_str());
+}
+
static int ddebug_parse_cmd(char *words[], int nwords)
{
if (nwords != 1)
@@ -537,7 +587,8 @@ static int ddebug_change(const struct ddebug_query *query,
nfound++;
nctrl.flags = (get_flags(dp) & modifiers->mask) | modifiers->flags;
- nctrl.trace_dst = modifiers->trace_dst;
+ nctrl.trace_dst = modifiers->trace_dst == DST_NOT_SET ?
+ get_trace_dst(dp) : modifiers->trace_dst;
if (!memcmp(&nctrl, get_ctrl(dp), sizeof(nctrl)))
continue;
#ifdef CONFIG_JUMP_LABEL
@@ -561,6 +612,9 @@ static int ddebug_change(const struct ddebug_query *query,
if (!nfound && verbose)
pr_info("no matches for query\n");
+ if (nfound)
+ update_tr_default_dst(modifiers);
+
return nfound;
}
@@ -833,7 +887,7 @@ static int ddebug_parse_flags(const char *str, struct flag_settings *modifiers)
static int ddebug_exec_query(char *query_string, const char *modname)
{
- struct flag_settings modifiers = {};
+ struct flag_settings modifiers = { .trace_dst = DST_NOT_SET };
struct ddebug_query query = {};
#define MAXWORDS 9
int nwords, nfound;
@@ -1595,15 +1649,21 @@ static int ddebug_proc_show(struct seq_file *m, void *p)
}
seq_puts(m, "\n");
- if (ddebug_iter_is_last(iter) &&
- !bitmap_empty(trc_tbl.bmap, trc_tbl.bmap_size)) {
- int idx = 1;
+ if (ddebug_iter_is_last(iter)) {
seq_puts(m, "\n");
- seq_puts(m, "#: Opened trace instances:");
- for_each_set_bit_from(idx, trc_tbl.bmap, trc_tbl.bmap_size)
- seq_printf(m, " %s", trc_tbl.buf[idx].name);
- seq_puts(m, "\n");
+ seq_printf(m, "#: Default trace destination: %s\n",
+ get_tr_default_dst_str());
+
+ if (!bitmap_empty(trc_tbl.bmap, trc_tbl.bmap_size)) {
+ int idx = 1;
+
+ seq_puts(m, "\n");
+ seq_puts(m, "#: Opened trace instances:");
+ for_each_set_bit_from(idx, trc_tbl.bmap, trc_tbl.bmap_size)
+ seq_printf(m, " %s", trc_tbl.buf[idx].name);
+ seq_puts(m, "\n");
+ }
}
return 0;
--
2.43.0.472.g3155946c3a-goog
When trace is enabled (T flag is set) and trace destination
field value is in range [1..63] (value 0 is reserved for
writing debug logs to trace prdbg and devdbg events) then
debug logs will be written to trace instance whose name is
stored in buf[trace destination].name, e.g. when trace
destination value is 2 and buf[2].name is set to tbt then
debug logs will be written to <debugfs>/tracing/instances/tbt.
Before using trace instance as a destination for writing debug
logs it has to be explicitly opened with open command.
Signed-off-by: Łukasz Bartosik <[email protected]>
---
lib/dynamic_debug.c | 28 ++++++++++++++++++++++++----
1 file changed, 24 insertions(+), 4 deletions(-)
diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
index 99ab5756f0ed..c382ea5dea19 100644
--- a/lib/dynamic_debug.c
+++ b/lib/dynamic_debug.c
@@ -1256,8 +1256,8 @@ static DEFINE_PER_CPU(struct ddebug_trace_bufs, ddebug_trace_bufs);
static DEFINE_PER_CPU(int, ddebug_trace_reserve);
__printf(3, 0)
-static void ddebug_trace(struct _ddebug *desc, const struct device *dev,
- const char *fmt, va_list args)
+static void ddebug_trace_event(struct _ddebug *desc, const struct device *dev,
+ const char *fmt, va_list args)
{
struct ddebug_trace_buf *buf;
int bufidx;
@@ -1288,6 +1288,18 @@ static void ddebug_trace(struct _ddebug *desc, const struct device *dev,
preempt_enable_notrace();
}
+__printf(2, 0)
+static void ddebug_trace_instance(struct _ddebug *desc, const char *fmt,
+ va_list *args)
+{
+ struct va_format vaf = { .fmt = fmt, .va = args};
+ struct trace_array *arr = trc_tbl.buf[get_trace_dst(desc)].arr;
+
+ WARN_ON_ONCE(!arr);
+
+ trace_array_printk(arr, 0, "%pV", &vaf);
+}
+
__printf(2, 3)
static void ddebug_printk(struct _ddebug *desc, const char *fmt, ...)
{
@@ -1300,7 +1312,12 @@ static void ddebug_printk(struct _ddebug *desc, const char *fmt, ...)
* All callers include the KERN_DEBUG prefix to keep the
* vprintk case simple; strip it out for tracing.
*/
- ddebug_trace(desc, NULL, fmt + strlen(KERN_DEBUG), args);
+ if (!get_trace_dst(desc))
+ ddebug_trace_event(desc, NULL,
+ fmt + strlen(KERN_DEBUG), args);
+ else
+ ddebug_trace_instance(desc, fmt + strlen(KERN_DEBUG),
+ &args);
va_end(args);
}
@@ -1322,7 +1339,10 @@ static void ddebug_dev_printk(struct _ddebug *desc, const struct device *dev,
va_list args;
va_start(args, fmt);
- ddebug_trace(desc, dev, fmt, args);
+ if (!get_trace_dst(desc))
+ ddebug_trace_event(desc, dev, fmt, args);
+ else
+ ddebug_trace_instance(desc, fmt, &args);
va_end(args);
}
--
2.43.0.472.g3155946c3a-goog
Add support for writing hex_dump debug logs to trace.
Signed-off-by: Łukasz Bartosik <[email protected]>
Signed-off-by: Jim Cromie <[email protected]>
---
include/linux/dynamic_debug.h | 16 ++++++++++------
lib/dynamic_debug.c | 36 +++++++++++++++++++++++++++++++++++
2 files changed, 46 insertions(+), 6 deletions(-)
diff --git a/include/linux/dynamic_debug.h b/include/linux/dynamic_debug.h
index dc10c7535f13..76eec3f05be9 100644
--- a/include/linux/dynamic_debug.h
+++ b/include/linux/dynamic_debug.h
@@ -298,12 +298,16 @@ void __dynamic_ibdev_dbg(struct _ddebug *descriptor,
_dynamic_func_call(fmt, __dynamic_ibdev_dbg, \
dev, fmt, ##__VA_ARGS__)
-#define dynamic_hex_dump(prefix_str, prefix_type, rowsize, \
- groupsize, buf, len, ascii) \
- _dynamic_func_call_no_desc(__builtin_constant_p(prefix_str) ? prefix_str : "hexdump", \
- print_hex_dump, \
- KERN_DEBUG, prefix_str, prefix_type, \
- rowsize, groupsize, buf, len, ascii)
+void _print_hex_dump(struct _ddebug *descriptor, const char *level,
+ const char *prefix_str, int prefix_type, int rowsize,
+ int groupsize, const void *buf, size_t len, bool ascii);
+
+#define dynamic_hex_dump(prefix_str, prefix_type, rowsize, \
+ groupsize, buf, len, ascii) \
+ _dynamic_func_call(__builtin_constant_p(prefix_str) ? prefix_str : "hexdump", \
+ _print_hex_dump, \
+ KERN_DEBUG, prefix_str, prefix_type, \
+ rowsize, groupsize, buf, len, ascii)
/* for test only, generally expect drm.debug style macro wrappers */
#define __pr_debug_cls(cls, fmt, ...) do { \
diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
index c382ea5dea19..65dafdec7b76 100644
--- a/lib/dynamic_debug.c
+++ b/lib/dynamic_debug.c
@@ -1355,6 +1355,42 @@ static void ddebug_dev_printk(struct _ddebug *desc, const struct device *dev,
}
}
+void _print_hex_dump(struct _ddebug *descriptor, const char *level,
+ const char *prefix_str, int prefix_type, int rowsize,
+ int groupsize, const void *buf, size_t len, bool ascii)
+{
+ const u8 *ptr = buf;
+ int i, linelen, remaining = len;
+ unsigned char linebuf[32 * 3 + 2 + 32 + 1];
+
+ if (rowsize != 16 && rowsize != 32)
+ rowsize = 16;
+
+ for (i = 0; i < len; i += rowsize) {
+ linelen = min(remaining, rowsize);
+ remaining -= rowsize;
+
+ hex_dump_to_buffer(ptr + i, linelen, rowsize, groupsize,
+ linebuf, sizeof(linebuf), ascii);
+
+ switch (prefix_type) {
+ case DUMP_PREFIX_ADDRESS:
+ ddebug_printk(descriptor, KERN_DEBUG "%s%s%p: %s\n",
+ level, prefix_str, ptr + i, linebuf);
+ break;
+ case DUMP_PREFIX_OFFSET:
+ ddebug_printk(descriptor, KERN_DEBUG "%s%s%.8x: %s\n",
+ level, prefix_str, i, linebuf);
+ break;
+ default:
+ ddebug_printk(descriptor, KERN_DEBUG "%s%s%s\n",
+ level, prefix_str, linebuf);
+ break;
+ }
+ }
+}
+EXPORT_SYMBOL(_print_hex_dump);
+
void __dynamic_pr_debug(struct _ddebug *descriptor, const char *fmt, ...)
{
va_list args;
--
2.43.0.472.g3155946c3a-goog
From: Jim Cromie <[email protected]>
When debugging a query parsing error, the debug message wraps the
query in escaped-double-quotes. This is confusing when mixed with any
quoted args where quotes are stripped by the shell.
So this replaces the \"%s\" with <%s> in the format string, allowing a
user to see how the shell strips quotes:
lx]# echo module "foo" format ,_ -f > /proc/dynamic_debug/control
[ 716.037430] dyndbg: read 26 bytes from userspace
[ 716.037966] dyndbg: query 0: <module foo format ,_ -f> on module: <*>
Signed-off-by: Jim Cromie <[email protected]>
---
lib/dynamic_debug.c | 2 +-
1 file changed, 1 insertion(+), 1 deletion(-)
diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
index 65dafdec7b76..8ce485fc84ff 100644
--- a/lib/dynamic_debug.c
+++ b/lib/dynamic_debug.c
@@ -955,7 +955,7 @@ static int ddebug_exec_queries(char *query, const char *modname)
if (!query || !*query || *query == '#')
continue;
- vpr_info("query %d: \"%s\" mod:%s\n", i, query, modname ?: "*");
+ vpr_info("query %d: <%s> on module: <%s>\n", i, query, modname ?: "*");
rc = ddebug_exec_query(query, modname);
if (rc < 0) {
--
2.43.0.472.g3155946c3a-goog
From: Jim Cromie <[email protected]>
Fix a BUG_ON from 2009. I have hit it while fuzzing >control on some
other patches, and panic from user input is bad. Replace the BUG_ON
with pr_error and return -EINVAL.
Signed-off-by: Jim Cromie <[email protected]>
---
lib/dynamic_debug.c | 6 +++++-
1 file changed, 5 insertions(+), 1 deletion(-)
diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
index 8ce485fc84ff..d4e50e4f6635 100644
--- a/lib/dynamic_debug.c
+++ b/lib/dynamic_debug.c
@@ -650,7 +650,11 @@ static int ddebug_tokenize(char *buf, char *words[], int maxwords)
} else {
for (end = buf; *end && !isspace(*end); end++)
;
- BUG_ON(end == buf);
+ if (end == buf) {
+ pr_err("parse err after word:%d=%s\n", nwords,
+ nwords ? words[nwords - 1] : "<none>");
+ return -EINVAL;
+ }
}
/* `buf' is start of word, `end' is one past its end */
--
2.43.0.472.g3155946c3a-goog
From: Jim Cromie <[email protected]>
The function skip_spaces_and_coma removes leading
spaces and coma. With this approach a user can
provide dynamic debug control commands in new format.
For example the following command (existing format)
modprobe test_dynamic_debug dyndbg="class D2_CORE +p"
can also be provided as (new format):
modprobe test_dynamic_debug dyndbg=class,D2_CORE,+p
Signed-off-by: Jim Cromie <[email protected]>
Signed-off-by: Łukasz Bartosik <[email protected]>
---
lib/dynamic_debug.c | 14 +++++++++++---
1 file changed, 11 insertions(+), 3 deletions(-)
diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
index 70d9440193a8..48ce24c39457 100644
--- a/lib/dynamic_debug.c
+++ b/lib/dynamic_debug.c
@@ -618,6 +618,14 @@ static int ddebug_change(const struct ddebug_query *query,
return nfound;
}
+char *skip_spaces_and_coma(const char *str)
+{
+ str = skip_spaces(str);
+ if (*str == ',')
+ str = skip_spaces(++str);
+ return (char *)str;
+}
+
/*
* Split the buffer `buf' into space-separated words.
* Handles simple " and ' quoting, i.e. without nested,
@@ -631,8 +639,8 @@ static int ddebug_tokenize(char *buf, char *words[], int maxwords)
while (*buf) {
char *end;
- /* Skip leading whitespace */
- buf = skip_spaces(buf);
+ /* Skip leading whitespace and coma */
+ buf = skip_spaces_and_coma(buf);
if (!*buf)
break; /* oh, it was trailing whitespace */
if (*buf == '#')
@@ -959,7 +967,7 @@ static int ddebug_exec_queries(char *query, const char *modname)
if (split)
*split++ = '\0';
- query = skip_spaces(query);
+ query = skip_spaces_and_coma(query);
if (!query || !*query || *query == '#')
continue;
--
2.43.0.472.g3155946c3a-goog
From: Jim Cromie <[email protected]>
If ddebug_parse_flags() rejects user input, identify that input value
in the error message.
Signed-off-by: Jim Cromie <[email protected]>
---
lib/dynamic_debug.c | 2 +-
1 file changed, 1 insertion(+), 1 deletion(-)
diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
index 4718e8faa719..d834581c785b 100644
--- a/lib/dynamic_debug.c
+++ b/lib/dynamic_debug.c
@@ -936,7 +936,7 @@ static int ddebug_exec_query(char *query_string, const char *modname)
/* check flags 1st (last arg) so query is pairs of spec,val */
if (ddebug_parse_flags(words[nwords-1], &modifiers)) {
- pr_err("flags parse failed\n");
+ pr_err("flags parse failed on word-%d: %s\n", nwords-1, words[nwords-1]);
goto err;
}
--
2.43.0.472.g3155946c3a-goog
From: Jim Cromie <[email protected]>
Treat comma as a token terminator, just like a space. This allows a
user to avoid quoting hassles when spaces are otherwise needed:
:#> modprobe drm dyndbg=class,DRM_UT_CORE,+p\;class,DRM_UT_KMS,+p
or as a boot arg:
drm.dyndbg=class,DRM_UT_CORE,+p # todo: support multi-query here
Given the myriad ways a boot-line can be assembled and then passed
in/down/around shell based tools, if the >control parser treats commas
like spacees, this would allow side-stepping all sorts of quoting
hassles thru those layers.
Signed-off-by: Jim Cromie <[email protected]>
---
lib/dynamic_debug.c | 6 +++++-
1 file changed, 5 insertions(+), 1 deletion(-)
diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
index d4e50e4f6635..70d9440193a8 100644
--- a/lib/dynamic_debug.c
+++ b/lib/dynamic_debug.c
@@ -637,6 +637,10 @@ static int ddebug_tokenize(char *buf, char *words[], int maxwords)
break; /* oh, it was trailing whitespace */
if (*buf == '#')
break; /* token starts comment, skip rest of line */
+ if (*buf == ',') {
+ buf++;
+ continue;
+ }
/* find `end' of word, whitespace separated or quoted */
if (*buf == '"' || *buf == '\'') {
@@ -648,7 +652,7 @@ static int ddebug_tokenize(char *buf, char *words[], int maxwords)
return -EINVAL; /* unclosed quote */
}
} else {
- for (end = buf; *end && !isspace(*end); end++)
+ for (end = buf; *end && !isspace(*end) && *end != ','; end++)
;
if (end == buf) {
pr_err("parse err after word:%d=%s\n", nwords,
--
2.43.0.472.g3155946c3a-goog
From: Jim Cromie <[email protected]>
currently, for verbose=3, these are logged for each query
dyndbg: query 0: <class DRM_UT_CORE +p> mod: <*>
dyndbg: split into words: "class" "DRM_UT_CORE" "+p"
dyndbg: op='+'
dyndbg: flags=0x1
dyndbg: *flagsp=0x1 *maskp=0xffffffff
dyndbg: parsed: func="" file="" module="" format="" lineno=0-0 class=...
dyndbg: no matches for query
dyndbg: no-match: func="" file="" module="" format="" lineno=0-0 class=...
dyndbg: processed 1 queries, with 0 matches, 0 errs
That is excessive, so this patch shrinks it to 4 lines:
dyndbg: query 0: <class D2_CORE +T:foo > on module: <*>
dyndbg: split into words: "class" "D2_CORE" "+T:foo"
dyndbg: op='+' flags=0x40 maskp=0xffffffff trace_dest=0x0
dyndbg: applied: func="" file="" module="" format="" lineno=0-0 class=...
Signed-off-by: Jim Cromie <[email protected]>
---
lib/dynamic_debug.c | 6 ++----
1 file changed, 2 insertions(+), 4 deletions(-)
diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
index 453eab7092dc..4718e8faa719 100644
--- a/lib/dynamic_debug.c
+++ b/lib/dynamic_debug.c
@@ -835,7 +835,6 @@ static int ddebug_parse_query(char *words[], int nwords,
*/
query->module = modname;
- vpr_info_dq(query, "parsed");
return 0;
}
@@ -860,7 +859,6 @@ static int ddebug_parse_flags(const char *str, struct flag_settings *modifiers)
pr_err("bad flag-op %c, at start of %s\n", *str, str);
return -EINVAL;
}
- v3pr_info("op='%c'\n", op);
for (; *str ; ++str) {
for (i = ARRAY_SIZE(opt_array) - 1; i >= 0; i--) {
@@ -880,7 +878,6 @@ static int ddebug_parse_flags(const char *str, struct flag_settings *modifiers)
return -EINVAL;
}
}
- v3pr_info("flags=0x%x, trace_dest=0x%x\n", modifiers->flags, modifiers->trace_dst);
/* calculate final flags, mask based upon op */
switch (op) {
@@ -896,7 +893,8 @@ static int ddebug_parse_flags(const char *str, struct flag_settings *modifiers)
modifiers->flags = 0;
break;
}
- v3pr_info("*flagsp=0x%x *maskp=0x%x\n", modifiers->flags, modifiers->mask);
+ v3pr_info("op='%c' flags=0x%x maskp=0x%x trace_dest=0x%x\n",
+ op, modifiers->flags, modifiers->mask, modifiers->trace_dst);
return 0;
}
--
2.43.0.472.g3155946c3a-goog
From: Jim Cromie <[email protected]>
Multi-query strings have long allowed:
modprobe drm dyndbg="class DRM_UT_CORE +p; class DRM_UT_KMS +p"
modprobe drm dyndbg=<<EOX
class DRM_UT_CORE +pmf
class DRM_UT_KMS +pmf
EOX
More recently, the need for quoting was avoided by treating a comma
like a space/token-terminator:
modprobe drm dyndbg=class,DRM_UT_CORE,+p\;class,DRM_UT_KMS,+p
But that leaves unfinished business; that semi-colon needs escaping,
and thats not robust to further string interpolation. In particular,
it fails when passed to vng (virtme-ng).
So this patch adds '%' to the existing ';' and '\n' multi-cmd
separators, which is more shell-friendly, and avoids quoting and
escaping hassles.
modprobe drm dyndbg=class,DRM_UT_CORE,+p%class,DRM_UT_KMS,+p
NOTE: it does alter/break this (ill conceived) search:
[root@v6 lx]# ddcmd format %s +p
[ 38.170998] dyndbg: read 13 bytes from userspace
[ 38.171542] dyndbg: query 0: <format > on module: <*>
[ 38.172011] dyndbg: bad flag-op f, at start of format
[ 38.172487] dyndbg: flags parse failed
[ 38.172839] dyndbg: query 1: <s +p> on module: <*>
[ 38.173285] dyndbg: expecting pairs of match-spec <value>
[ 38.173791] dyndbg: query parse failed
[ 38.174141] dyndbg: processed 2 queries, with 0 matches, 2 errs
bash: echo: write error: Invalid argument
In trade for that minor format selection limitation, we get to do:
vng -v --user root -p 4 \
-a dynamic_debug.verbose=3 \
-a drm.debug=0x15 \
-a i915.dyndbg=class,DRM_UT_CORE,+pfmlt_%class,DRM_UT_KMS,+pfml
modprobe drm
modprobe i915
NOTES/TLDR:
In this example, using both drm.debug & drm.dyndbg is mostly for
testing. Using drm.debug is preferred, because the drivers all
explicitly depend on that input/control-point, so settings there are
propagated to drivers.
But more to the point, drm.dyndbg explicitly limits the query to drm.
In fact, you could pass a module wildcard in the above, and achieve
the same thing:
vng -v --user root -p 4 \
-a dynamic_debug.verbose=3 \
-a \*.dyndbg=class,DRM_UT_CORE,+pfmlt_%class,DRM_UT_KMS,+pfm%class, \
DRM_UT_ATOMIC,+pf
':' would be a more natural multi-cmd separator, but is reserved
for +T:<trace_buf> to designate separate tracebuf instances.
If '%' is distasteful, the backup plan is ",_,", since that would
never appear in a useful <format "$foo"> cmd.
Signed-off-by: Jim Cromie <[email protected]>
---
lib/dynamic_debug.c | 2 +-
1 file changed, 1 insertion(+), 1 deletion(-)
diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
index 48ce24c39457..453eab7092dc 100644
--- a/lib/dynamic_debug.c
+++ b/lib/dynamic_debug.c
@@ -963,7 +963,7 @@ static int ddebug_exec_queries(char *query, const char *modname)
int i, errs = 0, exitcode = 0, rc, nfound = 0;
for (i = 0; query; query = split) {
- split = strpbrk(query, ";\n");
+ split = strpbrk(query, "%;\n");
if (split)
*split++ = '\0';
--
2.43.0.472.g3155946c3a-goog
re-adding gregkh, who fell off the cc's again.
he is one of our upstreams.
On Fri, Dec 22, 2023 at 6:51 PM Łukasz Bartosik <[email protected]> wrote:
>
> Add support for writing debug logs to trace events and trace instances.
> The rationale behing this feature is to be able to redirect debug logs
> (per each callsite individually) to trace to aid in debugging. The debug
> logs output to trace can be enabled with T flag. Additionally the T flag
> accepts trace destination which can be provided to the T flag after ":".
> The trace destination field is used to determine where debug logs will be
> written.
>
> In order to redirect callsite debug log to a trace instance it has to be
> initialized first with a newly introduced "open" command. For example,
> "usb" trace instance in <debugfs>/tracing/instances/ can be initialized
> by issuing the command:
>
> localhost ~ # echo "open usb" >
> <debugfs>/dynamic_debug/control
>
> If the trace instance <debugfs>/tracing/instances/usb already exists
> then it will be reused otherwise new usbcore instance will be created.
> Maximum 63 trace instances can be "opened". The trace instance name can
> include any of ^\w+ and underscore characters. There is also a special
> name "0" reserved for writing debug logs to trace prdbg and devdbg events.
> The reserved name "0" does not require to be "opened" before use.
theres implication here that p only works when :0.
Is that intended ?
it seems wrong, or at least unnecessary.
In fact, theres no specific reason to exclude +p:trcbuf.mf,
esp if we keep default-trace-buf
since +pTfml could have that meaning implicitly.
We can call it allowed and "unimplemented until proven useful" on +p
+p completely independent of +T is a simplicity,
lets keep that until proven useful otherwise.
>
> To enable writing usbcore module debug logs to the "usb" trace instance
> opened above a user can issue the command:
>
> localhost ~ # echo "module usbcore =pT:usb" >
> <debugfs>/dynamic_debug/control
>
> Please note that output of debug logs to syslog (p flag) and trace (T flag)
> can be independently enabled/disabled for each callsite. Therefore the
> above command will enable writing of debug logs not only to the trace
> instance "usb" but also to syslog.
>
> When trace destination is followed by another flag the next flag has to
> be preeceded with ".", for example
>
> localhost ~ # echo "module usbcore =pT:usb.l" >
> <debugfs>/dynamic_debug/control
>
> To simplify processing trace destination can be omitted when default
> trace destination is set, for example the command
>
> localhost ~ # echo "module usbcore =pTl" >
> <debugfs>/dynamic_debug/control
>
> will use default trace destination. If default trace destination is not
> set the above command will fail. The default trace destination is set
> when a command with any of the flags [-+=] and explicitly provided trace
> destination matches at least one callsite, for example the command
>
> localhost ~ # echo "module usbcore -T:usb" >
> <debugfs>/dynamic_debug/control
>
> will disable trace for all usbcore module callsites (if any was enabled)
> and will set "usb" instance as default trace destination. To enable writing
> thunderbolt module debug logs to the "usb" trace instance as well a user
> can issue the command:
>
> localhost ~ # echo "module thunderbolt =T" >
> <debugfs>/dynamic_debug/control
>
> Since default trace destination was previously set therefore "usb" instance
> name does not have to be explicitly provided.
>
> When no callsite writes debug logs to a trace instance then it can be
> released (its reference counter decrased) with the "close" command.
decreased
> Closing a trace instance make it unavailable for dynamic debug and also
makes
> allows a user to delete such a trace instance at convenient time later
> with rmdir command. For example when "usb" instance is not used anymore
> a user can issue the command:
>
> localhost ~ # echo "close usb" >
> <debugfs>/dynamic_debug/control
> and then to delete it with:
>
> localhost ~ # rmdir <debugfs>/tracing/instances/
>
> To enable writing usbcore module debug logs to trace dyndbg:prdbg and
> dyndbg:devdbg events user can issue the command:
>
> localhost ~ # echo "module usbcore =T:0" >
> <debugfs>/dynamic_debug/control
>
> Then dyndbg trace events can be for example captured with the command:
>
> localhost ~ # trace-cmd start -e dyndbg
>
> And displayed with the command:
>
> localhost ~ # trace-cmd show
>
is there a recipe to show private traces ? prolly worth a mention here.
>
>
> Jim, I made a few changes to the test script dd-selftest.rc you created
> and I also added new test scenarios. You can find the entire patchset
> with the test script changes on top here
> https://chromium.googlesource.com/chromiumos/third_party/kernel/+log/refs/sandbox/ukaszb/dyndbg_trace_v3
> I wonder where would be the proper place to store the test script
> (upstream, your github.com:jimc/linux.git)
> Do you have a suggestion for that ?
>
I got it (your HEAD), renamed and put it in:
tools/testing/selftests/dynamic_debug/
and copied & modified Makefile and config from ../users/
I added your SOB, that seems proper.
nice additions. and I like the colors. maybe they belong in lib.mk,
but thats 4 later.
and tweaked the modules / DUTs to *hopefully* get stable callsite counts
from the tests on them, in virtually any usable config.
DUTs: file init/main, module mm_init, and module test_dynamic_debug (a
config constraint)
The ref-counts are taken from a default virtme-ng -k config on my x86-64 box
I now pass tests up to:
[root@v6 wk-proof]# ./tools/testing/selftests/dynamic_debug/dyndbg_selftest.sh
...
# TEST_PRIVATE_TRACE_6
[ 1009.296557] dyndbg: read 3 bytes from userspace
[ 1009.296876] dyndbg: query 0: <=_> on module: <*>
[ 1009.297171] dyndbg: processed 1 queries, with 1559 matches, 0 errs
[ 1009.311621] dyndbg: read 39 bytes from userspace
[ 1009.312032] dyndbg: query 0: <open
A_bit_lengthy_trace_instance_name> on module: <*>
[ 1009.312569] dyndbg: instance is already opened
name:A_bit_lengthy_trace_instance_name
[ 1009.313063] dyndbg: processed 1 queries, with 0 matches, 1 errs
: ./tools/testing/selftests/dynamic_debug/dyndbg_selftest.sh:454
ddcmd() expected to exit with code 0
Error: 'File exists'
it seems invocation dependent
I suspect 2 possibilities:
1- invoking as shell-script, repeatedly vs vng -e script-name
(one-shot per boot)
2- virtme-ng's minimal-default config has no CONFIG_USB.
this changes post-conditions of the script, affecting preconditions
of the next run.
2 means that we should replace usbcore with some other always *builtin* module.
I chose module params, on the idea that its builtin, but also invoked later,
when modules are modprobed with params, so its callsites can be enabled &
then invoked via do_prints, to test for writes to the private trace-buf.
I've pushed it to lukas-v3.0 at jimc.github.com/linux
Would you look at err on _6, above,
and figure out if its insufficiently robust to test preconditions, or
something else ?
and also:
rename test_private_trace_N() to better names
- and/or comments to intent & pattern of use
more tweaks invited in its commit-msg
since cycle_test_problem() is not actually a problem, whats a better name ?
_not_best_practices ?
I think the final test script enhancement needed is (maybe separately):
private-buffer-expected-write-verification after do_prints,
and around modprobe test_dynamic_debug dyndbg=$multicmd
subject to 2 below.
> TODOs:
> - update dynamic debug documentation,
> - finalize discussion related to default trace destination
> (whether we want it at all, if yes then conclude on the details)
>
good list. before docs;
wrt default-trace, at least in some details, it seems extra rules to know.
for example, if the default were set on successful open,
rather than successful rule application (iirc), then it would read a lot
like "with" or "using" blocks, esp with <<EOX form
with that new form, it might be pretty expressive:
echo <<YMMV > /proc/dynamic_debug/control
open sesame # ie with
module magic_carpet function forward +Tfml
module magic_lamp function rub_vigorously +Tfmt
open voicetrace
module voice2ai function text2cmdprompt +T
module undo function oh_crap +T
YMMV
I think set-default-on-good-rule-applied is flawed:
it relies on the most complex expression in the grammar to be correct
and without spelling errors, where module unknown is
OK grammatically, but nonsense.
set-default-on-open is simpler to explain and test separately.
We should probably consider modifying the continue-looping behavior
of ddebug_exec_queries, depending upon the return-code.
open, close errors could reasonably warrant different treatment,
like terminating the mult-cmd loop prematurely on open/close errs.
Esp if we keep the set-default-on-good-rule-applied
What do you think ?
I'm inclined to reword a commit-msg or 2, drop RFC, obsolete comments etc.
I can do that in a lukas-v3.1, or as in-thread responses,
do you have a preference ?
some inline below..
> Changes:
> V3 -> V2
> - squash "dyndbg: export _print_hex_dump" with "dyndbg: add support for hex_dump output to trace",
> - squash "dyndbg: tweak pr_info format s/trace dest/trace_dest/" with "dyndbg: add processing of T(race) flag argument",
> - squash "dyndbg: change +T:name_terminator to dot" with "dyndbg: add processing of T(race) flag argument",
> - fix setting default trace destination,
> - decrease use count when callsite is being disabled as a part of module removal,
> - fix parsing of T flag argument,
> - update __get_str_strip_nl macro per Steve's comment,
> - drop commit "dyndbg: move lock,unlock into ddebug_change, drop goto" and add comment explaining why ddebug_parse_flags
> and ddebug_change have to be run in critical section,
> - add "depends on TRACING" for "DYNAMIC_DEBUG",
> - update DYNAMIC_DEBUG_BRANCH macro which is used when CONFIG_JUMP_LABEL is not set,
> - change structure name ddebug_trace_inst to dd_private_tracebuf,
> - change structure name ddebug_trace to dd_tracebuf_tbl_info,
> - rename is_ddebug_cmd to is_dd_trace_cmd,
> - rename validate_tr_name to dd_good_trace_name,
> - rename handle_tr_opend_cmd to handle_trace_opend_cmd and handle_tr_close_cmd to handle_trace_close_cmd,
> - refactor ddebug_parse_cmd,
> - add pr_err when trace_array_get_by_name or trace_array_init_printk fails in trace_array_init_printk,
> - add static prefix to show_T_args,
> - rename TRACE_DST_MAX to TRACE_DST_LAST and change its value to 64, reserve index 0 for trace events in dd_tracebuf_tbl_info (index 0 will be wasted),
> - add "#: " prefix to "Default trace destination" and "Opened trace instances" and print all opened trace instances on the same line,
>
> V2->V1
> Major rework after receiving feedback in
> https://lore.kernel.org/all/[email protected]/
>
> This includes among other things:
> - addittion of open/close commands,
> - use names instead of numbers for trace destinations,
> - change prdbg and devdbg trace events to strip newline
> on the slow path (read side),
> - change prdbg and devdbg trace events to stores actual values
> instead of pointers because if a pointer becomes invalid then
> the TP_printk call will cause a crash,
> - add support for default trace destination.
>
> V1
> Major rework after receiving feedback in
> https://lore.kernel.org/all/[email protected]/
>
> Jim Cromie (14):
> dyndbg: add _DPRINTK_FLAGS_ENABLED
> dyndbg: add _DPRINTK_FLAGS_TRACE
> dyndbg: add write events to tracefs code
> dyndbg: add 2 trace-events: prdbg, devdbg
> tracefs: add __get_str_strip_nl - RFC
> dyndbg: use __get_str_strip_nl in prdbg and devdbg
> dyndbg: repack _ddebug structure
> dyndbg: disambiguate quoting in a debug msg
> dyndbg: fix old BUG_ON in >control parser
> dyndbg: treat comma as a token separator
> dyndbg: add skip_spaces_and_coma()
probly just squash this with prev, its not separately tested,
and not worth isolating a test for it.
s/coma/comma/ otherwise.
> dyndbg: split multi-query strings with %
> dyndbg: reduce verbose/debug clutter
> dyndbg: id the bad word in parse-flags err msg
>
> Łukasz Bartosik (8):
> dyndbg: move flags field to a new structure
> dyndbg: add trace destination field to _ddebug
> dyndbg: add open and close commands for trace
> dyndbg: don't close trace instance when in use
> dyndbg: add processing of T(race) flag argument
tweak subject s/T(race)/+T:prv_trcbuf_name./ - might as well use
legal flag syntax.
> dyndbg: add support for default trace destination
> dyndbg: write debug logs to trace instance
> dyndbg: add support for hex_dump output to trace
>
> .../admin-guide/dynamic-debug-howto.rst | 5 +-
> MAINTAINERS | 1 +
> include/linux/dynamic_debug.h | 57 +-
> include/trace/events/dyndbg.h | 54 ++
> include/trace/stages/stage3_trace_output.h | 13 +
> lib/Kconfig.debug | 2 +
> lib/dynamic_debug.c | 736 ++++++++++++++++--
> 7 files changed, 775 insertions(+), 93 deletions(-)
> create mode 100644 include/trace/events/dyndbg.h
>
> --
> 2.43.0.472.g3155946c3a-goog
>
> >
> > Jim, I made a few changes to the test script dd-selftest.rc you created
> > and I also added new test scenarios. You can find the entire patchset
> > with the test script changes on top here
> > https://chromium.googlesource.com/chromiumos/third_party/kernel/+log/refs/sandbox/ukaszb/dyndbg_trace_v3
> > I wonder where would be the proper place to store the test script
> > (upstream, your github.com:jimc/linux.git)
> > Do you have a suggestion for that ?
> >
>
> I got it (your HEAD), renamed and put it in:
> tools/testing/selftests/dynamic_debug/
> and copied & modified Makefile and config from ../users/
> I added your SOB, that seems proper.
>
meh.
my select-paste of your HEAD dropped all the whitespace.
how annoying.
> nice additions. and I like the colors. maybe they belong in lib.mk,
> but thats 4 later.
>
> and tweaked the modules / DUTs to *hopefully* get stable callsite counts
> from the tests on them, in virtually any usable config.
> DUTs: file init/main, module mm_init, and module test_dynamic_debug (a
> config constraint)
> The ref-counts are taken from a default virtme-ng -k config on my x86-64 box
>
> I now pass tests up to:
>
> [root@v6 wk-proof]# ./tools/testing/selftests/dynamic_debug/dyndbg_selftest.sh
> ...
> # TEST_PRIVATE_TRACE_6
> [ 1009.296557] dyndbg: read 3 bytes from userspace
> [ 1009.296876] dyndbg: query 0: <=_> on module: <*>
> [ 1009.297171] dyndbg: processed 1 queries, with 1559 matches, 0 errs
> [ 1009.311621] dyndbg: read 39 bytes from userspace
> [ 1009.312032] dyndbg: query 0: <open
> A_bit_lengthy_trace_instance_name> on module: <*>
> [ 1009.312569] dyndbg: instance is already opened
> name:A_bit_lengthy_trace_instance_name
> [ 1009.313063] dyndbg: processed 1 queries, with 0 matches, 1 errs
> : ./tools/testing/selftests/dynamic_debug/dyndbg_selftest.sh:454
> ddcmd() expected to exit with code 0
> Error: 'File exists'
>
_7 has some obsolete counts, after previous $modname changes
śr., 27 gru 2023 o 05:23 <[email protected]> napisał(a):
>
> re-adding gregkh, who fell off the cc's again.
> he is one of our upstreams.
>
hi Jim,
It's good to hear from you.
Thanks. I missed to add Greg.
> On Fri, Dec 22, 2023 at 6:51 PM Łukasz Bartosik <[email protected]> wrote:
> >
> > Add support for writing debug logs to trace events and trace instances.
> > The rationale behing this feature is to be able to redirect debug logs
> > (per each callsite individually) to trace to aid in debugging. The debug
> > logs output to trace can be enabled with T flag. Additionally the T flag
> > accepts trace destination which can be provided to the T flag after ":".
> > The trace destination field is used to determine where debug logs will be
> > written.
> >
> > In order to redirect callsite debug log to a trace instance it has to be
> > initialized first with a newly introduced "open" command. For example,
> > "usb" trace instance in <debugfs>/tracing/instances/ can be initialized
> > by issuing the command:
> >
> > localhost ~ # echo "open usb" >
> > <debugfs>/dynamic_debug/control
> >
> > If the trace instance <debugfs>/tracing/instances/usb already exists
> > then it will be reused otherwise new usbcore instance will be created.
> > Maximum 63 trace instances can be "opened". The trace instance name can
> > include any of ^\w+ and underscore characters. There is also a special
> > name "0" reserved for writing debug logs to trace prdbg and devdbg events.
> > The reserved name "0" does not require to be "opened" before use.
>
> theres implication here that p only works when :0.
> Is that intended ?
> it seems wrong, or at least unnecessary.
>
I don't see clearly the implication that p only works when :0.
Which statement implies this to you ? Please keep in mind that English
is not my native.
> In fact, theres no specific reason to exclude +p:trcbuf.mf,
> esp if we keep default-trace-buf
> since +pTfml could have that meaning implicitly.
> We can call it allowed and "unimplemented until proven useful" on +p
>
> +p completely independent of +T is a simplicity,
> lets keep that until proven useful otherwise.
>
> >
> > To enable writing usbcore module debug logs to the "usb" trace instance
> > opened above a user can issue the command:
> >
> > localhost ~ # echo "module usbcore =pT:usb" >
> > <debugfs>/dynamic_debug/control
> >
> > Please note that output of debug logs to syslog (p flag) and trace (T flag)
> > can be independently enabled/disabled for each callsite. Therefore the
> > above command will enable writing of debug logs not only to the trace
> > instance "usb" but also to syslog.
> >
> > When trace destination is followed by another flag the next flag has to
> > be preeceded with ".", for example
> >
> > localhost ~ # echo "module usbcore =pT:usb.l" >
> > <debugfs>/dynamic_debug/control
> >
> > To simplify processing trace destination can be omitted when default
> > trace destination is set, for example the command
> >
> > localhost ~ # echo "module usbcore =pTl" >
> > <debugfs>/dynamic_debug/control
> >
> > will use default trace destination. If default trace destination is not
> > set the above command will fail. The default trace destination is set
> > when a command with any of the flags [-+=] and explicitly provided trace
> > destination matches at least one callsite, for example the command
> >
> > localhost ~ # echo "module usbcore -T:usb" >
> > <debugfs>/dynamic_debug/control
> >
> > will disable trace for all usbcore module callsites (if any was enabled)
> > and will set "usb" instance as default trace destination. To enable writing
> > thunderbolt module debug logs to the "usb" trace instance as well a user
> > can issue the command:
> >
> > localhost ~ # echo "module thunderbolt =T" >
> > <debugfs>/dynamic_debug/control
> >
> > Since default trace destination was previously set therefore "usb" instance
> > name does not have to be explicitly provided.
> >
> > When no callsite writes debug logs to a trace instance then it can be
> > released (its reference counter decrased) with the "close" command.
> decreased
>
Ack
> > Closing a trace instance make it unavailable for dynamic debug and also
> makes
Ack
> > allows a user to delete such a trace instance at convenient time later
> > with rmdir command. For example when "usb" instance is not used anymore
> > a user can issue the command:
> >
> > localhost ~ # echo "close usb" >
> > <debugfs>/dynamic_debug/control
> > and then to delete it with:
> >
> > localhost ~ # rmdir <debugfs>/tracing/instances/
> >
> > To enable writing usbcore module debug logs to trace dyndbg:prdbg and
> > dyndbg:devdbg events user can issue the command:
> >
> > localhost ~ # echo "module usbcore =T:0" >
> > <debugfs>/dynamic_debug/control
> >
> > Then dyndbg trace events can be for example captured with the command:
> >
> > localhost ~ # trace-cmd start -e dyndbg
> >
> > And displayed with the command:
> >
> > localhost ~ # trace-cmd show
> >
>
> is there a recipe to show private traces ? prolly worth a mention here.
>
Trace-cmd stat shows among other things open trace instances. I will add it.
>
> >
> >
> > Jim, I made a few changes to the test script dd-selftest.rc you created
> > and I also added new test scenarios. You can find the entire patchset
> > with the test script changes on top here
> > https://chromium.googlesource.com/chromiumos/third_party/kernel/+log/refs/sandbox/ukaszb/dyndbg_trace_v3
> > I wonder where would be the proper place to store the test script
> > (upstream, your github.com:jimc/linux.git)
> > Do you have a suggestion for that ?
> >
>
> I got it (your HEAD), renamed and put it in:
> tools/testing/selftests/dynamic_debug/
> and copied & modified Makefile and config from ../users/
> I added your SOB, that seems proper.
>
Great, thanks ;)
> nice additions. and I like the colors. maybe they belong in lib.mk,
> but thats 4 later.
>
> and tweaked the modules / DUTs to *hopefully* get stable callsite counts
> from the tests on them, in virtually any usable config.
> DUTs: file init/main, module mm_init, and module test_dynamic_debug (a
> config constraint)
> The ref-counts are taken from a default virtme-ng -k config on my x86-64 box
>
> I now pass tests up to:
>
> [root@v6 wk-proof]# ./tools/testing/selftests/dynamic_debug/dyndbg_selftest.sh
> ...
> # TEST_PRIVATE_TRACE_6
> [ 1009.296557] dyndbg: read 3 bytes from userspace
> [ 1009.296876] dyndbg: query 0: <=_> on module: <*>
> [ 1009.297171] dyndbg: processed 1 queries, with 1559 matches, 0 errs
> [ 1009.311621] dyndbg: read 39 bytes from userspace
> [ 1009.312032] dyndbg: query 0: <open
> A_bit_lengthy_trace_instance_name> on module: <*>
> [ 1009.312569] dyndbg: instance is already opened
> name:A_bit_lengthy_trace_instance_name
> [ 1009.313063] dyndbg: processed 1 queries, with 0 matches, 1 errs
> : ./tools/testing/selftests/dynamic_debug/dyndbg_selftest.sh:454
> ddcmd() expected to exit with code 0
> Error: 'File exists'
>
> it seems invocation dependent
> I suspect 2 possibilities:
> 1- invoking as shell-script, repeatedly vs vng -e script-name
> (one-shot per boot)
> 2- virtme-ng's minimal-default config has no CONFIG_USB.
> this changes post-conditions of the script, affecting preconditions
> of the next run.
>
I guess you must have enabled CONFIG_USB in your setup otherwise
dyndbg_selftest.sh should fail earlier in TEST_PRIVATE_TRACE_5 ?
> 2 means that we should replace usbcore with some other always *builtin* module.
>
Sounds good. Do you have a module candidate ?
I'm also concerned that we might need to validate dyndbg_selftest.sh
against specific kernel version because
I took the dyndbg_selftest.sh from lukas-v3.0 branch and I had to do
the following changes to make it work on kernel v6.6:
--- a/tools/testing/selftests/dynamic_debug/dyndbg_selftest.sh
+++ b/tools/testing/selftests/dynamic_debug/dyndbg_selftest.sh
@@ -166,12 +166,12 @@ EOF
function comma_terminator_tests {
echo -e "${GREEN}# COMMA_TERMINATOR_TESTS ${NC}"
# try combos of space & comma
- check_match_ct mm_init 5
+ check_match_ct mm_init 4
ddcmd module,mm_init,=_ # commas as spaces
ddcmd module,mm_init,+mpf # turn on non-classed
- check_match_ct =pmf 5
+ check_match_ct =pmf 4
ddcmd ,module ,, , mm_init, -p # extra commas & spaces
- check_match_ct =mf 5
+ check_match_ct =mf 4
ddcmd =_
}
function test_percent_splitting {
@@ -350,7 +350,7 @@ function test_private_trace_3 {
ddcmd class D2_CORE +T:foo \; class D2_KMS +T:foo
ddcmd "class,D2_CORE,+T:foo;,class,D2_KMS,+T:foo"
ddcmd class,D2_CORE,+T:foo\;class,D2_KMS,+T:foo
- check_match_ct =T 2 -v
+ check_match_ct =T 3 -v
check_match_ct =Tl 0
check_match_ct =Tmf 0
echo 1 >/sys/kernel/tracing/tracing_on
@@ -379,7 +379,7 @@ function test_private_trace_4 {
modprobe test_dynamic_debug dyndbg=class,D2_CORE,+T:foo%class,D2_KMS,+T:foo
check_match_ct =Tl 0
check_match_ct =Tmf 0
- check_match_ct =T 2
+ check_match_ct =T 3
echo 1 >/sys/kernel/tracing/tracing_on
What kernel version did you use for the testing ?
> I chose module params, on the idea that its builtin, but also invoked later,
> when modules are modprobed with params, so its callsites can be enabled &
> then invoked via do_prints, to test for writes to the private trace-buf.
>
> I've pushed it to lukas-v3.0 at jimc.github.com/linux
>
> Would you look at err on _6, above,
> and figure out if its insufficiently robust to test preconditions, or
> something else ?
The following change fixes failure in TEST_PRIVATE_TRACE_6:
@@ -455,7 +455,7 @@ function test_private_trace_6 {
ddcmd open $name
is_trace_instance_opened $name
check_trace_instance_dir $name 1
- ddcmd "module module =T:$name.l" -v
+ ddcmd "module usbcore =T:$name.l"
check_match_ct =T:A_bit_lengthy_trace....l 164
When dyndbg_selftest.sh completes with success which is announced by the line
# Done on: Thu Dec 28 23:04:17 CET 2023
then it leaves dynamic debug and trace in a state where next
dyndbg_selftest.sh run should also complete with success.
But when any of the tests fails manual intervention or reboot is
required at the moment.
Do you think we should have a cleanup function and call it whenever
dyndbg_selftest.sh fails in order
to prepare dynamic debug and trace for the next run of dyndbg_selftest.sh ?
> and also:
> rename test_private_trace_N() to better names
> - and/or comments to intent & pattern of use
> more tweaks invited in its commit-msg
>
I will rename the functions and add description of the tests.
> since cycle_test_problem() is not actually a problem, whats a better name ?
> _not_best_practices ?
>
Ack
> I think the final test script enhancement needed is (maybe separately):
> private-buffer-expected-write-verification after do_prints,
> and around modprobe test_dynamic_debug dyndbg=$multicmd
> subject to 2 below.
>
Ack
> > TODOs:
> > - update dynamic debug documentation,
> > - finalize discussion related to default trace destination
> > (whether we want it at all, if yes then conclude on the details)
> >
>
> good list. before docs;
>
> wrt default-trace, at least in some details, it seems extra rules to know.
> for example, if the default were set on successful open,
> rather than successful rule application (iirc), then it would read a lot
> like "with" or "using" blocks, esp with <<EOX form
>
> with that new form, it might be pretty expressive:
>
> echo <<YMMV > /proc/dynamic_debug/control
> open sesame # ie with
> module magic_carpet function forward +Tfml
> module magic_lamp function rub_vigorously +Tfmt
> open voicetrace
> module voice2ai function text2cmdprompt +T
> module undo function oh_crap +T
> YMMV
>
> I think set-default-on-good-rule-applied is flawed:
> it relies on the most complex expression in the grammar to be correct
> and without spelling errors, where module unknown is
> OK grammatically, but nonsense.
in case of "unknown" module default trace destination will not be
updated because
the code checks for nfound before updating default destination:
if (nfound)
update_tr_default_dst(modifiers);
> set-default-on-open is simpler to explain and test separately.
>
Actually I think we discussed set-default-on-open some time ago (in
the beginning).
But to sum up the default trace destination there were 3 directions
proposed/discussed:
- set-default-on-open,
- set-default-on-good-rule-applied,
- preset-default-per-each-callsite with -T:trace_dest_name,
All 3 pass information explicitly but IMHO
preset-default-per-each-callsite is most confusing as user would have
to remember what was preset for a given callsite when later passing a
T flag for the same callsite.
Then if it comes to set-default-on-open vs
set-default-on-good-rule-applied I don't have strong opinion but I
would
lean towards set-default-on-open because in this case it is pretty
straightforward, I mean last successful open sets default trace
destination.
If you also hesitate which one to choose maybe we should start with
very simple approach like that +T always defaults to trace events (:0)
?
> We should probably consider modifying the continue-looping behavior
> of ddebug_exec_queries, depending upon the return-code.
> open, close errors could reasonably warrant different treatment,
> like terminating the mult-cmd loop prematurely on open/close errs.
> Esp if we keep the set-default-on-good-rule-applied
> What do you think ?
>
Let's first conclude on default destination.
> I'm inclined to reword a commit-msg or 2, drop RFC, obsolete comments etc.
>
> I can do that in a lukas-v3.1, or as in-thread responses,
> do you have a preference ?
Please go ahead and make changes in the lukas-v3.1 branch. I find it
very convenient. I will just grab your changes from the branch.
> some inline below..
>
> > Changes:
> > V3 -> V2
> > - squash "dyndbg: export _print_hex_dump" with "dyndbg: add support for hex_dump output to trace",
> > - squash "dyndbg: tweak pr_info format s/trace dest/trace_dest/" with "dyndbg: add processing of T(race) flag argument",
> > - squash "dyndbg: change +T:name_terminator to dot" with "dyndbg: add processing of T(race) flag argument",
> > - fix setting default trace destination,
> > - decrease use count when callsite is being disabled as a part of module removal,
> > - fix parsing of T flag argument,
> > - update __get_str_strip_nl macro per Steve's comment,
> > - drop commit "dyndbg: move lock,unlock into ddebug_change, drop goto" and add comment explaining why ddebug_parse_flags
> > and ddebug_change have to be run in critical section,
> > - add "depends on TRACING" for "DYNAMIC_DEBUG",
> > - update DYNAMIC_DEBUG_BRANCH macro which is used when CONFIG_JUMP_LABEL is not set,
> > - change structure name ddebug_trace_inst to dd_private_tracebuf,
> > - change structure name ddebug_trace to dd_tracebuf_tbl_info,
> > - rename is_ddebug_cmd to is_dd_trace_cmd,
> > - rename validate_tr_name to dd_good_trace_name,
> > - rename handle_tr_opend_cmd to handle_trace_opend_cmd and handle_tr_close_cmd to handle_trace_close_cmd,
> > - refactor ddebug_parse_cmd,
> > - add pr_err when trace_array_get_by_name or trace_array_init_printk fails in trace_array_init_printk,
> > - add static prefix to show_T_args,
> > - rename TRACE_DST_MAX to TRACE_DST_LAST and change its value to 64, reserve index 0 for trace events in dd_tracebuf_tbl_info (index 0 will be wasted),
> > - add "#: " prefix to "Default trace destination" and "Opened trace instances" and print all opened trace instances on the same line,
> >
> > V2->V1
> > Major rework after receiving feedback in
> > https://lore.kernel.org/all/[email protected]/
> >
> > This includes among other things:
> > - addittion of open/close commands,
> > - use names instead of numbers for trace destinations,
> > - change prdbg and devdbg trace events to strip newline
> > on the slow path (read side),
> > - change prdbg and devdbg trace events to stores actual values
> > instead of pointers because if a pointer becomes invalid then
> > the TP_printk call will cause a crash,
> > - add support for default trace destination.
> >
> > V1
> > Major rework after receiving feedback in
> > https://lore.kernel.org/all/[email protected]/
> >
> > Jim Cromie (14):
> > dyndbg: add _DPRINTK_FLAGS_ENABLED
> > dyndbg: add _DPRINTK_FLAGS_TRACE
> > dyndbg: add write events to tracefs code
> > dyndbg: add 2 trace-events: prdbg, devdbg
> > tracefs: add __get_str_strip_nl - RFC
> > dyndbg: use __get_str_strip_nl in prdbg and devdbg
> > dyndbg: repack _ddebug structure
> > dyndbg: disambiguate quoting in a debug msg
> > dyndbg: fix old BUG_ON in >control parser
> > dyndbg: treat comma as a token separator
> > dyndbg: add skip_spaces_and_coma()
>
> probly just squash this with prev, its not separately tested,
> and not worth isolating a test for it.
> s/coma/comma/ otherwise.
>
I will squash it.
> > dyndbg: split multi-query strings with %
> > dyndbg: reduce verbose/debug clutter
> > dyndbg: id the bad word in parse-flags err msg
> >
> > Łukasz Bartosik (8):
> > dyndbg: move flags field to a new structure
> > dyndbg: add trace destination field to _ddebug
> > dyndbg: add open and close commands for trace
> > dyndbg: don't close trace instance when in use
> > dyndbg: add processing of T(race) flag argument
>
> tweak subject s/T(race)/+T:prv_trcbuf_name./ - might as well use
> legal flag syntax.
>
Ack
>
> > dyndbg: add support for default trace destination
> > dyndbg: write debug logs to trace instance
> > dyndbg: add support for hex_dump output to trace
> >
> > .../admin-guide/dynamic-debug-howto.rst | 5 +-
> > MAINTAINERS | 1 +
> > include/linux/dynamic_debug.h | 57 +-
> > include/trace/events/dyndbg.h | 54 ++
> > include/trace/stages/stage3_trace_output.h | 13 +
> > lib/Kconfig.debug | 2 +
> > lib/dynamic_debug.c | 736 ++++++++++++++++--
> > 7 files changed, 775 insertions(+), 93 deletions(-)
> > create mode 100644 include/trace/events/dyndbg.h
> >
> > --
> > 2.43.0.472.g3155946c3a-goog
> >
śr., 27 gru 2023 o 05:44 <[email protected]> napisał(a):
>
> > >
> > > Jim, I made a few changes to the test script dd-selftest.rc you created
> > > and I also added new test scenarios. You can find the entire patchset
> > > with the test script changes on top here
> > > https://chromium.googlesource.com/chromiumos/third_party/kernel/+log/refs/sandbox/ukaszb/dyndbg_trace_v3
> > > I wonder where would be the proper place to store the test script
> > > (upstream, your github.com:jimc/linux.git)
> > > Do you have a suggestion for that ?
> > >
> >
> > I got it (your HEAD), renamed and put it in:
> > tools/testing/selftests/dynamic_debug/
> > and copied & modified Makefile and config from ../users/
> > I added your SOB, that seems proper.
> >
>
> meh.
> my select-paste of your HEAD dropped all the whitespace.
> how annoying.
>
>
> > nice additions. and I like the colors. maybe they belong in lib.mk,
> > but thats 4 later.
> >
> > and tweaked the modules / DUTs to *hopefully* get stable callsite counts
> > from the tests on them, in virtually any usable config.
> > DUTs: file init/main, module mm_init, and module test_dynamic_debug (a
> > config constraint)
> > The ref-counts are taken from a default virtme-ng -k config on my x86-64 box
> >
> > I now pass tests up to:
> >
> > [root@v6 wk-proof]# ./tools/testing/selftests/dynamic_debug/dyndbg_selftest.sh
> > ...
> > # TEST_PRIVATE_TRACE_6
> > [ 1009.296557] dyndbg: read 3 bytes from userspace
> > [ 1009.296876] dyndbg: query 0: <=_> on module: <*>
> > [ 1009.297171] dyndbg: processed 1 queries, with 1559 matches, 0 errs
> > [ 1009.311621] dyndbg: read 39 bytes from userspace
> > [ 1009.312032] dyndbg: query 0: <open
> > A_bit_lengthy_trace_instance_name> on module: <*>
> > [ 1009.312569] dyndbg: instance is already opened
> > name:A_bit_lengthy_trace_instance_name
> > [ 1009.313063] dyndbg: processed 1 queries, with 0 matches, 1 errs
> > : ./tools/testing/selftests/dynamic_debug/dyndbg_selftest.sh:454
> > ddcmd() expected to exit with code 0
> > Error: 'File exists'
> >
>
> _7 has some obsolete counts, after previous $modname changes
Which obsolete counts are you referring to ?
Thanks,
Lukasz
ok, to catch up here,
Lukas & I have been nudging the test script forward,
some of this is settled..
On Thu, Dec 28, 2023 at 5:00 PM Łukasz Bartosik <[email protected]> wrote:
>
> śr., 27 gru 2023 o 05:23 <[email protected]> napisał(a):
> >
> > re-adding gregkh, who fell off the cc's again.
> > he is one of our upstreams.
> >
>
> hi Jim,
>
> It's good to hear from you.
>
> Thanks. I missed to add Greg.
>
> > On Fri, Dec 22, 2023 at 6:51 PM Łukasz Bartosik <[email protected]> wrote:
> > >
> > > Add support for writing debug logs to trace events and trace instances.
> > > The rationale behing this feature is to be able to redirect debug logs
> > > (per each callsite individually) to trace to aid in debugging. The debug
> > > logs output to trace can be enabled with T flag. Additionally the T flag
> > > accepts trace destination which can be provided to the T flag after ":".
> > > The trace destination field is used to determine where debug logs will be
> > > written.
> > >
> > > In order to redirect callsite debug log to a trace instance it has to be
> > > initialized first with a newly introduced "open" command. For example,
> > > "usb" trace instance in <debugfs>/tracing/instances/ can be initialized
> > > by issuing the command:
> > >
> > > localhost ~ # echo "open usb" >
> > > <debugfs>/dynamic_debug/control
> > >
> > > If the trace instance <debugfs>/tracing/instances/usb already exists
> > > then it will be reused otherwise new usbcore instance will be created.
> > > Maximum 63 trace instances can be "opened". The trace instance name can
> > > include any of ^\w+ and underscore characters. There is also a special
> > > name "0" reserved for writing debug logs to trace prdbg and devdbg events.
> > > The reserved name "0" does not require to be "opened" before use.
> >
> > theres implication here that p only works when :0.
> > Is that intended ?
> > it seems wrong, or at least unnecessary.
> >
>
> I don't see clearly the implication that p only works when :0.
> Which statement implies this to you ? Please keep in mind that English
> is not my native.
heh - Im not sure now - its mostly me probing for unseen inconsistencies.
> > In fact, theres no specific reason to exclude +p:trcbuf.mf,
> > esp if we keep default-trace-buf
> > since +pTfml could have that meaning implicitly.
> > We can call it allowed and "unimplemented until proven useful" on +p
> >
> > +p completely independent of +T is a simplicity,
> > lets keep that until proven useful otherwise.
> >
> > >
> > > To enable writing usbcore module debug logs to the "usb" trace instance
> > > opened above a user can issue the command:
> > >
> > > localhost ~ # echo "module usbcore =pT:usb" >
> > > <debugfs>/dynamic_debug/control
> > >
> > > Please note that output of debug logs to syslog (p flag) and trace (T flag)
> > > can be independently enabled/disabled for each callsite. Therefore the
> > > above command will enable writing of debug logs not only to the trace
> > > instance "usb" but also to syslog.
> > >
> > > When trace destination is followed by another flag the next flag has to
> > > be preeceded with ".", for example
> > >
> > > localhost ~ # echo "module usbcore =pT:usb.l" >
> > > <debugfs>/dynamic_debug/control
> > >
> > > To simplify processing trace destination can be omitted when default
> > > trace destination is set, for example the command
> > >
> > > localhost ~ # echo "module usbcore =pTl" >
> > > <debugfs>/dynamic_debug/control
> > >
> > > will use default trace destination. If default trace destination is not
> > > set the above command will fail. The default trace destination is set
> > > when a command with any of the flags [-+=] and explicitly provided trace
> > > destination matches at least one callsite, for example the command
> > >
> > > localhost ~ # echo "module usbcore -T:usb" >
> > > <debugfs>/dynamic_debug/control
> > >
> > > will disable trace for all usbcore module callsites (if any was enabled)
> > > and will set "usb" instance as default trace destination. To enable writing
> > > thunderbolt module debug logs to the "usb" trace instance as well a user
> > > can issue the command:
> > >
> > > localhost ~ # echo "module thunderbolt =T" >
> > > <debugfs>/dynamic_debug/control
> > >
> > > Since default trace destination was previously set therefore "usb" instance
> > > name does not have to be explicitly provided.
> > >
> > > When no callsite writes debug logs to a trace instance then it can be
> > > released (its reference counter decrased) with the "close" command.
> > decreased
> >
>
> Ack
>
> > > Closing a trace instance make it unavailable for dynamic debug and also
> > makes
>
> Ack
>
> > > allows a user to delete such a trace instance at convenient time later
> > > with rmdir command. For example when "usb" instance is not used anymore
> > > a user can issue the command:
> > >
> > > localhost ~ # echo "close usb" >
> > > <debugfs>/dynamic_debug/control
> > > and then to delete it with:
> > >
> > > localhost ~ # rmdir <debugfs>/tracing/instances/
> > >
> > > To enable writing usbcore module debug logs to trace dyndbg:prdbg and
> > > dyndbg:devdbg events user can issue the command:
> > >
> > > localhost ~ # echo "module usbcore =T:0" >
> > > <debugfs>/dynamic_debug/control
> > >
> > > Then dyndbg trace events can be for example captured with the command:
> > >
> > > localhost ~ # trace-cmd start -e dyndbg
> > >
> > > And displayed with the command:
> > >
> > > localhost ~ # trace-cmd show
> > >
> >
> > is there a recipe to show private traces ? prolly worth a mention here.
> >
>
> Trace-cmd stat shows among other things open trace instances. I will add it.
>
> >
> > >
> > >
> > > Jim, I made a few changes to the test script dd-selftest.rc you created
> > > and I also added new test scenarios. You can find the entire patchset
> > > with the test script changes on top here
> > > https://chromium.googlesource.com/chromiumos/third_party/kernel/+log/refs/sandbox/ukaszb/dyndbg_trace_v3
> > > I wonder where would be the proper place to store the test script
> > > (upstream, your github.com:jimc/linux.git)
> > > Do you have a suggestion for that ?
> > >
> >
> > I got it (your HEAD), renamed and put it in:
> > tools/testing/selftests/dynamic_debug/
> > and copied & modified Makefile and config from ../users/
> > I added your SOB, that seems proper.
> >
>
> Great, thanks ;)
>
> > nice additions. and I like the colors. maybe they belong in lib.mk,
> > but thats 4 later.
> >
> > and tweaked the modules / DUTs to *hopefully* get stable callsite counts
> > from the tests on them, in virtually any usable config.
> > DUTs: file init/main, module mm_init, and module test_dynamic_debug (a
> > config constraint)
> > The ref-counts are taken from a default virtme-ng -k config on my x86-64 box
> >
> > I now pass tests up to:
> >
> > [root@v6 wk-proof]# ./tools/testing/selftests/dynamic_debug/dyndbg_selftest.sh
> > ...
> > # TEST_PRIVATE_TRACE_6
> > [ 1009.296557] dyndbg: read 3 bytes from userspace
> > [ 1009.296876] dyndbg: query 0: <=_> on module: <*>
> > [ 1009.297171] dyndbg: processed 1 queries, with 1559 matches, 0 errs
> > [ 1009.311621] dyndbg: read 39 bytes from userspace
> > [ 1009.312032] dyndbg: query 0: <open
> > A_bit_lengthy_trace_instance_name> on module: <*>
> > [ 1009.312569] dyndbg: instance is already opened
> > name:A_bit_lengthy_trace_instance_name
> > [ 1009.313063] dyndbg: processed 1 queries, with 0 matches, 1 errs
> > : ./tools/testing/selftests/dynamic_debug/dyndbg_selftest.sh:454
> > ddcmd() expected to exit with code 0
> > Error: 'File exists'
> >
> > it seems invocation dependent
> > I suspect 2 possibilities:
> > 1- invoking as shell-script, repeatedly vs vng -e script-name
> > (one-shot per boot)
> > 2- virtme-ng's minimal-default config has no CONFIG_USB.
> > this changes post-conditions of the script, affecting preconditions
> > of the next run.
> >
>
> I guess you must have enabled CONFIG_USB in your setup otherwise
> dyndbg_selftest.sh should fail earlier in TEST_PRIVATE_TRACE_5 ?
>
Its usually on, but I have at least one config,
IIRC from default vng -vk, that left it off.
whats the shell syntax to check CONFIG_MODULES ?
ATM, basic-tests uses "module main" (maybe worth narrowing)
comma-terminator-tests uses "module params"
test-percent-splitting uses test_dynamic_debug to demo a useful case,
so it needs MODULES
so does the self-start-various-end tests
the private-trace tests appear to use a mix of
test_dynamic-debug, & module params,
maybe that can be materially improved, I dont know.
IIRC for builtins I think we're now using 'file kernel/
> > 2 means that we should replace usbcore with some other always *builtin* module.
> >
>
> Sounds good. Do you have a module candidate ?
>
> I'm also concerned that we might need to validate dyndbg_selftest.sh
> against specific kernel version because
> I took the dyndbg_selftest.sh from lukas-v3.0 branch and I had to do
> the following changes to make it work on kernel v6.6:
>
Yes, I hit this one too.
I decided to avoid using mm_init for this reason.
(without actually looking whether it was a config-based variance,
which I assumed, or a commit-based one)
I chose 'module params' instead,
despite the need to escape the brackets in the search:
check_match_ct '\[params\]' 4
> --- a/tools/testing/selftests/dynamic_debug/dyndbg_selftest.sh
> +++ b/tools/testing/selftests/dynamic_debug/dyndbg_selftest.sh
> @@ -166,12 +166,12 @@ EOF
> function comma_terminator_tests {
> echo -e "${GREEN}# COMMA_TERMINATOR_TESTS ${NC}"
> # try combos of space & comma
> - check_match_ct mm_init 5
> + check_match_ct mm_init 4
> ddcmd module,mm_init,=_ # commas as spaces
> ddcmd module,mm_init,+mpf # turn on non-classed
> - check_match_ct =pmf 5
> + check_match_ct =pmf 4
> ddcmd ,module ,, , mm_init, -p # extra commas & spaces
> - check_match_ct =mf 5
> + check_match_ct =mf 4
> ddcmd =_
> }
> function test_percent_splitting {
> @@ -350,7 +350,7 @@ function test_private_trace_3 {
> ddcmd class D2_CORE +T:foo \; class D2_KMS +T:foo
> ddcmd "class,D2_CORE,+T:foo;,class,D2_KMS,+T:foo"
> ddcmd class,D2_CORE,+T:foo\;class,D2_KMS,+T:foo
> - check_match_ct =T 2 -v
> + check_match_ct =T 3 -v
> check_match_ct =Tl 0
> check_match_ct =Tmf 0
> echo 1 >/sys/kernel/tracing/tracing_on
> @@ -379,7 +379,7 @@ function test_private_trace_4 {
> modprobe test_dynamic_debug dyndbg=class,D2_CORE,+T:foo%class,D2_KMS,+T:foo
> check_match_ct =Tl 0
> check_match_ct =Tmf 0
> - check_match_ct =T 2
> + check_match_ct =T 3
> echo 1 >/sys/kernel/tracing/tracing_on
>
> What kernel version did you use for the testing ?
turns out Im on top of -rc7
(I suppose I should pay closer attention :-)
> > I chose module params, on the idea that its builtin, but also invoked later,
> > when modules are modprobed with params, so its callsites can be enabled &
> > then invoked via do_prints, to test for writes to the private trace-buf.
> >
> > I've pushed it to lukas-v3.0 at jimc.github.com/linux
> >
> > Would you look at err on _6, above,
> > and figure out if its insufficiently robust to test preconditions, or
> > something else ?
>
> The following change fixes failure in TEST_PRIVATE_TRACE_6:
> @@ -455,7 +455,7 @@ function test_private_trace_6 {
> ddcmd open $name
> is_trace_instance_opened $name
> check_trace_instance_dir $name 1
> - ddcmd "module module =T:$name.l" -v
> + ddcmd "module usbcore =T:$name.l"
> check_match_ct =T:A_bit_lengthy_trace....l 164
>
> When dyndbg_selftest.sh completes with success which is announced by the line
> # Done on: Thu Dec 28 23:04:17 CET 2023
> then it leaves dynamic debug and trace in a state where next
> dyndbg_selftest.sh run should also complete with success.
yes .this works well for vng -e <script-path> runs
> But when any of the tests fails manual intervention or reboot is
> required at the moment.
> Do you think we should have a cleanup function and call it whenever
> dyndbg_selftest.sh fails in order
> to prepare dynamic debug and trace for the next run of dyndbg_selftest.sh ?
>
yes, I think so.
In part to prove that we can "un-wedge" whatever's wrong w/o a reboot.
and/or a rmmod, modprobe cycle.
self_end_* are doing various unwinds,
but a full-powered cleanup fn, with diagnostics and hints
would be a good addition, with demonstration value.
> > and also:
> > rename test_private_trace_N() to better names
> > - and/or comments to intent & pattern of use
> > more tweaks invited in its commit-msg
> >
>
> I will rename the functions and add description of the tests.
>
> > since cycle_test_problem() is not actually a problem, whats a better name ?
> > _not_best_practices ?
> >
>
> Ack
>
> > I think the final test script enhancement needed is (maybe separately):
> > private-buffer-expected-write-verification after do_prints,
> > and around modprobe test_dynamic_debug dyndbg=$multicmd
> > subject to 2 below.
> >
>
> Ack
we definitely have this in part, spread around the dozen or so functions
>
> > > TODOs:
> > > - update dynamic debug documentation,
> > > - finalize discussion related to default trace destination
> > > (whether we want it at all, if yes then conclude on the details)
> > >
> >
> > good list. before docs;
> >
> > wrt default-trace, at least in some details, it seems extra rules to know.
> > for example, if the default were set on successful open,
> > rather than successful rule application (iirc), then it would read a lot
> > like "with" or "using" blocks, esp with <<EOX form
> >
> > with that new form, it might be pretty expressive:
> >
> > echo <<YMMV > /proc/dynamic_debug/control
> > open sesame # ie with
> > module magic_carpet function forward +Tfml
> > module magic_lamp function rub_vigorously +Tfmt
> > open voicetrace
> > module voice2ai function text2cmdprompt +T
> > module undo function oh_crap +T
> > YMMV
> >
I was hoping this example was stupid enough to goad someone
into responding (with a better one). Alas no.
How might DRM want to use this ?
one practical example is to segregate hi-rate drm_dbg events to a
separate buffer,
so theyre not cluttering your trace-cmd view until you want them.
But thats a little contrived, cuz vblank events are already trace-events
into the global buffer, they dont have drm_dbg's for this.
echo <<DRM_TRACE_BLK > /proc/dynamic_debug/control
open vblank_stream # segregate noisy/hi-vol stuff
module amdgpu format *_vblank +:vblank_stream # one
way to select them
module amdgpu format "[DML]:DML_" +:vblank_strem # pretty
much same set ?
open drm_generic
class DRM_CORE +:drm_generic.mf
class DRM_DRIVER_ +:drm_generic.tmf
DRM_TRACE_BLK
> > I think set-default-on-good-rule-applied is flawed:
> > it relies on the most complex expression in the grammar to be correct
> > and without spelling errors, where module unknown is
> > OK grammatically, but nonsense.
>
> in case of "unknown" module default trace destination will not be
> updated because
> the code checks for nfound before updating default destination:
> if (nfound)
> update_tr_default_dst(modifiers);
>
> > set-default-on-open is simpler to explain and test separately.
> >
>
> Actually I think we discussed set-default-on-open some time ago (in
> the beginning).
we could have - I miss a lot :-}
anyway youve named our choices:
> But to sum up the default trace destination there were 3 directions
> proposed/discussed:
> - set-default-on-open,
> - set-default-on-good-rule-applied,
note in my DRM_TRC_BLK example above, I made a subtle error.
DRM_DRIVER_ doesnt exist cuz of the trailing _.
non-matching keywords are silently skipped. (not just class)
the rule wont apply.
If Id misspelled it as DRM_DRIVERS it would be just as quiet.
So now the good/bad status creates an order-dependence;
if the rule is 1st in a set, good/bad chooses the new/old default-dest.
and this affects any following rule, unless that has an explicit dest.
This sounds complicated.
set-default-on-open doesnt have these problems:
each rule gets the same setting
> - preset-default-per-each-callsite with -T:trace_dest_name,
this doesnt have a default-setting, it keeps what it had
>
> All 3 pass information explicitly but IMHO
> preset-default-per-each-callsite is most confusing as user would have
> to remember what was preset for a given callsite when later passing a
> T flag for the same callsite.
>
thats true, but for:
We could display the current destination in control, independent of the flags
(with the :0. default elided)
init/main.c:1117 [main]initcall_blacklist =pT:startup_trc.mf
"blacklisting initcall %s\n"
init/main.c:1156 [main]initcall_blacklisted =T:startup_trc.mf
"initcall %s blacklisted\n"
init/main.c:1351 [main]run_init_process =:startup_trc.mf " with arguments:\n"
1st line writes to syslog and to private startup_trc, both with
"module:function:" dynamic-prefix
2nd only to the private trace, with same prefix
3rd is not enabled, but has its dest preset to the private trace,
again with the prefix.
And the part I glossed over:
a new "trace_name" keyword would allow selection on the composed set
of sites with that preset.
ddcmd trace_name drm_generic +Ts # enable the set which is
pointing at drm_generic
> Then if it comes to set-default-on-open vs
> set-default-on-good-rule-applied I don't have strong opinion but I
> would
> lean towards set-default-on-open because in this case it is pretty
> straightforward, I mean last successful open sets default trace
> destination.
of the 1st 2 options, I lean strongly to on-open.
To test the limits, what if we renamed "open" to "using" ?
using could:
a) force a dest update, from any previous state.
b) only upgrade from :0. dont change :foo.
a is unnecessary, since +T:dest. explicitly does that.
b is more subtle, but more useful.
>
> If you also hesitate which one to choose maybe we should start with
> very simple approach like that +T always defaults to trace events (:0)
> ?
that makes sense.
keep-presets-per-callsite does need keyword to be complete.
>
> > We should probably consider modifying the continue-looping behavior
> > of ddebug_exec_queries, depending upon the return-code.
> > open, close errors could reasonably warrant different treatment,
> > like terminating the mult-cmd loop prematurely on open/close errs.
> > Esp if we keep the set-default-on-good-rule-applied
> > What do you think ?
this is still open, and worth a review, but minor.
> Let's first conclude on default destination.
>
> > I'm inclined to reword a commit-msg or 2, drop RFC, obsolete comments etc.
> >
> > I can do that in a lukas-v3.1, or as in-thread responses,
> > do you have a preference ?
>
> Please go ahead and make changes in the lukas-v3.1 branch. I find it
> very convenient. I will just grab your changes from the branch.
excellent, it does feel pretty smooth.
is your repo also public, or did I just miss the clonable url?
I'll write some trace-thing for howto in the next few days,
(in particular, I'll stay out of dyndbg_selftest.sh, I think its your turn :-)
theres also s/coma/comma/ in the comma-separator patch.
thats all I got now,
Thanks!!
Jim
wt., 2 sty 2024 o 20:13 <[email protected]> napisał(a):
>
> ok, to catch up here,
> Lukas & I have been nudging the test script forward,
> some of this is settled..
>
> On Thu, Dec 28, 2023 at 5:00 PM Łukasz Bartosik <[email protected]> wrote:
> >
> > śr., 27 gru 2023 o 05:23 <[email protected]> napisał(a):
> > >
> > > re-adding gregkh, who fell off the cc's again.
> > > he is one of our upstreams.
> > >
> >
> > hi Jim,
> >
> > It's good to hear from you.
> >
> > Thanks. I missed to add Greg.
> >
> > > On Fri, Dec 22, 2023 at 6:51 PM Łukasz Bartosik <[email protected]> wrote:
> > > >
> > > > Add support for writing debug logs to trace events and trace instances.
> > > > The rationale behing this feature is to be able to redirect debug logs
> > > > (per each callsite individually) to trace to aid in debugging. The debug
> > > > logs output to trace can be enabled with T flag. Additionally the T flag
> > > > accepts trace destination which can be provided to the T flag after ":".
> > > > The trace destination field is used to determine where debug logs will be
> > > > written.
> > > >
> > > > In order to redirect callsite debug log to a trace instance it has to be
> > > > initialized first with a newly introduced "open" command. For example,
> > > > "usb" trace instance in <debugfs>/tracing/instances/ can be initialized
> > > > by issuing the command:
> > > >
> > > > localhost ~ # echo "open usb" >
> > > > <debugfs>/dynamic_debug/control
> > > >
> > > > If the trace instance <debugfs>/tracing/instances/usb already exists
> > > > then it will be reused otherwise new usbcore instance will be created.
> > > > Maximum 63 trace instances can be "opened". The trace instance name can
> > > > include any of ^\w+ and underscore characters. There is also a special
> > > > name "0" reserved for writing debug logs to trace prdbg and devdbg events.
> > > > The reserved name "0" does not require to be "opened" before use.
> > >
> > > theres implication here that p only works when :0.
> > > Is that intended ?
> > > it seems wrong, or at least unnecessary.
> > >
> >
> > I don't see clearly the implication that p only works when :0.
> > Which statement implies this to you ? Please keep in mind that English
> > is not my native.
>
> heh - Im not sure now - its mostly me probing for unseen inconsistencies.
>
> > > In fact, theres no specific reason to exclude +p:trcbuf.mf,
> > > esp if we keep default-trace-buf
> > > since +pTfml could have that meaning implicitly.
> > > We can call it allowed and "unimplemented until proven useful" on +p
> > >
> > > +p completely independent of +T is a simplicity,
> > > lets keep that until proven useful otherwise.
> > >
> > > >
> > > > To enable writing usbcore module debug logs to the "usb" trace instance
> > > > opened above a user can issue the command:
> > > >
> > > > localhost ~ # echo "module usbcore =pT:usb" >
> > > > <debugfs>/dynamic_debug/control
> > > >
> > > > Please note that output of debug logs to syslog (p flag) and trace (T flag)
> > > > can be independently enabled/disabled for each callsite. Therefore the
> > > > above command will enable writing of debug logs not only to the trace
> > > > instance "usb" but also to syslog.
> > > >
> > > > When trace destination is followed by another flag the next flag has to
> > > > be preeceded with ".", for example
> > > >
> > > > localhost ~ # echo "module usbcore =pT:usb.l" >
> > > > <debugfs>/dynamic_debug/control
> > > >
> > > > To simplify processing trace destination can be omitted when default
> > > > trace destination is set, for example the command
> > > >
> > > > localhost ~ # echo "module usbcore =pTl" >
> > > > <debugfs>/dynamic_debug/control
> > > >
> > > > will use default trace destination. If default trace destination is not
> > > > set the above command will fail. The default trace destination is set
> > > > when a command with any of the flags [-+=] and explicitly provided trace
> > > > destination matches at least one callsite, for example the command
> > > >
> > > > localhost ~ # echo "module usbcore -T:usb" >
> > > > <debugfs>/dynamic_debug/control
> > > >
> > > > will disable trace for all usbcore module callsites (if any was enabled)
> > > > and will set "usb" instance as default trace destination. To enable writing
> > > > thunderbolt module debug logs to the "usb" trace instance as well a user
> > > > can issue the command:
> > > >
> > > > localhost ~ # echo "module thunderbolt =T" >
> > > > <debugfs>/dynamic_debug/control
> > > >
> > > > Since default trace destination was previously set therefore "usb" instance
> > > > name does not have to be explicitly provided.
> > > >
> > > > When no callsite writes debug logs to a trace instance then it can be
> > > > released (its reference counter decrased) with the "close" command.
> > > decreased
> > >
> >
> > Ack
> >
> > > > Closing a trace instance make it unavailable for dynamic debug and also
> > > makes
> >
> > Ack
> >
> > > > allows a user to delete such a trace instance at convenient time later
> > > > with rmdir command. For example when "usb" instance is not used anymore
> > > > a user can issue the command:
> > > >
> > > > localhost ~ # echo "close usb" >
> > > > <debugfs>/dynamic_debug/control
> > > > and then to delete it with:
> > > >
> > > > localhost ~ # rmdir <debugfs>/tracing/instances/
> > > >
> > > > To enable writing usbcore module debug logs to trace dyndbg:prdbg and
> > > > dyndbg:devdbg events user can issue the command:
> > > >
> > > > localhost ~ # echo "module usbcore =T:0" >
> > > > <debugfs>/dynamic_debug/control
> > > >
> > > > Then dyndbg trace events can be for example captured with the command:
> > > >
> > > > localhost ~ # trace-cmd start -e dyndbg
> > > >
> > > > And displayed with the command:
> > > >
> > > > localhost ~ # trace-cmd show
> > > >
> > >
> > > is there a recipe to show private traces ? prolly worth a mention here.
> > >
> >
> > Trace-cmd stat shows among other things open trace instances. I will add it.
> >
> > >
> > > >
> > > >
> > > > Jim, I made a few changes to the test script dd-selftest.rc you created
> > > > and I also added new test scenarios. You can find the entire patchset
> > > > with the test script changes on top here
> > > > https://chromium.googlesource.com/chromiumos/third_party/kernel/+log/refs/sandbox/ukaszb/dyndbg_trace_v3
> > > > I wonder where would be the proper place to store the test script
> > > > (upstream, your github.com:jimc/linux.git)
> > > > Do you have a suggestion for that ?
> > > >
> > >
> > > I got it (your HEAD), renamed and put it in:
> > > tools/testing/selftests/dynamic_debug/
> > > and copied & modified Makefile and config from ../users/
> > > I added your SOB, that seems proper.
> > >
> >
> > Great, thanks ;)
> >
> > > nice additions. and I like the colors. maybe they belong in lib.mk,
> > > but thats 4 later.
> > >
> > > and tweaked the modules / DUTs to *hopefully* get stable callsite counts
> > > from the tests on them, in virtually any usable config.
> > > DUTs: file init/main, module mm_init, and module test_dynamic_debug (a
> > > config constraint)
> > > The ref-counts are taken from a default virtme-ng -k config on my x86-64 box
> > >
> > > I now pass tests up to:
> > >
> > > [root@v6 wk-proof]# ./tools/testing/selftests/dynamic_debug/dyndbg_selftest.sh
> > > ...
> > > # TEST_PRIVATE_TRACE_6
> > > [ 1009.296557] dyndbg: read 3 bytes from userspace
> > > [ 1009.296876] dyndbg: query 0: <=_> on module: <*>
> > > [ 1009.297171] dyndbg: processed 1 queries, with 1559 matches, 0 errs
> > > [ 1009.311621] dyndbg: read 39 bytes from userspace
> > > [ 1009.312032] dyndbg: query 0: <open
> > > A_bit_lengthy_trace_instance_name> on module: <*>
> > > [ 1009.312569] dyndbg: instance is already opened
> > > name:A_bit_lengthy_trace_instance_name
> > > [ 1009.313063] dyndbg: processed 1 queries, with 0 matches, 1 errs
> > > : ./tools/testing/selftests/dynamic_debug/dyndbg_selftest.sh:454
> > > ddcmd() expected to exit with code 0
> > > Error: 'File exists'
> > >
> > > it seems invocation dependent
> > > I suspect 2 possibilities:
> > > 1- invoking as shell-script, repeatedly vs vng -e script-name
> > > (one-shot per boot)
> > > 2- virtme-ng's minimal-default config has no CONFIG_USB.
> > > this changes post-conditions of the script, affecting preconditions
> > > of the next run.
> > >
> >
> > I guess you must have enabled CONFIG_USB in your setup otherwise
> > dyndbg_selftest.sh should fail earlier in TEST_PRIVATE_TRACE_5 ?
> >
>
> Its usually on, but I have at least one config,
> IIRC from default vng -vk, that left it off.
>
> whats the shell syntax to check CONFIG_MODULES ?
>
Please elaborate what would you like to check ?
> ATM, basic-tests uses "module main" (maybe worth narrowing)
> comma-terminator-tests uses "module params"
> test-percent-splitting uses test_dynamic_debug to demo a useful case,
> so it needs MODULES
> so does the self-start-various-end tests
>
> the private-trace tests appear to use a mix of
> test_dynamic-debug, & module params,
> maybe that can be materially improved, I dont know.
>
> IIRC for builtins I think we're now using 'file kernel/
We can narrow further check conditions when there are different
results on different kernel versions.
> > > 2 means that we should replace usbcore with some other always *builtin* module.
> > >
> >
> > Sounds good. Do you have a module candidate ?
>
>
>
> >
> > I'm also concerned that we might need to validate dyndbg_selftest.sh
> > against specific kernel version because
> > I took the dyndbg_selftest.sh from lukas-v3.0 branch and I had to do
> > the following changes to make it work on kernel v6.6:
> >
>
> Yes, I hit this one too.
> I decided to avoid using mm_init for this reason.
> (without actually looking whether it was a config-based variance,
> which I assumed, or a commit-based one)
> I chose 'module params' instead,
> despite the need to escape the brackets in the search:
>
> check_match_ct '\[params\]' 4
>
When I took dyndbg_selftest from top of dd-classmaps2-on-lukas-v3.1
branch I had two check_match_ct errors but these were caused by too
loose check conditions.
After narrowing conditions all tests passed on top of v6.6 kernel.
> > --- a/tools/testing/selftests/dynamic_debug/dyndbg_selftest.sh
> > +++ b/tools/testing/selftests/dynamic_debug/dyndbg_selftest.sh
> > @@ -166,12 +166,12 @@ EOF
> > function comma_terminator_tests {
> > echo -e "${GREEN}# COMMA_TERMINATOR_TESTS ${NC}"
> > # try combos of space & comma
> > - check_match_ct mm_init 5
> > + check_match_ct mm_init 4
> > ddcmd module,mm_init,=_ # commas as spaces
> > ddcmd module,mm_init,+mpf # turn on non-classed
> > - check_match_ct =pmf 5
> > + check_match_ct =pmf 4
> > ddcmd ,module ,, , mm_init, -p # extra commas & spaces
> > - check_match_ct =mf 5
> > + check_match_ct =mf 4
> > ddcmd =_
> > }
> > function test_percent_splitting {
> > @@ -350,7 +350,7 @@ function test_private_trace_3 {
> > ddcmd class D2_CORE +T:foo \; class D2_KMS +T:foo
> > ddcmd "class,D2_CORE,+T:foo;,class,D2_KMS,+T:foo"
> > ddcmd class,D2_CORE,+T:foo\;class,D2_KMS,+T:foo
> > - check_match_ct =T 2 -v
> > + check_match_ct =T 3 -v
> > check_match_ct =Tl 0
> > check_match_ct =Tmf 0
> > echo 1 >/sys/kernel/tracing/tracing_on
> > @@ -379,7 +379,7 @@ function test_private_trace_4 {
> > modprobe test_dynamic_debug dyndbg=class,D2_CORE,+T:foo%class,D2_KMS,+T:foo
> > check_match_ct =Tl 0
> > check_match_ct =Tmf 0
> > - check_match_ct =T 2
> > + check_match_ct =T 3
> > echo 1 >/sys/kernel/tracing/tracing_on
> >
> > What kernel version did you use for the testing ?
>
> turns out Im on top of -rc7
> (I suppose I should pay closer attention :-)
>
>
> > > I chose module params, on the idea that its builtin, but also invoked later,
> > > when modules are modprobed with params, so its callsites can be enabled &
> > > then invoked via do_prints, to test for writes to the private trace-buf.
> > >
> > > I've pushed it to lukas-v3.0 at jimc.github.com/linux
> > >
> > > Would you look at err on _6, above,
> > > and figure out if its insufficiently robust to test preconditions, or
> > > something else ?
> >
> > The following change fixes failure in TEST_PRIVATE_TRACE_6:
> > @@ -455,7 +455,7 @@ function test_private_trace_6 {
> > ddcmd open $name
> > is_trace_instance_opened $name
> > check_trace_instance_dir $name 1
> > - ddcmd "module module =T:$name.l" -v
> > + ddcmd "module usbcore =T:$name.l"
> > check_match_ct =T:A_bit_lengthy_trace....l 164
> >
> > When dyndbg_selftest.sh completes with success which is announced by the line
> > # Done on: Thu Dec 28 23:04:17 CET 2023
> > then it leaves dynamic debug and trace in a state where next
> > dyndbg_selftest.sh run should also complete with success.
>
> yes .this works well for vng -e <script-path> runs
>
> > But when any of the tests fails manual intervention or reboot is
> > required at the moment.
> > Do you think we should have a cleanup function and call it whenever
> > dyndbg_selftest.sh fails in order
> > to prepare dynamic debug and trace for the next run of dyndbg_selftest.sh ?
> >
>
> yes, I think so.
> In part to prove that we can "un-wedge" whatever's wrong w/o a reboot.
> and/or a rmmod, modprobe cycle.
> self_end_* are doing various unwinds,
> but a full-powered cleanup fn, with diagnostics and hints
> would be a good addition, with demonstration value.
>
I will create such a cleanup function.
>
>
> > > and also:
> > > rename test_private_trace_N() to better names
> > > - and/or comments to intent & pattern of use
> > > more tweaks invited in its commit-msg
> > >
> >
> > I will rename the functions and add description of the tests.
> >
> > > since cycle_test_problem() is not actually a problem, whats a better name ?
> > > _not_best_practices ?
> > >
> >
> > Ack
> >
> > > I think the final test script enhancement needed is (maybe separately):
> > > private-buffer-expected-write-verification after do_prints,
> > > and around modprobe test_dynamic_debug dyndbg=$multicmd
> > > subject to 2 below.
> > >
> >
> > Ack
>
> we definitely have this in part, spread around the dozen or so functions
>
I will create new test to match the criteria above.
> >
> > > > TODOs:
> > > > - update dynamic debug documentation,
> > > > - finalize discussion related to default trace destination
> > > > (whether we want it at all, if yes then conclude on the details)
> > > >
> > >
> > > good list. before docs;
> > >
> > > wrt default-trace, at least in some details, it seems extra rules to know.
> > > for example, if the default were set on successful open,
> > > rather than successful rule application (iirc), then it would read a lot
> > > like "with" or "using" blocks, esp with <<EOX form
> > >
> > > with that new form, it might be pretty expressive:
> > >
> > > echo <<YMMV > /proc/dynamic_debug/control
> > > open sesame # ie with
> > > module magic_carpet function forward +Tfml
> > > module magic_lamp function rub_vigorously +Tfmt
> > > open voicetrace
> > > module voice2ai function text2cmdprompt +T
> > > module undo function oh_crap +T
> > > YMMV
> > >
>
> I was hoping this example was stupid enough to goad someone
> into responding (with a better one). Alas no.
>
> How might DRM want to use this ?
>
> one practical example is to segregate hi-rate drm_dbg events to a
> separate buffer,
> so theyre not cluttering your trace-cmd view until you want them.
>
> But thats a little contrived, cuz vblank events are already trace-events
> into the global buffer, they dont have drm_dbg's for this.
>
>
> echo <<DRM_TRACE_BLK > /proc/dynamic_debug/control
>
> open vblank_stream # segregate noisy/hi-vol stuff
>
> module amdgpu format *_vblank +:vblank_stream # one
> way to select them
> module amdgpu format "[DML]:DML_" +:vblank_strem # pretty
> much same set ?
>
> open drm_generic
> class DRM_CORE +:drm_generic.mf
> class DRM_DRIVER_ +:drm_generic.tmf
>
> DRM_TRACE_BLK
>
>
>
> > > I think set-default-on-good-rule-applied is flawed:
> > > it relies on the most complex expression in the grammar to be correct
> > > and without spelling errors, where module unknown is
> > > OK grammatically, but nonsense.
> >
> > in case of "unknown" module default trace destination will not be
> > updated because
> > the code checks for nfound before updating default destination:
> > if (nfound)
> > update_tr_default_dst(modifiers);
> >
> > > set-default-on-open is simpler to explain and test separately.
> > >
> >
> > Actually I think we discussed set-default-on-open some time ago (in
> > the beginning).
>
> we could have - I miss a lot :-}
> anyway youve named our choices:
>
> > But to sum up the default trace destination there were 3 directions
> > proposed/discussed:
> > - set-default-on-open,
> > - set-default-on-good-rule-applied,
>
> note in my DRM_TRC_BLK example above, I made a subtle error.
> DRM_DRIVER_ doesnt exist cuz of the trailing _.
> non-matching keywords are silently skipped. (not just class)
> the rule wont apply.
> If Id misspelled it as DRM_DRIVERS it would be just as quiet.
>
> So now the good/bad status creates an order-dependence;
> if the rule is 1st in a set, good/bad chooses the new/old default-dest.
> and this affects any following rule, unless that has an explicit dest.
> This sounds complicated.
>
I agree but I think the order-dependence issue also applies to open.
Let me explain below.
> set-default-on-open doesnt have these problems:
> each rule gets the same setting
>
Let's assume the following multi line command:
echo "open usb" > /proc/dynamic_debug/control # usb becomes default
trace destination
echo "module usbcore =T" > /proc/dynamic_debug/control # use usb as
trace destination
echo "open tbt" > /proc/dynamic_debug/control
echo "module thunderbolt =T" > /proc/dynamic_debug/control
Now the thunderbolt debug logs will be written to tbt trace (when
"open tbt" succeeds) or to usb trace (when "open tbt" fails)
> > - preset-default-per-each-callsite with -T:trace_dest_name,
>
> this doesnt have a default-setting, it keeps what it had
>
> >
> > All 3 pass information explicitly but IMHO
> > preset-default-per-each-callsite is most confusing as user would have
> > to remember what was preset for a given callsite when later passing a
> > T flag for the same callsite.
> >
>
> thats true, but for:
> We could display the current destination in control, independent of the flags
> (with the :0. default elided)
>
> init/main.c:1117 [main]initcall_blacklist =pT:startup_trc.mf
> "blacklisting initcall %s\n"
> init/main.c:1156 [main]initcall_blacklisted =T:startup_trc.mf
> "initcall %s blacklisted\n"
> init/main.c:1351 [main]run_init_process =:startup_trc.mf " with arguments:\n"
>
> 1st line writes to syslog and to private startup_trc, both with
> "module:function:" dynamic-prefix
> 2nd only to the private trace, with same prefix
> 3rd is not enabled, but has its dest preset to the private trace,
> again with the prefix.
>
Yes we can display preset trace destination even when T flag is not
set for a given callsite.
I just wonder how much this approach of presetting trace destination
per callsite would be helpful to users ?
> And the part I glossed over:
> a new "trace_name" keyword would allow selection on the composed set
> of sites with that preset.
>
> ddcmd trace_name drm_generic +Ts # enable the set which is
> pointing at drm_generic
>
How in this case drm_generic would be created ? Or is it just a
string/regexp which is used to select callsites ?
>
>
> > Then if it comes to set-default-on-open vs
> > set-default-on-good-rule-applied I don't have strong opinion but I
> > would
> > lean towards set-default-on-open because in this case it is pretty
> > straightforward, I mean last successful open sets default trace
> > destination.
>
> of the 1st 2 options, I lean strongly to on-open.
>
I realized there is one IMHO major advantage of
set-default-on-good-rule-applied over set-default-on-open because
it allows to change default destination without any side effects (
-T:trace_name on callsite which does not have T flag set) while
set-default-on-open causes side effect to change default destination
as new trace instance is opened as a result.
> To test the limits, what if we renamed "open" to "using" ?
> using could:
> a) force a dest update, from any previous state.
> b) only upgrade from :0. dont change :foo.
>
> a is unnecessary, since +T:dest. explicitly does that.
> b is more subtle, but more useful.
>
Or instead of using all this magic to implicitly set trace default
destination with set-default-on-open or
set-default-on-good-rule-applied we could create "using" command
to explicitly set default trace destination ?
> >
> > If you also hesitate which one to choose maybe we should start with
> > very simple approach like that +T always defaults to trace events (:0)
> > ?
>
> that makes sense.
> keep-presets-per-callsite does need keyword to be complete.
>
> >
> > > We should probably consider modifying the continue-looping behavior
> > > of ddebug_exec_queries, depending upon the return-code.
> > > open, close errors could reasonably warrant different treatment,
> > > like terminating the mult-cmd loop prematurely on open/close errs.
> > > Esp if we keep the set-default-on-good-rule-applied
> > > What do you think ?
>
> this is still open, and worth a review, but minor.
>
It makes sense to me to end multi command loop on open or close error.
> > Let's first conclude on default destination.
> >
> > > I'm inclined to reword a commit-msg or 2, drop RFC, obsolete comments etc.
> > >
> > > I can do that in a lukas-v3.1, or as in-thread responses,
> > > do you have a preference ?
> >
> > Please go ahead and make changes in the lukas-v3.1 branch. I find it
> > very convenient. I will just grab your changes from the branch.
>
> excellent, it does feel pretty smooth.
> is your repo also public, or did I just miss the clonable url?
>
Please try this:
git clone https://chromium.googlesource.com/chromiumos/third_party/kernel
kernel$ git ls-remote origin "refs/sandbox/ukaszb/*"
bdd057746b50a2f1c54b45274c60a51e64040b1f refs/sandbox/ukaszb/dyndbg_trace_v1
d07d243aba25650fc791c8af0c95d3904c64e043 refs/sandbox/ukaszb/dyndbg_trace_v3
git fetch origin refs/sandbox/ukaszb/dyndbg_trace_v3
> I'll write some trace-thing for howto in the next few days,
Great.
> (in particular, I'll stay out of dyndbg_selftest.sh, I think its your turn :-)
>
Yeah, it's my turn to add more colors ;).
> theres also s/coma/comma/ in the comma-separator patch.
>
Thanks for reminding me.
Thanks,
Lukasz
>
> thats all I got now,
> Thanks!!
> Jim