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

That patchset's objective is to be able to independently steer some of
the 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 this exceedingly well:

1- all work is behind jump-label's NOOP, zero off cost.
2- exact site selectivity, precisely the useful traffic.
   can do this interactively, at shell.

The basic elements:

per-callsite:
 - add a new +T flag to enable tracing independent of +p
 - adjust the static-key-enable/disable condition for (+p|+T)
 - if (p) before printk, since T enables too.
 - if (T) call tracer, if one is found for module.

per-module calls to:
 = int dynamic_debug_register_tracer(module, tracer);
 = int dynamic_debug_unregister_tracer(module, tracer);

private new hash: dyndbg_tracers_by_module

The calls manage the hash of module => tracer_fn, allowing client
modules to provide a callback function to handle any +T'd pr_debugs.
__dynamic_pr_debug etal get print-to-trace code.

If drm registers a callback, one could then do:

  echo module drm* format ^drm:atomic:fail: +T > /proc/dynamic_debug/control

to enable tracing on arbitrary groups of prdbgs, or categorized ones.

A client module must connect to tracefs, and provide a printk-ish
function to write to it, and register that function.  It should
unregister the same callback it registered, to allow adding modest
protection against tracefn 'pirating' (unregistering yours,
registering theirs)

SELFTEST: test_dynamic_debug.ko:

Uses the tracer facility to implement a selftest:
(that doesn't involve watching syslog)

- 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:

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:

I'm not crazy about dyndbg_register_tracer()s THIS_MODULE arg, but I
need &mod->name to use as the hashkey; this value is known ptr-equal
to the modname ptr embedded in ddebug_tables, as guaranteed (in part)
by:

4573fe1 dynamic_debug: use pointer comparison in ddebug_remove_module
cdf6d00 dynamic_debug: don't duplicate modname in ddebug_add_module

For pr_debug(), that key is available via (struct _ddebug *)desc->modname.

$> 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.

__dynamic_pr_debug() pr_warns if +T w/o a registered tracer, I tried a
WARN_ONCE, got a -cut-here- panic-once, so backed off that.  This
probably should be done with some validation on +T ops instead, but
the bikeshed awaits;

- only allowed on queries with a module specified ?
- enable +T on any registrant module ?
- ignore +T if no registrant on module ?
  this is probably simplest, to do and to explain.
- should unregister also do "module foo -T" automatically ?

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

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>

include/linux/dynamic_debug.h

@@ -27,7 +27,11 @@ struct _ddebug {
 	 * writes commands to <debugfs>/dynamic_debug/control
 	 */
 #define _DPRINTK_FLAGS_NONE	0
-#define _DPRINTK_FLAGS_PRINT	(1<<0) /* printk() a message using the format */
+#define _DPRINTK_FLAGS_PRINT		(1<<0) /* printk() a message */
+#define _DPRINTK_FLAGS_PRINT_TRACE	(1<<5) /* call (*tracefn) */
+
+#define _DPRINTK_ENABLED (_DPRINTK_FLAGS_PRINT | _DPRINTK_FLAGS_PRINT_TRACE)
+
 #define _DPRINTK_FLAGS_INCL_MODNAME	(1<<1)
 #define _DPRINTK_FLAGS_INCL_FUNCNAME	(1<<2)
 #define _DPRINTK_FLAGS_INCL_LINENO	(1<<3)
@@ -282,4 +286,9 @@ extern const struct kernel_param_ops param_ops_dyndbg;
 #endif
 #endif /* DYNDBG || _CORE &&_MODULE */
 
+int dynamic_debug_register_tracer(struct module *mod,
+				   void (*tracefn)(const char *lbl, struct va_format *vaf));
+int dynamic_debug_unregister_tracer(struct module *mod,
+				     void (*tracefn)(const char *lbl, struct va_format *vaf));
+
 #endif

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

@@ -67,6 +67,21 @@ struct flag_settings {
 	unsigned int mask;
 };
 
+struct ddebug_tracer {
+	struct hlist_node hnode;
+	u64 key;
+	void (*tracefn)(const char *lbl, struct va_format *vaf);
+};
+static DEFINE_HASHTABLE(ddebug_tracer_by_module, 6);
+/*
+ * This hashtable holds tracer-fns registered by modules wanting to
+ * trace their pr_debugs (or some subset of them).  For the key, we
+ * need to use something readily available from a pr_debug descriptor,
+ * which also has the uniqueness properties we want; the decorator
+ * fields/columns (modname, filename, function) in the __dyndbg table,
+ * packed by the linker, are suitable.
+ */
+
 static DEFINE_MUTEX(ddebug_lock);
 static LIST_HEAD(ddebug_tables);
 static int verbose;
@@ -85,6 +100,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_PRINT_TRACE, 'T' },
 	{ _DPRINTK_FLAGS_INCL_MODNAME, 'm' },
 	{ _DPRINTK_FLAGS_INCL_FUNCNAME, 'f' },
 	{ _DPRINTK_FLAGS_INCL_LINENO, 'l' },
@@ -207,11 +223,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 (dp->flags & _DPRINTK_ENABLED) {
+				if (!(modifiers->flags & _DPRINTK_ENABLED))
 					static_branch_disable(&dp->key.dd_key_true);
-			} else if (modifiers->flags & _DPRINTK_FLAGS_PRINT)
+			} else if (modifiers->flags & _DPRINTK_ENABLED)
 				static_branch_enable(&dp->key.dd_key_true);
 #endif
 			dp->flags = newflags;
