[PATCH v6 00/11] use DYNAMIC_DEBUG to implement DRM.debug

[PATCH v6 00/11] use DYNAMIC_DEBUG to implement DRM.debug

[Jim Cromie]

This patchset does 3 main things.

Adds DEFINE_DYNAMIC_DEBUG_CATEGORIES to define bitmap => category
control of pr_debugs, and to create their sysfs entries.

Uses it in amdgpu, i915 to control existing pr_debugs according to
their ad-hoc categorizations.

Plugs dyndbg into drm-debug framework, in a configurable manner.

v6: cleans up per v5 feedback, and adds RFC stuff:

- test_dynamic_debug.ko: uses tracer facility added in v5:8/9
- prototype print-once & rate-limiting

Hopefully adding RFC stuff doesnt distract too much.

Jim Cromie (11):
  moduleparam: add data member to struct kernel_param
  dyndbg: add DEFINE_DYNAMIC_DEBUG_CATEGORIES and callbacks
  i915/gvt: remove spaces in pr_debug "gvt: core:" etc prefixes
  i915/gvt: use DEFINE_DYNAMIC_DEBUG_CATEGORIES to create "gvt:core:"
    etc categories
  amdgpu: use DEFINE_DYNAMIC_DEBUG_CATEGORIES to control categorized
    pr_debugs
  drm_print: add choice to use dynamic debug in drm-debug
  drm_print: instrument drm_debug_enabled
  amdgpu_ucode: reduce number of pr_debug calls
  nouveau: fold multiple DRM_DEBUG_DRIVERs together
  dyndbg: RFC add debug-trace callback, selftest with it. RFC
  dyndbg: RFC add print-once and print-ratelimited features. RFC.

 drivers/gpu/drm/Kconfig                       |  13 +
 drivers/gpu/drm/amd/amdgpu/amdgpu_ucode.c     | 293 ++++++++-------
 .../gpu/drm/amd/display/dc/core/dc_debug.c    |  44 ++-
 drivers/gpu/drm/drm_print.c                   |  49 ++-
 drivers/gpu/drm/i915/gvt/Makefile             |   4 +
 drivers/gpu/drm/i915/gvt/debug.h              |  18 +-
 drivers/gpu/drm/i915/i915_params.c            |  35 ++
 drivers/gpu/drm/nouveau/nouveau_drm.c         |  36 +-
 include/drm/drm_print.h                       | 148 ++++++--
 include/linux/dynamic_debug.h                 |  81 ++++-
 include/linux/moduleparam.h                   |  11 +-
 lib/Kconfig.debug                             |  11 +
 lib/Makefile                                  |   1 +
 lib/dynamic_debug.c                           | 336 ++++++++++++++++--
 lib/test_dynamic_debug.c                      | 279 +++++++++++++++
 15 files changed, 1117 insertions(+), 242 deletions(-)
 create mode 100644 lib/test_dynamic_debug.c

-- 
2.31.1

[PATCH v6 01/11] moduleparam: add data member to struct kernel_param

[Jim Cromie]

Add a const void* data member to the struct, to allow attaching
private data that will be used soon by a setter method (via kp->data)
to perform more elaborate actions.

To attach the data at compile time, add new macros:

module_param_cb_data() derives from module_param_cb(), adding data
param, and latter is redefined to use former.

It calls __module_param_call_with_data(), which accepts new data param
and inits .data with it. Re-define __module_param_call() to use it.

Use of this new data member will be rare, it might be worth redoing
this as a separate/sub-type to de-bloat the base case.

Signed-off-by: Jim Cromie <jim.cromie@gmail.com>
---
v6:
. const void* data - <emil.l.velikov@gmail.com>
. better macro names s/_cbd/_cb_data/, s/_wdata/_with_data/
. more const, no cast - Willy
---
 include/linux/moduleparam.h | 11 +++++++++--
 1 file changed, 9 insertions(+), 2 deletions(-)

diff --git a/include/linux/moduleparam.h b/include/linux/moduleparam.h
index eed280fae433..b8871e514de5 100644
--- a/include/linux/moduleparam.h
+++ b/include/linux/moduleparam.h
@@ -78,6 +78,7 @@ struct kernel_param {
 		const struct kparam_string *str;
 		const struct kparam_array *arr;
 	};
+	const void *data;
 };
 
 extern const struct kernel_param __start___param[], __stop___param[];
@@ -175,6 +176,9 @@ struct kparam_array
 #define module_param_cb(name, ops, arg, perm)				      \
 	__module_param_call(MODULE_PARAM_PREFIX, name, ops, arg, perm, -1, 0)
 
+#define module_param_cb_data(name, ops, arg, perm, data)			\
+	__module_param_call_with_data(MODULE_PARAM_PREFIX, name, ops, arg, perm, -1, 0, data)
+
 #define module_param_cb_unsafe(name, ops, arg, perm)			      \
 	__module_param_call(MODULE_PARAM_PREFIX, name, ops, arg, perm, -1,    \
 			    KERNEL_PARAM_FL_UNSAFE)
@@ -284,14 +288,17 @@ struct kparam_array
 
 /* This is the fundamental function for registering boot/module
    parameters. */
-#define __module_param_call(prefix, name, ops, arg, perm, level, flags)	\
+#define __module_param_call(prefix, name, ops, arg, perm, level, flags) \
+	__module_param_call_with_data(prefix, name, ops, arg, perm, level, flags, NULL)
+
+#define __module_param_call_with_data(prefix, name, ops, arg, perm, level, flags, data) \
 	/* Default value instead of permissions? */			\
 	static const char __param_str_##name[] = prefix #name;		\
 	static struct kernel_param __moduleparam_const __param_##name	\
 	__used __section("__param")					\
 	__aligned(__alignof__(struct kernel_param))			\
 	= { __param_str_##name, THIS_MODULE, ops,			\
-	    VERIFY_OCTAL_PERMISSIONS(perm), level, flags, { arg } }
+	    VERIFY_OCTAL_PERMISSIONS(perm), level, flags, { arg }, data }
 
 /* Obsolete - use module_param_cb() */
 #define module_param_call(name, _set, _get, arg, perm)			\
-- 
2.31.1

Re: [PATCH v6 01/11] moduleparam: add data member to struct kernel_param

[Jason Baron]

On 8/22/21 6:19 PM, Jim Cromie wrote:
> Add a const void* data member to the struct, to allow attaching
> private data that will be used soon by a setter method (via kp->data)
> to perform more elaborate actions.
> 
> To attach the data at compile time, add new macros:
> 
> module_param_cb_data() derives from module_param_cb(), adding data
> param, and latter is redefined to use former.
> 
> It calls __module_param_call_with_data(), which accepts new data param
> and inits .data with it. Re-define __module_param_call() to use it.
> 
> Use of this new data member will be rare, it might be worth redoing
> this as a separate/sub-type to de-bloat the base case.
> 
> Signed-off-by: Jim Cromie <jim.cromie@gmail.com>
> ---
> v6:
> . const void* data - <emil.l.velikov@gmail.com>
> . better macro names s/_cbd/_cb_data/, s/_wdata/_with_data/
> . more const, no cast - Willy
> ---
>  include/linux/moduleparam.h | 11 +++++++++--
>  1 file changed, 9 insertions(+), 2 deletions(-)
> 
> diff --git a/include/linux/moduleparam.h b/include/linux/moduleparam.h
> index eed280fae433..b8871e514de5 100644
> --- a/include/linux/moduleparam.h
> +++ b/include/linux/moduleparam.h
> @@ -78,6 +78,7 @@ struct kernel_param {
>  		const struct kparam_string *str;
>  		const struct kparam_array *arr;
>  	};
> +	const void *data;
>  };
>  


I wonder if kp->arg can just be used for all this and avoid this patch entirely?

define something like:

struct dd_bitmap_param {
	int bitmap;
	struct dyndbg_bitdesc *bitmap_arr;
};

and then just pass a pointer to it as 'arg' for module_param_cb? And then in
the get/set callbacks you can use kp->bitmap and kp->bitmap_arr.

Thanks,

-Jason

>  extern const struct kernel_param __start___param[], __stop___param[];
> @@ -175,6 +176,9 @@ struct kparam_array
>  #define module_param_cb(name, ops, arg, perm)				      \
>  	__module_param_call(MODULE_PARAM_PREFIX, name, ops, arg, perm, -1, 0)
>  
> +#define module_param_cb_data(name, ops, arg, perm, data)			\
> +	__module_param_call_with_data(MODULE_PARAM_PREFIX, name, ops, arg, perm, -1, 0, data)
> +
>  #define module_param_cb_unsafe(name, ops, arg, perm)			      \
>  	__module_param_call(MODULE_PARAM_PREFIX, name, ops, arg, perm, -1,    \
>  			    KERNEL_PARAM_FL_UNSAFE)
> @@ -284,14 +288,17 @@ struct kparam_array
>  
>  /* This is the fundamental function for registering boot/module
>     parameters. */
> -#define __module_param_call(prefix, name, ops, arg, perm, level, flags)	\
> +#define __module_param_call(prefix, name, ops, arg, perm, level, flags) \
> +	__module_param_call_with_data(prefix, name, ops, arg, perm, level, flags, NULL)
> +
> +#define __module_param_call_with_data(prefix, name, ops, arg, perm, level, flags, data) \
>  	/* Default value instead of permissions? */			\
>  	static const char __param_str_##name[] = prefix #name;		\
>  	static struct kernel_param __moduleparam_const __param_##name	\
>  	__used __section("__param")					\
>  	__aligned(__alignof__(struct kernel_param))			\
>  	= { __param_str_##name, THIS_MODULE, ops,			\
> -	    VERIFY_OCTAL_PERMISSIONS(perm), level, flags, { arg } }
> +	    VERIFY_OCTAL_PERMISSIONS(perm), level, flags, { arg }, data }
>  
>  /* Obsolete - use module_param_cb() */
>  #define module_param_call(name, _set, _get, arg, perm)			\
> 

Re: [PATCH v6 01/11] moduleparam: add data member to struct kernel_param

[jim.cromie]

On Wed, Aug 25, 2021 at 11:13 AM Jason Baron <jbaron@akamai.com> wrote:
>
>
>
> On 8/22/21 6:19 PM, Jim Cromie wrote:
> > Add a const void* data member to the struct, to allow attaching
> > private data that will be used soon by a setter method (via kp->data)
> > to perform more elaborate actions.
> >
> > To attach the data at compile time, add new macros:
> >

>
> I wonder if kp->arg can just be used for all this and avoid this patch entirely?
>
> define something like:
>
> struct dd_bitmap_param {
>         int bitmap;
>         struct dyndbg_bitdesc *bitmap_arr;
> };
>
> and then just pass a pointer to it as 'arg' for module_param_cb? And then in
> the get/set callbacks you can use kp->bitmap and kp->bitmap_arr.
>

yes, thanks, this is working out nicely.
I think I was thrown off by the arg name,
if it had been called data, it would have slapped me

> Thanks,
>
> -Jason
>

[PATCH v6 02/11] dyndbg: add DEFINE_DYNAMIC_DEBUG_CATEGORIES and callbacks

[Jim Cromie]

DEFINE_DYNAMIC_DEBUG_CATEGORIES(name, var, bitmap_desc, @bit_descs)
allows users to define a drm.debug style (bitmap) sysfs interface, and
to specify the desired mapping from bits[0-N] to the format-prefix'd
pr_debug()s to be controlled.

DEFINE_DYNAMIC_DEBUG_CATEGORIES(debug_gvt, __gvt_debug,
	"i915/gvt bitmap desc",
	/**
	 * search-prefixes, passed to dd-exec_queries
	 * defines bits 0-N in order.
	 * leading ^ is tacitly inserted (by callback currently)
	 * trailing space used here excludes subcats.
	 * helper macro needs more work
	 * macro to autogen ++$i, 0x%x$i ?
	 */
	_DD_cat_("gvt:cmd: "),
	_DD_cat_("gvt:core: "),
	_DD_cat_("gvt:dpy: "),
	_DD_cat_("gvt:el: "),
	_DD_cat_("gvt:irq: "),
	_DD_cat_("gvt:mm: "),
	_DD_cat_("gvt:mmio: "),
	_DD_cat_("gvt:render: "),
	_DD_cat_("gvt:sched: "));

dynamic_debug.c: add 3 new elements:

 - int param_set_dyndbg()
 - int param_get_dyndbg()
 - struct kernel_param_ops param_ops_dyndbg

Following the model of kernel/params.c STANDARD_PARAM_DEFS, All 3 are
non-static and exported.

dynamic_debug.h:

Add DEFINE_DYNAMIC_DEBUG_CATEGORIES() described above, and a do-nothing stub.

Note that it also calls MODULE_PARM_DESC for the user, but expects the
user to catenate all the bit-descriptions together (as is done in
drm.debug), and in the following uses in amdgpu, i915.

This in the hope that someone can offer an auto-incrementing
label-generating macro, producing "\tbit-4 0x10\t" etc, and can show
how to apply it to __VA_ARGS__.

Also extern the struct kernel_param param_ops_dyndbg symbol, as is
done in moduleparams.h for all the STANDARD params.

USAGE NOTES:

Using dyndbg to query on "format ^$prefix" requires that the prefix be
present in the compiled-in format string; where run-time prefixing is
used, that format would be "%s...", which is not usefully selectable.

Adding structural query terms (func,file,lineno) could help (module is
already done), but DEFINE_DYNAMIC_DEBUG_CATEGORIES can't do that now,
adding it needs a better reason imo.

Dyndbg is completely agnostic wrt the categorization scheme used, to
play well with any prefix convention already in use.  Ad-hoc
categories and sub-categories are implicitly allowed, author
discipline and review is expected.

Here are some examples:

"1","2","3"		2 doesn't imply 1.
   			otherwize, sorta like printk levels
"1:","2:","3:"		are better, avoiding [1-9]\d+ ambiguity
"hi:","mid:","low:"	are reasonable, and imply independence
"todo:","rfc:","fixme:" might be handy
"A:".."Z:"		uhm, yeah

Hierarchical classes/categories are natural:

"drm:<CAT>:"		is used in later commit
"drm:<CAT>:<SUB>:"	is a natural extension.
"drm:atomic:fail:"	has been proposed, sounds directly useful

Some properties of a hierarchical category deserve explication:

Trailing spaces matter !

With 1..3-space ("drm: ", "drm:atomic: ", "drm:atomic:fail: "), the
":" doesn't terminate the search-space, the trailing space does.  So a
"drm:" search spec will match all DRM categories & subcategories, and
will not be useful in an interface where all categories are already
controlled together.  That said, "drm:atomic:" & "drm:atomic: " are
different, and both are useful in cases.

Ad-Hoc sub-categories:

These have a caveat wrt wrapper macros adding prefixes like
"drm:atomic: "; the trailing space in the prefix means that
drm_dbg_atomic("fail: ...") pastes as "drm:atomic: fail: ", which
obviously isn't ideal wrt clear and simple bitmaps.

A possible solution is to have a FOO_() version of every FOO() macro
which (anti-mnemonically) elides the trailing space, which is normally
inserted by a modified FOO().  Doing this would enforce a policy
decision that "debug categories will be space terminated", with an
pressure-relief valve.

Summarizing:

 - "drm:kms: " & "drm:kms:" are different
 - "drm:kms"		also different - includes drm:kms2:
 - "drm:kms:\t"		also different
 - "drm:kms:*"		doesn't work, no wildcard on format atm.

Order matters in DEFINE_DYNAMIC_DEBUG_CATEGORIES(... @bit_descs)

@bit_descs (array) position determines the bit mapping to the prefix,
so to keep a stable map, new categories or 3rd level categories must
be added to the end.

Since bits are/will-stay applied 0-N, the later bits can countermand
the earlier ones, but its tricky - consider;

    DD_CATs(... "drm:atomic:", "drm:atomic:fail:" ) // misleading

The 1st search-term is misleading, because it includes (modifies)
subcategories, but then 2nd overrides it.  So don't do that.

For "drm:atomic:fail:" in particular, its best not to add it into an
existing bitmap, because the current setting would be lost at every
(unrelated) write, and a separate bitmap is much more stable.

There is still plenty of bikeshedding to do.

Signed-off-by: Jim Cromie <jim.cromie@gmail.com>
---
v5:
. rename to DEFINE_DYNAMIC_DEBUG_CATEGORIES from DEFINE_DYNDBG_BITMAP
. in set_dyndbg, replace hardcoded "i915" w kp->mod->name
. static inline the stubs
. const *str in structs, const array. - Emil
. dyndbg: add do-nothing DEFINE_DYNAMIC_DEBUG_CATEGORIES if !DD_CORE
. call MOD_PARM_DESC(name, "$desc") for users
. simplify callback, remove bit-change detection
. config errs reported by <lkp@intel.com>

v6:
. return rc, bitmap->, snprintf, ws - Andy Shevchenko
. s/chgct/matches/ - old varname is misleading
. move code off file bottom to a "better" place
. change ##fsname to ##var for safer varname construct
. workaround for !CONFIG_MODULES
. move forward decl down to where its needed
---
 include/linux/dynamic_debug.h | 52 +++++++++++++++++++++++-
 lib/dynamic_debug.c           | 76 ++++++++++++++++++++++++++++++++---
 2 files changed, 121 insertions(+), 7 deletions(-)

diff --git a/include/linux/dynamic_debug.h b/include/linux/dynamic_debug.h
index dce631e678dd..51b7254daee0 100644
--- a/include/linux/dynamic_debug.h
+++ b/include/linux/dynamic_debug.h
@@ -51,8 +51,6 @@ struct _ddebug {
 #endif
 } __attribute__((aligned(8)));
 
-
-
 #if defined(CONFIG_DYNAMIC_DEBUG_CORE)
 
 /* exported for module authors to exercise >control */
@@ -181,6 +179,10 @@ void __dynamic_ibdev_dbg(struct _ddebug *descriptor,
 				   KERN_DEBUG, prefix_str, prefix_type,	\
 				   rowsize, groupsize, buf, len, ascii)
 
+struct kernel_param;
+int param_set_dyndbg(const char *instr, const struct kernel_param *kp);
+int param_get_dyndbg(char *buffer, const struct kernel_param *kp);
+
 #else /* !CONFIG_DYNAMIC_DEBUG_CORE */
 
 #include <linux/string.h>
@@ -227,6 +229,52 @@ static inline int dynamic_debug_exec_queries(const char *query, const char *modn
 	return 0;
 }
 
+static inline int param_set_dyndbg(const char *instr, const struct kernel_param *kp)
+	{ return 0; }
+static inline int param_get_dyndbg(char *buffer, const struct kernel_param *kp)
+	{ return 0; }
+
 #endif /* !CONFIG_DYNAMIC_DEBUG_CORE */
 
