dyndbg: RFC add debug-trace callback, selftest with it. RFC

Sean Paul seanpaul@chromium.org 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 with a drm.debug_trace knob.

2 advantages are identified:
  - syslog is heavyweight, alternate stream is lighter
  - steering selected categories separately means less traffic

Dynamic-Debug can do this better:

1- all work is behind jump-label's NOOP, Zero overhead when off.

2- perfect site selectivity, no unwanted traffic.

drm's debug categories are a general classification system, not one
tailored to pick out the exact pool of pr_debugs to watch/trace.

With drm.debug built on dyndbg, the given "drm:<cat>:" system can be
used to select a base trace-set, which can then be adjusted +/-,
and/or augmented with unrelated pr_debugs that just happen to be
useful.  And this tweaking can be done at the command-line, and
reduced to a script.

Then the string-prefix "drm:<cat>:" system can be extended to suit.

The basic elements:

 - add a new struct _ddebug member: (*tracer)(char *format, ...)
 - add a new T flag to enable tracer
 - adjust the static-key-enable/disable condition for (p|T)
 - if (p) before printk, since T enables too.
 - if (T) call tracer if its true

 = int dynamic_debug_register_tracer(query, modname, tracer);
 = int dynamic_debug_unregister_tracer(query, modname, cookie);

This new interface lets clients set/unset a tracer function on each
callsite matching the query, for example: "drm:atomic:fail:".

Clients must unregister the same callsites they register, allowing
protection of each client's dyndbg-state setup against overwrites by
others, while allowing maximal sharing of 1 slot/callsite.

The internal call-chain gets some rework: it gets new void* tracer
param, which dynamic_debug_exec_queries() hides from public.

And convert ddebug_exec_queries() to wrap __ddebug_exec_queries(), and
move the query copy code to it.

public:					passing down:
  dynamic_debug_(un)register_tracer	tracer
  dynamic_debug_exec_queries		tracer=NULL
  calling:
      ddebug_exec_queries		copies ro-query, tracer
          __ddebug_exec_queries		modifies query, tracer
              ddebug_exec_query		modifies query, tracer

Then adjust most ddebug_exec_queries users to __ddebug_exec_queries

Intended Behavior: (things are in flux, RFC)

- register sets empty slot, doesn't overwrite
  the query selects callsites, and sets +T (grammar requires +-action)

- register allows same-tracer over-set wo warn
  2nd register can then enable superset, subset, disjoint set

- unregister clears slot if it matches cookie/tracer
  query selects set, -T (as tested)
  tolerates over-clears

- dd-exec-queries(+/-T) can modify the enablements
  not sure its needed, but it falls out..

The code is currently in-line in ddebug_change(), to be moved to
separate fn, rc determines flow, may also veto/alter changes by
altering flag-settings - tbd.

TBD: Im not sure what happens when exec-queries(+T) hits a site wo a
tracer (silence I think. maybe not ideal).

SELFTEST: test_dynamic_debug.ko:

Uses the tracer facility to implement a selftest:

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

- test registers the tracer on the function,
  then iteratively:
  manipulates dyndbg states via query-cmds
  calls DUT(x)
  counts enabled callsite executions
  reports mismatches

- modprobe test_dynamic_debug broken_tracer=1
  attaches a broken tracer: recursive on pr_debug
  Bad Things Happen.
  has thrown me interesting panics.

This needs more work. RFC.
waste of time due to use_bad_tracer properties ?

NOTES:

Next step: replace tracer member with a hashtable lookup, done only
when T.  Registration then becomes populating the hashtable; mod->name
would make a good key, which would limit tracer mapping granularity to
1 registrant per module, but not enablement, which is still the
per-callsite bit.

ERRORS (or WARNINGS):

It should be an error to +T a callsite which has no aux_print set (ie
already registered with a query that selected that callsite).  This
tacitly enforces registration.

Then +T,-T can toggle those aux_print callsites (or subsets of them)
to tailor the debug-stream for the purpose.  Controlling flow is the
best work limiter.

Signed-off-by: Jim Cromie <jim.cromie@gmail.com>

include/linux/dynamic_debug.h

