dyndbg: add print-to-tracefs, selftest with it - RFC

Sean Paul proposed, in:
https://patchwork.freedesktop.org/series/78133/
drm/trace: Mirror DRM debug logs to tracefs

His patchset's objective is to be able to independently steer some of
the drm.debug stream to an alternate tracing destination, by splitting
drm_debug_enabled() into syslog & trace flavors, and enabling them
separately.  2 advantages were identified:

1- syslog is heavyweight, tracefs is much lighter
2- separate selection of enabled categories means less traffic

Dynamic-Debug can do 2nd exceedingly well:

A- all work is behind jump-label's NOOP, zero off cost.
B- exact site selectivity, precisely the useful traffic.
   can tailor enabled set interactively, at shell.

Since the tracefs interface is effective for drm (the threads suggest
so), adding that interface to dynamic-debug has real potential for
others as well as drm.

if CONFIG_TRACING:

Grab Sean's trace_init/cleanup code, use it to provide tracefs
available by default to all pr_debugs.  This will likely need some
further per-module treatment; perhaps something reflecting hierarchy
of module,file,function,line, maybe with a tuned flattening.

endif CONFIG_TRACING

Add a new +T flag to enable tracing, independent of +p, and add macros
to encapsulate/abstract the flag checks.  Existing code treats T like
other flags.

Add ddebug_validate_flags() as last step in ddebug_parse_flags().  Its
only job is to fail on +T for non-CONFIG_TRACING builds.  RFC.

ddebug_change() adjusts the static-key-enable/disable condition to use
_DPRINTK_ENABLED / abstraction macros.

dynamic_emit_prefix() now gates on _DPRINTK_ENABLED too, as an
optimization but mostly to allow decluttering of its users.

__dynamic_pr_debug() etal get minor changes:

 - call dynamic_emit_prefix() 1st.
 - if (p) before printk, since T enables too.
 - if (T) call trace_array_printk
 - share vaf across p|T

WRT <net|ib>_dev, I skipped all the <T,!!dev> specific dev_emit_prefix
additions for now.  tracefs is a fast customer (with different needs),
re-adding them should be done later, once the utility is understood.

SELFTEST: test_dynamic_debug.ko:

Uses the tracer facility to implement a kernel module selftest.

TODO:

Earlier core code had (tracerfn)() indirection, allowing a plugin
side-effector we could test the results of.

ATM all the tests which count +T'd callsite executions (and which
expect >0) are failing.

Now it needs a rethink to test from userspace, rather than the current
test-once at module-load.  It needs a parameters/testme button.

So remainder of this is a bit stale ....

- A custom tracer counts the number of calls (of T-enabled pr_debugs),
- do_debugging(x) calls a set of categorized pr_debugs x times

- test registers the tracer on the module
  then iteratively:
  manipulates dyndbg states via query-cmds, mostly format ^prefix
  runs do_debugging()
  counts enabled callsite executions
  reports mismatches

- modprobe test_dynamic_debug use_bad_tracer=1
  attaches a bad/recursive tracer
  Bad Things (did) Happen.
  has thrown me interesting panics.
  cannot replicate atm.

RFC: (DONE)

The "tracer" interface probably needs work and a new name.  It is only
1/2 way towards a real tracefs interface; and the code I lifted from
Sean Paul in the next patch could be implemented in dynamic_debug.c
instead, and made available for all pr_debug users.

This would also eliminate need for dynamic_debug_(un)register_tracer(),
since dyndbg could just provide it when TRACING is on.

NOTES:

$> modprobe test_dynamic_debug dyndbg=+p

   it fails 3/29 tests. havent looked at why.

$> modprobe test_dynamic_debug use_bad_tracer=1

Earlier in dev, bad_tracer() exploded in recursion, I havent been able
to replicate that lately.

Signed-off-by: Jim Cromie <jim.cromie@gmail.com>
---
v4: (rfc)
. fix printk (to syslog) needs if (+p), since +T also enables
. add prototypes for un/register_aux_print
. change iface names: s/aux_print/tracer/
. also s/trace_print/tracer/
. struct va_format *vaf - tighten further ?

v5: (rfc)
. fix "too many arguments to function", and name the args:
  int (*aux_print)(const char *fmt, char *prefix, char *label, void *);
   prefix : is a slot for dynamic_emit_prefix, or for custom buffer insert
   label  : for builtin-caller used by drm-trace-print
   void*  : vaf, add type constraint later.

v6: (rfc)
. more test in test module
. add mod arg to *register, following exec_queries pattern
. move code
. move kdoc to c from h

v7: (rfc)
. simplify tracer prototype (probably needs more tailoring)
. separate from dd-exec-queries
. drop struct _ddebug.tracer field
. 1 per module registration, into hash
. rework test_dynamic_debug