@@ -702,11 +719,14 @@ static inline char *dynamic_emit_prefix(struct _ddebug *desc, char *buf)
 	return buf;
 }
 
+static struct ddebug_tracer *ddebug_tracer_fetch(struct _ddebug *desc);
+
 void __dynamic_pr_debug(struct _ddebug *descriptor, const char *fmt, ...)
 {
 	va_list args;
 	struct va_format vaf;
 	char buf[PREFIX_SIZE] = "";
+	struct ddebug_tracer *trc;
 
 	BUG_ON(!descriptor);
 	BUG_ON(!fmt);
@@ -716,8 +736,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);
+	if (descriptor->flags & _DPRINTK_ENABLED)
+		dynamic_emit_prefix(descriptor, buf);
+
+	if (descriptor->flags & _DPRINTK_FLAGS_PRINT)
+		printk(KERN_DEBUG "%s%pV", buf, &vaf);
 
+	if (descriptor->flags & _DPRINTK_FLAGS_PRINT_TRACE) {
+		trc = ddebug_tracer_fetch(descriptor);
+		if (trc)
+			(*trc->tracefn)(buf, &vaf);
+		/* else warn_once ? */
+	}
 	va_end(args);
 }
 EXPORT_SYMBOL(__dynamic_pr_debug);
@@ -1233,3 +1263,136 @@ early_initcall(dynamic_debug_init);
 
 /* Debugfs setup must be done later */
 fs_initcall(dynamic_debug_init_control);