+struct dyndbg_bitdesc {
+	/* bitpos is inferred from index in containing array */
+	const char *prefix;
+	const char *help;
+};
+
+#if defined(CONFIG_DYNAMIC_DEBUG) || \
+	(defined(CONFIG_DYNAMIC_DEBUG_CORE) && defined(DYNAMIC_DEBUG_MODULE))
+/**
+ * DEFINE_DYNAMIC_DEBUG_CATEGORIES() - define debug categories, bitmap, sysfs-knob
+ * @fsname: parameter basename under /sys
+ * @var:    C-identifier holding state
+ * @_desc:  string summarizing the controls provided
+ * @...:    list of struct dyndbg_bitdesc initializations
+ *
+ * Defines /sys/modules/$modname/parameters/@fsname, and @bit_descs,
+ * which maps bits 0-N to categories of pr_debugs to be controlled.
+ * This is effectively write only, because controlled callsites can be
+ * further modified via >control.
+ *
+ * Also calls MODULE_PARM_DESC(fsname, _desc), with the intent to
+ * generate the bit_legend and apply it to the given bit_descs
+ */
+#define DEFINE_DYNAMIC_DEBUG_CATEGORIES(fsname, var, _desc, ...)	\
+	MODULE_PARM_DESC(fsname, _desc);				\
+	static const struct dyndbg_bitdesc dyndbg_cats_##var[] =	\
+		{ __VA_ARGS__, { NULL, NULL } };			\
+	module_param_cb_data(fsname, &param_ops_dyndbg, &var, 0644,	\
+			     &dyndbg_cats_##var)
+
+#define _DD_cat_(pfx)		{ .prefix = pfx, .help = "help for " pfx }
+#define _DD_cat_help_(pfx)	"\t   " pfx "\t- help for " pfx "\n"
+
+extern const struct kernel_param_ops param_ops_dyndbg;
+#else
+#define DEFINE_DYNAMIC_DEBUG_CATEGORIES(fsname, var, bitmap_desc, ...) \
+	MODULE_PARM_DESC(fsname, "auto: " bitmap_desc)
+#define _DD_cat_(pfx)
+#define _DD_cat_help_(pfx)
+#endif
+
 #endif
diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
index cb5abb42c16a..a43427c67c3f 100644
--- a/lib/dynamic_debug.c
+++ b/lib/dynamic_debug.c
@@ -511,10 +511,11 @@ static int ddebug_exec_query(char *query_string, const char *modname)
 	return nfound;
 }
 
-/* handle multiple queries in query string, continue on error, return
-   last error or number of matching callsites.  Module name is either
-   in param (for boot arg) or perhaps in query string.
-*/
+/*
+ * handle multiple queries in query string, continue on error, return
+ * 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)
 {
 	char *split;
@@ -529,7 +530,7 @@ static int ddebug_exec_queries(char *query, const char *modname)
 		if (!query || !*query || *query == '#')
 			continue;
 
-		vpr_info("query %d: \"%s\"\n", i, query);
+		vpr_info("query %d: \"%s\" %s\n", i, query, (modname) ? modname : "");
 
 		rc = ddebug_exec_query(query, modname);
 		if (rc < 0) {
@@ -577,6 +578,71 @@ int dynamic_debug_exec_queries(const char *query, const char *modname)
 }
 EXPORT_SYMBOL_GPL(dynamic_debug_exec_queries);
 
+#ifdef MODULES
+#define KP_MOD_NAME kp->mod->name
+#else
+#define KP_MOD_NAME NULL /* wildcard */
+#endif
+#define FMT_QUERY_SIZE 128 /* typically need <40 */
+/**
+ * param_set_dyndbg() - drm.debug style bits=>categories setter
+ * @instr: string echo>d to sysfs
+ * @kp:    struct kernel_param* ->data has bitmap
+ * Exported to support DEFINE_DYNAMIC_DEBUG_CATEGORIES
+ */
+int param_set_dyndbg(const char *instr, const struct kernel_param *kp)
+{
+	unsigned long inbits;
+	int rc, i, matches = 0, totct = 0;
+	char query[FMT_QUERY_SIZE];
+	const struct dyndbg_bitdesc *bitmap = kp->data;
+
+	if (!bitmap) {
+		pr_err("set_dyndbg: no bits=>queries map\n");
+		return -EINVAL;
+	}
+	rc = kstrtoul(instr, 0, &inbits);
+	if (rc) {
+		pr_err("set_dyndbg: failed\n");
+		return rc;
+	}
+	vpr_info("set_dyndbg: input 0x%lx\n", inbits);
+
+	for (i = 0; bitmap->prefix; i++, bitmap++) {
+		snprintf(query, FMT_QUERY_SIZE, "format '^%s' %cp", bitmap->prefix,
+			 test_bit(i, &inbits) ? '+' : '-');
+
+		matches = ddebug_exec_queries(query, KP_MOD_NAME);
+
+		v2pr_info("bit-%d: %d matches on '%s'\n", i, matches, query);
+		totct += matches;
+	}
+	vpr_info("total matches: %d\n", totct);
+	return 0;
+}
+EXPORT_SYMBOL(param_set_dyndbg);
+
+/**
+ * param_get_dyndbg() - drm.debug style bitmap to format-prefix categories
+ * @buffer: string returned to user via sysfs
+ * @kp:     struct kernel_param*
+ * Exported to provide required .get interface, not useful.
+ * pr_debugs may be altered after .set via `echo $foo >control`
+ */
+int param_get_dyndbg(char *buffer, const struct kernel_param *kp)
+{
+	return scnprintf(buffer, PAGE_SIZE, "%u\n",
+			 *((unsigned int *)kp->arg));
+}
+EXPORT_SYMBOL(param_get_dyndbg);
+
+const struct kernel_param_ops param_ops_dyndbg = {
+	.set = param_set_dyndbg,
+	.get = param_get_dyndbg,
+};
+/* support DEFINE_DYNAMIC_DEBUG_CATEGORIES users */
+EXPORT_SYMBOL(param_ops_dyndbg);
+
 #define PREFIX_SIZE 64
 
 static int remaining(int wrote)
-- 
2.31.1

Re: [PATCH v6 02/11] dyndbg: add DEFINE_DYNAMIC_DEBUG_CATEGORIES and callbacks

[Andy Shevchenko]

On Mon, Aug 23, 2021 at 1:21 AM Jim Cromie <jim.cromie@gmail.com> wrote:
>
> DEFINE_DYNAMIC_DEBUG_CATEGORIES(name, var, bitmap_desc, @bit_descs)
> allows users to define a drm.debug style (bitmap) sysfs interface, and
> to specify the desired mapping from bits[0-N] to the format-prefix'd
> pr_debug()s to be controlled.
>
> DEFINE_DYNAMIC_DEBUG_CATEGORIES(debug_gvt, __gvt_debug,
>         "i915/gvt bitmap desc",
>         /**
>          * search-prefixes, passed to dd-exec_queries
>          * defines bits 0-N in order.
>          * leading ^ is tacitly inserted (by callback currently)
>          * trailing space used here excludes subcats.
>          * helper macro needs more work
>          * macro to autogen ++$i, 0x%x$i ?
>          */
>         _DD_cat_("gvt:cmd: "),
>         _DD_cat_("gvt:core: "),
>         _DD_cat_("gvt:dpy: "),
>         _DD_cat_("gvt:el: "),
>         _DD_cat_("gvt:irq: "),
>         _DD_cat_("gvt:mm: "),
>         _DD_cat_("gvt:mmio: "),
>         _DD_cat_("gvt:render: "),
>         _DD_cat_("gvt:sched: "));
>
> dynamic_debug.c: add 3 new elements:
>
>  - int param_set_dyndbg()
>  - int param_get_dyndbg()
>  - struct kernel_param_ops param_ops_dyndbg
>
> Following the model of kernel/params.c STANDARD_PARAM_DEFS, All 3 are
> non-static and exported.
>
> dynamic_debug.h:
>
> Add DEFINE_DYNAMIC_DEBUG_CATEGORIES() described above, and a do-nothing stub.
>
> Note that it also calls MODULE_PARM_DESC for the user, but expects the
> user to catenate all the bit-descriptions together (as is done in
> drm.debug), and in the following uses in amdgpu, i915.
>
> This in the hope that someone can offer an auto-incrementing
> label-generating macro, producing "\tbit-4 0x10\t" etc, and can show
> how to apply it to __VA_ARGS__.
>
> Also extern the struct kernel_param param_ops_dyndbg symbol, as is
> done in moduleparams.h for all the STANDARD params.
>
> USAGE NOTES:
>
> Using dyndbg to query on "format ^$prefix" requires that the prefix be
> present in the compiled-in format string; where run-time prefixing is
> used, that format would be "%s...", which is not usefully selectable.
>
> Adding structural query terms (func,file,lineno) could help (module is
> already done), but DEFINE_DYNAMIC_DEBUG_CATEGORIES can't do that now,
> adding it needs a better reason imo.
>
> Dyndbg is completely agnostic wrt the categorization scheme used, to
> play well with any prefix convention already in use.  Ad-hoc
> categories and sub-categories are implicitly allowed, author
> discipline and review is expected.
>
> Here are some examples:
>
> "1","2","3"             2 doesn't imply 1.
>                         otherwize, sorta like printk levels
> "1:","2:","3:"          are better, avoiding [1-9]\d+ ambiguity
> "hi:","mid:","low:"     are reasonable, and imply independence
> "todo:","rfc:","fixme:" might be handy
> "A:".."Z:"              uhm, yeah
>
> Hierarchical classes/categories are natural:
>
> "drm:<CAT>:"            is used in later commit
> "drm:<CAT>:<SUB>:"      is a natural extension.
> "drm:atomic:fail:"      has been proposed, sounds directly useful
>
> Some properties of a hierarchical category deserve explication:
>
> Trailing spaces matter !
>
> With 1..3-space ("drm: ", "drm:atomic: ", "drm:atomic:fail: "), the
> ":" doesn't terminate the search-space, the trailing space does.  So a
> "drm:" search spec will match all DRM categories & subcategories, and
> will not be useful in an interface where all categories are already
> controlled together.  That said, "drm:atomic:" & "drm:atomic: " are
> different, and both are useful in cases.
>
> Ad-Hoc sub-categories:
>
> These have a caveat wrt wrapper macros adding prefixes like
> "drm:atomic: "; the trailing space in the prefix means that
> drm_dbg_atomic("fail: ...") pastes as "drm:atomic: fail: ", which
> obviously isn't ideal wrt clear and simple bitmaps.
>
> A possible solution is to have a FOO_() version of every FOO() macro
> which (anti-mnemonically) elides the trailing space, which is normally
> inserted by a modified FOO().  Doing this would enforce a policy
> decision that "debug categories will be space terminated", with an
> pressure-relief valve.
>
> Summarizing:
>
>  - "drm:kms: " & "drm:kms:" are different
>  - "drm:kms"            also different - includes drm:kms2:
>  - "drm:kms:\t"         also different
>  - "drm:kms:*"          doesn't work, no wildcard on format atm.
>
> Order matters in DEFINE_DYNAMIC_DEBUG_CATEGORIES(... @bit_descs)
>
> @bit_descs (array) position determines the bit mapping to the prefix,
> so to keep a stable map, new categories or 3rd level categories must
> be added to the end.
>
> Since bits are/will-stay applied 0-N, the later bits can countermand
> the earlier ones, but its tricky - consider;

it's

>     DD_CATs(... "drm:atomic:", "drm:atomic:fail:" ) // misleading
>
> The 1st search-term is misleading, because it includes (modifies)
> subcategories, but then 2nd overrides it.  So don't do that.
>
> For "drm:atomic:fail:" in particular, its best not to add it into an
> existing bitmap, because the current setting would be lost at every
> (unrelated) write, and a separate bitmap is much more stable.
>
> There is still plenty of bikeshedding to do.

...

> @@ -51,8 +51,6 @@ struct _ddebug {
>  #endif
>  } __attribute__((aligned(8)));
>
> -
> -

stray change.

...

> +static inline int param_set_dyndbg(const char *instr, const struct kernel_param *kp)
> +       { return 0; }
> +static inline int param_get_dyndbg(char *buffer, const struct kernel_param *kp)
> +       { return 0; }