@@ -20,14 +20,19 @@ struct _ddebug {
 	const char *function;
 	const char *filename;
 	const char *format;
+	int (*tracer)(const char *fmt, char *prefix, char *label, struct va_format *vaf);
 	unsigned int lineno:18;
 	/*
 	 * The flags field controls the behaviour at the callsite.
 	 * The bits here are changed dynamically when the user
 	 * 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 (*tracer) */
+
+#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)
@@ -277,4 +282,9 @@ extern const struct kernel_param_ops param_ops_dyndbg;
 #define _DD_cat_help_(pfx)
 #endif
 
+int dynamic_debug_register_tracer(const char *query, const char *mod,
+	int (*tracer)(const char *fmt, char *prefix, char *label, struct va_format *vaf));
+int dynamic_debug_unregister_tracer(const char *query, const char *mod,
+	int (*cookie)(const char *fmt, char *prefix, char *label, struct va_format *vaf));
+
 #endif

lib/Kconfig.debug

@@ -2483,6 +2483,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

@@ -85,6 +85,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' },
@@ -146,7 +147,8 @@ static void vpr_info_dq(const struct ddebug_query *query, const char *msg)
  * logs the changes.  Takes ddebug_lock.
  */
 static int ddebug_change(const struct ddebug_query *query,
-			 struct flag_settings *modifiers)
+			 struct flag_settings *modifiers,
+			 int (*tracer)(const char *, char *, char *, struct va_format *))
 {
 	int i;
 	struct ddebug_table *dt;
@@ -205,11 +207,42 @@ static int ddebug_change(const struct ddebug_query *query,
 			newflags = (dp->flags & modifiers->mask) | modifiers->flags;
 			if (newflags == dp->flags)
 				continue;
+
+			/* handle T flag */
+			if (newflags & _DPRINTK_FLAGS_PRINT_TRACE) {
+				if (!tracer)
+					v2pr_info("ok: tracer enable\n");
+				else {
+					/* register attempt */
+					if (!dp->tracer) {
+						v2pr_info("register tracer\n");
+						dp->tracer = tracer;
+
+					} else if (tracer == dp->tracer)
+						v2pr_info("ok: tracer over-set\n");
+					else
+						pr_warn("tracer register error\n");
+				}
+			} else if (dp->flags & _DPRINTK_FLAGS_PRINT_TRACE) {
+				if (!tracer)
+					v2pr_info("ok: disable\n");
+				else {
+					/* only unregister has a !!tracer */
+					if (!dp->tracer)
+						pr_warn("nok: tracer already unset\n");
+
+					else if (dp->tracer == tracer) {
+						v2pr_info("ok: cookie match, unregistering\n");
+						dp->tracer = NULL;
+					} else
+						pr_warn("nok: tracer cookie match fail\n");
+				}
+			}
 #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;
@@ -482,7 +515,7 @@ static int ddebug_parse_flags(const char *str, struct flag_settings *modifiers)
 	return 0;
 }
 
-static int ddebug_exec_query(char *query_string, const char *modname)
+static int ddebug_exec_query(char *query_string, const char *modname, void *tracer)
 {
 	struct flag_settings modifiers = {};
 	struct ddebug_query query = {};
@@ -505,7 +538,7 @@ static int ddebug_exec_query(char *query_string, const char *modname)
 		return -EINVAL;
 	}
 	/* actually go and implement the change */
-	nfound = ddebug_change(&query, &modifiers);
+	nfound = ddebug_change(&query, &modifiers, tracer);
 	vpr_info_dq(&query, nfound ? "applied" : "no-match");
 
 	return nfound;
@@ -516,7 +549,7 @@ static int ddebug_exec_query(char *query_string, const char *modname)
  * last error or number of matching callsites.  Module name is either
  * in param (for boot arg) or perhaps in query string.
  */
-static int ddebug_exec_queries(char *query, const char *modname)
+static int __ddebug_exec_queries(char *query, const char *modname, void *tracer)
 {
 	char *split;
 	int i, errs = 0, exitcode = 0, rc, nfound = 0;
@@ -532,7 +565,7 @@ static int ddebug_exec_queries(char *query, const char *modname)
 
 		vpr_info("query %d: \"%s\" %s\n", i, query, (modname) ? modname : "");
 
-		rc = ddebug_exec_query(query, modname);
+		rc = ddebug_exec_query(query, modname, tracer);
 		if (rc < 0) {
 			errs++;
 			exitcode = rc;
@@ -549,32 +582,35 @@ static int ddebug_exec_queries(char *query, const char *modname)
 	return nfound;
 }
 
+static int ddebug_exec_queries(const char *query_in, const char *modname, void *tracer)
+{
+	int rc;
+
+	if (!query_in) {
+		pr_err("non-null query/command string expected\n");
+		return -EINVAL;
+	}
+	query = kstrndup(query_in, PAGE_SIZE, GFP_KERNEL);
+	if (!query)
+		return -ENOMEM;
+
+	rc = __ddebug_exec_queries(query, modname, tracer);
+	kfree(query);
+	return rc;
+
 /**
  * dynamic_debug_exec_queries - select and change dynamic-debug prints
  * @query: query-string described in admin-guide/dynamic-debug-howto
  * @modname: string containing module name, usually &module.mod_name
  *
  * This uses the >/proc/dynamic_debug/control reader, allowing module
  * authors to modify their dynamic-debug callsites. The modname is
- * canonically struct module.mod_name, but can also be null or a
+ * canonically struct module.name, but can also be null or a
  * module-wildcard, for example: "drm*".
  */
 int dynamic_debug_exec_queries(const char *query, const char *modname)
 {
-	int rc;
-	char *qry; /* writable copy of query */
-
-	if (!query) {
-		pr_err("non-null query/command string expected\n");
-		return -EINVAL;
-	}
-	qry = kstrndup(query, PAGE_SIZE, GFP_KERNEL);
-	if (!qry)
-		return -ENOMEM;
-
-	rc = ddebug_exec_queries(qry, modname);
-	kfree(qry);
-	return rc;
+	return ddebug_exec_queries(qry, modname, NULL);
 }
 EXPORT_SYMBOL_GPL(dynamic_debug_exec_queries);
 
@@ -603,7 +639,7 @@ int param_set_dyndbg(const char *instr, const struct kernel_param *kp)
 	}
 	rc = kstrtoul(instr, 0, &inbits);
 	if (rc) {
-		pr_err("set_dyndbg: failed\n");
+		pr_err("set_dyndbg: bad input: %s\n", instr);
 		return rc;
 	}
 	vpr_info("set_dyndbg: input 0x%lx\n", inbits);
@@ -612,7 +648,7 @@ int param_set_dyndbg(const char *instr, const struct kernel_param *kp)
 		snprintf(query, FMT_QUERY_SIZE, "format '^%s' %cp", bitmap->prefix,
 			 test_bit(i, &inbits) ? '+' : '-');
 
-		matches = ddebug_exec_queries(query, KP_MOD_NAME);
+		matches = __ddebug_exec_queries(query, KP_MOD_NAME, NULL);
 
 		v2pr_info("bit-%d: %d matches on '%s'\n", i, matches, query);
 		totct += matches;
@@ -703,8 +739,20 @@ 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) {
 
+		if (descriptor->tracer) {
+			(*descriptor->tracer)("%s:%ps %pV", buf,
+						 __builtin_return_address(0), &vaf);
+		}
+		/* else shouldn't matter, but maybe for consistency */
+	}
 	va_end(args);
 }
 EXPORT_SYMBOL(__dynamic_pr_debug);