+
+static struct ddebug_tracer *ddebug_tracer_find(const char *modname)
+{
+	struct ddebug_tracer *trc;
+
+	hash_for_each_possible(ddebug_tracer_by_module, trc, hnode, (unsigned long)modname)
+		if (trc->key == (u64)modname)
+			return trc;
+
+	return NULL;
+}
+
+/* called when pr_debug has +T */
+static struct ddebug_tracer *ddebug_tracer_fetch(struct _ddebug *desc)
+{
+	struct ddebug_tracer *trc;
+
+	v4pr_info("fetch tracer for %s.%s.%d: 0x%x\n", desc->modname, desc->function, desc->lineno,
+		  desc->flags & _DPRINTK_FLAGS_PRINT_TRACE);
+
+	trc = ddebug_tracer_find(desc->modname);
+	if (trc)
+		v4pr_info("found tracer for %s\n", desc->modname);
+
+	else if (desc->flags & _DPRINTK_FLAGS_PRINT_TRACE)
+		pr_notice("missed tracer for %s\n", desc->modname);
+
+	return trc;
+}
+
+/*
+ * key computation is done on insert, such that lookup is trivial.
+ * We use the modname ref in the 1st ddebug descriptor, the others in
+ * the table are identical, giving us the module-scope lookup we want.
+ */
+static int ddebug_tracer_add(void (*tracer)(const char *lbl, struct va_format *vaf),
+			     struct module *mod, struct ddebug_table *dt)
+{
+	struct ddebug_tracer *trc;
+
+	trc = ddebug_tracer_find(dt->ddebugs[0].modname);
+	if (trc) {
+		pr_warn("tracer-fn already set for %s\n", mod->name);
+		return -1;
+	}
+	trc = kmalloc(sizeof(*trc), GFP_ATOMIC);
+	if (!trc)
+		return -ENOMEM;
+
+	trc->tracefn = tracer;
+	trc->key = (u64)dt->ddebugs[0].modname;
+	hash_add(ddebug_tracer_by_module, &trc->hnode, (u64)dt->ddebugs[0].modname);
+
+	vpr_info("added tracer-fn for module %s\n", dt->ddebugs[0].modname);
+
+	return 0;
+}
+
+static int ddebug_tracer_del(void (*tracer)(const char *lbl, struct va_format *vaf),
+			     struct module *mod, struct ddebug_table *dt)
+{
+	struct ddebug_tracer *trc;
+
+	trc = ddebug_tracer_find(dt->ddebugs[0].modname);
+	if (!trc) {
+		pr_warn("delete: cant find tracer for %s\n", mod->name);
+		return -1;
+	}
+	hash_del(&trc->hnode);
+	vpr_info("deleted tracer for %s\n", mod->name);
+
+	kfree(trc);
+	return 0;
+}
+
+static int __dynamic_debug_tracer_action(int (*action)
+					  (void (*tracer)
+					   (const char *lbl, struct va_format *vaf),
+					   struct module *mod, struct ddebug_table *dt),
+					  void (*tracer)(const char *lbl, struct va_format *vaf),
+					  struct module *mod)
+{
+	int rc = 0;
+	struct ddebug_table *dt;
+
+	mutex_lock(&ddebug_lock);
+	list_for_each_entry(dt, &ddebug_tables, link) {
+
+		/* want stronger ptr-eq, have strcmp to see if otherwize */
+		if (mod->name == dt->mod_name) {
+			rc = (*action)(tracer, mod, dt);
+			break;
+		}
+		if (!strcmp(mod->name, dt->mod_name)) {
+			vpr_info("streq !=== ptreq");
+			rc = (*action)(tracer, mod, dt);
+			break;
+		}
+	}
+	mutex_unlock(&ddebug_lock);
+	return rc;
+}
+/**
+ * dynamic_debug_register_tracer - register a "printer" function for module
+ * @modref: caller's THIS_MODULE
+ * @tracefn: printf-to-tracefs
+ *
+ * Attach a trace-print callback for the module, to enable tracing of pr_debugs.
+ */
+int dynamic_debug_register_tracer(struct module *mod,
+				   void (*tracefn)(const char *lbl, struct va_format *vaf))
+{
+	vpr_info("%s %s\n", __func__, mod->name);
+	return __dynamic_debug_tracer_action(ddebug_tracer_add, tracefn, mod);
+}
+EXPORT_SYMBOL(dynamic_debug_register_tracer);
+
+/**
+ * dynamic_debug_unregister_tracer - unregister your "printer" function
+ * @modref: caller's THIS_MODULE
+ * @tracefn: reserved to validate unregisters against pirates
+ *
+ * Detach the trace-print callback for the module. @tracer may be checked
+ * against registrant fn before unregistering, as a modest protection
+ * against tracer takeover.
+ */
+int dynamic_debug_unregister_tracer(struct module *mod,
+				     void (*tracefn)(const char *lbl, struct va_format *vaf))
+{
+	vpr_info("%s %s\n", __func__, mod->name);
+	return __dynamic_debug_tracer_action(ddebug_tracer_del, tracefn, mod);
+}
+EXPORT_SYMBOL(dynamic_debug_unregister_tracer);