Not sure if it's aligned with the style in this file, but usually we
put { at the very beginning of the line.

...

> -/* handle multiple queries in query string, continue on error, return
> -   last error or number of matching callsites.  Module name is either
> -   in param (for boot arg) or perhaps in query string.
> -*/
> +/*
> + * handle multiple queries in query string, continue on error, return
> + * last error or number of matching callsites.  Module name is either
> + * in param (for boot arg) or perhaps in query string.
> + */

Doesn't belong to the patch, split it separately.

...

> +               vpr_info("query %d: \"%s\" %s\n", i, query, (modname) ? modname : "");

too many parentheses. Also may use

  modname ?: ""

form (but not all maintainers are happy with it).

...

> +       if (!bitmap) {
> +               pr_err("set_dyndbg: no bits=>queries map\n");
> +               return -EINVAL;
> +       }
> +       rc = kstrtoul(instr, 0, &inbits);
> +       if (rc) {
> +               pr_err("set_dyndbg: failed\n");
> +               return rc;
> +       }
> +       vpr_info("set_dyndbg: input 0x%lx\n", inbits);
> +
> +       for (i = 0; bitmap->prefix; i++, bitmap++) {
> +               snprintf(query, FMT_QUERY_SIZE, "format '^%s' %cp", bitmap->prefix,
> +                        test_bit(i, &inbits) ? '+' : '-');
> +
> +               matches = ddebug_exec_queries(query, KP_MOD_NAME);
> +
> +               v2pr_info("bit-%d: %d matches on '%s'\n", i, matches, query);
> +               totct += matches;
> +       }

I'm wondering if there is a room to parse a bitmap as a bitmap.

...

> +int param_get_dyndbg(char *buffer, const struct kernel_param *kp)
> +{
> +       return scnprintf(buffer, PAGE_SIZE, "%u\n",
> +                        *((unsigned int *)kp->arg));

One line?

> +}

-- 
With Best Regards,
Andy Shevchenko

Re: [PATCH v6 02/11] dyndbg: add DEFINE_DYNAMIC_DEBUG_CATEGORIES and callbacks

[jim.cromie]

On Mon, Aug 23, 2021 at 12:41 AM Andy Shevchenko
<andy.shevchenko@gmail.com> wrote:
>
> On Mon, Aug 23, 2021 at 1:21 AM Jim Cromie <jim.cromie@gmail.com> wrote:
> >
> > DEFINE_DYNAMIC_DEBUG_CATEGORIES(name, var, bitmap_desc, @bit_descs)
> > allows users to define a drm.debug style (bitmap) sysfs interface, and
> > to specify the desired mapping from bits[0-N] to the format-prefix'd
> > pr_debug()s to be controlled.
> >

yes to everything, 1 question


> > +       if (!bitmap) {
> > +               pr_err("set_dyndbg: no bits=>queries map\n");
> > +               return -EINVAL;
> > +       }
> > +       rc = kstrtoul(instr, 0, &inbits);
> > +       if (rc) {
> > +               pr_err("set_dyndbg: failed\n");
> > +               return rc;
> > +       }
> > +       vpr_info("set_dyndbg: input 0x%lx\n", inbits);
> > +
> > +       for (i = 0; bitmap->prefix; i++, bitmap++) {
> > +               snprintf(query, FMT_QUERY_SIZE, "format '^%s' %cp", bitmap->prefix,
> > +                        test_bit(i, &inbits) ? '+' : '-');
> > +
> > +               matches = ddebug_exec_queries(query, KP_MOD_NAME);
> > +
> > +               v2pr_info("bit-%d: %d matches on '%s'\n", i, matches, query);
> > +               totct += matches;
> > +       }
>
> I'm wondering if there is a room to parse a bitmap as a bitmap.
>

I dont know what you mean here.
can you point to an example to crib from ?

thanks

> --
> With Best Regards,
> Andy Shevchenko

Re: [PATCH v6 02/11] dyndbg: add DEFINE_DYNAMIC_DEBUG_CATEGORIES and callbacks

[Jason Baron]

On 8/22/21 6:20 PM, Jim Cromie wrote:
> DEFINE_DYNAMIC_DEBUG_CATEGORIES(name, var, bitmap_desc, @bit_descs)
> allows users to define a drm.debug style (bitmap) sysfs interface, and
> to specify the desired mapping from bits[0-N] to the format-prefix'd
> pr_debug()s to be controlled.
> 
> DEFINE_DYNAMIC_DEBUG_CATEGORIES(debug_gvt, __gvt_debug,
> 	"i915/gvt bitmap desc",
> 	/**
> 	 * search-prefixes, passed to dd-exec_queries
> 	 * defines bits 0-N in order.
> 	 * leading ^ is tacitly inserted (by callback currently)
> 	 * trailing space used here excludes subcats.
> 	 * helper macro needs more work
> 	 * macro to autogen ++$i, 0x%x$i ?
> 	 */
> 	_DD_cat_("gvt:cmd: "),
> 	_DD_cat_("gvt:core: "),
> 	_DD_cat_("gvt:dpy: "),
> 	_DD_cat_("gvt:el: "),
> 	_DD_cat_("gvt:irq: "),
> 	_DD_cat_("gvt:mm: "),
> 	_DD_cat_("gvt:mmio: "),
> 	_DD_cat_("gvt:render: "),
> 	_DD_cat_("gvt:sched: "));
> 
> dynamic_debug.c: add 3 new elements:
> 
>  - int param_set_dyndbg()
>  - int param_get_dyndbg()
>  - struct kernel_param_ops param_ops_dyndbg
> 
> Following the model of kernel/params.c STANDARD_PARAM_DEFS, All 3 are
> non-static and exported.
> 
> dynamic_debug.h:
> 
> Add DEFINE_DYNAMIC_DEBUG_CATEGORIES() described above, and a do-nothing stub.
> 
> Note that it also calls MODULE_PARM_DESC for the user, but expects the
> user to catenate all the bit-descriptions together (as is done in
> drm.debug), and in the following uses in amdgpu, i915.
> 
> This in the hope that someone can offer an auto-incrementing
> label-generating macro, producing "\tbit-4 0x10\t" etc, and can show
> how to apply it to __VA_ARGS__.
> 
> Also extern the struct kernel_param param_ops_dyndbg symbol, as is
> done in moduleparams.h for all the STANDARD params.
> 
> USAGE NOTES:
> 
> Using dyndbg to query on "format ^$prefix" requires that the prefix be
> present in the compiled-in format string; where run-time prefixing is
> used, that format would be "%s...", which is not usefully selectable.
> 
> Adding structural query terms (func,file,lineno) could help (module is
> already done), but DEFINE_DYNAMIC_DEBUG_CATEGORIES can't do that now,
> adding it needs a better reason imo.
> 
> Dyndbg is completely agnostic wrt the categorization scheme used, to
> play well with any prefix convention already in use.  Ad-hoc
> categories and sub-categories are implicitly allowed, author
> discipline and review is expected.
> 
> Here are some examples:
> 
> "1","2","3"		2 doesn't imply 1.
>    			otherwize, sorta like printk levels
> "1:","2:","3:"		are better, avoiding [1-9]\d+ ambiguity
> "hi:","mid:","low:"	are reasonable, and imply independence
> "todo:","rfc:","fixme:" might be handy
> "A:".."Z:"		uhm, yeah
> 
> Hierarchical classes/categories are natural:
> 
> "drm:<CAT>:"		is used in later commit
> "drm:<CAT>:<SUB>:"	is a natural extension.
> "drm:atomic:fail:"	has been proposed, sounds directly useful
> 
> Some properties of a hierarchical category deserve explication:
> 
> Trailing spaces matter !
> 
> With 1..3-space ("drm: ", "drm:atomic: ", "drm:atomic:fail: "), the
> ":" doesn't terminate the search-space, the trailing space does.  So a
> "drm:" search spec will match all DRM categories & subcategories, and
> will not be useful in an interface where all categories are already
> controlled together.  That said, "drm:atomic:" & "drm:atomic: " are
> different, and both are useful in cases.
> 
> Ad-Hoc sub-categories:
> 
> These have a caveat wrt wrapper macros adding prefixes like
> "drm:atomic: "; the trailing space in the prefix means that
> drm_dbg_atomic("fail: ...") pastes as "drm:atomic: fail: ", which
> obviously isn't ideal wrt clear and simple bitmaps.
> 
> A possible solution is to have a FOO_() version of every FOO() macro
> which (anti-mnemonically) elides the trailing space, which is normally
> inserted by a modified FOO().  Doing this would enforce a policy
> decision that "debug categories will be space terminated", with an
> pressure-relief valve.
> 
> Summarizing:
> 
>  - "drm:kms: " & "drm:kms:" are different
>  - "drm:kms"		also different - includes drm:kms2:
>  - "drm:kms:\t"		also different
>  - "drm:kms:*"		doesn't work, no wildcard on format atm.
> 
> Order matters in DEFINE_DYNAMIC_DEBUG_CATEGORIES(... @bit_descs)
> 
> @bit_descs (array) position determines the bit mapping to the prefix,
> so to keep a stable map, new categories or 3rd level categories must
> be added to the end.
> 
> Since bits are/will-stay applied 0-N, the later bits can countermand
> the earlier ones, but its tricky - consider;
> 
>     DD_CATs(... "drm:atomic:", "drm:atomic:fail:" ) // misleading
> 
> The 1st search-term is misleading, because it includes (modifies)
> subcategories, but then 2nd overrides it.  So don't do that.
> 
> For "drm:atomic:fail:" in particular, its best not to add it into an
> existing bitmap, because the current setting would be lost at every
> (unrelated) write, and a separate bitmap is much more stable.
> 
> There is still plenty of bikeshedding to do.
> 
> Signed-off-by: Jim Cromie <jim.cromie@gmail.com>
> ---
> v5:
> . rename to DEFINE_DYNAMIC_DEBUG_CATEGORIES from DEFINE_DYNDBG_BITMAP
> . in set_dyndbg, replace hardcoded "i915" w kp->mod->name
> . static inline the stubs
> . const *str in structs, const array. - Emil
> . dyndbg: add do-nothing DEFINE_DYNAMIC_DEBUG_CATEGORIES if !DD_CORE
> . call MOD_PARM_DESC(name, "$desc") for users
> . simplify callback, remove bit-change detection
> . config errs reported by <lkp@intel.com>
> 
> v6:
> . return rc, bitmap->, snprintf, ws - Andy Shevchenko
> . s/chgct/matches/ - old varname is misleading
> . move code off file bottom to a "better" place
> . change ##fsname to ##var for safer varname construct
> . workaround for !CONFIG_MODULES
> . move forward decl down to where its needed
> ---
>  include/linux/dynamic_debug.h | 52 +++++++++++++++++++++++-
>  lib/dynamic_debug.c           | 76 ++++++++++++++++++++++++++++++++---
>  2 files changed, 121 insertions(+), 7 deletions(-)
> 
> diff --git a/include/linux/dynamic_debug.h b/include/linux/dynamic_debug.h
> index dce631e678dd..51b7254daee0 100644
> --- a/include/linux/dynamic_debug.h
> +++ b/include/linux/dynamic_debug.h
> @@ -51,8 +51,6 @@ struct _ddebug {
>  #endif
>  } __attribute__((aligned(8)));
>  
> -
> -
>  #if defined(CONFIG_DYNAMIC_DEBUG_CORE)
>  
>  /* exported for module authors to exercise >control */
> @@ -181,6 +179,10 @@ void __dynamic_ibdev_dbg(struct _ddebug *descriptor,
>  				   KERN_DEBUG, prefix_str, prefix_type,	\
>  				   rowsize, groupsize, buf, len, ascii)
>  
> +struct kernel_param;
> +int param_set_dyndbg(const char *instr, const struct kernel_param *kp);
> +int param_get_dyndbg(char *buffer, const struct kernel_param *kp);
> +
>  #else /* !CONFIG_DYNAMIC_DEBUG_CORE */
>  
>  #include <linux/string.h>
> @@ -227,6 +229,52 @@ static inline int dynamic_debug_exec_queries(const char *query, const char *modn
>  	return 0;
>  }
>  
> +static inline int param_set_dyndbg(const char *instr, const struct kernel_param *kp)
> +	{ return 0; }
> +static inline int param_get_dyndbg(char *buffer, const struct kernel_param *kp)
> +	{ return 0; }
> +
>  #endif /* !CONFIG_DYNAMIC_DEBUG_CORE */
>  
> +struct dyndbg_bitdesc {
> +	/* bitpos is inferred from index in containing array */
> +	const char *prefix;
> +	const char *help;
> +};
> +
> +#if defined(CONFIG_DYNAMIC_DEBUG) || \
> +	(defined(CONFIG_DYNAMIC_DEBUG_CORE) && defined(DYNAMIC_DEBUG_MODULE))
> +/**
> + * DEFINE_DYNAMIC_DEBUG_CATEGORIES() - define debug categories, bitmap, sysfs-knob
> + * @fsname: parameter basename under /sys
> + * @var:    C-identifier holding state
> + * @_desc:  string summarizing the controls provided
> + * @...:    list of struct dyndbg_bitdesc initializations
> + *
> + * Defines /sys/modules/$modname/parameters/@fsname, and @bit_descs,
> + * which maps bits 0-N to categories of pr_debugs to be controlled.
> + * This is effectively write only, because controlled callsites can be
> + * further modified via >control.
> + *
> + * Also calls MODULE_PARM_DESC(fsname, _desc), with the intent to
> + * generate the bit_legend and apply it to the given bit_descs
> + */
> +#define DEFINE_DYNAMIC_DEBUG_CATEGORIES(fsname, var, _desc, ...)	\
> +	MODULE_PARM_DESC(fsname, _desc);				\
> +	static const struct dyndbg_bitdesc dyndbg_cats_##var[] =	\
> +		{ __VA_ARGS__, { NULL, NULL } };			\
> +	module_param_cb_data(fsname, &param_ops_dyndbg, &var, 0644,	\
> +			     &dyndbg_cats_##var)
> +
> +#define _DD_cat_(pfx)		{ .prefix = pfx, .help = "help for " pfx }
> +#define _DD_cat_help_(pfx)	"\t   " pfx "\t- help for " pfx "\n"
> +
> +extern const struct kernel_param_ops param_ops_dyndbg;
> +#else
> +#define DEFINE_DYNAMIC_DEBUG_CATEGORIES(fsname, var, bitmap_desc, ...) \
> +	MODULE_PARM_DESC(fsname, "auto: " bitmap_desc)
> +#define _DD_cat_(pfx)
> +#define _DD_cat_help_(pfx)
> +#endif
> +
>  #endif
> diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
> index cb5abb42c16a..a43427c67c3f 100644
> --- a/lib/dynamic_debug.c
> +++ b/lib/dynamic_debug.c
> @@ -511,10 +511,11 @@ static int ddebug_exec_query(char *query_string, const char *modname)
>  	return nfound;
>  }
>  
> -/* handle multiple queries in query string, continue on error, return
> -   last error or number of matching callsites.  Module name is either
> -   in param (for boot arg) or perhaps in query string.
> -*/
> +/*
> + * handle multiple queries in query string, continue on error, return
> + * 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)
>  {
>  	char *split;
> @@ -529,7 +530,7 @@ static int ddebug_exec_queries(char *query, const char *modname)
>  		if (!query || !*query || *query == '#')
>  			continue;
>  
> -		vpr_info("query %d: \"%s\"\n", i, query);
> +		vpr_info("query %d: \"%s\" %s\n", i, query, (modname) ? modname : "");
>  
>  		rc = ddebug_exec_query(query, modname);
>  		if (rc < 0) {
> @@ -577,6 +578,71 @@ int dynamic_debug_exec_queries(const char *query, const char *modname)
>  }
>  EXPORT_SYMBOL_GPL(dynamic_debug_exec_queries);
>  
> +#ifdef MODULES
> +#define KP_MOD_NAME kp->mod->name
> +#else
> +#define KP_MOD_NAME NULL /* wildcard */
> +#endif
> +#define FMT_QUERY_SIZE 128 /* typically need <40 */
> +/**
> + * param_set_dyndbg() - drm.debug style bits=>categories setter
> + * @instr: string echo>d to sysfs
> + * @kp:    struct kernel_param* ->data has bitmap
> + * Exported to support DEFINE_DYNAMIC_DEBUG_CATEGORIES
> + */
> +int param_set_dyndbg(const char *instr, const struct kernel_param *kp)
> +{
> +	unsigned long inbits;
> +	int rc, i, matches = 0, totct = 0;
> +	char query[FMT_QUERY_SIZE];
> +	const struct dyndbg_bitdesc *bitmap = kp->data;
> +
> +	if (!bitmap) {
> +		pr_err("set_dyndbg: no bits=>queries map\n");
> +		return -EINVAL;
> +	}
> +	rc = kstrtoul(instr, 0, &inbits);
> +	if (rc) {
> +		pr_err("set_dyndbg: failed\n");
> +		return rc;
> +	}
> +	vpr_info("set_dyndbg: input 0x%lx\n", inbits);
> +
> +	for (i = 0; bitmap->prefix; i++, bitmap++) {
> +		snprintf(query, FMT_QUERY_SIZE, "format '^%s' %cp", bitmap->prefix,
> +			 test_bit(i, &inbits) ? '+' : '-');
> +
> +		matches = ddebug_exec_queries(query, KP_MOD_NAME);
> +
> +		v2pr_info("bit-%d: %d matches on '%s'\n", i, matches, query);
> +		totct += matches;
> +	}
> +	vpr_info("total matches: %d\n", totct);
> +	return 0;
> +}
> +EXPORT_SYMBOL(param_set_dyndbg);
> +
> +/**
> + * param_get_dyndbg() - drm.debug style bitmap to format-prefix categories
> + * @buffer: string returned to user via sysfs
> + * @kp:     struct kernel_param*
> + * Exported to provide required .get interface, not useful.
> + * pr_debugs may be altered after .set via `echo $foo >control`
> + */
> +int param_get_dyndbg(char *buffer, const struct kernel_param *kp)
> +{
> +	return scnprintf(buffer, PAGE_SIZE, "%u\n",
> +			 *((unsigned int *)kp->arg));


If kp->arg is read here, don't we need to set too somewhere? I'm wondering
if the 'get' can use one of the generic ones like param_get_int too? Instead
of a special case here.

Thanks,

-Jason

> +}
> +EXPORT_SYMBOL(param_get_dyndbg);
> +
> +const struct kernel_param_ops param_ops_dyndbg = {
> +	.set = param_set_dyndbg,
> +	.get = param_get_dyndbg,
> +};
> +/* support DEFINE_DYNAMIC_DEBUG_CATEGORIES users */
> +EXPORT_SYMBOL(param_ops_dyndbg);
> +
>  #define PREFIX_SIZE 64
>  
>  static int remaining(int wrote)
> 

[PATCH v6 03/11] i915/gvt: remove spaces in pr_debug "gvt: core:" etc prefixes

[Jim Cromie]

Taking embedded spaces out of existing prefixes makes them better
class-prefixes; simplifying the nested quoting needed otherwise:

  $> echo "format '^gvt: core:' +p" >control

Dropping the internal spaces means any trailing space in a query will
more clearly terminate the prefix being searched for.

Consider a generic drm-debug example:

  # turn off ATOMIC reports
  echo format "^drm:atomic: " -p > control

  # turn off all ATOMIC:* reports, including any sub-categories
  echo format "^drm:atomic:" -p > control

  # turn on ATOMIC:FAIL: reports
  echo format "^drm:atomic:fail: " +p > control

Removing embedded spaces in the class-prefixes simplifies the
corresponding match-prefix.  This means that "quoted" match-prefixes
are only needed when the trailing space is desired, in order to
exclude explicitly sub-categorized pr-debugs; in this example,
"drm:atomic:fail:".

RFC: maybe the prefix catenation should paste in the " " class-prefix
terminator explicitly.  A pr_debug_() flavor could exclude the " ",
allowing ad-hoc sub-categorization by appending for example, "fail:"
to "drm:atomic:".

Signed-off-by: Jim Cromie <jim.cromie@gmail.com>
---
 drivers/gpu/drm/i915/gvt/debug.h | 18 +++++++++---------
 1 file changed, 9 insertions(+), 9 deletions(-)

diff --git a/drivers/gpu/drm/i915/gvt/debug.h b/drivers/gpu/drm/i915/gvt/debug.h
index c6027125c1ec..b4021f41c546 100644
--- a/drivers/gpu/drm/i915/gvt/debug.h
+++ b/drivers/gpu/drm/i915/gvt/debug.h
@@ -36,30 +36,30 @@ do {									\
 } while (0)
 
 #define gvt_dbg_core(fmt, args...) \
-	pr_debug("gvt: core: "fmt, ##args)
+	pr_debug("gvt:core: "fmt, ##args)
 
 #define gvt_dbg_irq(fmt, args...) \
-	pr_debug("gvt: irq: "fmt, ##args)
+	pr_debug("gvt:irq: "fmt, ##args)
 
 #define gvt_dbg_mm(fmt, args...) \
-	pr_debug("gvt: mm: "fmt, ##args)
+	pr_debug("gvt:mm: "fmt, ##args)
 
 #define gvt_dbg_mmio(fmt, args...) \
-	pr_debug("gvt: mmio: "fmt, ##args)
+	pr_debug("gvt:mmio: "fmt, ##args)
 
 #define gvt_dbg_dpy(fmt, args...) \
-	pr_debug("gvt: dpy: "fmt, ##args)
+	pr_debug("gvt:dpy: "fmt, ##args)
 
 #define gvt_dbg_el(fmt, args...) \
-	pr_debug("gvt: el: "fmt, ##args)
+	pr_debug("gvt:el: "fmt, ##args)
 
 #define gvt_dbg_sched(fmt, args...) \
-	pr_debug("gvt: sched: "fmt, ##args)
+	pr_debug("gvt:sched: "fmt, ##args)
 
 #define gvt_dbg_render(fmt, args...) \
-	pr_debug("gvt: render: "fmt, ##args)
+	pr_debug("gvt:render: "fmt, ##args)
 
 #define gvt_dbg_cmd(fmt, args...) \
-	pr_debug("gvt: cmd: "fmt, ##args)
+	pr_debug("gvt:cmd: "fmt, ##args)
 
 #endif
-- 
2.31.1

[PATCH v6 04/11] i915/gvt: use DEFINE_DYNAMIC_DEBUG_CATEGORIES to create "gvt:core:" etc categories

[Jim Cromie]

The gvt component of this driver has ~120 pr_debugs, in 9 categories
quite similar to those in DRM.  Following the interface model of
drm.debug, add a parameter to map bits to these categorizations.

DEFINE_DYNAMIC_DEBUG_CATEGORIES(debug_gvt, __gvt_debug,
	"dyndbg bitmap desc",
	{ "gvt:cmd: ",  "command processing" },
	{ "gvt:core: ", "core help" },
	{ "gvt:dpy: ",  "display help" },
	{ "gvt:el: ",   "help" },
	{ "gvt:irq: ",  "help" },
	{ "gvt:mm: ",   "help" },
	{ "gvt:mmio: ", "help" },
	{ "gvt:render: ", "help" },
	{ "gvt:sched: " "help" });

The actual patch has a few details different, cmd_help() macro emits
the initialization construct.

if CONFIG_DRM_USE_DYNAMIC_DEBUG, then -DDYNAMIC_DEBUG_MODULE is added
cflags, by gvt/Makefile.

Signed-off-by: Jim Cromie <jim.cromie@gmail.com>
---
v4+:
. static decl of vector of bit->class descriptors - Emil.V
. relocate gvt-makefile chunk from elsewhere
---
 drivers/gpu/drm/i915/gvt/Makefile  |  4 ++++
 drivers/gpu/drm/i915/i915_params.c | 35 ++++++++++++++++++++++++++++++
 2 files changed, 39 insertions(+)

diff --git a/drivers/gpu/drm/i915/gvt/Makefile b/drivers/gpu/drm/i915/gvt/Makefile
index ea8324abc784..846ba73b8de6 100644
--- a/drivers/gpu/drm/i915/gvt/Makefile
+++ b/drivers/gpu/drm/i915/gvt/Makefile
@@ -7,3 +7,7 @@ GVT_SOURCE := gvt.o aperture_gm.o handlers.o vgpu.o trace_points.o firmware.o \
 
 ccflags-y				+= -I $(srctree)/$(src) -I $(srctree)/$(src)/$(GVT_DIR)/
 i915-y					+= $(addprefix $(GVT_DIR)/, $(GVT_SOURCE))
+
+#ifdef CONFIG_DRM_USE_DYNAMIC_DEBUG
+ccflags-y	+= -DDYNAMIC_DEBUG_MODULE
+#endif
diff --git a/drivers/gpu/drm/i915/i915_params.c b/drivers/gpu/drm/i915/i915_params.c
index e07f4cfea63a..683e942a074e 100644
--- a/drivers/gpu/drm/i915/i915_params.c
+++ b/drivers/gpu/drm/i915/i915_params.c
@@ -265,3 +265,38 @@ void i915_params_free(struct i915_params *params)
 	I915_PARAMS_FOR_EACH(FREE);
 #undef FREE
 }
+
+#ifdef DRM_USE_DYNAMIC_DEBUG
+/* todo: needs DYNAMIC_DEBUG_MODULE in some cases */
+
+unsigned long __gvt_debug;
+EXPORT_SYMBOL(__gvt_debug);
+
+#define _help(key)	"\t    \"" key "\"\t: help for " key "\n"
+
+#define I915_GVT_CATEGORIES(name) \
+	" Enable debug output via /sys/module/i915/parameters/" #name	\
+	", where each bit enables a debug category.\n"			\
+	_help("gvt:cmd:")						\
+	_help("gvt:core:")						\
+	_help("gvt:dpy:")						\
+	_help("gvt:el:")						\
+	_help("gvt:irq:")						\
+	_help("gvt:mm:")						\
+	_help("gvt:mmio:")						\
+	_help("gvt:render:")						\
+	_help("gvt:sched:")
+
+DEFINE_DYNAMIC_DEBUG_CATEGORIES(debug_gvt, __gvt_debug,
+				I915_GVT_CATEGORIES(debug_gvt),
+				_DD_cat_("gvt:cmd:"),
+				_DD_cat_("gvt:core:"),
+				_DD_cat_("gvt:dpy:"),
+				_DD_cat_("gvt:el:"),
+				_DD_cat_("gvt:irq:"),
+				_DD_cat_("gvt:mm:"),
+				_DD_cat_("gvt:mmio:"),
+				_DD_cat_("gvt:render:"),
+				_DD_cat_("gvt:sched:"));
+
+#endif
-- 
2.31.1

[PATCH v6 05/11] amdgpu: use DEFINE_DYNAMIC_DEBUG_CATEGORIES to control categorized pr_debugs

[Jim Cromie]

logger_types.h defines many DC_LOG_*() categorized debug wrappers.
Most of these use DRM debug API, so are controllable using drm.debug,
but others use bare pr_debug("$prefix: .."), each with a different
class-prefix matching "^\[\w+\]:"

Use DEFINE_DYNAMIC_DEBUG_CATEGORIES to create a /sys debug_dc
parameter, modinfos, and to specify a map from bits -> categorized
pr_debugs to be controlled.

Signed-off-by: Jim Cromie <jim.cromie@gmail.com>
---
 .../gpu/drm/amd/display/dc/core/dc_debug.c    | 44 ++++++++++++++++++-
 1 file changed, 43 insertions(+), 1 deletion(-)

diff --git a/drivers/gpu/drm/amd/display/dc/core/dc_debug.c b/drivers/gpu/drm/amd/display/dc/core/dc_debug.c
index 21be2a684393..69e68d721512 100644
--- a/drivers/gpu/drm/amd/display/dc/core/dc_debug.c
+++ b/drivers/gpu/drm/amd/display/dc/core/dc_debug.c
@@ -36,8 +36,50 @@
 
 #include "resource.h"
 
-#define DC_LOGGER_INIT(logger)
+#ifdef DRM_USE_DYNAMIC_DEBUG
+/* define a drm.debug style dyndbg pr-debug control point */
+#include <linux/dynamic_debug.h>
+
+unsigned long __debug_dc;
+EXPORT_SYMBOL(__debug_dc);
+
+#define _help_(key)	"\t   " key "\t- help for " key "\n"
+
+/* Id like to do these inside DEFINE_DYNAMIC_DEBUG_CATEGORIES, if possible */
+#define DC_DYNDBG_BITMAP_DESC(name)					\
+	"Control pr_debugs via /sys/module/amdgpu/parameters/" #name	\
+	", where each bit controls a debug category.\n"			\
+	_help_("[SURFACE]:")						\
+	_help_("[CURSOR]:")						\
+	_help_("[PFLIP]:")						\
+	_help_("[VBLANK]:")						\
+	_help_("[HW_LINK_TRAINING]:")					\
+	_help_("[HW_AUDIO]:")						\
+	_help_("[SCALER]:")						\
+	_help_("[BIOS]:")						\
+	_help_("[BANDWIDTH_CALCS]:")					\
+	_help_("[DML]:")						\
+	_help_("[IF_TRACE]:")						\
+	_help_("[GAMMA]:")						\
+	_help_("[SMU_MSG]:")
+
+DEFINE_DYNAMIC_DEBUG_CATEGORIES(debug_dc, __debug_dc,
+	DC_DYNDBG_BITMAP_DESC(debug_dc),
+	_DD_cat_("[CURSOR]:"),
+	_DD_cat_("[PFLIP]:"),
+	_DD_cat_("[VBLANK]:"),
+	_DD_cat_("[HW_LINK_TRAINING]:"),
+	_DD_cat_("[HW_AUDIO]:"),
+	_DD_cat_("[SCALER]:"),
+	_DD_cat_("[BIOS]:"),
+	_DD_cat_("[BANDWIDTH_CALCS]:"),
+	_DD_cat_("[DML]:"),
+	_DD_cat_("[IF_TRACE]:"),
+	_DD_cat_("[GAMMA]:"),
+	_DD_cat_("[SMU_MSG]:"));
+#endif
 
+#define DC_LOGGER_INIT(logger)
 
 #define SURFACE_TRACE(...) do {\
 		if (dc->debug.surface_trace) \
-- 
2.31.1

[PATCH v6 06/11] drm_print: add choice to use dynamic debug in drm-debug

[Jim Cromie]

drm's debug system writes 10 distinct categories of messages to syslog
using a small API[1]: drm_dbg*(10 names), DRM_DEBUG*(8 names),
DRM_DEV_DEBUG*(3 names).  There are thousands of these callsites, each
categorized by their authors.

These callsites can be enabled at runtime by their category, each
controlled by a bit in drm.debug (/sys/modules/drm/parameter/debug).
In the current "basic" implementation, drm_debug_enabled() tests these
bits in __drm_debug each time an API[1] call is executed; while cheap
individually, the costs accumulate.

This patch uses dynamic-debug with jump-label to patch enabled calls
onto their respective NOOP slots, avoiding all runtime bit-checks of
__drm_debug.

Dynamic debug has no concept of category, but we can emulate one by
replacing enum categories with a set of prefix-strings; "drm:core:",
"drm:kms:" "drm:driver:" etc, and prepend them (at compile time) to
the given formats.

Then we can use:
  `echo module drm format "^drm:core: " +p > control`

to enable the whole category with one query.

This conversion yields ~2100 new callsites on my i7/i915 laptop:

  dyndbg: 195 debug prints in module drm_kms_helper
  dyndbg: 298 debug prints in module drm
  dyndbg: 1630 debug prints in module i915

CONFIG_DRM_USE_DYNAMIC_DEBUG enables this, and is available if
CONFIG_DYNAMIC_DEBUG or CONFIG_DYNAMIC_DEBUG_CORE is chosen, and if
CONFIG_JUMP_LABEL is enabled; this because its required to get the
promised optimizations.

The "basic" -> "dyndbg" switchover is layered into the macro scheme

A. use DEFINE_DYNAMIC_DEBUG_CATEGORIES(debug, __drm_debug,
		"DRM debug category-per-bit control",
   	  	{ "drm:core:", "enable CORE debug messages" },
   	  	{ "drm:kms:", "enable KMS debug messages" }, ...);

B. A "classy" version of DRM_UT_<CATs> map, named DRM_DBG_CAT_<CATs>

   DRM_DBG_CLASS_<CATs> was proposed, I had agreed, but reconsidered;
   CATEGORY is already DRM's term-of-art, and adding a near-synonym
   'CLASS' only adds ambiguity.

   "basic":  DRM_DBG_CAT_<CATs>  <===  DRM_UT_<CATs>.  Identity map.
   "dyndbg":
     #define DRM_DBG_CAT_KMS    "drm:kms: "
     #define DRM_DBG_CAT_PRIME  "drm:prime: "
     #define DRM_DBG_CAT_ATOMIC "drm:atomic: "

   DRM_UT_* are preserved, since theyre used elsewhere.
   We can probably reduce its use further, but thats a separate thing.

C. drm_dev_dbg() & drm_debug() are interposed with macros

     basic:	forward to renamed fn, with args preserved
     enabled:	redirect to pr_debug, dev_dbg, with CATEGORY # format

   this is where drm_debug_enabled() is avoided.
   prefix is prepended at compile-time, no category at runtime.

D. API[1] uses DRM_DBG_CAT_<CAT>s
   these already use (C), now they use (B) too,
   to get the correct token type for "basic" and "dyndbg" configs.

NOTES:

Because the dyndbg callback is watching __drm_debug, it is coherent
with drm_debug_enabled(), the switchover should be transparent.

Code Review is expected to catch lack of correspondence between
bit=>prefix definitions (the selector) and the prefixes used in the
API[1] layer above pr_debug()

I've coded the search-prefixes/categories with a trailing space, which
excludes any sub-categories added later.  This convention protects any
"drm:atomic:fail:" callsites from getting stomped on by `echo 0 > debug`.
Other categories could differ, but we need some default.

Dyndbg requires that the prefix be in the compiled-in format string;
run-time prefixing evades callsite selection by category.

	pr_debug("%s: ...", __func__, ...) // not ideal

With "lineno X" in a query, its possible to enable single callsites,
but it is tedious, and useless in a category context.

Unfortunately __func__ is not a macro, and cannot be catenated at
preprocess/compile time.

Signed-off-by: Jim Cromie <jim.cromie@gmail.com>
---
v6:
. add kernel doc
. fix cpp paste, drop '#'
v5:
. use DEFINE_DYNAMIC_DEBUG_CATEGORIES in drm_print.c
. s/DRM_DBG_CLASS_/DRM_DBG_CAT_/ - dont need another term
. default=y in KBuild entry - per @DanVet
. move some commit-log prose to dyndbg commit
. add-prototyes to (param_get/set)_dyndbg
. more wrinkles found by <lkp@intel.com>
. relocate ratelimit chunk from elsewhere
---
 drivers/gpu/drm/Kconfig     |  13 ++++
 drivers/gpu/drm/drm_print.c |  49 +++++++++----
 include/drm/drm_print.h     | 142 ++++++++++++++++++++++++++++--------
 3 files changed, 160 insertions(+), 44 deletions(-)

diff --git a/drivers/gpu/drm/Kconfig b/drivers/gpu/drm/Kconfig
index 7ff89690a976..97e38d86fd27 100644
--- a/drivers/gpu/drm/Kconfig
+++ b/drivers/gpu/drm/Kconfig
@@ -57,6 +57,19 @@ config DRM_DEBUG_MM
 
 	  If in doubt, say "N".
 
+config DRM_USE_DYNAMIC_DEBUG
+	bool "use dynamic debug to implement drm.debug"
+	default y
+	depends on DRM
+	depends on DYNAMIC_DEBUG || DYNAMIC_DEBUG_CORE
+	depends on JUMP_LABEL
+	help
+	  The "basic" drm.debug facility does a lot of unlikely
+	  bit-field tests at runtime; while cheap individually, the
+	  cost accumulates.  DYNAMIC_DEBUG patches pr_debug()s in/out
+	  of the running kernel, so avoids those bit-test overheads,
+	  and is therefore recommended.
+
 config DRM_DEBUG_SELFTEST
 	tristate "kselftests for DRM"
 	depends on DRM
diff --git a/drivers/gpu/drm/drm_print.c b/drivers/gpu/drm/drm_print.c
index 111b932cf2a9..72b940a30779 100644
--- a/drivers/gpu/drm/drm_print.c
+++ b/drivers/gpu/drm/drm_print.c
@@ -28,6 +28,7 @@
 #include <stdarg.h>
 
 #include <linux/io.h>
+#include <linux/module.h>
 #include <linux/moduleparam.h>
 #include <linux/seq_file.h>
 #include <linux/slab.h>
@@ -43,16 +44,36 @@
 unsigned int __drm_debug;
 EXPORT_SYMBOL(__drm_debug);
 
-MODULE_PARM_DESC(debug, "Enable debug output, where each bit enables a debug category.\n"
-"\t\tBit 0 (0x01)  will enable CORE messages (drm core code)\n"
-"\t\tBit 1 (0x02)  will enable DRIVER messages (drm controller code)\n"
-"\t\tBit 2 (0x04)  will enable KMS messages (modesetting code)\n"
-"\t\tBit 3 (0x08)  will enable PRIME messages (prime code)\n"
-"\t\tBit 4 (0x10)  will enable ATOMIC messages (atomic code)\n"
-"\t\tBit 5 (0x20)  will enable VBL messages (vblank code)\n"
-"\t\tBit 7 (0x80)  will enable LEASE messages (leasing code)\n"
-"\t\tBit 8 (0x100) will enable DP messages (displayport code)");
+#define DRM_DEBUG_DESC \
+"Enable debug output, where each bit enables a debug category.\n"	\
+"\t\tBit 0 (0x01)  will enable CORE messages (drm core code)\n"		\
+"\t\tBit 1 (0x02)  will enable DRIVER messages (drm controller code)\n"	\
+"\t\tBit 2 (0x04)  will enable KMS messages (modesetting code)\n"	\
+"\t\tBit 3 (0x08)  will enable PRIME messages (prime code)\n"		\
+"\t\tBit 4 (0x10)  will enable ATOMIC messages (atomic code)\n"		\
+"\t\tBit 5 (0x20)  will enable VBL messages (vblank code)\n"		\
+"\t\tBit 7 (0x80)  will enable LEASE messages (leasing code)\n"		\
+"\t\tBit 8 (0x100) will enable DP messages (displayport code)."
+
+#ifdef CONFIG_DRM_USE_DYNAMIC_DEBUG
+#include <linux/dynamic_debug.h>
+DEFINE_DYNAMIC_DEBUG_CATEGORIES(debug, __drm_debug,
+	DRM_DEBUG_DESC,
+	_DD_cat_(DRM_DBG_CAT_CORE),
+	_DD_cat_(DRM_DBG_CAT_DRIVER),
+	_DD_cat_(DRM_DBG_CAT_KMS),
+	_DD_cat_(DRM_DBG_CAT_PRIME),
+	_DD_cat_(DRM_DBG_CAT_ATOMIC),
+	_DD_cat_(DRM_DBG_CAT_VBL),
+	_DD_cat_(DRM_DBG_CAT_STATE),
+	_DD_cat_(DRM_DBG_CAT_LEASE),
+	_DD_cat_(DRM_DBG_CAT_DP),
+	_DD_cat_(DRM_DBG_CAT_DRMRES));
+
+#else
+MODULE_PARM_DESC(debug, DRM_DEBUG_DESC);
 module_param_named(debug, __drm_debug, int, 0600);
+#endif
 
 void __drm_puts_coredump(struct drm_printer *p, const char *str)
 {
@@ -256,8 +277,8 @@ void drm_dev_printk(const struct device *dev, const char *level,
 }
 EXPORT_SYMBOL(drm_dev_printk);
 
-void drm_dev_dbg(const struct device *dev, enum drm_debug_category category,
-		 const char *format, ...)
+void __drm_dev_dbg(const struct device *dev, enum drm_debug_category category,
+		   const char *format, ...)
 {
 	struct va_format vaf;
 	va_list args;
@@ -278,9 +299,9 @@ void drm_dev_dbg(const struct device *dev, enum drm_debug_category category,
 
 	va_end(args);
 }
-EXPORT_SYMBOL(drm_dev_dbg);
+EXPORT_SYMBOL(__drm_dev_dbg);
 
-void __drm_dbg(enum drm_debug_category category, const char *format, ...)
+void ___drm_dbg(enum drm_debug_category category, const char *format, ...)
 {
 	struct va_format vaf;
 	va_list args;
@@ -297,7 +318,7 @@ void __drm_dbg(enum drm_debug_category category, const char *format, ...)
 
 	va_end(args);
 }
-EXPORT_SYMBOL(__drm_dbg);
+EXPORT_SYMBOL(___drm_dbg);
 
 void __drm_err(const char *format, ...)
 {
diff --git a/include/drm/drm_print.h b/include/drm/drm_print.h
index 9b66be54dd16..8775b67ecb30 100644
--- a/include/drm/drm_print.h
+++ b/include/drm/drm_print.h
@@ -252,15 +252,15 @@ static inline struct drm_printer drm_err_printer(const char *prefix)
 /**
  * enum drm_debug_category - The DRM debug categories
  *
- * Each of the DRM debug logging macros use a specific category, and the logging
- * is filtered by the drm.debug module parameter. This enum specifies the values
- * for the interface.
+ * The drm.debug logging API[1] has 10 enumerated categories of
+ * messages, issued by 3 families of macros: 10 drm_dbg_<CATs>, 8
+ * DRM_DEBUG_<CATs>, and 3 DRM_DEV_DEBUG_<CATs>.
  *
  * Each DRM_DEBUG_<CATEGORY> macro logs to DRM_UT_<CATEGORY> category, except
  * DRM_DEBUG() logs to DRM_UT_CORE.
  *
- * Enabling verbose debug messages is done through the drm.debug parameter, each
- * category being enabled by a bit:
+ * Enabling categories of debug messages is done through the drm.debug
+ * parameter, each category being enabled by a bit:
  *
  *  - drm.debug=0x1 will enable CORE messages
  *  - drm.debug=0x2 will enable DRIVER messages
@@ -319,6 +319,86 @@ enum drm_debug_category {
 	DRM_UT_DRMRES		= 0x200,
 };
 
+/**
+ * DOC: DRM_USE_DYNAMIC_DEBUG - using dyndbg in drm.debug
+ *
+ * In the "basic" drm.debug implementation outlined above, each time a
+ * drm-debug API[1] call is executed, drm_debug_enabled(cat) tests
+ * drm.debug vs cat before printing.
+ *
+ * DYNAMIC_DEBUG (aka: dyndbg) patches pr_debug()s in^out of the
+ * running kernel, so it can avoid drm_debug_enabled() and skip lots
+ * of unlikely bit tests.
+ *
+ * dyndbg has no concept of category, but we can prepend a
+ * class-prefix string: "drm:core: ", "drm:kms: ", "drm:driver: " etc,
+ * to pr_debug's format (at compile time).
+ *
+ * Then control the category
+ *    `echo module drm format "^drm:core: " +p > control`
+ *    `dynamic_debug_exec_queries("format '^drm:core: ' +p", "drm");`
+ *
+ * To do this for "basic" | "dyndbg", adaptation adds some macro indirection:
+ *
+ * 0. use dyndbg support to define the bits => prefixes map, attach callback.
+ *
+ *    DYNDBG_BITMAP_DESC(debug, __drm_debug,
+ *			 "drm.debug - overview",
+ *			 { "drm:core:", "enable CORE debug messages" },
+ *			 { "drm:kms:", "enable KMS debug messages" }, ...);
+ *
+ * 1. DRM_DBG_CAT_<CAT>
+ *
+ * This set of symbols replaces DRM_UT_<CAT> in the drm-debug API; it
+ * is either a copy of DRM_UT_<CAT>, or the class-prefix strings.
+ *
+ * 2. drm_dev_dbg & drm_debug are called by drm.debug API
+ *
+ * These are now macros, either forwarding to renamed functions, or
+ * prepending the class string to the format, and invoking pr_debug
+ * directly.  Since the API is all macros, dyndbg remembers
+ * per-pr_debug: module,file,func,line,format and uses that to find
+ * and enable them.
+ */
+#if !defined(CONFIG_DRM_USE_DYNAMIC_DEBUG)
+
+#define __drm_dbg(cls, fmt, ...)			\
+	___drm_dbg(cls, fmt, ##__VA_ARGS__)
+#define drm_dev_dbg(dev, cls, fmt, ...)			\
+	__drm_dev_dbg(dev, cls, fmt, ##__VA_ARGS__)
+
+#define DRM_DBG_CAT_CORE	DRM_UT_CORE
+#define DRM_DBG_CAT_DRIVER	DRM_UT_DRIVER
+#define DRM_DBG_CAT_KMS		DRM_UT_KMS
+#define DRM_DBG_CAT_PRIME	DRM_UT_PRIME
+#define DRM_DBG_CAT_ATOMIC	DRM_UT_ATOMIC
+#define DRM_DBG_CAT_VBL		DRM_UT_VBL
+#define DRM_DBG_CAT_STATE	DRM_UT_STATE
+#define DRM_DBG_CAT_LEASE	DRM_UT_LEASE
+#define DRM_DBG_CAT_DP		DRM_UT_DP
+#define DRM_DBG_CAT_DRMRES	DRM_UT_DRMRES
+
+#else /* CONFIG_DRM_USE_DYNAMIC_DEBUG */
+
+/* join prefix+format in cpp so dyndbg can see it */
+#define __drm_dbg(cls, fmt, ...)		\
+	pr_debug(cls fmt, ##__VA_ARGS__)
+#define drm_dev_dbg(dev, cls, fmt, ...)		\
+	dev_dbg(dev, cls fmt, ##__VA_ARGS__)
+
+#define DRM_DBG_CAT_CORE	"drm:core: "
+#define DRM_DBG_CAT_DRIVER	"drm:drvr: "
+#define DRM_DBG_CAT_KMS		"drm:kms: "
+#define DRM_DBG_CAT_PRIME	"drm:prime: "
+#define DRM_DBG_CAT_ATOMIC	"drm:atomic: "
+#define DRM_DBG_CAT_VBL		"drm:vbl: "
+#define DRM_DBG_CAT_STATE	"drm:state: "
+#define DRM_DBG_CAT_LEASE	"drm:lease: "
+#define DRM_DBG_CAT_DP		"drm:dp: "
+#define DRM_DBG_CAT_DRMRES	"drm:res: " /* not in MODULE_PARM_DESC */
+
+#endif /* CONFIG_DRM_USE_DYNAMIC_DEBUG */
+
 static inline bool drm_debug_enabled(enum drm_debug_category category)
 {
 	return unlikely(__drm_debug & category);
@@ -334,8 +414,8 @@ __printf(3, 4)
 void drm_dev_printk(const struct device *dev, const char *level,
 		    const char *format, ...);
 __printf(3, 4)
-void drm_dev_dbg(const struct device *dev, enum drm_debug_category category,
-		 const char *format, ...);
+void __drm_dev_dbg(const struct device *dev, enum drm_debug_category category,
+		   const char *format, ...);
 
 /**
  * DRM_DEV_ERROR() - Error output.
@@ -383,7 +463,7 @@ void drm_dev_dbg(const struct device *dev, enum drm_debug_category category,
  * @fmt: printf() like format string.
  */
 #define DRM_DEV_DEBUG(dev, fmt, ...)					\
-	drm_dev_dbg(dev, DRM_UT_CORE, fmt, ##__VA_ARGS__)
+	drm_dev_dbg(dev, DRM_DBG_CAT_CORE, fmt, ##__VA_ARGS__)
 /**
  * DRM_DEV_DEBUG_DRIVER() - Debug output for vendor specific part of the driver
  *
@@ -391,7 +471,7 @@ void drm_dev_dbg(const struct device *dev, enum drm_debug_category category,
  * @fmt: printf() like format string.
  */
 #define DRM_DEV_DEBUG_DRIVER(dev, fmt, ...)				\
-	drm_dev_dbg(dev, DRM_UT_DRIVER,	fmt, ##__VA_ARGS__)
+	drm_dev_dbg(dev, DRM_DBG_CAT_DRIVER, fmt, ##__VA_ARGS__)
 /**
  * DRM_DEV_DEBUG_KMS() - Debug output for modesetting code
  *
@@ -399,7 +479,7 @@ void drm_dev_dbg(const struct device *dev, enum drm_debug_category category,
  * @fmt: printf() like format string.
  */
 #define DRM_DEV_DEBUG_KMS(dev, fmt, ...)				\
-	drm_dev_dbg(dev, DRM_UT_KMS, fmt, ##__VA_ARGS__)
+	drm_dev_dbg(dev, DRM_DBG_CAT_KMS, fmt, ##__VA_ARGS__)
 
 /*
  * struct drm_device based logging
@@ -443,25 +523,25 @@ void drm_dev_dbg(const struct device *dev, enum drm_debug_category category,
 
 
 #define drm_dbg_core(drm, fmt, ...)					\
-	drm_dev_dbg((drm) ? (drm)->dev : NULL, DRM_UT_CORE, fmt, ##__VA_ARGS__)
+	drm_dev_dbg((drm) ? (drm)->dev : NULL, DRM_DBG_CAT_CORE, fmt, ##__VA_ARGS__)
 #define drm_dbg(drm, fmt, ...)						\
-	drm_dev_dbg((drm) ? (drm)->dev : NULL, DRM_UT_DRIVER, fmt, ##__VA_ARGS__)
+	drm_dev_dbg((drm) ? (drm)->dev : NULL, DRM_DBG_CAT_DRIVER, fmt, ##__VA_ARGS__)
 #define drm_dbg_kms(drm, fmt, ...)					\
-	drm_dev_dbg((drm) ? (drm)->dev : NULL, DRM_UT_KMS, fmt, ##__VA_ARGS__)
+	drm_dev_dbg((drm) ? (drm)->dev : NULL, DRM_DBG_CAT_KMS, fmt, ##__VA_ARGS__)
 #define drm_dbg_prime(drm, fmt, ...)					\
-	drm_dev_dbg((drm) ? (drm)->dev : NULL, DRM_UT_PRIME, fmt, ##__VA_ARGS__)
+	drm_dev_dbg((drm) ? (drm)->dev : NULL, DRM_DBG_CAT_PRIME, fmt, ##__VA_ARGS__)
 #define drm_dbg_atomic(drm, fmt, ...)					\
-	drm_dev_dbg((drm) ? (drm)->dev : NULL, DRM_UT_ATOMIC, fmt, ##__VA_ARGS__)
+	drm_dev_dbg((drm) ? (drm)->dev : NULL, DRM_DBG_CAT_ATOMIC, fmt, ##__VA_ARGS__)
 #define drm_dbg_vbl(drm, fmt, ...)					\
-	drm_dev_dbg((drm) ? (drm)->dev : NULL, DRM_UT_VBL, fmt, ##__VA_ARGS__)
+	drm_dev_dbg((drm) ? (drm)->dev : NULL, DRM_DBG_CAT_VBL, fmt, ##__VA_ARGS__)
 #define drm_dbg_state(drm, fmt, ...)					\
-	drm_dev_dbg((drm) ? (drm)->dev : NULL, DRM_UT_STATE, fmt, ##__VA_ARGS__)
+	drm_dev_dbg((drm) ? (drm)->dev : NULL, DRM_DBG_CAT_STATE, fmt, ##__VA_ARGS__)
 #define drm_dbg_lease(drm, fmt, ...)					\
-	drm_dev_dbg((drm) ? (drm)->dev : NULL, DRM_UT_LEASE, fmt, ##__VA_ARGS__)
+	drm_dev_dbg((drm) ? (drm)->dev : NULL, DRM_DBG_CAT_LEASE, fmt, ##__VA_ARGS__)
 #define drm_dbg_dp(drm, fmt, ...)					\
-	drm_dev_dbg((drm) ? (drm)->dev : NULL, DRM_UT_DP, fmt, ##__VA_ARGS__)
+	drm_dev_dbg((drm) ? (drm)->dev : NULL, DRM_DBG_CAT_DP, fmt, ##__VA_ARGS__)
 #define drm_dbg_drmres(drm, fmt, ...)					\
-	drm_dev_dbg((drm) ? (drm)->dev : NULL, DRM_UT_DRMRES, fmt, ##__VA_ARGS__)
+	drm_dev_dbg((drm) ? (drm)->dev : NULL, DRM_DBG_CAT_DRMRES, fmt, ##__VA_ARGS__)
 
 
 /*
@@ -471,7 +551,7 @@ void drm_dev_dbg(const struct device *dev, enum drm_debug_category category,
  */
 
 __printf(2, 3)
-void __drm_dbg(enum drm_debug_category category, const char *format, ...);
+void ___drm_dbg(enum drm_debug_category category, const char *format, ...);
 __printf(1, 2)
 void __drm_err(const char *format, ...);
 
@@ -500,29 +580,30 @@ void __drm_err(const char *format, ...);
 #define DRM_ERROR_RATELIMITED(fmt, ...)					\
 	DRM_DEV_ERROR_RATELIMITED(NULL, fmt, ##__VA_ARGS__)
 
+
 #define DRM_DEBUG(fmt, ...)						\
-	__drm_dbg(DRM_UT_CORE, fmt, ##__VA_ARGS__)
+	__drm_dbg(DRM_DBG_CAT_CORE, fmt, ##__VA_ARGS__)
 
 #define DRM_DEBUG_DRIVER(fmt, ...)					\
-	__drm_dbg(DRM_UT_DRIVER, fmt, ##__VA_ARGS__)
+	__drm_dbg(DRM_DBG_CAT_DRIVER, fmt, ##__VA_ARGS__)
 
 #define DRM_DEBUG_KMS(fmt, ...)						\
-	__drm_dbg(DRM_UT_KMS, fmt, ##__VA_ARGS__)
+	__drm_dbg(DRM_DBG_CAT_KMS, fmt, ##__VA_ARGS__)
 
 #define DRM_DEBUG_PRIME(fmt, ...)					\
-	__drm_dbg(DRM_UT_PRIME, fmt, ##__VA_ARGS__)
+	__drm_dbg(DRM_DBG_CAT_PRIME, fmt, ##__VA_ARGS__)
 
 #define DRM_DEBUG_ATOMIC(fmt, ...)					\
-	__drm_dbg(DRM_UT_ATOMIC, fmt, ##__VA_ARGS__)
+	__drm_dbg(DRM_DBG_CAT_ATOMIC, fmt, ##__VA_ARGS__)
 
 #define DRM_DEBUG_VBL(fmt, ...)						\
-	__drm_dbg(DRM_UT_VBL, fmt, ##__VA_ARGS__)
+	__drm_dbg(DRM_DBG_CAT_VBL, fmt, ##__VA_ARGS__)
 
 #define DRM_DEBUG_LEASE(fmt, ...)					\
-	__drm_dbg(DRM_UT_LEASE, fmt, ##__VA_ARGS__)
+	__drm_dbg(DRM_DBG_CAT_LEASE, fmt, ##__VA_ARGS__)
 
 #define DRM_DEBUG_DP(fmt, ...)						\
-	__drm_dbg(DRM_UT_DP, fmt, ## __VA_ARGS__)
+	__drm_dbg(DRM_DBG_CAT_DP, fmt, ## __VA_ARGS__)
 
 #define __DRM_DEFINE_DBG_RATELIMITED(category, drm, fmt, ...)					\
 ({												\
@@ -530,7 +611,8 @@ void __drm_err(const char *format, ...);
 	const struct drm_device *drm_ = (drm);							\
 												\
 	if (drm_debug_enabled(DRM_UT_ ## category) && __ratelimit(&rs_))			\
-		drm_dev_printk(drm_ ? drm_->dev : NULL, KERN_DEBUG, fmt, ## __VA_ARGS__);	\
+		drm_dev_dbg((drm_) ? (drm_)->dev : NULL,					\
+			    DRM_DBG_CAT_ ## category, fmt, ##__VA_ARGS__);			\
 })
 
 #define drm_dbg_kms_ratelimited(drm, fmt, ...) \
-- 
2.31.1

[PATCH v6 07/11] drm_print: instrument drm_debug_enabled

[Jim Cromie]

Duplicate drm_debug_enabled() code into both "basic" and "dyndbg"
ifdef branches.  Then add a pr_debug("todo: ...") into the "dyndbg"
branch.

Then convert the "dyndbg" branch's code to a macro, so that its
pr_debug() get its callsite info from the invoking function, instead
of from drm_debug_enabled() itself.

This gives us unique callsite info for the 8 remaining users of
drm_debug_enabled(), and lets us enable them individually to see how
much logging traffic they generate.  The oft-visited callsites can
then be reviewed for runtime cost and possible optimizations.

Heres what we get:

bash-5.1# modprobe drm
dyndbg: 384 debug prints in module drm
bash-5.1# grep todo: /proc/dynamic_debug/control
drivers/gpu/drm/drm_edid.c:1843 [drm]connector_bad_edid =_ "todo: maybe avoid via dyndbg\012"
drivers/gpu/drm/drm_print.c:309 [drm]___drm_dbg =p "todo: maybe avoid via dyndbg\012"
drivers/gpu/drm/drm_print.c:286 [drm]__drm_dev_dbg =p "todo: maybe avoid via dyndbg\012"
drivers/gpu/drm/drm_vblank.c:1491 [drm]drm_vblank_restore =_ "todo: maybe avoid via dyndbg\012"
drivers/gpu/drm/drm_vblank.c:787 [drm]drm_crtc_vblank_helper_get_vblank_timestamp_internal =_ "todo: maybe avoid via dyndbg\012"
drivers/gpu/drm/drm_vblank.c:410 [drm]drm_crtc_accurate_vblank_count =_ "todo: maybe avoid via dyndbg\012"
drivers/gpu/drm/drm_atomic_uapi.c:1457 [drm]drm_mode_atomic_ioctl =_ "todo: maybe avoid via dyndbg\012"
drivers/gpu/drm/drm_edid_load.c:178 [drm]edid_load =_ "todo: maybe avoid via dyndbg\012"

At quick glance, edid won't qualify, drm_print might, drm_vblank is
strongest chance, maybe atomic-ioctl too.

Signed-off-by: Jim Cromie <jim.cromie@gmail.com>
---
---
 include/drm/drm_print.h | 16 +++++++++++-----
 1 file changed, 11 insertions(+), 5 deletions(-)

diff --git a/include/drm/drm_print.h b/include/drm/drm_print.h
index 8775b67ecb30..1f8a65eb5d9a 100644
--- a/include/drm/drm_print.h
+++ b/include/drm/drm_print.h
@@ -378,6 +378,11 @@ enum drm_debug_category {
 #define DRM_DBG_CAT_DP		DRM_UT_DP
 #define DRM_DBG_CAT_DRMRES	DRM_UT_DRMRES
 
+static inline bool drm_debug_enabled(enum drm_debug_category category)
+{
+	return unlikely(__drm_debug & category);
+}
+
 #else /* CONFIG_DRM_USE_DYNAMIC_DEBUG */
 
 /* join prefix+format in cpp so dyndbg can see it */
@@ -397,12 +402,13 @@ enum drm_debug_category {
 #define DRM_DBG_CAT_DP		"drm:dp: "
 #define DRM_DBG_CAT_DRMRES	"drm:res: " /* not in MODULE_PARM_DESC */
 
-#endif /* CONFIG_DRM_USE_DYNAMIC_DEBUG */
+#define drm_debug_enabled(category)			\
+	({						\
+	pr_debug("todo: maybe avoid via dyndbg\n");	\
+	unlikely(__drm_debug & category);		\
+	})
 
-static inline bool drm_debug_enabled(enum drm_debug_category category)
-{
-	return unlikely(__drm_debug & category);
-}
+#endif /* CONFIG_DRM_USE_DYNAMIC_DEBUG */
 
 /*
  * struct device based logging
-- 
2.31.1

[PATCH v6 08/11] amdgpu_ucode: reduce number of pr_debug calls

[Jim Cromie]

There are blocks of DRM_DEBUG calls, consolidate their args into
single calls.  With dynamic-debug in use, each callsite consumes 56
bytes of ro callsite data, and this patch removes about 65 calls, so
it saves ~3.5kb.

no functional changes.

RFC: this creates multi-line log messages, does that break any syslog
conventions ?

Signed-off-by: Jim Cromie <jim.cromie@gmail.com>
---
 drivers/gpu/drm/amd/amdgpu/amdgpu_ucode.c | 293 ++++++++++++----------
 1 file changed, 158 insertions(+), 135 deletions(-)

diff --git a/drivers/gpu/drm/amd/amdgpu/amdgpu_ucode.c b/drivers/gpu/drm/amd/amdgpu/amdgpu_ucode.c
index 2834981f8c08..14a9fef1f4c6 100644
--- a/drivers/gpu/drm/amd/amdgpu/amdgpu_ucode.c
+++ b/drivers/gpu/drm/amd/amdgpu/amdgpu_ucode.c
@@ -30,17 +30,26 @@
 
 static void amdgpu_ucode_print_common_hdr(const struct common_firmware_header *hdr)
 {
-	DRM_DEBUG("size_bytes: %u\n", le32_to_cpu(hdr->size_bytes));
-	DRM_DEBUG("header_size_bytes: %u\n", le32_to_cpu(hdr->header_size_bytes));
-	DRM_DEBUG("header_version_major: %u\n", le16_to_cpu(hdr->header_version_major));
-	DRM_DEBUG("header_version_minor: %u\n", le16_to_cpu(hdr->header_version_minor));
-	DRM_DEBUG("ip_version_major: %u\n", le16_to_cpu(hdr->ip_version_major));
-	DRM_DEBUG("ip_version_minor: %u\n", le16_to_cpu(hdr->ip_version_minor));
-	DRM_DEBUG("ucode_version: 0x%08x\n", le32_to_cpu(hdr->ucode_version));
-	DRM_DEBUG("ucode_size_bytes: %u\n", le32_to_cpu(hdr->ucode_size_bytes));
-	DRM_DEBUG("ucode_array_offset_bytes: %u\n",
-		  le32_to_cpu(hdr->ucode_array_offset_bytes));
-	DRM_DEBUG("crc32: 0x%08x\n", le32_to_cpu(hdr->crc32));
+	DRM_DEBUG("size_bytes: %u\n"
+		  "header_size_bytes: %u\n"
+		  "header_version_major: %u\n"
+		  "header_version_minor: %u\n"
+		  "ip_version_major: %u\n"
+		  "ip_version_minor: %u\n"
+		  "ucode_version: 0x%08x\n"
+		  "ucode_size_bytes: %u\n"
+		  "ucode_array_offset_bytes: %u\n"
+		  "crc32: 0x%08x\n",
+		  le32_to_cpu(hdr->size_bytes),
+		  le32_to_cpu(hdr->header_size_bytes),
+		  le16_to_cpu(hdr->header_version_major),
+		  le16_to_cpu(hdr->header_version_minor),
+		  le16_to_cpu(hdr->ip_version_major),
+		  le16_to_cpu(hdr->ip_version_minor),
+		  le32_to_cpu(hdr->ucode_version),
+		  le32_to_cpu(hdr->ucode_size_bytes),
+		  le32_to_cpu(hdr->ucode_array_offset_bytes),
+		  le32_to_cpu(hdr->crc32));
 }
 
 void amdgpu_ucode_print_mc_hdr(const struct common_firmware_header *hdr)
@@ -55,9 +64,9 @@ void amdgpu_ucode_print_mc_hdr(const struct common_firmware_header *hdr)
 		const struct mc_firmware_header_v1_0 *mc_hdr =
 			container_of(hdr, struct mc_firmware_header_v1_0, header);
 
-		DRM_DEBUG("io_debug_size_bytes: %u\n",
-			  le32_to_cpu(mc_hdr->io_debug_size_bytes));
-		DRM_DEBUG("io_debug_array_offset_bytes: %u\n",
+		DRM_DEBUG("io_debug_size_bytes: %u\n"
+			  "io_debug_array_offset_bytes: %u\n",
+			  le32_to_cpu(mc_hdr->io_debug_size_bytes),
 			  le32_to_cpu(mc_hdr->io_debug_array_offset_bytes));
 	} else {
 		DRM_ERROR("Unknown MC ucode version: %u.%u\n", version_major, version_minor);
@@ -82,13 +91,17 @@ void amdgpu_ucode_print_smc_hdr(const struct common_firmware_header *hdr)
 		switch (version_minor) {
 		case 0:
 			v2_0_hdr = container_of(hdr, struct smc_firmware_header_v2_0, v1_0.header);
-			DRM_DEBUG("ppt_offset_bytes: %u\n", le32_to_cpu(v2_0_hdr->ppt_offset_bytes));
-			DRM_DEBUG("ppt_size_bytes: %u\n", le32_to_cpu(v2_0_hdr->ppt_size_bytes));
+			DRM_DEBUG("ppt_offset_bytes: %u\n"
+				  "ppt_size_bytes: %u\n",
+				  le32_to_cpu(v2_0_hdr->ppt_offset_bytes),
+				  le32_to_cpu(v2_0_hdr->ppt_size_bytes));
 			break;
 		case 1:
 			v2_1_hdr = container_of(hdr, struct smc_firmware_header_v2_1, v1_0.header);
-			DRM_DEBUG("pptable_count: %u\n", le32_to_cpu(v2_1_hdr->pptable_count));
-			DRM_DEBUG("pptable_entry_offset: %u\n", le32_to_cpu(v2_1_hdr->pptable_entry_offset));
+			DRM_DEBUG("pptable_count: %u\n"
+				  "pptable_entry_offset: %u\n",
+				  le32_to_cpu(v2_1_hdr->pptable_count),
+				  le32_to_cpu(v2_1_hdr->pptable_entry_offset));
 			break;
 		default:
 			break;
@@ -111,10 +124,12 @@ void amdgpu_ucode_print_gfx_hdr(const struct common_firmware_header *hdr)
 		const struct gfx_firmware_header_v1_0 *gfx_hdr =
 			container_of(hdr, struct gfx_firmware_header_v1_0, header);
 
-		DRM_DEBUG("ucode_feature_version: %u\n",
-			  le32_to_cpu(gfx_hdr->ucode_feature_version));
-		DRM_DEBUG("jt_offset: %u\n", le32_to_cpu(gfx_hdr->jt_offset));
-		DRM_DEBUG("jt_size: %u\n", le32_to_cpu(gfx_hdr->jt_size));
+		DRM_DEBUG("ucode_feature_version: %u\n"
+			  "jt_offset: %u\n"
+			  "jt_size: %u\n",
+			  le32_to_cpu(gfx_hdr->ucode_feature_version),
+			  le32_to_cpu(gfx_hdr->jt_offset),
+			  le32_to_cpu(gfx_hdr->jt_size));
 	} else {
 		DRM_ERROR("Unknown GFX ucode version: %u.%u\n", version_major, version_minor);
 	}
@@ -132,82 +147,88 @@ void amdgpu_ucode_print_rlc_hdr(const struct common_firmware_header *hdr)
 		const struct rlc_firmware_header_v1_0 *rlc_hdr =
 			container_of(hdr, struct rlc_firmware_header_v1_0, header);
 
-		DRM_DEBUG("ucode_feature_version: %u\n",
-			  le32_to_cpu(rlc_hdr->ucode_feature_version));
-		DRM_DEBUG("save_and_restore_offset: %u\n",
-			  le32_to_cpu(rlc_hdr->save_and_restore_offset));
-		DRM_DEBUG("clear_state_descriptor_offset: %u\n",
-			  le32_to_cpu(rlc_hdr->clear_state_descriptor_offset));
-		DRM_DEBUG("avail_scratch_ram_locations: %u\n",
-			  le32_to_cpu(rlc_hdr->avail_scratch_ram_locations));
-		DRM_DEBUG("master_pkt_description_offset: %u\n",
+		DRM_DEBUG("ucode_feature_version: %u\n"
+			  "save_and_restore_offset: %u\n"
+			  "clear_state_descriptor_offset: %u\n"
+			  "avail_scratch_ram_locations: %u\n"
+			  "master_pkt_description_offset: %u\n",
+			  le32_to_cpu(rlc_hdr->ucode_feature_version),
+			  le32_to_cpu(rlc_hdr->save_and_restore_offset),
+			  le32_to_cpu(rlc_hdr->clear_state_descriptor_offset),
+			  le32_to_cpu(rlc_hdr->avail_scratch_ram_locations),
 			  le32_to_cpu(rlc_hdr->master_pkt_description_offset));
+
 	} else if (version_major == 2) {
 		const struct rlc_firmware_header_v2_0 *rlc_hdr =
 			container_of(hdr, struct rlc_firmware_header_v2_0, header);
 
-		DRM_DEBUG("ucode_feature_version: %u\n",
-			  le32_to_cpu(rlc_hdr->ucode_feature_version));
-		DRM_DEBUG("jt_offset: %u\n", le32_to_cpu(rlc_hdr->jt_offset));
-		DRM_DEBUG("jt_size: %u\n", le32_to_cpu(rlc_hdr->jt_size));
-		DRM_DEBUG("save_and_restore_offset: %u\n",
-			  le32_to_cpu(rlc_hdr->save_and_restore_offset));
-		DRM_DEBUG("clear_state_descriptor_offset: %u\n",
-			  le32_to_cpu(rlc_hdr->clear_state_descriptor_offset));
-		DRM_DEBUG("avail_scratch_ram_locations: %u\n",
-			  le32_to_cpu(rlc_hdr->avail_scratch_ram_locations));
-		DRM_DEBUG("reg_restore_list_size: %u\n",
-			  le32_to_cpu(rlc_hdr->reg_restore_list_size));
-		DRM_DEBUG("reg_list_format_start: %u\n",
-			  le32_to_cpu(rlc_hdr->reg_list_format_start));
-		DRM_DEBUG("reg_list_format_separate_start: %u\n",
+		DRM_DEBUG("ucode_feature_version: %u\n"
+			  "jt_offset: %u\n"
+			  "jt_size: %u\n"
+			  "save_and_restore_offset: %u\n"
+			  "clear_state_descriptor_offset: %u\n"
+			  "avail_scratch_ram_locations: %u\n"
+			  "reg_restore_list_size: %u\n"
+			  "reg_list_format_start: %u\n"
+			  "reg_list_format_separate_start: %u\n",
+			  le32_to_cpu(rlc_hdr->ucode_feature_version),
+			  le32_to_cpu(rlc_hdr->jt_offset),
+			  le32_to_cpu(rlc_hdr->jt_size),
+			  le32_to_cpu(rlc_hdr->save_and_restore_offset),
+			  le32_to_cpu(rlc_hdr->clear_state_descriptor_offset),
+			  le32_to_cpu(rlc_hdr->avail_scratch_ram_locations),
+			  le32_to_cpu(rlc_hdr->reg_restore_list_size),
+			  le32_to_cpu(rlc_hdr->reg_list_format_start),
 			  le32_to_cpu(rlc_hdr->reg_list_format_separate_start));
-		DRM_DEBUG("starting_offsets_start: %u\n",
-			  le32_to_cpu(rlc_hdr->starting_offsets_start));
-		DRM_DEBUG("reg_list_format_size_bytes: %u\n",
-			  le32_to_cpu(rlc_hdr->reg_list_format_size_bytes));
-		DRM_DEBUG("reg_list_format_array_offset_bytes: %u\n",
-			  le32_to_cpu(rlc_hdr->reg_list_format_array_offset_bytes));
-		DRM_DEBUG("reg_list_size_bytes: %u\n",
-			  le32_to_cpu(rlc_hdr->reg_list_size_bytes));
-		DRM_DEBUG("reg_list_array_offset_bytes: %u\n",
-			  le32_to_cpu(rlc_hdr->reg_list_array_offset_bytes));
-		DRM_DEBUG("reg_list_format_separate_size_bytes: %u\n",
-			  le32_to_cpu(rlc_hdr->reg_list_format_separate_size_bytes));
-		DRM_DEBUG("reg_list_format_separate_array_offset_bytes: %u\n",
-			  le32_to_cpu(rlc_hdr->reg_list_format_separate_array_offset_bytes));
-		DRM_DEBUG("reg_list_separate_size_bytes: %u\n",
-			  le32_to_cpu(rlc_hdr->reg_list_separate_size_bytes));
-		DRM_DEBUG("reg_list_separate_array_offset_bytes: %u\n",
+
+		DRM_DEBUG("starting_offsets_start: %u\n"
+			  "reg_list_format_size_bytes: %u\n"
+			  "reg_list_format_array_offset_bytes: %u\n"
+			  "reg_list_size_bytes: %u\n"
+			  "reg_list_array_offset_bytes: %u\n"
+			  "reg_list_format_separate_size_bytes: %u\n"
+			  "reg_list_format_separate_array_offset_bytes: %u\n"
+			  "reg_list_separate_size_bytes: %u\n"
+			  "reg_list_separate_array_offset_bytes: %u\n",
+			  le32_to_cpu(rlc_hdr->starting_offsets_start),
+			  le32_to_cpu(rlc_hdr->reg_list_format_size_bytes),
+			  le32_to_cpu(rlc_hdr->reg_list_format_array_offset_bytes),
+			  le32_to_cpu(rlc_hdr->reg_list_size_bytes),
+			  le32_to_cpu(rlc_hdr->reg_list_array_offset_bytes),
+			  le32_to_cpu(rlc_hdr->reg_list_format_separate_size_bytes),
+			  le32_to_cpu(rlc_hdr->reg_list_format_separate_array_offset_bytes),
+			  le32_to_cpu(rlc_hdr->reg_list_separate_size_bytes),
 			  le32_to_cpu(rlc_hdr->reg_list_separate_array_offset_bytes));
+
 		if (version_minor == 1) {
 			const struct rlc_firmware_header_v2_1 *v2_1 =
 				container_of(rlc_hdr, struct rlc_firmware_header_v2_1, v2_0);
-			DRM_DEBUG("reg_list_format_direct_reg_list_length: %u\n",
-				  le32_to_cpu(v2_1->reg_list_format_direct_reg_list_length));
-			DRM_DEBUG("save_restore_list_cntl_ucode_ver: %u\n",
-				  le32_to_cpu(v2_1->save_restore_list_cntl_ucode_ver));
-			DRM_DEBUG("save_restore_list_cntl_feature_ver: %u\n",
-				  le32_to_cpu(v2_1->save_restore_list_cntl_feature_ver));
-			DRM_DEBUG("save_restore_list_cntl_size_bytes %u\n",
-				  le32_to_cpu(v2_1->save_restore_list_cntl_size_bytes));
-			DRM_DEBUG("save_restore_list_cntl_offset_bytes: %u\n",
-				  le32_to_cpu(v2_1->save_restore_list_cntl_offset_bytes));
-			DRM_DEBUG("save_restore_list_gpm_ucode_ver: %u\n",
-				  le32_to_cpu(v2_1->save_restore_list_gpm_ucode_ver));
-			DRM_DEBUG("save_restore_list_gpm_feature_ver: %u\n",
-				  le32_to_cpu(v2_1->save_restore_list_gpm_feature_ver));
-			DRM_DEBUG("save_restore_list_gpm_size_bytes %u\n",
-				  le32_to_cpu(v2_1->save_restore_list_gpm_size_bytes));
-			DRM_DEBUG("save_restore_list_gpm_offset_bytes: %u\n",
-				  le32_to_cpu(v2_1->save_restore_list_gpm_offset_bytes));
-			DRM_DEBUG("save_restore_list_srm_ucode_ver: %u\n",
-				  le32_to_cpu(v2_1->save_restore_list_srm_ucode_ver));
-			DRM_DEBUG("save_restore_list_srm_feature_ver: %u\n",
-				  le32_to_cpu(v2_1->save_restore_list_srm_feature_ver));
-			DRM_DEBUG("save_restore_list_srm_size_bytes %u\n",
-				  le32_to_cpu(v2_1->save_restore_list_srm_size_bytes));
-			DRM_DEBUG("save_restore_list_srm_offset_bytes: %u\n",
+
+			DRM_DEBUG("reg_list_format_direct_reg_list_length: %u\n"
+				  "save_restore_list_cntl_ucode_ver: %u\n"
+				  "save_restore_list_cntl_feature_ver: %u\n"
+				  "save_restore_list_cntl_size_bytes %u\n"
+				  "save_restore_list_cntl_offset_bytes: %u\n"
+				  "save_restore_list_gpm_ucode_ver: %u\n"
+				  "save_restore_list_gpm_feature_ver: %u\n"
+				  "save_restore_list_gpm_size_bytes %u\n"
+				  "save_restore_list_gpm_offset_bytes: %u\n"
+				  "save_restore_list_srm_ucode_ver: %u\n"
+				  "save_restore_list_srm_feature_ver: %u\n"
+				  "save_restore_list_srm_size_bytes %u\n"
+				  "save_restore_list_srm_offset_bytes: %u\n",
+				  le32_to_cpu(v2_1->reg_list_format_direct_reg_list_length),
+				  le32_to_cpu(v2_1->save_restore_list_cntl_ucode_ver),
+				  le32_to_cpu(v2_1->save_restore_list_cntl_feature_ver),
+				  le32_to_cpu(v2_1->save_restore_list_cntl_size_bytes),
+				  le32_to_cpu(v2_1->save_restore_list_cntl_offset_bytes),
+				  le32_to_cpu(v2_1->save_restore_list_gpm_ucode_ver),
+				  le32_to_cpu(v2_1->save_restore_list_gpm_feature_ver),
+				  le32_to_cpu(v2_1->save_restore_list_gpm_size_bytes),
+				  le32_to_cpu(v2_1->save_restore_list_gpm_offset_bytes),
+				  le32_to_cpu(v2_1->save_restore_list_srm_ucode_ver),
+				  le32_to_cpu(v2_1->save_restore_list_srm_feature_ver),
+				  le32_to_cpu(v2_1->save_restore_list_srm_size_bytes),
 				  le32_to_cpu(v2_1->save_restore_list_srm_offset_bytes));
 		}
 	} else {
@@ -227,12 +248,14 @@ void amdgpu_ucode_print_sdma_hdr(const struct common_firmware_header *hdr)
 		const struct sdma_firmware_header_v1_0 *sdma_hdr =
 			container_of(hdr, struct sdma_firmware_header_v1_0, header);
 
-		DRM_DEBUG("ucode_feature_version: %u\n",
-			  le32_to_cpu(sdma_hdr->ucode_feature_version));
-		DRM_DEBUG("ucode_change_version: %u\n",
-			  le32_to_cpu(sdma_hdr->ucode_change_version));
-		DRM_DEBUG("jt_offset: %u\n", le32_to_cpu(sdma_hdr->jt_offset));
-		DRM_DEBUG("jt_size: %u\n", le32_to_cpu(sdma_hdr->jt_size));
+		DRM_DEBUG("ucode_feature_version: %u\n"
+			  "ucode_change_version: %u\n"
+			  "jt_offset: %u\n"
+			  "jt_size: %u\n",
+			  le32_to_cpu(sdma_hdr->ucode_feature_version),
+			  le32_to_cpu(sdma_hdr->ucode_change_version),
+			  le32_to_cpu(sdma_hdr->jt_offset),
+			  le32_to_cpu(sdma_hdr->jt_size));
 		if (version_minor >= 1) {
 			const struct sdma_firmware_header_v1_1 *sdma_v1_1_hdr =
 				container_of(sdma_hdr, struct sdma_firmware_header_v1_1, v1_0);
@@ -256,36 +279,36 @@ void amdgpu_ucode_print_psp_hdr(const struct common_firmware_header *hdr)
 		const struct psp_firmware_header_v1_0 *psp_hdr =
 			container_of(hdr, struct psp_firmware_header_v1_0, header);
 
-		DRM_DEBUG("ucode_feature_version: %u\n",
-			  le32_to_cpu(psp_hdr->sos.fw_version));
-		DRM_DEBUG("sos_offset_bytes: %u\n",
-			  le32_to_cpu(psp_hdr->sos.offset_bytes));
-		DRM_DEBUG("sos_size_bytes: %u\n",
+		DRM_DEBUG("ucode_feature_version: %u\n"
+			  "sos_offset_bytes: %u\n"
+			  "sos_size_bytes: %u\n",
+			  le32_to_cpu(psp_hdr->sos.fw_version),
+			  le32_to_cpu(psp_hdr->sos.offset_bytes),
 			  le32_to_cpu(psp_hdr->sos.size_bytes));
 		if (version_minor == 1) {
 			const struct psp_firmware_header_v1_1 *psp_hdr_v1_1 =
 				container_of(psp_hdr, struct psp_firmware_header_v1_1, v1_0);
-			DRM_DEBUG("toc_header_version: %u\n",
-				  le32_to_cpu(psp_hdr_v1_1->toc.fw_version));
-			DRM_DEBUG("toc_offset_bytes: %u\n",
-				  le32_to_cpu(psp_hdr_v1_1->toc.offset_bytes));
-			DRM_DEBUG("toc_size_bytes: %u\n",
-				  le32_to_cpu(psp_hdr_v1_1->toc.size_bytes));
-			DRM_DEBUG("kdb_header_version: %u\n",
-				  le32_to_cpu(psp_hdr_v1_1->kdb.fw_version));
-			DRM_DEBUG("kdb_offset_bytes: %u\n",
-				  le32_to_cpu(psp_hdr_v1_1->kdb.offset_bytes));
-			DRM_DEBUG("kdb_size_bytes: %u\n",
+			DRM_DEBUG("toc_header_version: %u\n"
+				  "toc_offset_bytes: %u\n"
+				  "toc_size_bytes: %u\n"
+				  "kdb_header_version: %u\n"
+				  "kdb_offset_bytes: %u\n"
+				  "kdb_size_bytes: %u\n",
+				  le32_to_cpu(psp_hdr_v1_1->toc.fw_version),
+				  le32_to_cpu(psp_hdr_v1_1->toc.offset_bytes),
+				  le32_to_cpu(psp_hdr_v1_1->toc.size_bytes),
+				  le32_to_cpu(psp_hdr_v1_1->kdb.fw_version),
+				  le32_to_cpu(psp_hdr_v1_1->kdb.offset_bytes),
 				  le32_to_cpu(psp_hdr_v1_1->kdb.size_bytes));
 		}
 		if (version_minor == 2) {
 			const struct psp_firmware_header_v1_2 *psp_hdr_v1_2 =
 				container_of(psp_hdr, struct psp_firmware_header_v1_2, v1_0);
-			DRM_DEBUG("kdb_header_version: %u\n",
-				  le32_to_cpu(psp_hdr_v1_2->kdb.fw_version));
-			DRM_DEBUG("kdb_offset_bytes: %u\n",
-				  le32_to_cpu(psp_hdr_v1_2->kdb.offset_bytes));
-			DRM_DEBUG("kdb_size_bytes: %u\n",
+			DRM_DEBUG("kdb_header_version: %u\n"
+				  "kdb_offset_bytes: %u\n"
+				  "kdb_size_bytes: %u\n",
+				  le32_to_cpu(psp_hdr_v1_2->kdb.fw_version),
+				  le32_to_cpu(psp_hdr_v1_2->kdb.offset_bytes),
 				  le32_to_cpu(psp_hdr_v1_2->kdb.size_bytes));
 		}
 		if (version_minor == 3) {
@@ -293,23 +316,23 @@ void amdgpu_ucode_print_psp_hdr(const struct common_firmware_header *hdr)
 				container_of(psp_hdr, struct psp_firmware_header_v1_1, v1_0);
 			const struct psp_firmware_header_v1_3 *psp_hdr_v1_3 =
 				container_of(psp_hdr_v1_1, struct psp_firmware_header_v1_3, v1_1);
-			DRM_DEBUG("toc_header_version: %u\n",
-				  le32_to_cpu(psp_hdr_v1_3->v1_1.toc.fw_version));
-			DRM_DEBUG("toc_offset_bytes: %u\n",
-				  le32_to_cpu(psp_hdr_v1_3->v1_1.toc.offset_bytes));
-			DRM_DEBUG("toc_size_bytes: %u\n",
-				  le32_to_cpu(psp_hdr_v1_3->v1_1.toc.size_bytes));
-			DRM_DEBUG("kdb_header_version: %u\n",
-				  le32_to_cpu(psp_hdr_v1_3->v1_1.kdb.fw_version));
-			DRM_DEBUG("kdb_offset_bytes: %u\n",
-				  le32_to_cpu(psp_hdr_v1_3->v1_1.kdb.offset_bytes));
-			DRM_DEBUG("kdb_size_bytes: %u\n",
-				  le32_to_cpu(psp_hdr_v1_3->v1_1.kdb.size_bytes));
-			DRM_DEBUG("spl_header_version: %u\n",
-				  le32_to_cpu(psp_hdr_v1_3->spl.fw_version));
-			DRM_DEBUG("spl_offset_bytes: %u\n",
-				  le32_to_cpu(psp_hdr_v1_3->spl.offset_bytes));
-			DRM_DEBUG("spl_size_bytes: %u\n",
+			DRM_DEBUG("toc_header_version: %u\n"
+				  "toc_offset_bytes: %u\n"
+				  "toc_size_bytes: %u\n"
+				  "kdb_header_version: %u\n"
+				  "kdb_offset_bytes: %u\n"
+				  "kdb_size_bytes: %u\n"
+				  "spl_header_version: %u\n"
+				  "spl_offset_bytes: %u\n"
+				  "spl_size_bytes: %u\n",
+				  le32_to_cpu(psp_hdr_v1_3->v1_1.toc.fw_version),
+				  le32_to_cpu(psp_hdr_v1_3->v1_1.toc.offset_bytes),
+				  le32_to_cpu(psp_hdr_v1_3->v1_1.toc.size_bytes),
+				  le32_to_cpu(psp_hdr_v1_3->v1_1.kdb.fw_version),
+				  le32_to_cpu(psp_hdr_v1_3->v1_1.kdb.offset_bytes),
+				  le32_to_cpu(psp_hdr_v1_3->v1_1.kdb.size_bytes),
+				  le32_to_cpu(psp_hdr_v1_3->spl.fw_version),
+				  le32_to_cpu(psp_hdr_v1_3->spl.offset_bytes),
 				  le32_to_cpu(psp_hdr_v1_3->spl.size_bytes));
 		}
 	} else {
@@ -330,9 +353,9 @@ void amdgpu_ucode_print_gpu_info_hdr(const struct common_firmware_header *hdr)
 		const struct gpu_info_firmware_header_v1_0 *gpu_info_hdr =
 			container_of(hdr, struct gpu_info_firmware_header_v1_0, header);
 
-		DRM_DEBUG("version_major: %u\n",
-			  le16_to_cpu(gpu_info_hdr->version_major));
-		DRM_DEBUG("version_minor: %u\n",
+		DRM_DEBUG("version_major: %u\n"
+			  "version_minor: %u\n",
+			  le16_to_cpu(gpu_info_hdr->version_major),
 			  le16_to_cpu(gpu_info_hdr->version_minor));
 	} else {
 		DRM_ERROR("Unknown gpu_info ucode version: %u.%u\n", version_major, version_minor);
-- 
2.31.1

[PATCH v6 09/11] nouveau: fold multiple DRM_DEBUG_DRIVERs together

[Jim Cromie]

With DRM_USE_DYNAMIC_DEBUG, each callsite record requires 56 bytes.
We can combine 12 into one here and save ~620 bytes.

Signed-off-by: Jim Cromie <jim.cromie@gmail.com>
---
---
 drivers/gpu/drm/nouveau/nouveau_drm.c | 36 +++++++++++++++++----------
 1 file changed, 23 insertions(+), 13 deletions(-)

diff --git a/drivers/gpu/drm/nouveau/nouveau_drm.c b/drivers/gpu/drm/nouveau/nouveau_drm.c
index a616cf4573b8..58693e40b447 100644
--- a/drivers/gpu/drm/nouveau/nouveau_drm.c
+++ b/drivers/gpu/drm/nouveau/nouveau_drm.c
@@ -1246,19 +1246,29 @@ nouveau_drm_pci_table[] = {
 
 static void nouveau_display_options(void)
 {
-	DRM_DEBUG_DRIVER("Loading Nouveau with parameters:\n");
-
-	DRM_DEBUG_DRIVER("... tv_disable   : %d\n", nouveau_tv_disable);
-	DRM_DEBUG_DRIVER("... ignorelid    : %d\n", nouveau_ignorelid);
-	DRM_DEBUG_DRIVER("... duallink     : %d\n", nouveau_duallink);
-	DRM_DEBUG_DRIVER("... nofbaccel    : %d\n", nouveau_nofbaccel);
-	DRM_DEBUG_DRIVER("... config       : %s\n", nouveau_config);
-	DRM_DEBUG_DRIVER("... debug        : %s\n", nouveau_debug);
-	DRM_DEBUG_DRIVER("... noaccel      : %d\n", nouveau_noaccel);
-	DRM_DEBUG_DRIVER("... modeset      : %d\n", nouveau_modeset);
-	DRM_DEBUG_DRIVER("... runpm        : %d\n", nouveau_runtime_pm);
-	DRM_DEBUG_DRIVER("... vram_pushbuf : %d\n", nouveau_vram_pushbuf);
-	DRM_DEBUG_DRIVER("... hdmimhz      : %d\n", nouveau_hdmimhz);
+	DRM_DEBUG_DRIVER("Loading Nouveau with parameters:\n"
+			 "... tv_disable   : %d\n"
+			 "... ignorelid    : %d\n"
+			 "... duallink     : %d\n"
+			 "... nofbaccel    : %d\n"
+			 "... config       : %s\n"
+			 "... debug        : %s\n"
+			 "... noaccel      : %d\n"
+			 "... modeset      : %d\n"
+			 "... runpm        : %d\n"
+			 "... vram_pushbuf : %d\n"
+			 "... hdmimhz      : %d\n"
+			 , nouveau_tv_disable
+			 , nouveau_ignorelid
+			 , nouveau_duallink
+			 , nouveau_nofbaccel
+			 , nouveau_config
+			 , nouveau_debug
+			 , nouveau_noaccel
+			 , nouveau_modeset
+			 , nouveau_runtime_pm
+			 , nouveau_vram_pushbuf
+			 , nouveau_hdmimhz);
 }
 
 static const struct dev_pm_ops nouveau_pm_ops = {
-- 
2.31.1

[PATCH v6 10/11] dyndbg: RFC add debug-trace callback, selftest with it. RFC

[Jim Cromie]

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

v5: (this patch sent after (on top of) v4)

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

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

v6: (this version)
. add test module
. add mod arg to *register, following exec_queries pattern
. move code off file bottom to "better" spot
. move kdoc to c from h

__dxq
---
 include/linux/dynamic_debug.h |  12 +-
 lib/Kconfig.debug             |  11 ++
 lib/Makefile                  |   1 +
 lib/dynamic_debug.c           | 145 ++++++++++++++----
 lib/test_dynamic_debug.c      | 279 ++++++++++++++++++++++++++++++++++
 5 files changed, 418 insertions(+), 30 deletions(-)
 create mode 100644 lib/test_dynamic_debug.c

diff --git a/include/linux/dynamic_debug.h b/include/linux/dynamic_debug.h
index 51b7254daee0..8807367c7903 100644
--- a/include/linux/dynamic_debug.h
+++ b/include/linux/dynamic_debug.h
@@ -20,6 +20,7 @@ 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.
@@ -27,7 +28,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 (*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
diff --git a/lib/Kconfig.debug b/lib/Kconfig.debug
index 5ddd575159fb..f3454b2bfc8e 100644
--- a/lib/Kconfig.debug
+++ b/lib/Kconfig.debug
@@ -2486,6 +2486,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
diff --git a/lib/Makefile b/lib/Makefile
index 5efd1b435a37..01c3c76980ba 100644
--- a/lib/Makefile
+++ b/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
diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
index a43427c67c3f..60bf2c01db1a 100644
--- a/lib/dynamic_debug.c
+++ b/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,6 +582,22 @@ 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
@@ -556,25 +605,12 @@ static int ddebug_exec_queries(char *query, const char *modname)
  *
  * 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);
diff --git a/lib/test_dynamic_debug.c b/lib/test_dynamic_debug.c
new file mode 100644
index 000000000000..802199e2507a
--- /dev/null
+++ b/lib/test_dynamic_debug.c
@@ -0,0 +1,279 @@
+// SPDX-License-Identifier: GPL-2.0-only
+/*
+ * Kernel module for testing dynamic_debug
+ *
+ * Author:
+ *      Jim Cromie	<jim.cromie@gmail.com>
+ */
+
+/*
+ * test-setup:
+ * - use register_tracer to attach a test harness
+ * - a custom trace_printer which counts invocations of enabled pr_debugs
+ * - a DUT (device under test), calling categorized pr_debugs
+ * test-run:
+ * - manipulate the pr_debugs' enablements -> match_ct
+ * - call event generator with loop-ct
+ *   its pr_debug()s are Traced: trace_ct++
+ * - count and compare: mainly trace_ct, but also match_ct
+ */
+
+#include <linux/module.h>
+
+static int trace_ct;	/* the state var */
+static int test_ct;
+static int errors;
+
+static int verbose;
+module_param_named(verbose, verbose, int, 0444);
+MODULE_PARM_DESC(verbose, "notice on tracer");
+
+static int __test_resv;
+module_param_named(test_reserve, __test_resv, int, 0444);
+MODULE_PARM_DESC(test_reserve, "test 'reservation' against 'poaching'\n");
+
+static int __broken_tracer;
+module_param_named(broken_tracer, __broken_tracer, int, 0444);
+MODULE_PARM_DESC(broken_tracer,
+		 "use broken tracer, recursing with pr_debug\n"
+		 "\tonly works at modprobe time\n");
+
+static int good_tracer(const char *decorator, char *prefix, char *label, struct va_format *vaf)
+{
+	trace_ct++;
+	if (verbose)
+		pr_notice("my_tracer: %pV", vaf);
+	return 0;
+}
+
+static int bad_tracer(const char *decorator, char *prefix, char *label, struct va_format *vaf)
+{
+	/* dont try pr_debug, it recurses back here */
+	pr_debug("oops! recursion, crash?\n");
+	return 0;
+}
+
+static int (*my_tracer)
+	(const char *decorator, char *prefix, char *label, struct va_format *vaf);
+
+static void pick_tracer(void)
+{
+	if (__broken_tracer)
+		my_tracer = bad_tracer;
+	else
+		my_tracer = good_tracer;
+}
+
+/* call pr_debug (4 * reps) + 2 times, for tracer side-effects */
+static void DUT(int reps)
+{
+	int i;
+
+	pr_debug("Entry:\n");
+	pr_info(" DUT %d time(s)\n", reps);
+	for (i = 0; i < reps; i++) {
+		pr_debug("hi: %d\n", i);
+		pr_debug("mid: %d\n", i);
+		pr_debug("low: %d\n", i);
+		pr_debug("low:lower: %d subcategory test\n", i);
+	}
+	pr_debug("Exit:\n");
+}
+
+struct test_spec {
+	int matches;	/* expected rc from applying qry */
+	int loops;	/* passed to DUT */
+	int hits;	/* should match trace_ct after gen */
+	const char *mod;	/* Anyof: wildcarded-string, null, &mod.name */
+	const char *qry;	/* echo $qry > control */
+	const char *story;	/* test purpose explanation progress */
+};
+
+static void expect_count(struct test_spec *t)
+{
+	test_ct++;
+	if (trace_ct != t->hits) {
+		pr_err("fail#%d: got %d != %d by \"%s\"\tfor \"%s\"\n",
+		       test_ct, trace_ct, t->hits, t->qry, t->story);
+		errors++;
+	} else
+		pr_info("pass#%d, hits %d, on \"%s\"\n", test_ct, t->hits, t->story);
+
+	trace_ct = 0;
+}
+
+static void expect_matches(int got, struct test_spec *t)
+{
+	if (got != t->matches) {
+		pr_warn(" nok: got %d != %d on \"%s\"\n", got, t->matches, t->qry);
+		errors++;
+	} else
+		pr_info(" ok: %d matches by \"%s\"\t for \"%s\"\n", got, t->qry, t->story);
+}
+
+static void do_test_spec(struct test_spec *t)
+{
+	int match_count;
+
+	match_count = dynamic_debug_exec_queries(t->qry, t->mod);
+	if (match_count < 0) {
+		pr_err("exec-queries fail rc:%d\n", match_count);
+		return;
+	}
+	expect_matches(match_count, t);
+	DUT(t->loops);
+	expect_count(t);
+}
+
+static const char modnm[] = "test_dynamic_debug";
+
+static void do_register_test(struct test_spec *t, int deep)
+{
+	int match_count;
+
+	pr_debug("enter: %s\n", t->story);
+	if (deep)
+		pr_debug("register good tracer\n");
+
+	match_count = dynamic_debug_register_tracer(t->qry, t->mod, good_tracer);
+	if (match_count < 0) {
+		pr_err("exec-queries fail rc:%d\n", match_count);
+		return;
+	}
+	expect_matches(match_count, t);
+	DUT(t->loops);
+	expect_count(t);
+
+	if (!deep)
+		return;
+
+	pr_debug("unregister bad tracer\n");
+	match_count = dynamic_debug_unregister_tracer(t->qry, t->mod, bad_tracer);
+	if (match_count < 0) {
+		pr_err("exec-queries fail rc:%d\n", match_count);
+		return;
+	}
+	expect_matches(match_count, t);
+	DUT(t->loops);
+	expect_count(t);
+
+	pr_debug("unregister good tracer\n");
+	match_count = dynamic_debug_unregister_tracer(t->qry, t->mod, good_tracer);
+	if (match_count < 0) {
+		pr_err("exec-queries fail rc:%d\n", match_count);
+		return;
+	}
+	expect_matches(match_count, t);
+	DUT(t->loops);
+	expect_count(t);
+}
+
+struct test_spec registry_tests[] = {
+
+	/* matches, loops, hits, modname, query, story */
+	{ 6, 1, 0,   modnm, "func DUT +_",	"probe: DUT 1" },
+	{ 6, 1, 2+4, modnm, "func DUT +T",	"enable (T)" },
+	{ 6, 2, 10,  modnm, "func DUT -_",	"probe: DUT 2" },
+	{ 6, 3, 14,  modnm, "func DUT +T",	"over-enable, ok" },
+	{ 6, 2, 10,  modnm, "func DUT -_",	"probe: DUT 3" },
+	{ 6, 3, 0,   modnm, "func DUT -T",	"disable" },
+
+	/* 5 other callsites here */
+	{ 11, 1, 0,  modnm, "+_",	"probe: whole module" },
+	{ 11, 5, 22, modnm, "+T",	"enable (T) whole module" },
+	{ 11, 1, 7, modnm, "+T",	"re-enable whole module" },
+	{ 11, 3, 1,  modnm, "-T",	"disable whole module" },
+
+	{ 3, 2, 0,  modnm, "func test_* +_",	"probe: count test_*" },
+	{ 3, 2, 0,  modnm, "func test_* +_",	"probe: count test_*" },
+
+	/* terminate registry tests in a known T state */
+	{ 6, 3, 14, modnm, "func DUT +T",	"enable just function" },
+};
+
+/* these tests rely on register stuff having been done ?? */
+struct test_spec exec_tests[] = {
+	/*
+	 * preferred use of exec_queries(qry, modnm) is with true
+	 * modnm, since that removes 'module $modnm' from the query
+	 * string. (supports modprobe $modname dyndbg=+p).
+	 *
+	 * But start the old way. with Ts enabled.
+	 */
+	{ 6, 1, 6, NULL, "module test_dynamic_debug func DUT +p",
+			 "Hello! using original module-in-query style" },
+
+	{ 11, 1, 6, modnm, "+p",	"enable (p) whole module, run DUT 1x" },
+	{ 11, 1, 0, modnm, "-p",	"disable (p) whole module, run DUT(1x)" },
+
+	{ 6, 4, 18, modnm, "func DUT +T", "enable (T) DUT(4)" },
+
+	{ 1, 4, 14, modnm, "format '^hi:' -T",		"disable 1 callsite" },
+	{ 1, 4, 10, modnm, "format '^mid:' -T",		"disable 1 callsite" },
+	{ 1, 4, 10, modnm, "format '^mid:' -T",		"re-disable" },
+	{ 1, 5, 12, modnm, "format '^mid:' -T",		"re-disable with more loops" },
+	{ 2, 4, 2, modnm, "format '^low:' -T",		"disable with subclass" },
+	{ 1, 4, 2, modnm, "format '^low: ' -T",		"re-disable, exclude subclass" },
+	{ 1, 4, 6, modnm, "format '^low: ' +T",		"enable, exclude subclass" },
+	{ 1, 4, 10, modnm, "format '^low:lower:' +T",	"enable the subclass" },
+	{ 1, 6, 14, modnm, "format '^low:lower:' +T",	"re-enable the subclass" },
+};
+
+struct test_spec ratelimit_tests[] = {
+	{ 6, 3000, 0, modnm, "func DUT +Tr" }
+};
+
+static void do_test_vec(struct test_spec *t, int len)
+{
+	int i;
+
+	for (i = 0; i < len; i++, t++)
+		do_test_spec(t);
+}
+
+static void test_all(void)
+{
+	int i;
+
+	pr_debug("Entry:\n");
+	pick_tracer();
+
+	for (i = 0; i < ARRAY_SIZE(registry_tests); i++)
+		; //do_register_test(&registry_tests[i], __test_resv);
+
+	for (i = 0; i < ARRAY_SIZE(registry_tests); i++)
+		do_register_test(&registry_tests[i], 0);
+
+	do_test_vec(exec_tests, ARRAY_SIZE(exec_tests));
+	do_test_vec(ratelimit_tests, ARRAY_SIZE(ratelimit_tests));
+}
+
+static void report(char *who)
+{
+	if (errors)
+		pr_err("%s: failed %d of %d tests\n", who, errors, test_ct);
+	else
+		pr_notice("%s: passed %d tests\n", who, test_ct);
+}
+
+static int __init test_dynamic_debug_init(void)
+{
+	pr_debug("Init:\n");
+
+	test_all();
+	report("complete");
+
+	return 0;
+}
+
+static void __exit test_dynamic_debug_exit(void)
+{
+	report("exit");
+	pr_debug("Exit:");
+}
+
+module_init(test_dynamic_debug_init);
+module_exit(test_dynamic_debug_exit);
+
+MODULE_AUTHOR("Jim Cromie <jim.cromie@gmail.com>");
+MODULE_LICENSE("GPL");
-- 
2.31.1

[PATCH v6 11/11] dyndbg: RFC add print-once and print-ratelimited features. RFC.

[Jim Cromie]

Its tautological that having pr_debug()s with optional print-once and
rate-limiting features could be useful.  Build it, they will come.

The advantages:

- dynamically configured with flags
- can use them on existing callsites
- printonce is easy, (almost) just new flags
  no additional resources
- ratelimiting is pooled, expecting rare use
  provisioned only for enabled & ratelimited callsites
- RFC ratelimit grouping
  mostly to reduce resources
  reduces to choice of hash key: module, function, file, line

Whats done here:

Expand ddebug.flags to 11 bits, and define new flags to support
print-once and ratelimited semantics:

  echo file init/main.c +o > control	# init/main runs just once anyway
  echo module foo +r > control		# turn on ratelimiting
  echo module foo +g > control		# turn on group flag

is_onced_or_ratelimited() tests these conditions, it is called from
__dynamic_pr_debug() and others (which are all behind the '+p'
enablement test).

NB: test_dynamic_debug.ko ratelimiting test triggers reports on
is_onced_or_ratelimited() as the limited source.

PRINT-ONCE: can be done with just +2 bits in flags;

.o _DPRINTK_FLAGS_ONCE     enables state test and set
.P _DPRINTK_FLAGS_PRINTED  state bit

Just adding the flags lets the existing code operate on them.
We will need new code to enforce constraints on flag combos;
'+ro' is nonsense, but this can wait, or can take a new meaning.

RATE-LIMITING:

.r _DPRINTK_FLAGS_RATELIMITED - track & limit prdbgs callrate

We wait until a prdebug is called, and if RATELIMITED is set, THEN
lookup a RateLimitState (RL) for it.  If found, bump its state and
return true/false, otherwise create & initialize one and return false.

RFC: GROUP-FLAG:

.g _DPRINTK_FLAGS_GROUPED

Currently, the hash-key is just the prdebug descriptor, so is unique
per prdebug.  With the 'g' flag, we could use a different key, for
example desc->site.function, to get a shared ratelimit for whole
functions.

This gets subtly different behavior at the ratelimit transition, but
it is predictable for a given function (except perhaps recursive, but
thats not done anyway).

Note also that any function can have a single group of prdebugs, plus
any number of prdbgs without 'g', either with or without 'r'.  So
grouping should be flexible enough to use advantageously.

Signed-off-by: Jim Cromie <jim.cromie@gmail.com>
---
v6: new to patchset
---
 include/linux/dynamic_debug.h |  19 ++++--
 lib/dynamic_debug.c           | 125 +++++++++++++++++++++++++++++++++-
 2 files changed, 137 insertions(+), 7 deletions(-)

diff --git a/include/linux/dynamic_debug.h b/include/linux/dynamic_debug.h
index 8807367c7903..e9871557cff1 100644
--- a/include/linux/dynamic_debug.h
+++ b/include/linux/dynamic_debug.h
@@ -28,26 +28,33 @@ struct _ddebug {
 	 * writes commands to <debugfs>/dynamic_debug/control
 	 */
 #define _DPRINTK_FLAGS_NONE	0
-#define _DPRINTK_FLAGS_PRINT		(1<<0) /* printk() a message */
+#define _DPRINTK_FLAGS_PRINT		(1<<4) /* 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)
-#define _DPRINTK_FLAGS_INCL_TID		(1<<4)
+#define _DPRINTK_FLAGS_INCL_MODNAME	(1<<0)
+#define _DPRINTK_FLAGS_INCL_FUNCNAME	(1<<1)
+#define _DPRINTK_FLAGS_INCL_LINENO	(1<<2)
+#define _DPRINTK_FLAGS_INCL_TID		(1<<3)
 
 #define _DPRINTK_FLAGS_INCL_ANY		\
 	(_DPRINTK_FLAGS_INCL_MODNAME | _DPRINTK_FLAGS_INCL_FUNCNAME |\
 	 _DPRINTK_FLAGS_INCL_LINENO  | _DPRINTK_FLAGS_INCL_TID)
 
+#define _DPRINTK_FLAGS_ONCE		(1<<6) /* print once flag */
+#define _DPRINTK_FLAGS_PRINTED		(1<<7) /* print once state */
+#define _DPRINTK_FLAGS_RATELIMITED	(1<<8)
+#define _DPRINTK_FLAGS_GROUPED		(1<<9) /* manipulate as a group */
+#define _DPRINTK_FLAGS_DELETE_SITE	(1<<10) /* drop site info to save ram */
+
 #if defined DEBUG
 #define _DPRINTK_FLAGS_DEFAULT _DPRINTK_FLAGS_PRINT
 #else
 #define _DPRINTK_FLAGS_DEFAULT 0
 #endif
-	unsigned int flags:8;
+	unsigned int flags:11;
+
 #ifdef CONFIG_JUMP_LABEL
 	union {
 		struct static_key_true dd_key_true;
diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
index 60bf2c01db1a..16e4db04082b 100644
--- a/lib/dynamic_debug.c
+++ b/lib/dynamic_debug.c
@@ -83,13 +83,19 @@ static inline const char *trim_prefix(const char *path)
 	return path + skip;
 }
 
-static struct { unsigned flag:8; char opt_char; } opt_array[] = {
+static struct { unsigned flag:12; 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' },
 	{ _DPRINTK_FLAGS_INCL_TID, 't' },
+
+	{ _DPRINTK_FLAGS_ONCE, 'o' },
+	{ _DPRINTK_FLAGS_PRINTED, 'P' },
+	{ _DPRINTK_FLAGS_RATELIMITED, 'r' },
+	{ _DPRINTK_FLAGS_GROUPED, 'g' },
+	{ _DPRINTK_FLAGS_DELETE_SITE, 'D' },
 	{ _DPRINTK_FLAGS_NONE, '_' },
 };
 
@@ -119,6 +125,8 @@ do {								\
 
 #define vpr_info(fmt, ...)	vnpr_info(1, fmt, ##__VA_ARGS__)
 #define v2pr_info(fmt, ...)	vnpr_info(2, fmt, ##__VA_ARGS__)
+#define v3pr_info(fmt, ...)	vnpr_info(3, fmt, ##__VA_ARGS__)
+#define v4pr_info(fmt, ...)	vnpr_info(4, fmt, ##__VA_ARGS__)
 
 static void vpr_info_dq(const struct ddebug_query *query, const char *msg)
 {
@@ -725,6 +733,49 @@ static inline char *dynamic_emit_prefix(struct _ddebug *desc, char *buf)
 	return buf;
 }
 
+struct ddebug_ratelimit {
+	struct hlist_node hnode;
+	struct ratelimit_state rs;
+	u64 key;
+};
+
+/* test print-once or ratelimited conditions */
+#define is_rated(desc) unlikely(desc->flags & _DPRINTK_FLAGS_RATELIMITED)
+#define is_once(desc) unlikely(desc->flags & _DPRINTK_FLAGS_ONCE)
+#define is_onced(desc)						\
+	unlikely((desc->flags & _DPRINTK_FLAGS_ONCE)		\
+		 && (desc->flags & _DPRINTK_FLAGS_PRINTED))
+
+static struct ddebug_ratelimit *ddebug_rl_fetch(struct _ddebug *desc);
+
+static inline bool is_onced_or_limited(struct _ddebug *desc)
+{
+	if (unlikely(desc->flags & _DPRINTK_FLAGS_ONCE &&
+		     desc->flags & _DPRINTK_FLAGS_RATELIMITED))
+		pr_info(" ONCE & RATELIMITED together is nonsense\n");
+
+	if (is_once(desc)) {
+		if (is_onced(desc)) {
+			v4pr_info("already printed once\n");
+			return true;
+		}
+		desc->flags |= _DPRINTK_FLAGS_PRINTED;
+		return false;
+
+	} else if (is_rated(desc)) {
+		/* test rate-limits */
+		bool state = __ratelimit(&ddebug_rl_fetch(desc)->rs);
+
+		v4pr_info("RLstate{%s}=%d on %s.%s.%d\n",
+			  (desc->flags & _DPRINTK_FLAGS_GROUPED
+			   ? "grouped" : "solo"), state,
+			  desc->modname, desc->function, desc->lineno);
+
+		return state;
+	}
+	return false;
+}
+
 void __dynamic_pr_debug(struct _ddebug *descriptor, const char *fmt, ...)
 {
 	va_list args;
@@ -734,6 +785,9 @@ void __dynamic_pr_debug(struct _ddebug *descriptor, const char *fmt, ...)
 	BUG_ON(!descriptor);
 	BUG_ON(!fmt);
 
+	if (is_onced_or_limited(descriptor))
+		return;
+
 	va_start(args, fmt);
 
 	vaf.fmt = fmt;
@@ -766,6 +820,9 @@ void __dynamic_dev_dbg(struct _ddebug *descriptor,
 	BUG_ON(!descriptor);
 	BUG_ON(!fmt);
 
+	if (is_onced_or_limited(descriptor))
+		return;
+
 	va_start(args, fmt);
 
 	vaf.fmt = fmt;
@@ -797,6 +854,9 @@ void __dynamic_netdev_dbg(struct _ddebug *descriptor,
 	BUG_ON(!descriptor);
 	BUG_ON(!fmt);
 
+	if (is_onced_or_limited(descriptor))
+		return;
+
 	va_start(args, fmt);
 
 	vaf.fmt = fmt;
@@ -833,6 +893,9 @@ void __dynamic_ibdev_dbg(struct _ddebug *descriptor,
 	struct va_format vaf;
 	va_list args;
 
+	if (is_onced_or_limited(descriptor))
+		return;
+
 	va_start(args, fmt);
 
 	vaf.fmt = fmt;
@@ -1307,3 +1370,63 @@ int dynamic_debug_unregister_tracer(const char *query, const char *modname,
 	return ddebug_exec_queries(query, modname, tracer);
 }
 EXPORT_SYMBOL(dynamic_debug_unregister_tracer);
+
+/*
+ * Rate-Limited debug is expected to rarely be needed, so it is
+ * provisioned on-demand when an enabled and rate-limit-flagged
+ * pr_debug is called, by ddebug_rl_fetch().  For now, key is just
+ * descriptor, so is unique per site.
+
+ * Plan: for 'gr' flagged callsites, choose a key that is same across
+ * all prdebugs in a function, to apply a single rate-limit to the
+ * whole function.  This should give nearly identical behavior at much
+ * lower memory cost.
+ */
+static DEFINE_HASHTABLE(ddebug_rl_map, 6);
+
+static struct ddebug_ratelimit *ddebug_rl_find(u64 key)
+{
+	struct ddebug_ratelimit *limiter;
+
+	hash_for_each_possible(ddebug_rl_map, limiter, hnode, key) {
+		if (limiter->key == key)
+			return limiter;
+	}
+	return NULL;
+}
+
+/* Must be called with ddebug_rl_lock locked. */
+static struct ddebug_ratelimit *ddebug_rl_add(u64 key)
+{
+	struct ddebug_ratelimit *limiter;
+
+	limiter = ddebug_rl_find(key);
+	if (limiter)
+		return limiter;
+	limiter = kmalloc(sizeof(*limiter), GFP_ATOMIC);
+	if (!limiter)
+		return ERR_PTR(-ENOMEM);
+
+	limiter->key = key;
+	ratelimit_default_init(&limiter->rs);
+	hash_add(ddebug_rl_map, &limiter->hnode, key);
+
+	v3pr_info("added %llx\n", key);
+	return limiter;
+}
+
+/*
+ * called when enabled callsite has _DPRINTK_FLAGS_RATELIMITED flag
+ * set (echo +pr >control), it hashes on &table-header+index
+ */
+static struct ddebug_ratelimit *ddebug_rl_fetch(struct _ddebug *desc)
+{
+	u64 key = (u64)desc;
+	struct ddebug_ratelimit *ddebug_rl = ddebug_rl_find(key);
+
+	if (ddebug_rl) {
+		v4pr_info("found %llx\n", key);
+		return ddebug_rl;
+	}
+	return ddebug_rl_add(key);
+}
-- 
2.31.1

Re: [PATCH v6 00/11] use DYNAMIC_DEBUG to implement DRM.debug

[Jason Baron]

On 8/22/21 6:19 PM, Jim Cromie wrote:
> This patchset does 3 main things.
> 
> Adds DEFINE_DYNAMIC_DEBUG_CATEGORIES to define bitmap => category
> control of pr_debugs, and to create their sysfs entries.
> 
> Uses it in amdgpu, i915 to control existing pr_debugs according to
> their ad-hoc categorizations.
> 
> Plugs dyndbg into drm-debug framework, in a configurable manner.
> 
> v6: cleans up per v5 feedback, and adds RFC stuff:
> 
> - test_dynamic_debug.ko: uses tracer facility added in v5:8/9
> - prototype print-once & rate-limiting
> 
> Hopefully adding RFC stuff doesnt distract too much.


Hi Jim,

Yeah, I feel like the RFC patches should be in a separate series
unless there is a drm dependency for them?

Thanks,

-Jason


> 
> Jim Cromie (11):
>   moduleparam: add data member to struct kernel_param
>   dyndbg: add DEFINE_DYNAMIC_DEBUG_CATEGORIES and callbacks
>   i915/gvt: remove spaces in pr_debug "gvt: core:" etc prefixes
>   i915/gvt: use DEFINE_DYNAMIC_DEBUG_CATEGORIES to create "gvt:core:"
>     etc categories
>   amdgpu: use DEFINE_DYNAMIC_DEBUG_CATEGORIES to control categorized
>     pr_debugs
>   drm_print: add choice to use dynamic debug in drm-debug
>   drm_print: instrument drm_debug_enabled
>   amdgpu_ucode: reduce number of pr_debug calls
>   nouveau: fold multiple DRM_DEBUG_DRIVERs together
>   dyndbg: RFC add debug-trace callback, selftest with it. RFC
>   dyndbg: RFC add print-once and print-ratelimited features. RFC.
> 
>  drivers/gpu/drm/Kconfig                       |  13 +
>  drivers/gpu/drm/amd/amdgpu/amdgpu_ucode.c     | 293 ++++++++-------
>  .../gpu/drm/amd/display/dc/core/dc_debug.c    |  44 ++-
>  drivers/gpu/drm/drm_print.c                   |  49 ++-
>  drivers/gpu/drm/i915/gvt/Makefile             |   4 +
>  drivers/gpu/drm/i915/gvt/debug.h              |  18 +-
>  drivers/gpu/drm/i915/i915_params.c            |  35 ++
>  drivers/gpu/drm/nouveau/nouveau_drm.c         |  36 +-
>  include/drm/drm_print.h                       | 148 ++++++--
>  include/linux/dynamic_debug.h                 |  81 ++++-
>  include/linux/moduleparam.h                   |  11 +-
>  lib/Kconfig.debug                             |  11 +
>  lib/Makefile                                  |   1 +
>  lib/dynamic_debug.c                           | 336 ++++++++++++++++--
>  lib/test_dynamic_debug.c                      | 279 +++++++++++++++
>  15 files changed, 1117 insertions(+), 242 deletions(-)
>  create mode 100644 lib/test_dynamic_debug.c
>