@@ -849,7 +897,7 @@ static ssize_t ddebug_proc_write(struct file *file, const char __user *ubuf,
 		return PTR_ERR(tmpbuf);
 	vpr_info("read %d bytes from userspace\n", (int)len);
 
-	ret = ddebug_exec_queries(tmpbuf, NULL);
+	ret = __ddebug_exec_queries(tmpbuf, NULL, NULL);
 	kfree(tmpbuf);
 	if (ret < 0)
 		return ret;
@@ -1055,7 +1103,7 @@ static int ddebug_dyndbg_param_cb(char *param, char *val,
 	if (strcmp(param, "dyndbg"))
 		return on_err; /* determined by caller */
 
-	ddebug_exec_queries((val ? val : "+p"), modname);
+	__ddebug_exec_queries((val ? val : "+p"), modname, NULL);
 
 	return 0; /* query failure shouldn't stop module load */
 }
@@ -1190,7 +1238,7 @@ static int __init dynamic_debug_init(void)
 	/* apply ddebug_query boot param, dont unload tables on err */
 	if (ddebug_setup_string[0] != '\0') {
 		pr_warn("ddebug_query param name is deprecated, change it to dyndbg\n");
-		ret = ddebug_exec_queries(ddebug_setup_string, NULL);
+		ret = __ddebug_exec_queries(ddebug_setup_string, NULL, NULL);
 		if (ret < 0)
 			pr_warn("Invalid ddebug boot param %s\n",
 				ddebug_setup_string);
@@ -1220,3 +1268,42 @@ early_initcall(dynamic_debug_init);
 
 /* Debugfs setup must be done later */
 fs_initcall(dynamic_debug_init_control);
+
+/**
+ * dynamic_debug_register_tracer() - register a "printer" function
+ * @query:   query-command string to select callsites getting the function
+ * @modname: added into query-command, may include wildcards
+ * @tracer:  &vprintf-ish accepting 3 char* ptrs & a vaf
+ *
+ * Attach a tracer callback callsites selected by the query.  If
+ * another tracer is already attached, warn and skip, applying the
+ * rest of the query.  This protects existing setups, while allowing
+ * maximal coexistence of (mostly) non-competing listeners. RFC.
+ *
+ * Returns: <0   error
+ *	    >=0  matches on query, not changes by query
+ */
+int dynamic_debug_register_tracer(const char *query, const char *modname,
+	int (*tracer)(const char *fmt, char *prefix, char *label, struct va_format *vaf))
+{
+	return ddebug_exec_queries(query, modname, tracer);
+}
+EXPORT_SYMBOL(dynamic_debug_register_tracer);
+
+/**
+ * dynamic_debug_unregister_tracer - unregister your "printer" function
+ * @query:   query-command string to select callsites to reset
+ * @modname: name of module, or search string (ex: "drm*"), or null
+ * @tracer:  reserved to validate unregisters against pirates
+ *
+ * Detach the tracer callback from callsites selected by the query, if
+ * it matches the callsite's tracer.  This protects existing setups,
+ * while allowing maximal coexistence of (mostly) non-competing
+ * listeners. RFC.
+ */
+int dynamic_debug_unregister_tracer(const char *query, const char *modname,
+	int (*tracer)(const char *fmt, char *prefix, char *label, struct va_format *vaf))
+{
+	return ddebug_exec_queries(query, modname, tracer);
+}
+EXPORT_SYMBOL(dynamic_debug_unregister_tracer);