v10:
. change rc s/void/int/ dynamic_debug_register_tracer

vlatest:
. drop all register_tracer code, and supporting hash code.
. copy trace init/cleanup from Seans drm patch
  use it to provide tracing for all clients, wo needing registration
. add dyndbg_site_is_enabled|logging|tracing macros, declutter with them.

MAINTAINERS

@@ -6561,6 +6561,7 @@ M:	Jason Baron <jbaron@akamai.com>
 S:	Maintained
 F:	include/linux/dynamic_debug.h
 F:	lib/dynamic_debug.c
+F:	lib/test_dynamic_debug.c
 
 DYNAMIC INTERRUPT MODERATION
 M:	Tal Gilboa <talgi@nvidia.com>

drivers/gpu/drm/drm_print.c

@@ -32,6 +32,7 @@
 #include <linux/moduleparam.h>
 #include <linux/seq_file.h>
 #include <linux/slab.h>
+#include <linux/dynamic_debug.h>
 
 #include <drm/drm.h>
 #include <drm/drm_drv.h>

include/linux/dynamic_debug.h

@@ -28,15 +28,24 @@ struct _ddebug {
 	 */
 #define _DPRINTK_FLAGS_NONE	0
 #define _DPRINTK_FLAGS_PRINT	(1<<0) /* printk() a message using the format */
+#define _DPRINTK_FLAGS_TRACE	(1<<5) /* trace_printk() the message */
+#define _DPRINTK_ENABLED	(_DPRINTK_FLAGS_PRINT | _DPRINTK_FLAGS_TRACE)
+
+#define dyndbg_site_is_enabled(desc) (!!(desc->flags & _DPRINTK_ENABLED))
+#define dyndbg_site_is_logging(desc) (!!(desc->flags & _DPRINTK_FLAGS_PRINT))
+#define dyndbg_site_is_tracing(desc) (!!(desc->flags & _DPRINTK_FLAGS_TRACE))
+
 #define _DPRINTK_FLAGS_INCL_MODNAME	(1<<1)
 #define _DPRINTK_FLAGS_INCL_FUNCNAME	(1<<2)
 #define _DPRINTK_FLAGS_INCL_LINENO	(1<<3)
 #define _DPRINTK_FLAGS_INCL_TID		(1<<4)
 
-#define _DPRINTK_FLAGS_INCL_ANY		\
+#define _DPRINTK_FLAGS_INCL_ANY						\
 	(_DPRINTK_FLAGS_INCL_MODNAME | _DPRINTK_FLAGS_INCL_FUNCNAME |\
 	 _DPRINTK_FLAGS_INCL_LINENO  | _DPRINTK_FLAGS_INCL_TID)
 
+#define dyndbg_site_is_decorated(desc) !!(desc->flags & _DPRINTK_FLAGS_INCL_ANY)
+
 #if defined DEBUG
 #define _DPRINTK_FLAGS_DEFAULT _DPRINTK_FLAGS_PRINT
 #else

lib/Kconfig.debug

@@ -2468,6 +2468,17 @@ config TEST_STATIC_KEYS
 
 	  If unsure, say N.
 
+config TEST_DYNAMIC_DEBUG
+	tristate "Test DYNAMIC_DEBUG"
+	depends on m
+	depends on DYNAMIC_DEBUG
+	help
+	  This module registers a tracer callback to count enabled
+	  pr_debugs in a 'do_debugging' function, then alters their
+	  enablements, calls the function, and compares counts.
+
+	  If unsure, say N.
+
 config TEST_KMOD
 	tristate "kmod stress tester"
 	depends on m

lib/Makefile

@@ -82,6 +82,7 @@ obj-$(CONFIG_TEST_SORT) += test_sort.o
 obj-$(CONFIG_TEST_USER_COPY) += test_user_copy.o
 obj-$(CONFIG_TEST_STATIC_KEYS) += test_static_keys.o
 obj-$(CONFIG_TEST_STATIC_KEYS) += test_static_key_base.o
+obj-$(CONFIG_TEST_DYNAMIC_DEBUG) += test_dynamic_debug.o
 obj-$(CONFIG_TEST_PRINTF) += test_printf.o
 obj-$(CONFIG_TEST_SCANF) += test_scanf.o
 obj-$(CONFIG_TEST_BITMAP) += test_bitmap.o

lib/dynamic_debug.c

@@ -36,6 +36,7 @@
 #include <linux/sched.h>
 #include <linux/device.h>
 #include <linux/netdevice.h>
+#include <linux/trace.h>
 
 #include <rdma/ib_verbs.h>
 
@@ -72,6 +73,7 @@ static LIST_HEAD(ddebug_tables);
 static int verbose;
 module_param(verbose, int, 0644);
 
+
 /* Return the path relative to source root */
 static inline const char *trim_prefix(const char *path)
 {
@@ -85,6 +87,7 @@ static inline const char *trim_prefix(const char *path)
 
 static struct { unsigned flag:8; char opt_char; } opt_array[] = {
 	{ _DPRINTK_FLAGS_PRINT, 'p' },
+	{ _DPRINTK_FLAGS_TRACE, 'T' },
 	{ _DPRINTK_FLAGS_INCL_MODNAME, 'm' },
 	{ _DPRINTK_FLAGS_INCL_FUNCNAME, 'f' },
 	{ _DPRINTK_FLAGS_INCL_LINENO, 'l' },
@@ -207,11 +210,12 @@ static int ddebug_change(const struct ddebug_query *query,
 			newflags = (dp->flags & modifiers->mask) | modifiers->flags;
 			if (newflags == dp->flags)
 				continue;
+
 #ifdef CONFIG_JUMP_LABEL
-			if (dp->flags & _DPRINTK_FLAGS_PRINT) {
-				if (!(modifiers->flags & _DPRINTK_FLAGS_PRINT))
+			if (dyndbg_site_is_enabled(dp)) {
+				if (!(dyndbg_site_is_enabled(modifiers)))
 					static_branch_disable(&dp->key.dd_key_true);
-			} else if (modifiers->flags & _DPRINTK_FLAGS_PRINT)
+			} else if (dyndbg_site_is_enabled(modifiers))
 				static_branch_enable(&dp->key.dd_key_true);
 #endif
 			dp->flags = newflags;
@@ -429,6 +433,16 @@ static int ddebug_parse_query(char *words[], int nwords,
 	return 0;
 }
 
+static int ddebug_validate_flags(struct flag_settings *modifiers)
+{
+#if !defined(CONFIG_TRACING)
+	if (dyndbg_site_is_tracing(modifiers)) {
+		WARN_ONCE("cannot enable T, CONFIG_TRACE=n\n");
+		return -EINVAL;
+	}
+#endif
+	return 0;
+}
 /*
  * Parse `str' as a flags specification, format [-+=][p]+.
  * Sets up *maskp and *flagsp to be used when changing the
@@ -481,7 +495,7 @@ static int ddebug_parse_flags(const char *str, struct flag_settings *modifiers)
 	}
 	v3pr_info("*flagsp=0x%x *maskp=0x%x\n", modifiers->flags, modifiers->mask);
 
-	return 0;
+	return ddebug_validate_flags(modifiers);
 }
 
 static int ddebug_exec_query(char *query_string, const char *modname)
@@ -697,11 +711,14 @@ 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((dyndbg_site_is_enabled(desc)) &&
+		     (dyndbg_site_is_decorated(desc)))
 		return __dynamic_emit_prefix(desc, buf);
 	return buf;
 }
 
+static struct trace_array *trace_arr;
+
 void __dynamic_pr_debug(struct _ddebug *descriptor, const char *fmt, ...)
 {
 	va_list args;
@@ -716,7 +733,13 @@ void __dynamic_pr_debug(struct _ddebug *descriptor, const char *fmt, ...)
 	vaf.fmt = fmt;
 	vaf.va = &args;
 
-	printk(KERN_DEBUG "%s%pV", dynamic_emit_prefix(descriptor, buf), &vaf);
+	dynamic_emit_prefix(descriptor, buf);
+
+	if (dyndbg_site_is_tracing(descriptor))
+		trace_array_printk(trace_arr, _THIS_IP_, "%s%pV", buf, &vaf);
+
+	if (dyndbg_site_is_logging(descriptor))
+		printk(KERN_DEBUG "%s%pV", buf, &vaf);
 
 	va_end(args);
 }
@@ -727,6 +750,7 @@ void __dynamic_dev_dbg(struct _ddebug *descriptor,
 {
 	struct va_format vaf;
 	va_list args;
+	char buf[PREFIX_SIZE] = "";
 
 	BUG_ON(!descriptor);
 	BUG_ON(!fmt);
@@ -736,17 +760,21 @@ void __dynamic_dev_dbg(struct _ddebug *descriptor,
 	vaf.fmt = fmt;
 	vaf.va = &args;
 
+	dynamic_emit_prefix(descriptor, buf);
+
+	if (dyndbg_site_is_tracing(descriptor))
+		trace_array_printk(trace_arr, _THIS_IP_, "%s%pV", buf, &vaf);
+
+	if (!dyndbg_site_is_logging(descriptor))
+		goto out;
+
 	if (!dev) {
 		printk(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);
+				buf, dev_driver_string(dev), dev_name(dev), &vaf);
 	}
-
+out:
 	va_end(args);
 }
 EXPORT_SYMBOL(__dynamic_dev_dbg);
@@ -758,6 +786,7 @@ void __dynamic_netdev_dbg(struct _ddebug *descriptor,
 {
 	struct va_format vaf;
 	va_list args;
+	char buf[PREFIX_SIZE] = "";
 
 	BUG_ON(!descriptor);
 	BUG_ON(!fmt);
@@ -767,12 +796,17 @@ void __dynamic_netdev_dbg(struct _ddebug *descriptor,
 	vaf.fmt = fmt;
 	vaf.va = &args;
 
-	if (dev && dev->dev.parent) {
-		char buf[PREFIX_SIZE] = "";
+	dynamic_emit_prefix(descriptor, buf);
 
+	if (dyndbg_site_is_tracing(descriptor))
+		trace_array_printk(trace_arr, _THIS_IP_, "%s%pV", buf, &vaf);
+
+	if (!dyndbg_site_is_logging(descriptor))
+		goto out;
+
+	if (dev && dev->dev.parent) {
 		dev_printk_emit(LOGLEVEL_DEBUG, dev->dev.parent,
-				"%s%s %s %s%s: %pV",
-				dynamic_emit_prefix(descriptor, buf),
+				"%s%s %s %s%s: %pV", buf,
 				dev_driver_string(dev->dev.parent),
 				dev_name(dev->dev.parent),
 				netdev_name(dev), netdev_reg_state(dev),
@@ -783,7 +817,7 @@ void __dynamic_netdev_dbg(struct _ddebug *descriptor,
 	} else {
 		printk(KERN_DEBUG "(NULL net_device): %pV", &vaf);
 	}
-
+out:
 	va_end(args);
 }
 EXPORT_SYMBOL(__dynamic_netdev_dbg);
@@ -797,18 +831,24 @@ void __dynamic_ibdev_dbg(struct _ddebug *descriptor,
 {
 	struct va_format vaf;
 	va_list args;
+	char buf[PREFIX_SIZE] = "";
 
 	va_start(args, fmt);
 
 	vaf.fmt = fmt;
 	vaf.va = &args;
 
-	if (ibdev && ibdev->dev.parent) {
-		char buf[PREFIX_SIZE] = "";
+	dynamic_emit_prefix(descriptor, buf);
 
+	if (dyndbg_site_is_tracing(descriptor))
+		trace_array_printk(trace_arr, _THIS_IP_, "%s%pV", buf, &vaf);
+
+	if (!dyndbg_site_is_logging(descriptor))
+		goto out;
+
+	if (ibdev && ibdev->dev.parent) {
 		dev_printk_emit(LOGLEVEL_DEBUG, ibdev->dev.parent,
-				"%s%s %s %s: %pV",
-				dynamic_emit_prefix(descriptor, buf),
+				"%s%s %s %s: %pV", buf,
 				dev_driver_string(ibdev->dev.parent),
 				dev_name(ibdev->dev.parent),
 				dev_name(&ibdev->dev),
@@ -818,7 +858,7 @@ void __dynamic_ibdev_dbg(struct _ddebug *descriptor,
 	} else {
 		printk(KERN_DEBUG "(NULL ib_device): %pV", &vaf);
 	}
-
+out:
 	va_end(args);
 }
 EXPORT_SYMBOL(__dynamic_ibdev_dbg);
@@ -1133,6 +1173,35 @@ static void ddebug_remove_all_tables(void)
 	mutex_unlock(&ddebug_lock);
 }
 
+#if defined(CONFIG_TRACING)
+
+static void ddebug_trace_cleanup(void)
+{
+	if (trace_arr) {
+		trace_array_put(trace_arr);
+		trace_array_destroy(trace_arr);
+		trace_arr = NULL;
+	}
+}
+
+static void ddebug_trace_init(void)
+{
+	int ret;
+
+	trace_arr = trace_array_get_by_name("dyndbg-tracefs");
+	if (!trace_arr)
+		return;
+
+	ret = trace_array_init_printk(trace_arr);
+	if (ret)
+		ddebug_trace_cleanup();
+}
+
+#else
+static inline void ddebug_trace_init(void) {}
+static inline void ddebug_trace_cleanup(void) {}
+#endif
+
 static __initdata int ddebug_init_success;
 
 static int __init dynamic_debug_init_control(void)
@@ -1175,6 +1244,9 @@ static int __init dynamic_debug_init(void)
 		ddebug_init_success = 1;
 		return 0;
 	}
+
+	ddebug_trace_init();
+
 	iter = __start___dyndbg;
 	modname = iter->modname;
 	iter_start = iter;