[PATCH v10 00/10 RESEND] use DYNAMIC_DEBUG to implement DRM.debug & DRM.trace

[PATCH v10 00/10 RESEND] use DYNAMIC_DEBUG to implement DRM.debug & DRM.trace

[Jim Cromie]

Hi Jason, Greg, DRM-everyone, everyone,

resend to add more people, after rebasing on master to pick up
306589856399 drm/print: Add deprecation notes to DRM_...() functions

This patchset has 3 separate but related parts:

1. DEFINE_DYNAMIC_DEBUG_BITGRPS macro [patch 1/10]

   Declares DRM.debug style bitmap, bits control pr_debugs by matching formats
   Adds callback to translate bits to $cmd > dynamic_debug/control
   This could obsolete EXPORT(dynamic_debug_exec_queries) not included.

   /* anticipated_usage */
   static struct dyndbg_desc drm_categories_map[] = {
   	  [0] = { DRM_DBG_CAT_CORE },
	  [1] = { DRM_DBG_CAT_DRIVER },
	  [2] = { DRM_DBG_CAT_KMS },
	  [3] = { DRM_DBG_CAT_PRIME }, ... };

   DEFINE_DYNAMIC_DEBUG_BITGRPS(debug, __drm_debug,
				" bits control drm.debug categories ",
				drm_categories_map);

   Please consider this patch for -next/now/current:
   - new interface, new code, no users to break
   - allows DRM folks to consider in earnest.
   - api bikeshedding to do ?
     struct dyndbg_desc isnt that great a name, others too probably.

2. use (1) to reimplement drm.debug [patches 3-7]:

   1st in amdgpu & i915 to control existing pr_debugs by their formats
   POC for (1)
   then in drm-print, for all drm.debug API users
   has kernel-footprint impact:
      amdgpu has ~3k pr_debugs.  (120kb callsite data)
      i915.ko has ~2k  

   avoids drm_debug_enabled(), gives NOOP savings & new flexibility.
   changes drm.debug categories from enum to format-prefix-string
   alters in-log format to include the format-prefix-string
   Daniel Vetter liked this at -v3
   https://lore.kernel.org/lkml/YPbPvm%2FxcBlTK1wq@phenom.ffwll.local/
   Im sure Ive (still) missed stuff.


3. separately, Sean Paul proposed: drm.trace to mirror drm.debug to tracefs
   https://patchwork.freedesktop.org/series/78133/

He argues:
   tracefs is fast/lightweight compared to syslog
   independent selection (of drm categories) to tracefs
       gives tailored traffic w.o flooding syslog

ISTM he's correct.  So it follows that write-to-tracefs is also a good
feature for dyndbg, where its then available for all pr_debug users,
including all of drm, on a per-site basis, via echo +T >control.  (iff
CONFIG_TRACING).

So basically, I borg'd his:
   [patch 14/14] drm/print: Add tracefs support to the drm logging helpers

Then I added a T flag, so it can be toggled from shell:

   # turn on all drm's pr_debug --> tracefs
   echo module drm +T > /proc/dynamic_debug/control

It appears to just work: (RFC)

The instance name is a placeholder, per-module subdirs kinda fits the
tracefs pattern, but full mod/file-basename/function/line feels like
overkill, mod/basename-func.line would flatten it nicely. RFC.


[root@gandalf dyndbg-tracefs]# pwd
/sys/kernel/tracing/instances/dyndbg-tracefs
[root@gandalf dyndbg-tracefs]# echo 1 > /sys/module/drm/parameters/trace
[root@gandalf dyndbg-tracefs]# head -n16 trace | sed -e 's/^#//'
 tracer: nop

 entries-in-buffer/entries-written: 405/405   #P:24

                                _-----=> irqs-off
                               / _----=> need-resched
                              | / _---=> hardirq/softirq
                              || / _--=> preempt-depth
                              ||| / _-=> migrate-disable
                              |||| /     delay
           TASK-PID     CPU#  |||||  TIMESTAMP  FUNCTION
              | |         |   |||||     |         |
           <...>-2254    [000] .....  7040.894352: __dynamic_pr_debug: drm:core: comm="gnome-shel:cs0" pid=2254, dev=0xe200, auth=1, AMDGPU_CS
           <...>-2207    [015] .....  7040.894654: __dynamic_pr_debug: drm:core: comm="gnome-shell" pid=2207, dev=0xe200, auth=1, DRM_IOCTL_MODE_ADDFB2
           <...>-2207    [015] .....  7040.995403: __dynamic_pr_debug: drm:core: comm="gnome-shell" pid=2207, dev=0xe200, auth=1, DRM_IOCTL_MODE_RMFB
           <...>-2207    [015] .....  7040.995413: __dynamic_pr_debug: drm:core: OBJ ID: 121 (2)

This is the pr-debug doing most of that logging: (from dynamic_debug/control)

  drivers/gpu/drm/drm_ioctl.c:866 [drm]drm_ioctl =T "drm:core: comm=\042%s\042 pid=%d, dev=0x%lx, auth=%d, %s\012"

Turning on decoration flags changes the trace:

  echo module drm format drm:core: +mflt > /proc/dynamic_debug/control 

           TASK-PID     CPU#  |||||  TIMESTAMP  FUNCTION
              | |         |   |||||     |         |
           <...>-2254    [003] ..... 15980.936660: __dynamic_pr_debug: [2254] drm:drm_ioctl:866: drm:core: comm="gnome-shel:cs0" pid=2254, dev=0xe200, auth=1, AMDGPU_CS
           <...>-2207    [015] ..... 15980.936966: __dynamic_pr_debug: [2207] drm:drm_ioctl:866: drm:core: comm="gnome-shell" pid=2207, dev=0xe200, auth=1, DRM_IOCTL_MODE_ADDFB2
           <...>-2207    [015] ..... 15981.037727: __dynamic_pr_debug: [2207] drm:drm_ioctl:866: drm:core: comm="gnome-shell" pid=2207, dev=0xe200, auth=1, DRM_IOCTL_MODE_RMFB
           <...>-2207    [015] ..... 15981.037739: __dynamic_pr_debug: [2207] drm:drm_mode_object_put:195: drm:core: OBJ ID: 124 (2)
           <...>-2207    [015] ..... 15981.037742: __dynamic_pr_debug: [2207] drm:drm_mode_object_put:195: drm:core: OBJ ID: 124 (1)

The FUNCTION could stand tweaking (to match the callsite in the
control file, cited above), or perhaps replaced by the 'mfl'
decorations; the 't' flag is redundant for trace. Meh.

SELFTEST

A previous version of this patchset added test_dynamic_debug.ko, but
it relied upon code I ripped out when I made tracefs available by
default (without modules having to register 1st).  So it fails 10/29
tests, which counted +T sites executed, via side effect.

TODO: userspace selftest

  # to set expected tracing activity
  echo module test_dynamic_debug function do_debugging +T > control

  # run do_debugging function (todo: add sysfs knob) 
  echo 2 > /sys/module/test-dynamic-debug/parameters/run_me

If thats wrapped in the right trace_on, trace_pipe, etc incantations,
the +T enabled pr_debugs in do_debugging() can be counted, compared
against expectations, and passed or failed.

change since v9:
. patch confict against drm-misc resolved
. s/CATEGORIES/BITGRPS/ in 1/10 - keep name generic: bitmap + groups
. CATEGORIES is drm term, use it there only
. fix api friction wrt drm.trace knob
  2 separate macros: DEFINE_DYNAMIC_DEBUG_{LOG,TRACE}_GROUPS - JBaron

v9: https://patchwork.freedesktop.org/series/96327/
v8: https://patchwork.freedesktop.org/series/93914/
    https://lore.kernel.org/lkml/20210915163957.2949166-1-jim.cromie@gmail.com/

The major change since v8 is that +T now works for all users, if
CONFIG_TRACING=y, otherwise it complains/errors.

SUMMARY

- drm as dyndbg user adds almost 9k callsites to kernel running this patchset
  substantial footprint
  substantial source of pr-debug-trace events (not all, but some useful)

[jimc@gandalf wk-next]$ wc /proc/dynamic_debug/control 
8927 71062 1099699 /proc/dynamic_debug/control
[jimc@gandalf wk-next]$ uname -a
Linux gandalf 5.15.0-rh2-12144-g5d5db04dfb0c #3 SMP PREEMPT Thu Nov 11 10:5

- pr_debug as event provider
  using exported trace_array_printk 
  cheap with JUMP_LABEL
  precise, ad-hoc or organized callsite enablement
  callsite descriptor is in its interface, so are VARARGS
  inspectable, extensible wo api churn,
  iff trace_array_printk can do it.


Jim Cromie (10):
  dyndbg: add DEFINE_DYNAMIC_DEBUG_BITGRPS macro and callbacks
  drm: fix doc grammar
  amdgpu: use dyndbg.BITGRPS to control existing pr_debugs
  i915/gvt: trim spaces from pr_debug "gvt: core:" prefixes
  i915/gvt: use dyndbg.BITGRPS for existing pr_debugs
  drm_print: add choice to use dynamic debug in drm-debug
  drm_print: instrument drm_debug_enabled
  dyndbg: add print-to-tracefs, selftest with it - RFC
  dyndbg: create DEFINE_DYNAMIC_DEBUG_LOG|TRACE_GROUPS
  drm: use DEFINE_DYNAMIC_DEBUG_TRACE_GROUPS in 3 places

 .../admin-guide/dynamic-debug-howto.rst       |   7 +-
 MAINTAINERS                                   |   1 +
 drivers/gpu/drm/Kconfig                       |  26 ++
 drivers/gpu/drm/Makefile                      |   2 +
 drivers/gpu/drm/amd/amdgpu/Makefile           |   2 +
 .../gpu/drm/amd/display/dc/core/dc_debug.c    |  55 ++++-
 drivers/gpu/drm/drm_print.c                   |  62 +++--
 drivers/gpu/drm/i915/Makefile                 |   2 +
 drivers/gpu/drm/i915/gvt/debug.h              |  18 +-
 drivers/gpu/drm/i915/intel_gvt.c              |  47 ++++
 include/drm/drm_drv.h                         |   2 +-
 include/drm/drm_print.h                       | 182 +++++++++++---
 include/linux/dynamic_debug.h                 |  88 ++++++-
 lib/Kconfig.debug                             |  11 +
 lib/Makefile                                  |   1 +
 lib/dynamic_debug.c                           | 203 ++++++++++++++--
 lib/test_dynamic_debug.c                      | 222 ++++++++++++++++++
 17 files changed, 843 insertions(+), 88 deletions(-)
 create mode 100644 lib/test_dynamic_debug.c

-- 
2.31.1

[PATCH v10 01/10] dyndbg: add DEFINE_DYNAMIC_DEBUG_BITGRPS macro and callbacks

[Jim Cromie]

DEFINE_DYNAMIC_DEBUG_BITGRPS(fsname, var, bitmap_desc, bitmap)
allows users to create a drm.debug style (bitmap) sysfs interface,
mapping each bit to a group of pr_debugs, matching on their formats.

This works well when the formats systematically include a prefix
string such as ERR|WARN|INFO, etc.

Such groups can (already) be manipulated like so:

    echo "format $prefix +p" >control

This macro merely makes it easier to operate them as groups

/* standard usage */
static struct dyndbg_bitdesc my_bitmap[] = {
	[0] = { "gvt:cmd:" },
	[1] = { "gvt:core:" },
	[2] = { "gvt:dpy:" },
	[3] = { "gvt:el:" },
	[4] = { "gvt:irq:" },
	[5] = { "gvt:mm:" },
	[6] = { "gvt:mmio:" },
	[7] = { "gvt:render:" },
	[8] = { "gvt:sched:" }
};
DEFINE_DYNAMIC_DEBUG_BITGRPS(debug_gvt, __gvt_debug,
			     "i915/gvt bitmap desc", my_bitmap);

In addition to the macro, patch adds:

 - 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, these are
non-static and exported.

get/set use an augmented kernel_param; the arg refs a new struct
dyndbg_bitmap_param containing:

A- the map of "categories", an array of struct dyndbg_bitdescs,
   indexed by bitpos, defining the match against pr_debug formats.

B- a pointer to the user module's ulong holding the bits/state.
   By sharing state, we coordinate with code that still uses it
   directly.  This allows drm-debug api to be converted incrementally,
   while still using __drm_debug & drm_debug_enabled() in other parts.

param_set_dyndbg() compares new vs old bits, and only updates prdbgs
on changes.  This maximally preserves the underlying state, which may
have been customized via later `echo $cmd >control`.  So if a user
really wants to know that all prdbgs are set precisely, they must
pre-clear then set.

dynamic_debug.h:

Add DEFINE_DYNAMIC_DEBUG_BITGRPS() described above, and a stub
throwing a BUILD_BUG (RFC) when used without DYNAMIC_DEBUG support.

Add structs dyndbg_bitdesc, dyndbg_bitmap_param to support the main
macro, and several helper macros wrapping the given categories with
^prefix and ' ' suffix.  This way the callback can be more broadly
used, by using the right helper macro.

Also externs 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 $str" requires that $str must be
present in the compiled-in format string.  Searching on "%s" does not
define a useful set of callsites.

Using DEFINE_DYNAMIC_DEBUG_CATEGORIES wo support gets a BUILD_BUG.
ISTM there is already action at a declarative distance, nobody needs
mystery as to why the /sysfs thingy didn't appear.

Dyndbg is agnostic wrt the categorization scheme used, in order to
play well with any prefix convention already in use in the codebase.
In fact, "prefix" is not strictly accurate without ^ anchor.

Ad-hoc categories and sub-categories are implicitly allowed, author
discipline and review is expected.

Hierarchical classes/categories are natural:

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

RFC: in a real sense we abandon enum strictures here, and lose some
compiler help, on spelling errs for example.  Obviously "drm:" != "DRM:".

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 categories & sub-categories:

Ad-hoc categories are those format-prefixes already in use; both
amdgpu and i915 have numerous (120,~1800) pr_debugs, most of these use
a system, a small set (9,13) of prefixes, to categorize the output.
Dyndbg already works on these, this patch just allows adding a new
bitmap knob to control them.

Ad-hoc sub-categories are slightly trickier.
  since drm_dbg_atomic("fail: ...") is a macro:
    pr_debug("drm:atomic:" " " format,...) // cpp-paste in a trailing space

We get "drm:atomic: fail:", with that undesirable embedded space;
obviously not ideal wrt clear and simple prefixes.

a possible fix: drm_dbg_atomic_("fail: ..."); // trailing _ for ad-hoc subcat

Summarizing:

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

Order matters in DEFINE_DYNAMIC_DEBUG_CATEGORIES(... @bit_descs)

Since bits are/will-stay applied 0-N, the later bits can countermand
the earlier ones, but it is 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.

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

vlatest:
. change /CATEGORIES/BITGRP/, leave former for app use
---
 include/linux/dynamic_debug.h | 54 +++++++++++++++++++++++++
 lib/dynamic_debug.c           | 76 +++++++++++++++++++++++++++++++++++
 2 files changed, 130 insertions(+)

diff --git a/include/linux/dynamic_debug.h b/include/linux/dynamic_debug.h
index dce631e678dd..a9430168b072 100644
--- a/include/linux/dynamic_debug.h
+++ b/include/linux/dynamic_debug.h
@@ -181,6 +181,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 +231,56 @@ static inline int dynamic_debug_exec_queries(const char *query, const char *modn
 	return 0;
 }
 
+struct kernel_param;
+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 {
+	const char *match;	/* search format for this substr */
+};
+
+struct dyndbg_bitmap_param {
+	unsigned long *bits;		/* ref to shared state */
+	unsigned int maplen;
+	struct dyndbg_bitdesc *map;	/* indexed by bitpos */
+};
+
+#if defined(CONFIG_DYNAMIC_DEBUG) || \
+	(defined(CONFIG_DYNAMIC_DEBUG_CORE) && defined(DYNAMIC_DEBUG_MODULE))
+/**
+ * DEFINE_DYNAMIC_DEBUG_BITGRPS() - bitmap control of pr_debugs, by format match
+ * @fsname: parameter basename under /sys
+ * @_var:   C-identifier holding bitmap
+ * @desc:   string summarizing the controls provided
+ * @bitmap: C array of struct dyndbg_bitdescs
+ *
+ * Intended for modules with a systematic use of pr_debug prefixes in
+ * the format strings, this allows modules calling pr_debugs to
+ * control them in groups by matching against their formats, and map
+ * them to bits 0-N of a sysfs control point.
+ */
+#define DEFINE_DYNAMIC_DEBUG_BITGRPS(fsname, _var, desc, data)	\
+	MODULE_PARM_DESC(fsname, desc);					\
+	static struct dyndbg_bitmap_param ddcats_##_var =		\
+	{ .bits = &(_var), .map = data,					\
+	  .maplen = ARRAY_SIZE(data) };				\
+	module_param_cb(fsname, &param_ops_dyndbg, &ddcats_##_var, 0644)
+
+extern const struct kernel_param_ops param_ops_dyndbg;
+
+#else /* no dyndbg configured, throw error on macro use */
+
+#if (defined(CONFIG_DYNAMIC_DEBUG_CORE) && !defined(DYNAMIC_DEBUG_MODULE))
+#define DEFINE_DYNAMIC_DEBUG_BITGRPS(fsname, var, bitmap_desc, ...)	\
+	BUILD_BUG_ON_MSG(1, "you need -DDYNAMIC_DEBUG_MODULE in compile")
+#else
+#define DEFINE_DYNAMIC_DEBUG_BITGRPS(fsname, var, bitmap_desc, ...)	\
+	BUILD_BUG_ON_MSG(1, "CONFIG_DYNAMIC_DEBUG needed to use this macro: " #var)
+#endif
+#endif
+
 #endif
diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
index dd7f56af9aed..760e1f1f09ed 100644
--- a/lib/dynamic_debug.c
+++ b/lib/dynamic_debug.c
@@ -582,6 +582,82 @@ int dynamic_debug_exec_queries(const char *query, const char *modname)
 }
 EXPORT_SYMBOL_GPL(dynamic_debug_exec_queries);
 
+#ifdef CONFIG_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 - bits => categories >control setter
+ * @instr: string echo>d to sysfs
+ * @kp:    kp->arg has state: bits, map
+ *
+ * Enable/disable prdbgs by their "category", as specified in the
+ * DEFINE_DYNAMIC_DEBUG_BITGRPS.bitmap argument.
+ *
+ * Returns: 0 or <0 if error.
+ */
+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_bitmap_param *p = kp->arg;
+	const struct dyndbg_bitdesc *map = p->map;
+
+	if (!map) {
+		pr_err("set_dyndbg: no bits=>queries map\n");
+		return -EINVAL;
+	}
+	rc = kstrtoul(instr, 0, &inbits);
+	if (rc) {
+		pr_err("set_dyndbg: expecting unsigned int\n");
+		return rc;
+	}
+	vpr_info("set_dyndbg: new 0x%lx old 0x%lx\n", inbits, *p->bits);
+
+	for (i = 0; i < p->maplen && i < BITS_PER_LONG; map++, i++) {
+		if (test_bit(i, &inbits) == test_bit(i, p->bits))
+			continue;
+		snprintf(query, FMT_QUERY_SIZE, "format '%s' %cp", map->match,
+			 test_bit(i, &inbits) ? '+' : '-');
+
+		matches = ddebug_exec_queries(query, KP_MOD_NAME);
+
+		v2pr_info("bit-%d: %d matches on format <%s>\n", i,
+			  matches, map->match);
+		totct += matches;
+	}
+	*p->bits = inbits;
+	vpr_info("total matches: %d\n", totct);
+	return 0;
+}
+EXPORT_SYMBOL(param_set_dyndbg);
+
+/**
+ * param_get_dyndbg - bitmap reader
+ * @buffer: receives string rep of bitmap
+ * @kp:    kp->arg has state: bits, map
+ *
+ * Reads last written bits, underlying prdbg state may have changed since.
+ * Returns: #chars written
+ */
+int param_get_dyndbg(char *buffer, const struct kernel_param *kp)
+{
+	const struct dyndbg_bitmap_param *p = kp->arg;
+	unsigned long val = *p->bits;
+
+	return scnprintf(buffer, PAGE_SIZE, "0x%lx\n", val);
+}
+EXPORT_SYMBOL(param_get_dyndbg);
+
+const struct kernel_param_ops param_ops_dyndbg = {
+	.set = param_set_dyndbg,
+	.get = param_get_dyndbg,
+};
+EXPORT_SYMBOL(param_ops_dyndbg);
+
 #define PREFIX_SIZE 64
 
 static int remaining(int wrote)
-- 
2.31.1

[PATCH v10 02/10] drm: fix doc grammar

[Jim Cromie]

allocates and initializes ...

Signed-off-by: Jim Cromie <jim.cromie@gmail.com>
---
 include/drm/drm_drv.h | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/include/drm/drm_drv.h b/include/drm/drm_drv.h
index 0cd95953cdf5..4b29261c4537 100644
--- a/include/drm/drm_drv.h
+++ b/include/drm/drm_drv.h
@@ -486,7 +486,7 @@ void *__devm_drm_dev_alloc(struct device *parent,
  * @type: the type of the struct which contains struct &drm_device
  * @member: the name of the &drm_device within @type.
  *
- * This allocates and initialize a new DRM device. No device registration is done.
+ * This allocates and initializes a new DRM device. No device registration is done.
  * Call drm_dev_register() to advertice the device to user space and register it
  * with other core subsystems. This should be done last in the device
  * initialization sequence to make sure userspace can't access an inconsistent
-- 
2.31.1

[PATCH v10 03/10] amdgpu: use dyndbg.BITGRPS to control existing pr_debugs

[Jim Cromie]

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

Use DEFINE_DYNAMIC_DEBUG_BITGRPS to create a sysfs location which maps
from bits to these 13 sets of categorized pr_debugs to en/disable.

Makefile adds -DDYNAMIC_DEBUG_MODULE for CONFIG_DYNAMIC_DEBUG_CORE,
otherwise BUILD_BUG_ON triggers (obvious errors on subtle misuse is
better than mysterious ones).

Signed-off-by: Jim Cromie <jim.cromie@gmail.com>
---
 drivers/gpu/drm/amd/amdgpu/Makefile           |  2 +
 .../gpu/drm/amd/display/dc/core/dc_debug.c    | 47 ++++++++++++++++++-
 2 files changed, 48 insertions(+), 1 deletion(-)

diff --git a/drivers/gpu/drm/amd/amdgpu/Makefile b/drivers/gpu/drm/amd/amdgpu/Makefile
index 653726588956..077342ca803f 100644
--- a/drivers/gpu/drm/amd/amdgpu/Makefile
+++ b/drivers/gpu/drm/amd/amdgpu/Makefile
@@ -38,6 +38,8 @@ ccflags-y := -I$(FULL_AMD_PATH)/include/asic_reg \
 	-I$(FULL_AMD_DISPLAY_PATH)/amdgpu_dm \
 	-I$(FULL_AMD_PATH)/amdkfd
 
+ccflags-$(CONFIG_DYNAMIC_DEBUG_CORE) += -DYNAMIC_DEBUG_MODULE
+
 amdgpu-y := amdgpu_drv.o
 
 # add KMS driver
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..e49a755c6a69 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,53 @@
 
 #include "resource.h"
 
-#define DC_LOGGER_INIT(logger)
+#if defined(CONFIG_DRM_USE_DYNAMIC_DEBUG)
+#include <linux/dynamic_debug.h>
+
+unsigned long __debug_dc;
+EXPORT_SYMBOL(__debug_dc);
+
+#define help_(_N, _cat)	"\t  Bit-" #_N "\t" _cat "\n"
+
+#define DC_DYNDBG_BITMAP_DESC(name)					\
+	"Control pr_debugs via /sys/module/amdgpu/parameters/" #name	\
+	", where each bit controls a debug category.\n"			\
+	help_(0, "[SURFACE]:")						\
+	help_(1, "[CURSOR]:")						\
+	help_(2, "[PFLIP]:")						\
+	help_(3, "[VBLANK]:")						\
+	help_(4, "[HW_LINK_TRAINING]:")					\
+	help_(5, "[HW_AUDIO]:")						\
+	help_(6, "[SCALER]:")						\
+	help_(7, "[BIOS]:")						\
+	help_(8, "[BANDWIDTH_CALCS]:")					\
+	help_(9, "[DML]:")						\
+	help_(10, "[IF_TRACE]:")					\
+	help_(11, "[GAMMA]:")						\
+	help_(12, "[SMU_MSG]:")
+
+static struct dyndbg_bitdesc amdgpu_bitmap[] = {
+	[0] = { "[CURSOR]:" },
+	[1] = { "[PFLIP]:" },
+	[2] = { "[VBLANK]:" },
+	[3] = { "[HW_LINK_TRAINING]:" },
+	[4] = { "[HW_AUDIO]:" },
+	[5] = { "[SCALER]:" },
+	[6] = { "[BIOS]:" },
+	[7] = { "[BANDWIDTH_CALCS]:" },
+	[8] = { "[DML]:" },
+	[9] = { "[IF_TRACE]:" },
+	[10] = { "[GAMMA]:" },
+	[11] = { "[SMU_MSG]:" }
+};
+
+DEFINE_DYNAMIC_DEBUG_LOG_GROUPS(debug_dc, __debug_dc,
+				DC_DYNDBG_BITMAP_DESC(debug_dc),
+				amdgpu_bitmap);
+
+#endif
 
+#define DC_LOGGER_INIT(logger)
 
 #define SURFACE_TRACE(...) do {\
 		if (dc->debug.surface_trace) \
-- 
2.31.1

[PATCH v10 04/10] i915/gvt: trim spaces from pr_debug "gvt: core:" prefixes

[Jim Cromie]

Taking embedded spaces out of existing prefixes makes them more easily
searchable; simplifying the extra 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 format prefixes simplifies the
corresponding match string.  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:".

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..bbecc279e077 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 v10 05/10] i915/gvt: use dyndbg.BITGRPS for existing pr_debugs

[Jim Cromie]

The gvt component of this driver has ~120 pr_debugs with formats using
one of 9 fixed string prefixes, which are quite similar to those
enumerated in DRM debug categories.  Following the interface model of
drm.debug, add a parameter to map bits to these format prefixes.

static struct dyndbg_bitdesc i915_bitmap[] = {
	[0] = { "gvt:cmd:" },
	[1] = { "gvt:core:" },
	[2] = { "gvt:dpy:" },
	[3] = { "gvt:el:" },
	[4] = { "gvt:irq:" },
	[5] = { "gvt:mm:" },
	[6] = { "gvt:mmio:" },
	[7] = { "gvt:render:" },
	[8] = { "gvt:sched:" }
};
DEFINE_DYNAMIC_DEBUG_BITGRPS(debug_gvt, __gvt_debug,
	"dyndbg bitmap desc",

If CONFIG_DYNAMIC_DEBUG_CORE=y, then gvt/Makefile adds
-DDYNAMIC_DEBUG_MODULE to cflags, which CONFIG_DYNAMIC_DEBUG=n
(CORE-only) builds need.  This is redone more comprehensively soon.

Signed-off-by: Jim Cromie <jim.cromie@gmail.com>
---
 drivers/gpu/drm/i915/Makefile    |  2 ++
 drivers/gpu/drm/i915/intel_gvt.c | 38 ++++++++++++++++++++++++++++++++
 2 files changed, 40 insertions(+)

diff --git a/drivers/gpu/drm/i915/Makefile b/drivers/gpu/drm/i915/Makefile
index 660bb03de6fc..0fa5f53312a8 100644
--- a/drivers/gpu/drm/i915/Makefile
+++ b/drivers/gpu/drm/i915/Makefile
@@ -317,6 +317,8 @@ i915-y += intel_gvt.o
 include $(src)/gvt/Makefile
 endif
 
+ccflags-$(CONFIG_DYNAMIC_DEBUG_CORE) += -DDYNAMIC_DEBUG_MODULE
+
 obj-$(CONFIG_DRM_I915) += i915.o
 obj-$(CONFIG_DRM_I915_GVT_KVMGT) += gvt/kvmgt.o
 
diff --git a/drivers/gpu/drm/i915/intel_gvt.c b/drivers/gpu/drm/i915/intel_gvt.c
index 4e70c1a9ef2e..efaac5777873 100644
--- a/drivers/gpu/drm/i915/intel_gvt.c
+++ b/drivers/gpu/drm/i915/intel_gvt.c
@@ -162,3 +162,41 @@ void intel_gvt_resume(struct drm_i915_private *dev_priv)
 	if (intel_gvt_active(dev_priv))
 		intel_gvt_pm_resume(dev_priv->gvt);
 }
+
+#if defined(CONFIG_DRM_USE_DYNAMIC_DEBUG)
+
+unsigned long __gvt_debug;
+EXPORT_SYMBOL(__gvt_debug);
+
+static struct dyndbg_bitdesc i915_dyndbg_bitmap[] = {
+	[0] = { "gvt:cmd:" },
+	[1] = { "gvt:core:" },
+	[2] = { "gvt:dpy:" },
+	[3] = { "gvt:el:" },
+	[4] = { "gvt:irq:" },
+	[5] = { "gvt:mm:" },
+	[6] = { "gvt:mmio:" },
+	[7] = { "gvt:render:" },
+	[8] = { "gvt:sched:" }
+};
+
+#define help_(_N, _cat)	"\t  Bit-" #_N ":\t" _cat "\n"
+
+#define I915_GVT_CATEGORIES(name) \
+	" Enable debug output via /sys/module/i915/parameters/" #name	\
+	", where each bit enables a debug category.\n"			\
+	help_(0, "gvt:cmd:")						\
+	help_(1, "gvt:core:")						\
+	help_(2, "gvt:dpy:")						\
+	help_(3, "gvt:el:")						\
+	help_(4, "gvt:irq:")						\
+	help_(5, "gvt:mm:")						\
+	help_(6, "gvt:mmio:")						\
+	help_(7, "gvt:render:")						\
+	help_(8, "gvt:sched:")
+
+DEFINE_DYNAMIC_DEBUG_BITGRPS(debug_gvt, __gvt_debug,
+			     I915_GVT_CATEGORIES(debug_gvt),
+			     i915_dyndbg_bitmap);
+
+#endif
-- 
2.31.1

[PATCH v10 06/10] 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_DEV_DEBUG*(3 names),
DRM_DEBUG*(8 names).  There are thousands of these callsites, each
categorized in this systematized way.

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

This patch uses dynamic-debug with (required) jump-label to patch
enabled callsites onto their respective NOOP slots, avoiding all
runtime bit-checks of __drm_debug by drm_debug_enabled().

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 many new prdbg callsites:

  dyndbg: 207 debug prints in module drm_kms_helper
  dyndbg: 376 debug prints in module drm
  dyndbg: 1811 debug prints in module i915
  dyndbg: 3917 debug prints in module amdgpu

Each site costs 56 bytes of .data, which is a big increase for
drm modules, so CONFIG_DRM_USE_DYNAMIC_DEBUG makes it optional.

CONFIG_JUMP_LABEL is also required, to get the promised optimizations.

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

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

"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.  Since the
callback maintains its state in __drm_debug, drm_debug_enabled() will
stay synchronized, and continue to work.  We can address them
separately if they are called enough to be worth fixing.

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

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

C. API[1] uses DRM_DBG_CAT_<CAT>s

The API already uses B, now it uses A too, instead of DRM_UT_<CAT>, to
get the correct token type for "basic" and "dyndbg" configs.

D. use DEFINE_DYNAMIC_DEBUG_CATEGORIES()

This defines the map using DRM_CAT_<CAT>s, and creates the /sysfs
bitmap to control those categories.

CONFIG_DRM_USE_DYNAMIC_DEBUG is also used to adjust amdgpu, i915
makefiles to add -DDYNAMIC_DEBUG_MODULE; it includes the current
CONFIG_DYNAMIC_DEBUG_CORE and is enabled by the user.

LIMITATIONS:

dev_dbg(etal) effectively prepends twice, category then driver-name,
yielding format strings like so:

bash-5.1# grep amdgpu: /proc/dynamic_debug/control | grep drm: | cut -d= -f2-
_ "amdgpu: drm:core: fence driver on ring %s use gpu addr 0x%016llx\012"
_ "amdgpu: drm:kms: Cannot create framebuffer from imported dma_buf\012"

This means we cannot use anchored "^drm:kms: " to specify the
category, a small loss of precision.

Note that searching on "format ^amdgpu: " works, but this is less
valuable, because the same can be done with "module amdgpu".

NOTES:

Because the dyndbg callback is keeping state in __drm_debug, it
synchronizes with drm_debug_enabled() and its remaining users; the
switchover should be transparent.

Code Review is expected to catch the 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 categories with trailing spaces.  This excludes any
sub-categories which might get 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

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

If you want that, you might consider +mfl flags instead;)

Signed-off-by: Jim Cromie <jim.cromie@gmail.com>
---
v5:
. use DEFINE_DYNAMIC_DEBUG_CATEGORIES in drm_print.c
. s/DRM_DBG_CLASS_/DRM_DBG_CAT_/ - dont need another term
. default=y in Kconfig 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
v6:
. add kernel doc
. fix cpp paste, drop '#'
v7:
. change __drm_debug to long, to fit with DEFINE_DYNAMIC_DEBUG_CATEGORIES
. add -DDYNAMIC_DEBUG_MODULE to ccflags if DRM_USE_DYNAMIC_DEBUG
v8:
. adapt to altered ^ insertion
. add mem cost numbers to kconfig
. kdoc improvements (I hope)
---
 drivers/gpu/drm/Kconfig             |  26 +++++
 drivers/gpu/drm/Makefile            |   2 +
 drivers/gpu/drm/amd/amdgpu/Makefile |   2 +-
 drivers/gpu/drm/drm_print.c         |  55 ++++++---
 drivers/gpu/drm/i915/Makefile       |   2 +-
 include/drm/drm_print.h             | 175 ++++++++++++++++++++++------
 6 files changed, 210 insertions(+), 52 deletions(-)

diff --git a/drivers/gpu/drm/Kconfig b/drivers/gpu/drm/Kconfig
index 2a926d0de423..6223d853907d 100644
--- a/drivers/gpu/drm/Kconfig
+++ b/drivers/gpu/drm/Kconfig
@@ -62,6 +62,32 @@ 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 can patch pr_debug()s into
+	  NOOP slots, in a running kernel, so avoids those bit-test
+	  overheads, and is therefore recommended by default.
+
+	  DRM_USE_DYNAMIC_DEBUG converts "basic" to "dyndbg", this
+	  creates many new dyndbg callsites (56 bytes each), which
+	  significantly increases drm* module .data, so is optional.
+	  On an x86-64 kernel, with a config derived from fedora, that
+	  price is:
+		       #prdbgs  KiB     #with DRM_USE_DYNAMIC_DEBUG=y
+	  kernel       3079	166k
+	  drm		  1	.06k     376	 21k
+	  drm_kms_helper		 207	 12k
+	  i915	        167	9.3k	1811	101k
+	  amdgpu       2339	130k	3917	220k
+	  nouveau      	  3	.17k	 105	~60k
+
 config DRM_DEBUG_SELFTEST
 	tristate "kselftests for DRM"
 	depends on DRM
diff --git a/drivers/gpu/drm/Makefile b/drivers/gpu/drm/Makefile
index 0dff40bb863c..786d3256a163 100644
--- a/drivers/gpu/drm/Makefile
+++ b/drivers/gpu/drm/Makefile
@@ -33,6 +33,8 @@ drm-$(CONFIG_PCI) += drm_pci.o
 drm-$(CONFIG_DEBUG_FS) += drm_debugfs.o drm_debugfs_crc.o
 drm-$(CONFIG_DRM_LOAD_EDID_FIRMWARE) += drm_edid_load.o
 
+ccflags-$(CONFIG_DRM_USE_DYNAMIC_DEBUG) += -DDYNAMIC_DEBUG_MODULE
+
 obj-$(CONFIG_DRM_DP_AUX_BUS) += drm_dp_aux_bus.o
 
 drm_vram_helper-y := drm_gem_vram_helper.o
diff --git a/drivers/gpu/drm/amd/amdgpu/Makefile b/drivers/gpu/drm/amd/amdgpu/Makefile
index 077342ca803f..d840319d29a5 100644
--- a/drivers/gpu/drm/amd/amdgpu/Makefile
+++ b/drivers/gpu/drm/amd/amdgpu/Makefile
@@ -38,7 +38,7 @@ ccflags-y := -I$(FULL_AMD_PATH)/include/asic_reg \
 	-I$(FULL_AMD_DISPLAY_PATH)/amdgpu_dm \
 	-I$(FULL_AMD_PATH)/amdkfd
 
-ccflags-$(CONFIG_DYNAMIC_DEBUG_CORE) += -DYNAMIC_DEBUG_MODULE
+ccflags-$(CONFIG_DRM_USE_DYNAMIC_DEBUG) += -DYNAMIC_DEBUG_MODULE
 
 amdgpu-y := amdgpu_drv.o
 
diff --git a/drivers/gpu/drm/drm_print.c b/drivers/gpu/drm/drm_print.c
index f783d4963d4b..d5e0ffad467b 100644
--- a/drivers/gpu/drm/drm_print.c
+++ b/drivers/gpu/drm/drm_print.c
@@ -28,9 +28,11 @@
 #include <linux/stdarg.h>
 
 #include <linux/io.h>
+#include <linux/module.h>
 #include <linux/moduleparam.h>
 #include <linux/seq_file.h>
 #include <linux/slab.h>
+#include <linux/dynamic_debug.h>
 
 #include <drm/drm.h>
 #include <drm/drm_drv.h>
@@ -40,19 +42,40 @@
  * __drm_debug: Enable debug output.
  * Bitmask of DRM_UT_x. See include/drm/drm_print.h for details.
  */
-unsigned int __drm_debug;
+unsigned long __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)");
-module_param_named(debug, __drm_debug, int, 0600);
+#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)."
+
+#if !defined(CONFIG_DRM_USE_DYNAMIC_DEBUG)
+MODULE_PARM_DESC(debug, DRM_DEBUG_DESC);
+module_param_named(debug, __drm_debug, ulong, 0600);
+#else
+static struct dyndbg_bitdesc drm_dyndbg_bitmap[] = {
+	[0] = { DRM_DBG_CAT_CORE },
+	[1] = { DRM_DBG_CAT_DRIVER },
+	[2] = { DRM_DBG_CAT_KMS },
+	[3] = { DRM_DBG_CAT_PRIME },
+	[4] = { DRM_DBG_CAT_ATOMIC },
+	[5] = { DRM_DBG_CAT_VBL },
+	[6] = { DRM_DBG_CAT_STATE },
+	[7] = { DRM_DBG_CAT_LEASE },
+	[8] = { DRM_DBG_CAT_DP },
+	[9] = { DRM_DBG_CAT_DRMRES }
+};
+DEFINE_DYNAMIC_DEBUG_BITGRPS(debug, __drm_debug, DRM_DEBUG_DESC,
+			     drm_dyndbg_bitmap);
+
+#endif
 
 void __drm_puts_coredump(struct drm_printer *p, const char *str)
 {
@@ -256,8 +279,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 +301,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 +320,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/drivers/gpu/drm/i915/Makefile b/drivers/gpu/drm/i915/Makefile
index 0fa5f53312a8..9801ac245b5d 100644
--- a/drivers/gpu/drm/i915/Makefile
+++ b/drivers/gpu/drm/i915/Makefile
@@ -317,7 +317,7 @@ i915-y += intel_gvt.o
 include $(src)/gvt/Makefile
 endif
 
-ccflags-$(CONFIG_DYNAMIC_DEBUG_CORE) += -DDYNAMIC_DEBUG_MODULE
+ccflags-$(CONFIG_DRM_USE_DYNAMIC_DEBUG) += -DDYNAMIC_DEBUG_MODULE
 
 obj-$(CONFIG_DRM_I915) += i915.o
 obj-$(CONFIG_DRM_I915_GVT_KVMGT) += gvt/kvmgt.o
diff --git a/include/drm/drm_print.h b/include/drm/drm_print.h
index 22fabdeed297..392cff7cb95c 100644
--- a/include/drm/drm_print.h
+++ b/include/drm/drm_print.h
@@ -35,7 +35,7 @@
 #include <drm/drm.h>
 
 /* Do *not* use outside of drm_print.[ch]! */
-extern unsigned int __drm_debug;
+extern unsigned long __drm_debug;
 
 /**
  * DOC: print
@@ -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
@@ -268,8 +268,8 @@ static inline struct drm_printer drm_err_printer(const char *prefix)
  *  - ...
  *  - drm.debug=0x1ff will enable all messages
  *
- * An interesting feature is that it's possible to enable verbose logging at
- * run-time by echoing the debug value in its sysfs node::
+ * It's possible to enable drm.debug logging at run-time by echoing
+ * the debug value in its sysfs node::
  *
  *   # echo 0xf > /sys/module/drm/parameters/debug
  *
@@ -319,6 +319,103 @@ enum drm_debug_category {
 	DRM_UT_DRMRES		= 0x200,
 };
 
+/**
+ * DOC: CONFIG_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
+ *    c: 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, and creates sysfs node
+ *
+ *    DEFINE_DYNAMIC_DEBUG_CATEGORIES(debug, __drm_debug,
+ *			 "drm.debug - overview",
+ *			 { [0] = "drm:core: " },
+ *			 { [1] = "drm:kms: " }, ...);
+ *
+ * 1. DRM_DBG_CAT_<CAT>
+ *
+ * This set of symbols replaces DRM_UT_<CAT> inside the drm-debug API;
+ * for "basic" it is a copy of DRM_UT_<CAT>, otherwise they are the set
+ * of class prefix strings used in pr_debugs (either directly or by
+ * macro wrappers).
+ *
+ * 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's pr_debug sees the
+ * actual (broad population of) callsites, and they're all
+ * individually controllable.
+ */
+#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(pfx, fmt, ...)		\
+	pr_debug(pfx fmt, ##__VA_ARGS__)
+#define drm_dev_dbg(dev, pfx, fmt, ...)		\
+	dev_dbg(dev, pfx fmt, ##__VA_ARGS__)
+
+/**
+ * enum-ish DRM_DBG_CAT_<categories>::
+ *
+ * - DRM_DBG_CAT_CORE	"drm:core: "
+ * - DRM_DBG_CAT_DRIVER	"drm:drvr: "
+ * - DRM_DBG_CAT_KMS	"drm:kms: "
+ * - DRM_DBG_CAT_PRIME	"drm:prime: "
+ * - DRM_DBG_CAT_ATOMIC	"drm:atomic: "
+ * - DRM_DBG_CAT_VBL	"drm:vbl: "
+ * - DRM_DBG_CAT_STATE	"drm:state: "
+ * - DRM_DBG_CAT_LEASE	"drm:lease: "
+ * - DRM_DBG_CAT_DP	"drm:dp: "
+ * - DRM_DBG_CAT_DRMRES	"drm:res: "
+ */
+#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: "
+
+#endif /* CONFIG_DRM_USE_DYNAMIC_DEBUG */
+
 static inline bool drm_debug_enabled(enum drm_debug_category category)
 {
 	return unlikely(__drm_debug & category);
@@ -334,8 +431,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,6 +480,16 @@ void drm_dev_dbg(const struct device *dev, enum drm_debug_category category,
 	}								\
 })
 
+/**
+ * DRM debug API - library of macros to issue categorized syslog messages
+ *
+ * multiple flavors::
+ * - DRM_DEV_DEBUG<,_DRIVER,_KMS>
+ * - drm_dbg_<core,kms,prime,atomic,vbl,state,lease,dp,drmres>	(prefer these)
+ * - DRM_DEBUG<,_DRIVER,_KMS,_PRIME,_ATOMIC,_VBL,_LEASE,_DP>	(over these)
+ * - DRM_DEBUG_KMS_RATELIMITED
+ */
+
 /**
  * DRM_DEV_DEBUG() - Debug output for generic drm code
  *
@@ -392,7 +499,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
  *
@@ -402,7 +509,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
  *
@@ -412,7 +519,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
@@ -454,27 +561,26 @@ void drm_dev_dbg(const struct device *dev, enum drm_debug_category category,
 #define drm_err_ratelimited(drm, fmt, ...)				\
 	__drm_printk((drm), err, _ratelimited, "*ERROR* " fmt, ##__VA_ARGS__)
 
-
 #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__)
 
 
 /*
@@ -484,7 +590,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, ...);
 
@@ -523,35 +629,35 @@ void __drm_err(const char *format, ...);
 
 /* NOTE: this is deprecated in favor of drm_dbg_core(NULL, ...). */
 #define DRM_DEBUG(fmt, ...)						\
-	__drm_dbg(DRM_UT_CORE, fmt, ##__VA_ARGS__)
+	__drm_dbg(DRM_DBG_CAT_CORE, fmt, ##__VA_ARGS__)
 
 /* NOTE: this is deprecated in favor of drm_dbg(NULL, ...). */
 #define DRM_DEBUG_DRIVER(fmt, ...)					\
-	__drm_dbg(DRM_UT_DRIVER, fmt, ##__VA_ARGS__)
+	__drm_dbg(DRM_DBG_CAT_DRIVER, fmt, ##__VA_ARGS__)
 
 /* NOTE: this is deprecated in favor of drm_dbg_kms(NULL, ...). */
 #define DRM_DEBUG_KMS(fmt, ...)						\
-	__drm_dbg(DRM_UT_KMS, fmt, ##__VA_ARGS__)
+	__drm_dbg(DRM_DBG_CAT_KMS, fmt, ##__VA_ARGS__)
 
 /* NOTE: this is deprecated in favor of drm_dbg_prime(NULL, ...). */
 #define DRM_DEBUG_PRIME(fmt, ...)					\
-	__drm_dbg(DRM_UT_PRIME, fmt, ##__VA_ARGS__)
+	__drm_dbg(DRM_DBG_CAT_PRIME, fmt, ##__VA_ARGS__)
 
 /* NOTE: this is deprecated in favor of drm_dbg_atomic(NULL, ...). */
 #define DRM_DEBUG_ATOMIC(fmt, ...)					\
-	__drm_dbg(DRM_UT_ATOMIC, fmt, ##__VA_ARGS__)
+	__drm_dbg(DRM_DBG_CAT_ATOMIC, fmt, ##__VA_ARGS__)
 
 /* NOTE: this is deprecated in favor of drm_dbg_vbl(NULL, ...). */
 #define DRM_DEBUG_VBL(fmt, ...)						\
-	__drm_dbg(DRM_UT_VBL, fmt, ##__VA_ARGS__)
+	__drm_dbg(DRM_DBG_CAT_VBL, fmt, ##__VA_ARGS__)
 
 /* NOTE: this is deprecated in favor of drm_dbg_lease(NULL, ...). */
 #define DRM_DEBUG_LEASE(fmt, ...)					\
-	__drm_dbg(DRM_UT_LEASE, fmt, ##__VA_ARGS__)
+	__drm_dbg(DRM_DBG_CAT_LEASE, fmt, ##__VA_ARGS__)
 
 /* NOTE: this is deprecated in favor of drm_dbg_dp(NULL, ...). */
 #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, ...)					\
 ({												\
@@ -559,7 +665,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 v10 07/10] 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 the
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 | 17 +++++++++++------
 1 file changed, 11 insertions(+), 6 deletions(-)

diff --git a/include/drm/drm_print.h b/include/drm/drm_print.h
index 392cff7cb95c..a902bd4d8c55 100644
--- a/include/drm/drm_print.h
+++ b/include/drm/drm_print.h
@@ -381,6 +381,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 */
@@ -414,12 +419,13 @@ enum drm_debug_category {
 #define DRM_DBG_CAT_DP		"drm:dp: "
 #define DRM_DBG_CAT_DRMRES	"drm:res: "
 
-#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
@@ -582,7 +588,6 @@ void __drm_dev_dbg(const struct device *dev, enum drm_debug_category category,
 #define drm_dbg_drmres(drm, fmt, ...)					\
 	drm_dev_dbg((drm) ? (drm)->dev : NULL, DRM_DBG_CAT_DRMRES, fmt, ##__VA_ARGS__)
 
-
 /*
  * printk based logging
  *
-- 
2.31.1

[PATCH v10 08/10] dyndbg: add print-to-tracefs, selftest with it - RFC

[Jim Cromie]

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

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

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

Dynamic-Debug can do 2nd exceedingly well:

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

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

if CONFIG_TRACING:

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

endif CONFIG_TRACING

Add a new +T flag to enable tracing, independent of +p, and add and
use 3 macros: dyndbg_site_is_enabled/logging/tracing(), to encapsulate
the flag checks.  Existing code treats T like other flags.

Add ddebug_validate_flags() as last step in ddebug_parse_flags().  Its
only job is to fail on +T for non-CONFIG_TRACING builds.  It only sees
the new flags, and cannot validate specific state transitions.  This
is fine, since we have no need for that; such a test would have to be
done in ddebug_change(), which actually updates the callsites.

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

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

__dynamic_pr_debug() etal get minor changes:

 - call dynamic_emit_prefix() 1st, _enabled() optimizes.
 - if (T) call trace_array_printk
 - if (!p) go around original printk code.
   done to minimize diff,
   goto-ectomy + reindent later/separately
 - share vaf across p|T

WRT <net|ib>_dev, I skipped all the <T,!!dev> specific dev_emit_prefix
additions for now.  tracefs is a fast customer with different needs,
its not clear that pretty device-ID-ish strings is useful tracefs
content (on ingest), or that couldn't be done more efficiently while
analysing or postprocesing the tracefs buffer.

SELFTEST: test_dynamic_debug.ko:

Uses the tracer facility to implement a kernel module selftest.

TODO:

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

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

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

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

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

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

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

RFC: (DONE)

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

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

NOTES:

$> modprobe test_dynamic_debug dyndbg=+p

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

$> modprobe test_dynamic_debug use_bad_tracer=1

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

Signed-off-by: Jim Cromie <jim.cromie@gmail.com>
---
 .../admin-guide/dynamic-debug-howto.rst       |   7 +-
 MAINTAINERS                                   |   1 +
 include/linux/dynamic_debug.h                 |  12 +-
 lib/Kconfig.debug                             |  11 +
 lib/Makefile                                  |   1 +
 lib/dynamic_debug.c                           | 127 ++++++++--
 lib/test_dynamic_debug.c                      | 222 ++++++++++++++++++
 7 files changed, 355 insertions(+), 26 deletions(-)
 create mode 100644 lib/test_dynamic_debug.c

diff --git a/Documentation/admin-guide/dynamic-debug-howto.rst b/Documentation/admin-guide/dynamic-debug-howto.rst
index a89cfa083155..bf2a561cc9bc 100644
--- a/Documentation/admin-guide/dynamic-debug-howto.rst
+++ b/Documentation/admin-guide/dynamic-debug-howto.rst
@@ -227,7 +227,8 @@ of the characters::
 
 The flags are::
 
-  p    enables the pr_debug() callsite.
+  p    enables the pr_debug() callsite to syslog
+  T    enables the pr_debug() callsite to tracefs
   f    Include the function name in the printed message
   l    Include line number in the printed message
   m    Include module name in the printed message
@@ -240,8 +241,8 @@ have meaning, other flags ignored.
 For display, the flags are preceded by ``=``
 (mnemonic: what the flags are currently equal to).
 
-Note the regexp ``^[-+=][flmpt_]+$`` matches a flags specification.
-To clear all flags at once, use ``=_`` or ``-flmpt``.
+Note the regexp ``^[-+=][flmptT_]+$`` matches a flags specification.
+To clear all flags at once, use ``=_`` or ``-flmptT``.
 
 
 Debug messages during Boot Process
diff --git a/MAINTAINERS b/MAINTAINERS
index 5b7a13f706fa..db5513b3201b 100644
--- a/MAINTAINERS
+++ b/MAINTAINERS
@@ -6663,6 +6663,7 @@ M:	Jason Baron <jbaron@akamai.com>
 S:	Maintained
 F:	include/linux/dynamic_debug.h
 F:	lib/dynamic_debug.c
+F:	lib/test_dynamic_debug.c
 
 DYNAMIC INTERRUPT MODERATION
 M:	Tal Gilboa <talgi@nvidia.com>
diff --git a/include/linux/dynamic_debug.h b/include/linux/dynamic_debug.h
index a9430168b072..792bcff0297e 100644
--- a/include/linux/dynamic_debug.h
+++ b/include/linux/dynamic_debug.h
@@ -28,15 +28,25 @@ struct _ddebug {
 	 */
 #define _DPRINTK_FLAGS_NONE	0
 #define _DPRINTK_FLAGS_PRINT	(1<<0) /* printk() a message using the format */
+#define _DPRINTK_FLAGS_TRACE	(1<<5) /* trace_printk() the message */
+#define _DPRINTK_ENABLED	(_DPRINTK_FLAGS_PRINT | _DPRINTK_FLAGS_TRACE)
+
+/* internal, need type protection for external use */
+#define __dyndbg_site_is_enabled(desc) (!!(desc->flags & _DPRINTK_ENABLED))
+#define __dyndbg_site_is_logging(desc) (!!(desc->flags & _DPRINTK_FLAGS_PRINT))
+#define __dyndbg_site_is_tracing(desc) (!!(desc->flags & _DPRINTK_FLAGS_TRACE))
+
 #define _DPRINTK_FLAGS_INCL_MODNAME	(1<<1)
 #define _DPRINTK_FLAGS_INCL_FUNCNAME	(1<<2)
 #define _DPRINTK_FLAGS_INCL_LINENO	(1<<3)
 #define _DPRINTK_FLAGS_INCL_TID		(1<<4)
 
-#define _DPRINTK_FLAGS_INCL_ANY		\
+#define _DPRINTK_FLAGS_INCL_ANY						\
 	(_DPRINTK_FLAGS_INCL_MODNAME | _DPRINTK_FLAGS_INCL_FUNCNAME |\
 	 _DPRINTK_FLAGS_INCL_LINENO  | _DPRINTK_FLAGS_INCL_TID)
 
+#define __dyndbg_site_is_decorated(desc) (!!(desc->flags & _DPRINTK_FLAGS_INCL_ANY))
+
 #if defined DEBUG
 #define _DPRINTK_FLAGS_DEFAULT _DPRINTK_FLAGS_PRINT
 #else
diff --git a/lib/Kconfig.debug b/lib/Kconfig.debug
index 9ef7ce18b4f5..b4a299d57c9e 100644
--- a/lib/Kconfig.debug
+++ b/lib/Kconfig.debug
@@ -2480,6 +2480,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 364c23f15578..5dd4cb7c02c6 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 760e1f1f09ed..d493ed6658b9 100644
--- a/lib/dynamic_debug.c
+++ b/lib/dynamic_debug.c
@@ -36,6 +36,7 @@
 #include <linux/sched.h>
 #include <linux/device.h>
 #include <linux/netdevice.h>
+#include <linux/trace.h>
 
 #include <rdma/ib_verbs.h>
 
@@ -74,6 +75,7 @@ module_param(verbose, int, 0644);
 MODULE_PARM_DESC(verbose, " dynamic_debug/control processing "
 		 "( 0 = off (default), 1 = module add/rm, 2 = >control summary, 3 = parsing, 4 = per-site changes)");
 
+
 /* Return the path relative to source root */
 static inline const char *trim_prefix(const char *path)
 {
@@ -87,6 +89,7 @@ static inline const char *trim_prefix(const char *path)
 
 static struct { unsigned flag:8; char opt_char; } opt_array[] = {
 	{ _DPRINTK_FLAGS_PRINT, 'p' },
+	{ _DPRINTK_FLAGS_TRACE, 'T' },
 	{ _DPRINTK_FLAGS_INCL_MODNAME, 'm' },
 	{ _DPRINTK_FLAGS_INCL_FUNCNAME, 'f' },
 	{ _DPRINTK_FLAGS_INCL_LINENO, 'l' },
@@ -209,11 +212,12 @@ static int ddebug_change(const struct ddebug_query *query,
 			newflags = (dp->flags & modifiers->mask) | modifiers->flags;
 			if (newflags == dp->flags)
 				continue;
+
 #ifdef CONFIG_JUMP_LABEL
-			if (dp->flags & _DPRINTK_FLAGS_PRINT) {
-				if (!(modifiers->flags & _DPRINTK_FLAGS_PRINT))
+			if (__dyndbg_site_is_enabled(dp)) {
+				if (!__dyndbg_site_is_enabled(modifiers))
 					static_branch_disable(&dp->key.dd_key_true);
-			} else if (modifiers->flags & _DPRINTK_FLAGS_PRINT)
+			} else if (__dyndbg_site_is_enabled(modifiers))
 				static_branch_enable(&dp->key.dd_key_true);
 #endif
 			dp->flags = newflags;
@@ -431,6 +435,16 @@ static int ddebug_parse_query(char *words[], int nwords,
 	return 0;
 }
 
+static int ddebug_validate_flags(struct flag_settings *modifiers)
+{
+#if !defined(CONFIG_TRACING)
+	if (__dyndbg_site_is_tracing(modifiers)) {
+		WARN_ONCE(1, "cannot enable T, CONFIG_TRACE=n\n");
+		return -EINVAL;
+	}
+#endif
+	return 0;
+}
 /*
  * Parse `str' as a flags specification, format [-+=][p]+.
  * Sets up *maskp and *flagsp to be used when changing the
@@ -483,7 +497,7 @@ static int ddebug_parse_flags(const char *str, struct flag_settings *modifiers)
 	}
 	v3pr_info("*flagsp=0x%x *maskp=0x%x\n", modifiers->flags, modifiers->mask);
 
-	return 0;
+	return ddebug_validate_flags(modifiers);
 }
 
 static int ddebug_exec_query(char *query_string, const char *modname)
@@ -699,11 +713,24 @@ static char *__dynamic_emit_prefix(const struct _ddebug *desc, char *buf)
 
 static inline char *dynamic_emit_prefix(struct _ddebug *desc, char *buf)
 {
-	if (unlikely(desc->flags & _DPRINTK_FLAGS_INCL_ANY))
+	if (unlikely(__dyndbg_site_is_enabled(desc) &&
+		     __dyndbg_site_is_decorated(desc)))
 		return __dynamic_emit_prefix(desc, buf);
 	return buf;
 }
 
+static struct trace_array *trace_arr;
+
+#if !defined(CONFIG_TRACING)
+/* private stub for 4 users below */
+static inline int __printf(3, 0)
+	trace_array_printk(struct trace_array *tr, unsigned long ip,
+			   const char *fmt, ...)
+{
+	return 0;
+}
+#endif
+
 void __dynamic_pr_debug(struct _ddebug *descriptor, const char *fmt, ...)
 {
 	va_list args;
@@ -718,7 +745,13 @@ void __dynamic_pr_debug(struct _ddebug *descriptor, const char *fmt, ...)
 	vaf.fmt = fmt;
 	vaf.va = &args;
 
-	printk(KERN_DEBUG "%s%pV", dynamic_emit_prefix(descriptor, buf), &vaf);
+	dynamic_emit_prefix(descriptor, buf);
+
+	if (__dyndbg_site_is_tracing(descriptor))
+		trace_array_printk(trace_arr, _THIS_IP_, "%s%pV", buf, &vaf);
+
+	if (__dyndbg_site_is_logging(descriptor))
+		printk(KERN_DEBUG "%s%pV", buf, &vaf);
 
 	va_end(args);
 }
@@ -729,6 +762,7 @@ void __dynamic_dev_dbg(struct _ddebug *descriptor,
 {
 	struct va_format vaf;
 	va_list args;
+	char buf[PREFIX_SIZE] = "";
 
 	BUG_ON(!descriptor);
 	BUG_ON(!fmt);
@@ -738,17 +772,21 @@ void __dynamic_dev_dbg(struct _ddebug *descriptor,
 	vaf.fmt = fmt;
 	vaf.va = &args;
 
+	dynamic_emit_prefix(descriptor, buf);
+
+	if (__dyndbg_site_is_tracing(descriptor))
+		trace_array_printk(trace_arr, _THIS_IP_, "%s%pV", buf, &vaf);
+
+	if (!__dyndbg_site_is_logging(descriptor))
+		goto out;
+
 	if (!dev) {
 		printk(KERN_DEBUG "(NULL device *): %pV", &vaf);
 	} else {
-		char buf[PREFIX_SIZE] = "";
-
 		dev_printk_emit(LOGLEVEL_DEBUG, dev, "%s%s %s: %pV",
-				dynamic_emit_prefix(descriptor, buf),
-				dev_driver_string(dev), dev_name(dev),
-				&vaf);
+				buf, dev_driver_string(dev), dev_name(dev), &vaf);
 	}
-
+out:
 	va_end(args);
 }
 EXPORT_SYMBOL(__dynamic_dev_dbg);
@@ -760,6 +798,7 @@ void __dynamic_netdev_dbg(struct _ddebug *descriptor,
 {
 	struct va_format vaf;
 	va_list args;
+	char buf[PREFIX_SIZE] = "";
 
 	BUG_ON(!descriptor);
 	BUG_ON(!fmt);
@@ -769,12 +808,17 @@ void __dynamic_netdev_dbg(struct _ddebug *descriptor,
 	vaf.fmt = fmt;
 	vaf.va = &args;
 
-	if (dev && dev->dev.parent) {
-		char buf[PREFIX_SIZE] = "";
+	dynamic_emit_prefix(descriptor, buf);
+
+	if (__dyndbg_site_is_tracing(descriptor))
+		trace_array_printk(trace_arr, _THIS_IP_, "%s%pV", buf, &vaf);
 
+	if (!__dyndbg_site_is_logging(descriptor))
+		goto out;
+
+	if (dev && dev->dev.parent) {
 		dev_printk_emit(LOGLEVEL_DEBUG, dev->dev.parent,
-				"%s%s %s %s%s: %pV",
-				dynamic_emit_prefix(descriptor, buf),
+				"%s%s %s %s%s: %pV", buf,
 				dev_driver_string(dev->dev.parent),
 				dev_name(dev->dev.parent),
 				netdev_name(dev), netdev_reg_state(dev),
@@ -785,7 +829,7 @@ void __dynamic_netdev_dbg(struct _ddebug *descriptor,
 	} else {
 		printk(KERN_DEBUG "(NULL net_device): %pV", &vaf);
 	}
-
+out:
 	va_end(args);
 }
 EXPORT_SYMBOL(__dynamic_netdev_dbg);
@@ -799,18 +843,24 @@ void __dynamic_ibdev_dbg(struct _ddebug *descriptor,
 {
 	struct va_format vaf;
 	va_list args;
+	char buf[PREFIX_SIZE] = "";
 
 	va_start(args, fmt);
 
 	vaf.fmt = fmt;
 	vaf.va = &args;
 
-	if (ibdev && ibdev->dev.parent) {
-		char buf[PREFIX_SIZE] = "";
+	dynamic_emit_prefix(descriptor, buf);
+
+	if (__dyndbg_site_is_tracing(descriptor))
+		trace_array_printk(trace_arr, _THIS_IP_, "%s%pV", buf, &vaf);
+
+	if (!__dyndbg_site_is_logging(descriptor))
+		goto out;
 
+	if (ibdev && ibdev->dev.parent) {
 		dev_printk_emit(LOGLEVEL_DEBUG, ibdev->dev.parent,
-				"%s%s %s %s: %pV",
-				dynamic_emit_prefix(descriptor, buf),
+				"%s%s %s %s: %pV", buf,
 				dev_driver_string(ibdev->dev.parent),
 				dev_name(ibdev->dev.parent),
 				dev_name(&ibdev->dev),
@@ -820,7 +870,7 @@ void __dynamic_ibdev_dbg(struct _ddebug *descriptor,
 	} else {
 		printk(KERN_DEBUG "(NULL ib_device): %pV", &vaf);
 	}
-
+out:
 	va_end(args);
 }
 EXPORT_SYMBOL(__dynamic_ibdev_dbg);
@@ -1132,6 +1182,35 @@ static void ddebug_remove_all_tables(void)
 	mutex_unlock(&ddebug_lock);
 }
 
+#if defined(CONFIG_TRACING)
+
+static void ddebug_trace_cleanup(void)
+{
+	if (trace_arr) {
+		trace_array_put(trace_arr);
+		trace_array_destroy(trace_arr);
+		trace_arr = NULL;
+	}
+}
+
+static void ddebug_trace_init(void)
+{
+	int ret;
+
+	trace_arr = trace_array_get_by_name("dyndbg-tracefs");
+	if (!trace_arr)
+		return;
+
+	ret = trace_array_init_printk(trace_arr);
+	if (ret)
+		ddebug_trace_cleanup();
+}
+
+#else
+static inline void ddebug_trace_init(void) {}
+static inline void ddebug_trace_cleanup(void) {}
+#endif
+
 static __initdata int ddebug_init_success;
 
 static int __init dynamic_debug_init_control(void)
@@ -1174,6 +1253,9 @@ static int __init dynamic_debug_init(void)
 		ddebug_init_success = 1;
 		return 0;
 	}
+
+	ddebug_trace_init();
+
 	iter = __start___dyndbg;
 	modname = iter->modname;
 	iter_start = iter;
@@ -1215,6 +1297,7 @@ static int __init dynamic_debug_init(void)
 
 out_err:
 	ddebug_remove_all_tables();
+	ddebug_trace_cleanup();
 	return 0;
 }
 /* Allow early initialization for boot messages via boot param */
diff --git a/lib/test_dynamic_debug.c b/lib/test_dynamic_debug.c
new file mode 100644
index 000000000000..dd41a09fd9c8
--- /dev/null
+++ b/lib/test_dynamic_debug.c
@@ -0,0 +1,222 @@
+// SPDX-License-Identifier: GPL-2.0-only
+/*
+ * Kernel module for testing dynamic_debug
+ *
+ * Authors:
+ *      Jim Cromie	<jim.cromie@gmail.com>
+ */
+
+/*
+ * test-setup: use trace_print attachment interface as a test harness,
+ * define a custom trace_printer which counts invocations, and a
+ * pr_debug event generator function which calls a set of categorized
+ * pr_debugs.
+ * test-run: manipulate the pr_debug's enablement, run the event
+ * generator, and check for the expected side effects.
+ */
+
+#define pr_fmt(fmt) "test_dd: " fmt
+
+#include <linux/module.h>
+
+static int hit_ct;
+static int test_ct;
+static int errors;
+
+static int __verbose;
+module_param_named(verbose, __verbose, int, 0444);
+MODULE_PARM_DESC(verbose, "enable print from trace (output verify)");
+
+static int __bad_tracer;
+module_param_named(use_bad_tracer, __bad_tracer, int, 0444);
+MODULE_PARM_DESC(use_bad_tracer,
+		 "use broken tracer, recursing with pr_debug\n"
+		 "\tonly works at modprobe time\n");
+
+static void (*my_tracer)(const char *lbl, struct va_format *vaf);
+
+static void good_tracer(const char *lbl, struct va_format *vaf)
+{
+	hit_ct++;
+
+	if (__verbose)
+		pr_notice("%s%pV", lbl, vaf);
+}
+
+static void bad_tracer(const char *lbl, struct va_format *vaf)
+{
+	hit_ct++;
+	if (__verbose)
+		pr_notice("%s%pV", lbl, vaf);
+
+	pr_debug("%s.%pV", lbl, vaf);
+}
+
+static void pick_tracer(void)
+{
+	if (__bad_tracer) {
+		pr_notice("using bad tracer - fails hit count tests\n");
+		my_tracer = bad_tracer;
+	} else
+		my_tracer = good_tracer;
+}
+
+static int expect_count(int want, const char *story)
+{
+	test_ct++;
+	if (want != hit_ct) {
+		pr_err("nok %d: want %d, got %d: %s\n", test_ct, want, hit_ct, story);
+		errors++;
+		hit_ct = 0;
+		return 1;
+	}
+	pr_info("ok %d: hits %d, on <%s>\n", test_ct, want, story);
+	hit_ct = 0;
+	return 0;
+}
+
+/* call pr_debug (4 * reps) + 2 times, for tracer side-effects */
+static void do_debugging(int reps)
+{
+	int i;
+
+	pr_debug("Entry:\n");
+	pr_info("%s %d time(s)\n", __func__, 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");
+}
+
+static void expect_matches(int want, int got, const char *story)
+{
+	/* todo: got <0 are errors, bubbled up. no test for that */
+	test_ct++;
+	if (got != want) {
+		pr_warn("nok %d: want %d matches, got %d on <%s>\n", test_ct, want, got, story);
+		errors++;
+	} else
+		pr_info("ok %d: %d matches on <%s>\n", test_ct, want, story);
+}
+
+static int report(char *who)
+{
+	if (errors)
+		pr_err("%s failed %d of %d tests\n", who, errors, test_ct);
+	else
+		pr_info("%s passed %d tests\n", who, test_ct);
+	return errors;
+}
+
+struct exec_test {
+	int matches;
+	int loops;
+	int hits;
+	const char *mod;
+	const char *qry;
+};
+
+static void do_exec_test(struct exec_test *tst)
+{
+	int match_count;
+
+	match_count = dynamic_debug_exec_queries(tst->qry, tst->mod);
+	expect_matches(tst->matches, match_count, tst->qry);
+	do_debugging(tst->loops);
+	expect_count(tst->hits, tst->qry);
+}
+
+/* these tests rely on register stuff having been done ?? */
+struct exec_test exec_tests[] = {
+	/*
+	 * use original single string query style once, to test it.
+	 * standard use is with separate module param, like:
+	 * dynamic_debug_exec_queries("func do_debugging +_", "test_dynamic_debug");
+	 */
+	{ 6, 1, 0, NULL, "module test_dynamic_debug func do_debugging -T" },
+
+	/* no modification probe */
+	{ 6, 3, 0, KBUILD_MODNAME, "func do_debugging +_" },
+
+	/* enable all prdbgs in DUT */
+	{ 6, 4, 18, KBUILD_MODNAME, "func do_debugging +T" },
+
+	/* disable hi call */
+	{ 1, 4, 14, KBUILD_MODNAME, "format '^hi:' -T" },
+
+	/* disable mid call */
+	{ 1, 4, 10, KBUILD_MODNAME, "format '^mid:' -T" },
+
+	/* repeat same disable */
+	{ 1, 4, 10, KBUILD_MODNAME, "format '^mid:' -T" },
+
+	/* repeat same disable, diff run ct */
+	{ 1, 5, 12, KBUILD_MODNAME, "format '^mid:' -T" },
+
+	/* include subclass */
+	{ 2, 4, 2, KBUILD_MODNAME, "format '^low:' -T" },
+
+	/* re-disable, exclude subclass */
+	{ 1, 4, 2, KBUILD_MODNAME, "format '^low: ' -T" },
+
+	/* enable, exclude subclass */
+	{ 1, 4, 6, KBUILD_MODNAME, "format '^low: ' +T" },
+
+	/* enable the subclass */
+	{ 1, 4, 10, KBUILD_MODNAME, "format '^low:lower:' +T" },
+
+	/* enable the subclass */
+	{ 1, 6, 14, KBUILD_MODNAME, "format '^low:lower:' +T" },
+};
+
+static int __init test_dynamic_debug_init(void)
+{
+	int i;
+
+	pick_tracer();
+
+	pr_debug("Entry:\n");
+	do_debugging(1);
+	expect_count(0, "nothing on");
+
+	//dynamic_debug_register_tracer(THIS_MODULE, my_tracer);
+	/* 2nd time gets a complaint */
+	//dynamic_debug_register_tracer(THIS_MODULE, my_tracer);
+
+	for (i = 0; i < ARRAY_SIZE(exec_tests); i++)
+		do_exec_test(&exec_tests[i]);
+
+	//dynamic_debug_unregister_tracer(THIS_MODULE, my_tracer);
+
+	/* this gets missing tracer warnings, cuz +T is still on */
+	do_debugging(1);
+	expect_count(0, "unregistered, but +T still on");
+
+	/* reuse test 0 to turn off T */
+	do_exec_test(&exec_tests[0]);
+
+	/* this draws warning about failed deregistration */
+	//dynamic_debug_unregister_tracer(THIS_MODULE, my_tracer);
+
+	do_debugging(1);
+	expect_count(0, "all off");
+
+	report("init");
+	pr_debug("Exit:\n");
+	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 v10 09/10] dyndbg: create DEFINE_DYNAMIC_DEBUG_LOG|TRACE_GROUPS

[Jim Cromie]

With the recent addition of pr_debug to tracefs via +T flag, we now
want to add drm.trace; like its model: drm.debug, it maps bits to
pr_debug categories, but this one enables/disables writing to tracefs
(iff CONFIG_TRACING).

Do this by:

1. add flags to dyndbg_bitmap_param, holds "p" or "T" to work for either.

   add DEFINE_DYNAMIC_DEBUG_BITGRPS_FLAGS to init .flags
   DEFINE_DYNAMIC_DEBUG_BITGRPS gets "p" for compat.
   use it from...

2. DEFINE_DYNAMIC_DEBUG_LOG_GROUPS as (1) with "p" flags - print to syslog
   DEFINE_DYNAMIC_DEBUG_TRACE_GROUPS as (1) with "T" flags - trace to tracefs
   add kdoc to these

NOTES

The flags args (1) is a string, not just a 'p' or 'T'.  This allows
use of decorator flags ("mflt") too, in case the module author wants
to insure those decorations are in the trace & log.

The LOG|TRACE (2) macros don't use any decorator flags, (and therefore
don't toggle them), allowing users to control those themselves.

Decorator flags are shared for both LOG and TRACE consumers,
coordination between users is expected.  ATM, theres no declarative
way to preset decorator flags, but DEFINE_DYNAMIC_DEBUG_BITGRPS_FLAGS
can be used to explicitly toggle them.

Signed-off-by: Jim Cromie <jim.cromie@gmail.com>
---
 include/linux/dynamic_debug.h | 44 ++++++++++++++++++++++++++---------
 lib/dynamic_debug.c           |  4 ++--
 2 files changed, 35 insertions(+), 13 deletions(-)

diff --git a/include/linux/dynamic_debug.h b/include/linux/dynamic_debug.h
index 792bcff0297e..918ac1a92358 100644
--- a/include/linux/dynamic_debug.h
+++ b/include/linux/dynamic_debug.h
@@ -255,30 +255,52 @@ struct dyndbg_bitdesc {
 
 struct dyndbg_bitmap_param {
 	unsigned long *bits;		/* ref to shared state */
+	const char *flags;
 	unsigned int maplen;
 	struct dyndbg_bitdesc *map;	/* indexed by bitpos */
 };
 
 #if defined(CONFIG_DYNAMIC_DEBUG) || \
 	(defined(CONFIG_DYNAMIC_DEBUG_CORE) && defined(DYNAMIC_DEBUG_MODULE))
+
+#define DEFINE_DYNAMIC_DEBUG_BITGRPS_FLAGS(fsname, _var, _flags, desc, data) \
+	MODULE_PARM_DESC(fsname, desc);					\
+	static struct dyndbg_bitmap_param ddcats_##_var =		\
+	{ .bits = &(_var), .flags = (_flags),				\
+	  .map = data, .maplen = ARRAY_SIZE(data) };			\
+	module_param_cb(fsname, &param_ops_dyndbg, &ddcats_##_var, 0644)
+
+#define DEFINE_DYNAMIC_DEBUG_BITGRPS(fsname, _var, desc, data) \
+	DEFINE_DYNAMIC_DEBUG_BITGRPS_FLAGS(fsname, _var, "p", desc, data)
+
 /**
- * DEFINE_DYNAMIC_DEBUG_BITGRPS() - bitmap control of pr_debugs, by format match
+ * DEFINE_DYNAMIC_DEBUG_LOG_GROUPS() - bitmap control of grouped pr_debugs --> syslog
+ *
  * @fsname: parameter basename under /sys
  * @_var:   C-identifier holding bitmap
  * @desc:   string summarizing the controls provided
  * @bitmap: C array of struct dyndbg_bitdescs
  *
- * Intended for modules with a systematic use of pr_debug prefixes in
- * the format strings, this allows modules calling pr_debugs to
- * control them in groups by matching against their formats, and map
- * them to bits 0-N of a sysfs control point.
+ * Intended for modules having pr_debugs with prefixed/categorized
+ * formats; this lets you group them by substring match, map groups to
+ * bits, and enable per group to write to syslog, via @fsname.
  */
-#define DEFINE_DYNAMIC_DEBUG_BITGRPS(fsname, _var, desc, data)	\
-	MODULE_PARM_DESC(fsname, desc);					\
-	static struct dyndbg_bitmap_param ddcats_##_var =		\
-	{ .bits = &(_var), .map = data,					\
-	  .maplen = ARRAY_SIZE(data) };				\
-	module_param_cb(fsname, &param_ops_dyndbg, &ddcats_##_var, 0644)
+#define DEFINE_DYNAMIC_DEBUG_LOG_GROUPS(fsname, _var, desc, data)	\
+	DEFINE_DYNAMIC_DEBUG_BITGRPS_FLAGS(fsname, _var, "p", desc, data)
+
+/**
+ * DEFINE_DYNAMIC_DEBUG_TRACE_GROUPS() - bitmap control of pr_debugs --> tracefs
+ * @fsname: parameter basename under /sys
+ * @_var:   C-identifier holding bitmap
+ * @desc:   string summarizing the controls provided
+ * @bitmap: C array of struct dyndbg_bitdescs
+ *
+ * Intended for modules having pr_debugs with prefixed/categorized
+ * formats; this lets you group them by substring match, map groups to
+ * bits, and enable per group to write to tracebuf, via @fsname.
+ */
+#define DEFINE_DYNAMIC_DEBUG_TRACE_GROUPS(fsname, _var, desc, data)	\
+	DEFINE_DYNAMIC_DEBUG_BITGRPS_FLAGS(fsname, _var, "T", desc, data)
 
 extern const struct kernel_param_ops param_ops_dyndbg;
 
diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
index d493ed6658b9..f5ba07668020 100644
--- a/lib/dynamic_debug.c
+++ b/lib/dynamic_debug.c
@@ -634,8 +634,8 @@ int param_set_dyndbg(const char *instr, const struct kernel_param *kp)
 	for (i = 0; i < p->maplen && i < BITS_PER_LONG; map++, i++) {
 		if (test_bit(i, &inbits) == test_bit(i, p->bits))
 			continue;
-		snprintf(query, FMT_QUERY_SIZE, "format '%s' %cp", map->match,
-			 test_bit(i, &inbits) ? '+' : '-');
+		snprintf(query, FMT_QUERY_SIZE, "format '%s' %c%s", map->match,
+			 test_bit(i, &inbits) ? '+' : '-', p->flags);
 
 		matches = ddebug_exec_queries(query, KP_MOD_NAME);
 
-- 
2.31.1

[PATCH v10 10/10] drm: use DEFINE_DYNAMIC_DEBUG_TRACE_GROUPS in 3 places

[Jim Cromie]

add sysfs knobs to enable modules' pr_debug()s ---> tracefs

Signed-off-by: Jim Cromie <jim.cromie@gmail.com>
---
 drivers/gpu/drm/amd/display/dc/core/dc_debug.c |  8 ++++++++
 drivers/gpu/drm/drm_print.c                    | 13 ++++++++++---
 drivers/gpu/drm/i915/intel_gvt.c               | 15 ++++++++++++---
 3 files changed, 30 insertions(+), 6 deletions(-)

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 e49a755c6a69..58c56c1708e7 100644
--- a/drivers/gpu/drm/amd/display/dc/core/dc_debug.c
+++ b/drivers/gpu/drm/amd/display/dc/core/dc_debug.c
@@ -80,6 +80,14 @@ DEFINE_DYNAMIC_DEBUG_LOG_GROUPS(debug_dc, __debug_dc,
 				DC_DYNDBG_BITMAP_DESC(debug_dc),
 				amdgpu_bitmap);
 
+#if defined(CONFIG_TRACING)
+
+unsigned long __trace_dc;
+EXPORT_SYMBOL(__trace_dc);
+DEFINE_DYNAMIC_DEBUG_LOG_GROUPS(trace_dc, __trace_dc,
+				DC_DYNDBG_BITMAP_DESC(trace_dc),
+				amdgpu_bitmap);
+#endif
 #endif
 
 #define DC_LOGGER_INIT(logger)
diff --git a/drivers/gpu/drm/drm_print.c b/drivers/gpu/drm/drm_print.c
index d5e0ffad467b..ee20e9c14ce9 100644
--- a/drivers/gpu/drm/drm_print.c
+++ b/drivers/gpu/drm/drm_print.c
@@ -72,9 +72,16 @@ static struct dyndbg_bitdesc drm_dyndbg_bitmap[] = {
 	[8] = { DRM_DBG_CAT_DP },
 	[9] = { DRM_DBG_CAT_DRMRES }
 };
-DEFINE_DYNAMIC_DEBUG_BITGRPS(debug, __drm_debug, DRM_DEBUG_DESC,
-			     drm_dyndbg_bitmap);
-
+DEFINE_DYNAMIC_DEBUG_LOG_GROUPS(debug, __drm_debug, DRM_DEBUG_DESC,
+				drm_dyndbg_bitmap);
+
+#ifdef CONFIG_TRACING
+struct trace_array *trace_arr;
+unsigned long __drm_trace;
+EXPORT_SYMBOL(__drm_trace);
+DEFINE_DYNAMIC_DEBUG_TRACE_GROUPS(trace, __drm_trace, DRM_DEBUG_DESC,
+				  drm_dyndbg_bitmap);
+#endif
 #endif
 
 void __drm_puts_coredump(struct drm_printer *p, const char *str)
diff --git a/drivers/gpu/drm/i915/intel_gvt.c b/drivers/gpu/drm/i915/intel_gvt.c
index efaac5777873..84348d4aedf6 100644
--- a/drivers/gpu/drm/i915/intel_gvt.c
+++ b/drivers/gpu/drm/i915/intel_gvt.c
@@ -195,8 +195,17 @@ static struct dyndbg_bitdesc i915_dyndbg_bitmap[] = {
 	help_(7, "gvt:render:")						\
 	help_(8, "gvt:sched:")
 
-DEFINE_DYNAMIC_DEBUG_BITGRPS(debug_gvt, __gvt_debug,
-			     I915_GVT_CATEGORIES(debug_gvt),
-			     i915_dyndbg_bitmap);
+DEFINE_DYNAMIC_DEBUG_LOG_GROUPS(debug_gvt, __gvt_debug,
+				I915_GVT_CATEGORIES(debug_gvt),
+				i915_dyndbg_bitmap);
 
+#if defined(CONFIG_TRACING)
+
+unsigned long __gvt_trace;
+EXPORT_SYMBOL(__gvt_trace);
+DEFINE_DYNAMIC_DEBUG_TRACE_GROUPS(trace_gvt, __gvt_trace,
+				  I915_GVT_CATEGORIES(trace_gvt),
+				  i915_dyndbg_bitmap);
+
+#endif
 #endif
-- 
2.31.1

Re: [PATCH v10 08/10] dyndbg: add print-to-tracefs, selftest with it - RFC

[Vincent Whitchurch]

On Thu, Nov 11, 2021 at 03:02:04PM -0700, Jim Cromie wrote:
> Sean Paul proposed, in:
> https://patchwork.freedesktop.org/series/78133/
> drm/trace: Mirror DRM debug logs to tracefs
> 
> His patchset's objective is to be able to independently steer some of
> the drm.debug stream to an alternate tracing destination, by splitting
> drm_debug_enabled() into syslog & trace flavors, and enabling them
> separately.  2 advantages were identified:
> 
> 1- syslog is heavyweight, tracefs is much lighter
> 2- separate selection of enabled categories means less traffic
> 
> Dynamic-Debug can do 2nd exceedingly well:
> 
> A- all work is behind jump-label's NOOP, zero off cost.
> B- exact site selectivity, precisely the useful traffic.
>    can tailor enabled set interactively, at shell.
> 
> Since the tracefs interface is effective for drm (the threads suggest
> so), adding that interface to dynamic-debug has real potential for
> everyone including drm.
> 
> if CONFIG_TRACING:
> 
> Grab Sean's trace_init/cleanup code, use it to provide tracefs
> available by default to all pr_debugs.  This will likely need some
> further per-module treatment; perhaps something reflecting hierarchy
> of module,file,function,line, maybe with a tuned flattening.
> 
> endif CONFIG_TRACING
> 
> Add a new +T flag to enable tracing, independent of +p, and add and
> use 3 macros: dyndbg_site_is_enabled/logging/tracing(), to encapsulate
> the flag checks.  Existing code treats T like other flags.

I posted a patchset a while ago to do something very similar, but that
got stalled for some reason and I unfortunately didn't follow it up:

 https://lore.kernel.org/lkml/20200825153338.17061-1-vincent.whitchurch@axis.com/

A key difference between that patchset and this patch (besides that
small fact that I used +x instead of +T) was that my patchset allowed
the dyndbg trace to be emitted to the main buffer and did not force them
to be in an instance-specific buffer.

That feature is quite important at least for my use case since I often
use dyndbg combined with function tracing, and the latter doesn't work
on non-main instances according to Documentation/trace/ftrace.rst.

For example, here's a random example of a bootargs from one of my recent
debugging sessions:

 trace_event=printk:* ftrace_filter=_mmc*,mmc*,sd*,dw_mci*,mci*
 ftrace=function trace_buf_size=20M dyndbg="file drivers/mmc/* +x"

Re: [PATCH v10 08/10] dyndbg: add print-to-tracefs, selftest with it - RFC

[Jason Baron]

On 11/12/21 6:49 AM, Vincent Whitchurch wrote:
> On Thu, Nov 11, 2021 at 03:02:04PM -0700, Jim Cromie wrote:
>> Sean Paul proposed, in:
>> https://urldefense.com/v3/__https://patchwork.freedesktop.org/series/78133/__;!!GjvTz_vk!HcKnMRByYkIdyF1apqQjlN5aBIomzJR1an3YWXM6KXs0EftVMQdrewRA8Dki4A$ 
>> drm/trace: Mirror DRM debug logs to tracefs
>>
>> His patchset's objective is to be able to independently steer some of
>> the drm.debug stream to an alternate tracing destination, by splitting
>> drm_debug_enabled() into syslog & trace flavors, and enabling them
>> separately.  2 advantages were identified:
>>
>> 1- syslog is heavyweight, tracefs is much lighter
>> 2- separate selection of enabled categories means less traffic
>>
>> Dynamic-Debug can do 2nd exceedingly well:
>>
>> A- all work is behind jump-label's NOOP, zero off cost.
>> B- exact site selectivity, precisely the useful traffic.
>>    can tailor enabled set interactively, at shell.
>>
>> Since the tracefs interface is effective for drm (the threads suggest
>> so), adding that interface to dynamic-debug has real potential for
>> everyone including drm.
>>
>> if CONFIG_TRACING:
>>
>> Grab Sean's trace_init/cleanup code, use it to provide tracefs
>> available by default to all pr_debugs.  This will likely need some
>> further per-module treatment; perhaps something reflecting hierarchy
>> of module,file,function,line, maybe with a tuned flattening.
>>
>> endif CONFIG_TRACING
>>
>> Add a new +T flag to enable tracing, independent of +p, and add and
>> use 3 macros: dyndbg_site_is_enabled/logging/tracing(), to encapsulate
>> the flag checks.  Existing code treats T like other flags.
> 
> I posted a patchset a while ago to do something very similar, but that
> got stalled for some reason and I unfortunately didn't follow it up:
> 
>  https://urldefense.com/v3/__https://lore.kernel.org/lkml/20200825153338.17061-1-vincent.whitchurch@axis.com/__;!!GjvTz_vk!HcKnMRByYkIdyF1apqQjlN5aBIomzJR1an3YWXM6KXs0EftVMQdrewRGytKHPg$ 
> 
> A key difference between that patchset and this patch (besides that
> small fact that I used +x instead of +T) was that my patchset allowed
> the dyndbg trace to be emitted to the main buffer and did not force them
> to be in an instance-specific buffer.

Yes, I agree I'd prefer that we print here to the 'main' buffer - it seems to keep things simpler and easier to combine the output from different
sources as you mentioned.

Thanks,

-Jason

> 
> That feature is quite important at least for my use case since I often
> use dyndbg combined with function tracing, and the latter doesn't work
> on non-main instances according to Documentation/trace/ftrace.rst.
> 
> For example, here's a random example of a bootargs from one of my recent
> debugging sessions:
> 
>  trace_event=printk:* ftrace_filter=_mmc*,mmc*,sd*,dw_mci*,mci*
>  ftrace=function trace_buf_size=20M dyndbg="file drivers/mmc/* +x"
> 

Re: [PATCH v10 08/10] dyndbg: add print-to-tracefs, selftest with it - RFC

[Steven Rostedt]

On Fri, 12 Nov 2021 10:08:41 -0500
Jason Baron <jbaron@akamai.com> wrote:

> > A key difference between that patchset and this patch (besides that
> > small fact that I used +x instead of +T) was that my patchset allowed
> > the dyndbg trace to be emitted to the main buffer and did not force them
> > to be in an instance-specific buffer.  
> 
> Yes, I agree I'd prefer that we print here to the 'main' buffer - it seems to keep things simpler and easier to combine the output from different
> sources as you mentioned.

I do not want anything to print to the "main buffer" that can not be
filtered or turned off by the tracing infrastructure itself (aka tracefs
file system).

Once we allow that, then the trace file will become useless because
everything will write to the main buffer and fill it with noise.

Events that can be enabled and disabled from tracefs are fine, as they can
be limited. This is why I added that nasty warning if people leave around
trace_printk(), because it does exactly this (write to the main buffer).
It's fine for debugging a custom kernel, but should never be enabled in
something that is shipped, or part of mainline.

-- Steve

Re: [PATCH v10 08/10] dyndbg: add print-to-tracefs, selftest with it - RFC

[Jason Baron]

On 11/12/21 12:07 PM, Steven Rostedt wrote:
> On Fri, 12 Nov 2021 10:08:41 -0500
> Jason Baron <jbaron@akamai.com> wrote:
> 
>>> A key difference between that patchset and this patch (besides that
>>> small fact that I used +x instead of +T) was that my patchset allowed
>>> the dyndbg trace to be emitted to the main buffer and did not force them
>>> to be in an instance-specific buffer.  
>>
>> Yes, I agree I'd prefer that we print here to the 'main' buffer - it seems to keep things simpler and easier to combine the output from different
>> sources as you mentioned.
> 
> I do not want anything to print to the "main buffer" that can not be
> filtered or turned off by the tracing infrastructure itself (aka tracefs
> file system).
> 
> Once we allow that, then the trace file will become useless because
> everything will write to the main buffer and fill it with noise.
> 
> Events that can be enabled and disabled from tracefs are fine, as they can
> be limited. This is why I added that nasty warning if people leave around
> trace_printk(), because it does exactly this (write to the main buffer).
> It's fine for debugging a custom kernel, but should never be enabled in
> something that is shipped, or part of mainline.
> 
> -- Steve
> 

Ok, it looks like Vincent's patch defines a dyndbg event and then uses
'trace_dyndbg()' to output to the 'main' log. So all dynamic output to
the 'main' ftrace buffer goes through that event if I understand it
correctly. Here's a pointer to it for reference:

https://lore.kernel.org/lkml/20200825153338.17061-3-vincent.whitchurch@axis.com/

Would you be ok with that approach?

Thanks,

-Jason

Re: [PATCH v10 08/10] dyndbg: add print-to-tracefs, selftest with it - RFC

[Steven Rostedt]

On Fri, 12 Nov 2021 12:32:23 -0500
Jason Baron <jbaron@akamai.com> wrote:

> Ok, it looks like Vincent's patch defines a dyndbg event and then uses
> 'trace_dyndbg()' to output to the 'main' log. So all dynamic output to
> the 'main' ftrace buffer goes through that event if I understand it
> correctly. Here's a pointer to it for reference:
> 
> https://lore.kernel.org/lkml/20200825153338.17061-3-vincent.whitchurch@axis.com/
> 
> Would you be ok with that approach?

Yes that approach is fine, because it doesn't actually go to the main log
unless you enable the dyndbg trace event in the main buffer. You could
also enable that event in an instance and have it go there.

-- Steve

Re: [PATCH v10 08/10] dyndbg: add print-to-tracefs, selftest with it - RFC

[Pekka Paalanen]

[-- Attachment #1: Type: text/plain, Size: 4574 bytes --]

On Fri, 12 Nov 2021 10:08:41 -0500
Jason Baron <jbaron@akamai.com> wrote:

> On 11/12/21 6:49 AM, Vincent Whitchurch wrote:
> > On Thu, Nov 11, 2021 at 03:02:04PM -0700, Jim Cromie wrote:  
> >> Sean Paul proposed, in:
> >> https://urldefense.com/v3/__https://patchwork.freedesktop.org/series/78133/__;!!GjvTz_vk!HcKnMRByYkIdyF1apqQjlN5aBIomzJR1an3YWXM6KXs0EftVMQdrewRA8Dki4A$ 
> >> drm/trace: Mirror DRM debug logs to tracefs
> >>
> >> His patchset's objective is to be able to independently steer some of
> >> the drm.debug stream to an alternate tracing destination, by splitting
> >> drm_debug_enabled() into syslog & trace flavors, and enabling them
> >> separately.  2 advantages were identified:
> >>
> >> 1- syslog is heavyweight, tracefs is much lighter
> >> 2- separate selection of enabled categories means less traffic
> >>
> >> Dynamic-Debug can do 2nd exceedingly well:
> >>
> >> A- all work is behind jump-label's NOOP, zero off cost.
> >> B- exact site selectivity, precisely the useful traffic.
> >>    can tailor enabled set interactively, at shell.
> >>
> >> Since the tracefs interface is effective for drm (the threads suggest
> >> so), adding that interface to dynamic-debug has real potential for
> >> everyone including drm.
> >>
> >> if CONFIG_TRACING:
> >>
> >> Grab Sean's trace_init/cleanup code, use it to provide tracefs
> >> available by default to all pr_debugs.  This will likely need some
> >> further per-module treatment; perhaps something reflecting hierarchy
> >> of module,file,function,line, maybe with a tuned flattening.
> >>
> >> endif CONFIG_TRACING
> >>
> >> Add a new +T flag to enable tracing, independent of +p, and add and
> >> use 3 macros: dyndbg_site_is_enabled/logging/tracing(), to encapsulate
> >> the flag checks.  Existing code treats T like other flags.  
> > 
> > I posted a patchset a while ago to do something very similar, but that
> > got stalled for some reason and I unfortunately didn't follow it up:
> > 
> >  https://urldefense.com/v3/__https://lore.kernel.org/lkml/20200825153338.17061-1-vincent.whitchurch@axis.com/__;!!GjvTz_vk!HcKnMRByYkIdyF1apqQjlN5aBIomzJR1an3YWXM6KXs0EftVMQdrewRGytKHPg$ 
> > 
> > A key difference between that patchset and this patch (besides that
> > small fact that I used +x instead of +T) was that my patchset allowed
> > the dyndbg trace to be emitted to the main buffer and did not force them
> > to be in an instance-specific buffer.  
> 
> Yes, I agree I'd prefer that we print here to the 'main' buffer - it
> seems to keep things simpler and easier to combine the output from
> different sources as you mentioned.

Hi,

I'm not quite sure I understand this discussion, but I would like to
remind you all of what Sean's original work is about:

Userspace configures DRM tracing into a flight recorder buffer (I guess
this is what you refer to "instance-specific buffer").

Userspace runs happily for months, and then hits a problem: a failure
in the DRM sub-system most likely, e.g. an ioctl that should never
fail, failed. Userspace handles that failure by dumping the flight
recorder buffer into a file and saving or sending a bug report. The
flight recorder contents give a log of all relevant DRM in-kernel
actions leading to the unexpected failure to help developers debug it.

I don't mind if one can additionally send the flight recorder stream to
the main buffer, but I do want the separate flight recorder buffer to
be an option so that a) unrelated things cannot flood the interesting
bits out of it, and b) the scope of collected information is relevant.

The very reason for this work is problems that are very difficult to
reproduce in practice, either because the problem itself is triggered
very rarely and randomly, or because the end users of the system have
either no knowledge or no access to reconfigure debug logging and then
reproduce the problem with good debug logs.

Thank you very much for pushing this work forward!


Thanks,
pq

> 
> Thanks,
> 
> -Jason
> 
> > 
> > That feature is quite important at least for my use case since I often
> > use dyndbg combined with function tracing, and the latter doesn't work
> > on non-main instances according to Documentation/trace/ftrace.rst.
> > 
> > For example, here's a random example of a bootargs from one of my recent
> > debugging sessions:
> > 
> >  trace_event=printk:* ftrace_filter=_mmc*,mmc*,sd*,dw_mci*,mci*
> >  ftrace=function trace_buf_size=20M dyndbg="file drivers/mmc/* +x"
> >   


[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 833 bytes --]

Re: [PATCH v10 08/10] dyndbg: add print-to-tracefs, selftest with it - RFC

[Jason Baron]

On 11/16/21 3:46 AM, Pekka Paalanen wrote:
> On Fri, 12 Nov 2021 10:08:41 -0500
> Jason Baron <jbaron@akamai.com> wrote:
> 
>> On 11/12/21 6:49 AM, Vincent Whitchurch wrote:
>>> On Thu, Nov 11, 2021 at 03:02:04PM -0700, Jim Cromie wrote:  
>>>> Sean Paul proposed, in:
>>>> https://urldefense.com/v3/__https://patchwork.freedesktop.org/series/78133/__;!!GjvTz_vk!HcKnMRByYkIdyF1apqQjlN5aBIomzJR1an3YWXM6KXs0EftVMQdrewRA8Dki4A$ 
>>>> drm/trace: Mirror DRM debug logs to tracefs
>>>>
>>>> His patchset's objective is to be able to independently steer some of
>>>> the drm.debug stream to an alternate tracing destination, by splitting
>>>> drm_debug_enabled() into syslog & trace flavors, and enabling them
>>>> separately.  2 advantages were identified:
>>>>
>>>> 1- syslog is heavyweight, tracefs is much lighter
>>>> 2- separate selection of enabled categories means less traffic
>>>>
>>>> Dynamic-Debug can do 2nd exceedingly well:
>>>>
>>>> A- all work is behind jump-label's NOOP, zero off cost.
>>>> B- exact site selectivity, precisely the useful traffic.
>>>>    can tailor enabled set interactively, at shell.
>>>>
>>>> Since the tracefs interface is effective for drm (the threads suggest
>>>> so), adding that interface to dynamic-debug has real potential for
>>>> everyone including drm.
>>>>
>>>> if CONFIG_TRACING:
>>>>
>>>> Grab Sean's trace_init/cleanup code, use it to provide tracefs
>>>> available by default to all pr_debugs.  This will likely need some
>>>> further per-module treatment; perhaps something reflecting hierarchy
>>>> of module,file,function,line, maybe with a tuned flattening.
>>>>
>>>> endif CONFIG_TRACING
>>>>
>>>> Add a new +T flag to enable tracing, independent of +p, and add and
>>>> use 3 macros: dyndbg_site_is_enabled/logging/tracing(), to encapsulate
>>>> the flag checks.  Existing code treats T like other flags.  
>>>
>>> I posted a patchset a while ago to do something very similar, but that
>>> got stalled for some reason and I unfortunately didn't follow it up:
>>>
>>>  https://urldefense.com/v3/__https://lore.kernel.org/lkml/20200825153338.17061-1-vincent.whitchurch@axis.com/__;!!GjvTz_vk!HcKnMRByYkIdyF1apqQjlN5aBIomzJR1an3YWXM6KXs0EftVMQdrewRGytKHPg$ 
>>>
>>> A key difference between that patchset and this patch (besides that
>>> small fact that I used +x instead of +T) was that my patchset allowed
>>> the dyndbg trace to be emitted to the main buffer and did not force them
>>> to be in an instance-specific buffer.  
>>
>> Yes, I agree I'd prefer that we print here to the 'main' buffer - it
>> seems to keep things simpler and easier to combine the output from
>> different sources as you mentioned.
> 
> Hi,
> 
> I'm not quite sure I understand this discussion, but I would like to
> remind you all of what Sean's original work is about:
> 
> Userspace configures DRM tracing into a flight recorder buffer (I guess
> this is what you refer to "instance-specific buffer").
> 
> Userspace runs happily for months, and then hits a problem: a failure
> in the DRM sub-system most likely, e.g. an ioctl that should never
> fail, failed. Userspace handles that failure by dumping the flight
> recorder buffer into a file and saving or sending a bug report. The
> flight recorder contents give a log of all relevant DRM in-kernel
> actions leading to the unexpected failure to help developers debug it.
> 
> I don't mind if one can additionally send the flight recorder stream to
> the main buffer, but I do want the separate flight recorder buffer to
> be an option so that a) unrelated things cannot flood the interesting
> bits out of it, and b) the scope of collected information is relevant.
> 
> The very reason for this work is problems that are very difficult to
> reproduce in practice, either because the problem itself is triggered
> very rarely and randomly, or because the end users of the system have
> either no knowledge or no access to reconfigure debug logging and then
> reproduce the problem with good debug logs.
> 
> Thank you very much for pushing this work forward!
> 
> 

So I think Vincent (earlier in the thread) was saying that he finds it
very helpful have dynamic debug output go to the 'main' trace buffer,
while you seem to be saying you'd prefer it just go to dynamic debug
specific trace buffer.

So we certainly can have dynamic output potentially go to both places -
although I think this would mean two tracepoints? But I really wonder
if we really need a separate tracing buffer for dynamic debug when
what goes to the 'main' buffer can be controlled and filtered to avoid
your concern around a 'flood'?

Thanks,

-Jason

Re: [PATCH v10 08/10] dyndbg: add print-to-tracefs, selftest with it - RFC

[Pekka Paalanen]

[-- Attachment #1: Type: text/plain, Size: 6254 bytes --]

On Thu, 18 Nov 2021 09:29:27 -0500
Jason Baron <jbaron@akamai.com> wrote:

> On 11/16/21 3:46 AM, Pekka Paalanen wrote:
> > On Fri, 12 Nov 2021 10:08:41 -0500
> > Jason Baron <jbaron@akamai.com> wrote:
> >   
> >> On 11/12/21 6:49 AM, Vincent Whitchurch wrote:  
> >>> On Thu, Nov 11, 2021 at 03:02:04PM -0700, Jim Cromie wrote:    
> >>>> Sean Paul proposed, in:
> >>>> https://urldefense.com/v3/__https://patchwork.freedesktop.org/series/78133/__;!!GjvTz_vk!HcKnMRByYkIdyF1apqQjlN5aBIomzJR1an3YWXM6KXs0EftVMQdrewRA8Dki4A$ 
> >>>> drm/trace: Mirror DRM debug logs to tracefs
> >>>>
> >>>> His patchset's objective is to be able to independently steer some of
> >>>> the drm.debug stream to an alternate tracing destination, by splitting
> >>>> drm_debug_enabled() into syslog & trace flavors, and enabling them
> >>>> separately.  2 advantages were identified:
> >>>>
> >>>> 1- syslog is heavyweight, tracefs is much lighter
> >>>> 2- separate selection of enabled categories means less traffic
> >>>>
> >>>> Dynamic-Debug can do 2nd exceedingly well:
> >>>>
> >>>> A- all work is behind jump-label's NOOP, zero off cost.
> >>>> B- exact site selectivity, precisely the useful traffic.
> >>>>    can tailor enabled set interactively, at shell.
> >>>>
> >>>> Since the tracefs interface is effective for drm (the threads suggest
> >>>> so), adding that interface to dynamic-debug has real potential for
> >>>> everyone including drm.
> >>>>
> >>>> if CONFIG_TRACING:
> >>>>
> >>>> Grab Sean's trace_init/cleanup code, use it to provide tracefs
> >>>> available by default to all pr_debugs.  This will likely need some
> >>>> further per-module treatment; perhaps something reflecting hierarchy
> >>>> of module,file,function,line, maybe with a tuned flattening.
> >>>>
> >>>> endif CONFIG_TRACING
> >>>>
> >>>> Add a new +T flag to enable tracing, independent of +p, and add and
> >>>> use 3 macros: dyndbg_site_is_enabled/logging/tracing(), to encapsulate
> >>>> the flag checks.  Existing code treats T like other flags.    
> >>>
> >>> I posted a patchset a while ago to do something very similar, but that
> >>> got stalled for some reason and I unfortunately didn't follow it up:
> >>>
> >>>  https://urldefense.com/v3/__https://lore.kernel.org/lkml/20200825153338.17061-1-vincent.whitchurch@axis.com/__;!!GjvTz_vk!HcKnMRByYkIdyF1apqQjlN5aBIomzJR1an3YWXM6KXs0EftVMQdrewRGytKHPg$ 
> >>>
> >>> A key difference between that patchset and this patch (besides that
> >>> small fact that I used +x instead of +T) was that my patchset allowed
> >>> the dyndbg trace to be emitted to the main buffer and did not force them
> >>> to be in an instance-specific buffer.    
> >>
> >> Yes, I agree I'd prefer that we print here to the 'main' buffer - it
> >> seems to keep things simpler and easier to combine the output from
> >> different sources as you mentioned.  
> > 
> > Hi,
> > 
> > I'm not quite sure I understand this discussion, but I would like to
> > remind you all of what Sean's original work is about:
> > 
> > Userspace configures DRM tracing into a flight recorder buffer (I guess
> > this is what you refer to "instance-specific buffer").
> > 
> > Userspace runs happily for months, and then hits a problem: a failure
> > in the DRM sub-system most likely, e.g. an ioctl that should never
> > fail, failed. Userspace handles that failure by dumping the flight
> > recorder buffer into a file and saving or sending a bug report. The
> > flight recorder contents give a log of all relevant DRM in-kernel
> > actions leading to the unexpected failure to help developers debug it.
> > 
> > I don't mind if one can additionally send the flight recorder stream to
> > the main buffer, but I do want the separate flight recorder buffer to
> > be an option so that a) unrelated things cannot flood the interesting
> > bits out of it, and b) the scope of collected information is relevant.
> > 
> > The very reason for this work is problems that are very difficult to
> > reproduce in practice, either because the problem itself is triggered
> > very rarely and randomly, or because the end users of the system have
> > either no knowledge or no access to reconfigure debug logging and then
> > reproduce the problem with good debug logs.
> > 
> > Thank you very much for pushing this work forward!
> > 
> >   
> 
> So I think Vincent (earlier in the thread) was saying that he finds it
> very helpful have dynamic debug output go to the 'main' trace buffer,
> while you seem to be saying you'd prefer it just go to dynamic debug
> specific trace buffer.

Seems like we have different use cases: traditional debugging, and
in-production flight recorder for problem reporting. I'm not surprised
if they need different treatment.

> So we certainly can have dynamic output potentially go to both places -
> although I think this would mean two tracepoints? But I really wonder
> if we really need a separate tracing buffer for dynamic debug when
> what goes to the 'main' buffer can be controlled and filtered to avoid
> your concern around a 'flood'?

If the DRM tracing goes into the main buffer, then systems in
production cannot have any other sub-system traced in a similar
fashion. To me it would feel very arrogant to say that to make use of
DRM flight recording, you cannot trace much or anything else.

The very purpose of the flight recorder is run in production all the
time, not in a special debugging session.

There is also the question of access and contents of the trace buffer.
Ultimately, if automatic bug reports are enabled in a system, the
contents of the trace buffer would be sent as-is to some bug tracking
system. If there is a chance to put non-DRM stuff in the trace buffer,
that could be a security problem.

My use case is Weston. When Weston encounters an unexpected problem in
production, something should automatically capture the DRM flight
recorder contents and save it alongside the Weston log. Would be really
nice if Weston itself could do that, but I suspect it is going to need
root privileges so it needs some helper daemon.

Maybe Sean can reiterate their use case more?


Thanks,
pq

[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 833 bytes --]

Re: [PATCH v10 08/10] dyndbg: add print-to-tracefs, selftest with it - RFC

[Jason Baron]

On 11/18/21 10:24 AM, Pekka Paalanen wrote:
> On Thu, 18 Nov 2021 09:29:27 -0500
> Jason Baron <jbaron@akamai.com> wrote:
> 
>> On 11/16/21 3:46 AM, Pekka Paalanen wrote:
>>> On Fri, 12 Nov 2021 10:08:41 -0500
>>> Jason Baron <jbaron@akamai.com> wrote:
>>>   
>>>> On 11/12/21 6:49 AM, Vincent Whitchurch wrote:  
>>>>> On Thu, Nov 11, 2021 at 03:02:04PM -0700, Jim Cromie wrote:    
>>>>>> Sean Paul proposed, in:
>>>>>> https://urldefense.com/v3/__https://patchwork.freedesktop.org/series/78133/__;!!GjvTz_vk!HcKnMRByYkIdyF1apqQjlN5aBIomzJR1an3YWXM6KXs0EftVMQdrewRA8Dki4A$ 
>>>>>> drm/trace: Mirror DRM debug logs to tracefs
>>>>>>
>>>>>> His patchset's objective is to be able to independently steer some of
>>>>>> the drm.debug stream to an alternate tracing destination, by splitting
>>>>>> drm_debug_enabled() into syslog & trace flavors, and enabling them
>>>>>> separately.  2 advantages were identified:
>>>>>>
>>>>>> 1- syslog is heavyweight, tracefs is much lighter
>>>>>> 2- separate selection of enabled categories means less traffic
>>>>>>
>>>>>> Dynamic-Debug can do 2nd exceedingly well:
>>>>>>
>>>>>> A- all work is behind jump-label's NOOP, zero off cost.
>>>>>> B- exact site selectivity, precisely the useful traffic.
>>>>>>    can tailor enabled set interactively, at shell.
>>>>>>
>>>>>> Since the tracefs interface is effective for drm (the threads suggest
>>>>>> so), adding that interface to dynamic-debug has real potential for
>>>>>> everyone including drm.
>>>>>>
>>>>>> if CONFIG_TRACING:
>>>>>>
>>>>>> Grab Sean's trace_init/cleanup code, use it to provide tracefs
>>>>>> available by default to all pr_debugs.  This will likely need some
>>>>>> further per-module treatment; perhaps something reflecting hierarchy
>>>>>> of module,file,function,line, maybe with a tuned flattening.
>>>>>>
>>>>>> endif CONFIG_TRACING
>>>>>>
>>>>>> Add a new +T flag to enable tracing, independent of +p, and add and
>>>>>> use 3 macros: dyndbg_site_is_enabled/logging/tracing(), to encapsulate
>>>>>> the flag checks.  Existing code treats T like other flags.    
>>>>>
>>>>> I posted a patchset a while ago to do something very similar, but that
>>>>> got stalled for some reason and I unfortunately didn't follow it up:
>>>>>
>>>>>  https://urldefense.com/v3/__https://lore.kernel.org/lkml/20200825153338.17061-1-vincent.whitchurch@axis.com/__;!!GjvTz_vk!HcKnMRByYkIdyF1apqQjlN5aBIomzJR1an3YWXM6KXs0EftVMQdrewRGytKHPg$ 
>>>>>
>>>>> A key difference between that patchset and this patch (besides that
>>>>> small fact that I used +x instead of +T) was that my patchset allowed
>>>>> the dyndbg trace to be emitted to the main buffer and did not force them
>>>>> to be in an instance-specific buffer.    
>>>>
>>>> Yes, I agree I'd prefer that we print here to the 'main' buffer - it
>>>> seems to keep things simpler and easier to combine the output from
>>>> different sources as you mentioned.  
>>>
>>> Hi,
>>>
>>> I'm not quite sure I understand this discussion, but I would like to
>>> remind you all of what Sean's original work is about:
>>>
>>> Userspace configures DRM tracing into a flight recorder buffer (I guess
>>> this is what you refer to "instance-specific buffer").
>>>
>>> Userspace runs happily for months, and then hits a problem: a failure
>>> in the DRM sub-system most likely, e.g. an ioctl that should never
>>> fail, failed. Userspace handles that failure by dumping the flight
>>> recorder buffer into a file and saving or sending a bug report. The
>>> flight recorder contents give a log of all relevant DRM in-kernel
>>> actions leading to the unexpected failure to help developers debug it.
>>>
>>> I don't mind if one can additionally send the flight recorder stream to
>>> the main buffer, but I do want the separate flight recorder buffer to
>>> be an option so that a) unrelated things cannot flood the interesting
>>> bits out of it, and b) the scope of collected information is relevant.
>>>
>>> The very reason for this work is problems that are very difficult to
>>> reproduce in practice, either because the problem itself is triggered
>>> very rarely and randomly, or because the end users of the system have
>>> either no knowledge or no access to reconfigure debug logging and then
>>> reproduce the problem with good debug logs.
>>>
>>> Thank you very much for pushing this work forward!
>>>
>>>   
>>
>> So I think Vincent (earlier in the thread) was saying that he finds it
>> very helpful have dynamic debug output go to the 'main' trace buffer,
>> while you seem to be saying you'd prefer it just go to dynamic debug
>> specific trace buffer.
> 
> Seems like we have different use cases: traditional debugging, and
> in-production flight recorder for problem reporting. I'm not surprised
> if they need different treatment.
> 
>> So we certainly can have dynamic output potentially go to both places -
>> although I think this would mean two tracepoints? But I really wonder
>> if we really need a separate tracing buffer for dynamic debug when
>> what goes to the 'main' buffer can be controlled and filtered to avoid
>> your concern around a 'flood'?
> 
> If the DRM tracing goes into the main buffer, then systems in
> production cannot have any other sub-system traced in a similar
> fashion. To me it would feel very arrogant to say that to make use of
> DRM flight recording, you cannot trace much or anything else.
> 
> The very purpose of the flight recorder is run in production all the
> time, not in a special debugging session.
> 
> There is also the question of access and contents of the trace buffer.
> Ultimately, if automatic bug reports are enabled in a system, the
> contents of the trace buffer would be sent as-is to some bug tracking
> system. If there is a chance to put non-DRM stuff in the trace buffer,
> that could be a security problem.
> 
> My use case is Weston. When Weston encounters an unexpected problem in
> production, something should automatically capture the DRM flight
> recorder contents and save it alongside the Weston log. Would be really
> nice if Weston itself could do that, but I suspect it is going to need
> root privileges so it needs some helper daemon.
> 
> Maybe Sean can reiterate their use case more?
> 
> 
> Thanks,
> pq
> 

Ok, so in this current thread the proposal was to create a "dyndbg-tracefs"
buffer to put the dynamic debug output (including drm output from dynamic
debug) into. And I was saying let's just put in the 'main' trace buffer
(predicated on a dynamic debug specific tracepoint), since there seems
to be a a use-case for that and it keeps things simpler.

But I went back to Sean's original patch, and it creates a drm specific
trace buffer "drm" (via trace_array_get_by_name("drm")). Here:
https://patchwork.freedesktop.org/patch/445549/?series=78133&rev=5

So I think that may be some of the confusion here? The current thread/
proposal is not for a drm specific trace buffer...

Having a subsystem specific trace buffer would allow subsystem specific
trace log permissions depending on the sensitivity of the data. But
doesn't drm output today go to the system log which is typically world
readable today?

So I could see us supporting subsystem specific trace buffer output
via dynamic debug here. We could add new dev_debug() variants that
allow say a trace buffer to be supplied. So in that way subsystems
could 'opt-out' of having their data put into the global trace buffer.
And perhaps some subsystems we would want to allow output to both
buffers? The subsystem specific one and the global one?

Thanks,

-Jason

Re: [PATCH v10 08/10] dyndbg: add print-to-tracefs, selftest with it - RFC

[jim.cromie]

On Fri, Nov 19, 2021 at 9:21 AM Jason Baron <jbaron@akamai.com> wrote:
>
>
>
> On 11/18/21 10:24 AM, Pekka Paalanen wrote:
> > On Thu, 18 Nov 2021 09:29:27 -0500
> > Jason Baron <jbaron@akamai.com> wrote:
> >
> >> On 11/16/21 3:46 AM, Pekka Paalanen wrote:
> >>> On Fri, 12 Nov 2021 10:08:41 -0500
> >>> Jason Baron <jbaron@akamai.com> wrote:
> >>>
> >>>> On 11/12/21 6:49 AM, Vincent Whitchurch wrote:
> >>>>> On Thu, Nov 11, 2021 at 03:02:04PM -0700, Jim Cromie wrote:
> >>>>>> Sean Paul proposed, in:
> >>>>>> https://urldefense.com/v3/__https://patchwork.freedesktop.org/series/78133/__;!!GjvTz_vk!HcKnMRByYkIdyF1apqQjlN5aBIomzJR1an3YWXM6KXs0EftVMQdrewRA8Dki4A$
> >>>>>> drm/trace: Mirror DRM debug logs to tracefs
> >>>>>>
> >>>>>> His patchset's objective is to be able to independently steer some of
> >>>>>> the drm.debug stream to an alternate tracing destination, by splitting
> >>>>>> drm_debug_enabled() into syslog & trace flavors, and enabling them
> >>>>>> separately.  2 advantages were identified:
> >>>>>>
> >>>>>> 1- syslog is heavyweight, tracefs is much lighter
> >>>>>> 2- separate selection of enabled categories means less traffic
> >>>>>>
> >>>>>> Dynamic-Debug can do 2nd exceedingly well:
> >>>>>>
> >>>>>> A- all work is behind jump-label's NOOP, zero off cost.
> >>>>>> B- exact site selectivity, precisely the useful traffic.
> >>>>>>    can tailor enabled set interactively, at shell.
> >>>>>>
> >>>>>> Since the tracefs interface is effective for drm (the threads suggest
> >>>>>> so), adding that interface to dynamic-debug has real potential for
> >>>>>> everyone including drm.
> >>>>>>
> >>>>>> if CONFIG_TRACING:
> >>>>>>
> >>>>>> Grab Sean's trace_init/cleanup code, use it to provide tracefs
> >>>>>> available by default to all pr_debugs.  This will likely need some
> >>>>>> further per-module treatment; perhaps something reflecting hierarchy
> >>>>>> of module,file,function,line, maybe with a tuned flattening.
> >>>>>>
> >>>>>> endif CONFIG_TRACING
> >>>>>>
> >>>>>> Add a new +T flag to enable tracing, independent of +p, and add and
> >>>>>> use 3 macros: dyndbg_site_is_enabled/logging/tracing(), to encapsulate
> >>>>>> the flag checks.  Existing code treats T like other flags.
> >>>>>
> >>>>> I posted a patchset a while ago to do something very similar, but that
> >>>>> got stalled for some reason and I unfortunately didn't follow it up:
> >>>>>
> >>>>>  https://urldefense.com/v3/__https://lore.kernel.org/lkml/20200825153338.17061-1-vincent.whitchurch@axis.com/__;!!GjvTz_vk!HcKnMRByYkIdyF1apqQjlN5aBIomzJR1an3YWXM6KXs0EftVMQdrewRGytKHPg$
> >>>>>
> >>>>> A key difference between that patchset and this patch (besides that
> >>>>> small fact that I used +x instead of +T) was that my patchset allowed
> >>>>> the dyndbg trace to be emitted to the main buffer and did not force them
> >>>>> to be in an instance-specific buffer.
> >>>>
> >>>> Yes, I agree I'd prefer that we print here to the 'main' buffer - it
> >>>> seems to keep things simpler and easier to combine the output from
> >>>> different sources as you mentioned.
> >>>
> >>> Hi,
> >>>
> >>> I'm not quite sure I understand this discussion, but I would like to
> >>> remind you all of what Sean's original work is about:
> >>>
> >>> Userspace configures DRM tracing into a flight recorder buffer (I guess
> >>> this is what you refer to "instance-specific buffer").
> >>>
> >>> Userspace runs happily for months, and then hits a problem: a failure
> >>> in the DRM sub-system most likely, e.g. an ioctl that should never
> >>> fail, failed. Userspace handles that failure by dumping the flight
> >>> recorder buffer into a file and saving or sending a bug report. The
> >>> flight recorder contents give a log of all relevant DRM in-kernel
> >>> actions leading to the unexpected failure to help developers debug it.
> >>>
> >>> I don't mind if one can additionally send the flight recorder stream to
> >>> the main buffer, but I do want the separate flight recorder buffer to
> >>> be an option so that a) unrelated things cannot flood the interesting
> >>> bits out of it, and b) the scope of collected information is relevant.
> >>>
> >>> The very reason for this work is problems that are very difficult to
> >>> reproduce in practice, either because the problem itself is triggered
> >>> very rarely and randomly, or because the end users of the system have
> >>> either no knowledge or no access to reconfigure debug logging and then
> >>> reproduce the problem with good debug logs.
> >>>
> >>> Thank you very much for pushing this work forward!
> >>>
> >>>
> >>
> >> So I think Vincent (earlier in the thread) was saying that he finds it
> >> very helpful have dynamic debug output go to the 'main' trace buffer,
> >> while you seem to be saying you'd prefer it just go to dynamic debug
> >> specific trace buffer.
> >
> > Seems like we have different use cases: traditional debugging, and
> > in-production flight recorder for problem reporting. I'm not surprised
> > if they need different treatment.
> >
> >> So we certainly can have dynamic output potentially go to both places -
> >> although I think this would mean two tracepoints? But I really wonder
> >> if we really need a separate tracing buffer for dynamic debug when
> >> what goes to the 'main' buffer can be controlled and filtered to avoid
> >> your concern around a 'flood'?
> >
> > If the DRM tracing goes into the main buffer, then systems in
> > production cannot have any other sub-system traced in a similar
> > fashion. To me it would feel very arrogant to say that to make use of
> > DRM flight recording, you cannot trace much or anything else.
> >
> > The very purpose of the flight recorder is run in production all the
> > time, not in a special debugging session.
> >
> > There is also the question of access and contents of the trace buffer.
> > Ultimately, if automatic bug reports are enabled in a system, the
> > contents of the trace buffer would be sent as-is to some bug tracking
> > system. If there is a chance to put non-DRM stuff in the trace buffer,
> > that could be a security problem.
> >
> > My use case is Weston. When Weston encounters an unexpected problem in
> > production, something should automatically capture the DRM flight
> > recorder contents and save it alongside the Weston log. Would be really
> > nice if Weston itself could do that, but I suspect it is going to need
> > root privileges so it needs some helper daemon.
> >
> > Maybe Sean can reiterate their use case more?
> >
> >
> > Thanks,
> > pq
> >
>
> Ok, so in this current thread the proposal was to create a "dyndbg-tracefs"
> buffer to put the dynamic debug output (including drm output from dynamic
> debug) into. And I was saying let's just put in the 'main' trace buffer
> (predicated on a dynamic debug specific tracepoint), since there seems
> to be a a use-case for that and it keeps things simpler.
>
> But I went back to Sean's original patch, and it creates a drm specific
> trace buffer "drm" (via trace_array_get_by_name("drm")). Here:
> https://patchwork.freedesktop.org/patch/445549/?series=78133&rev=5
>
> So I think that may be some of the confusion here? The current thread/
> proposal is not for a drm specific trace buffer...
>

while thats true, it was a KISS choice, not intrinsic.
Now that a requirement has emerged, I can think about it.

I thought use of all the pr_debug()s as a tracefs event provider made sense,
since the callsite descriptor is passed in, and could be passed in to
the tracefs interface.

Vincent's code has the macro magic to define that event, which IIUC
is what  makes it controllable by ftrace, and therefore acceptable in
principle to Steve.
Would there be any reason to expand his set of 2 events into dev_dbg,
pr_debug etc varieties ?
(ie any value to separating dev, !dev ?, maybe so)

Sean's code uses trace_array_printk primarily, which is EXPORTed,
which is a virtue.

Vincents code does
+/*
+ * This code is heavily based on __ftrace_trace_stack().
+ *
+ * Allow 4 levels of nesting: normal, softirq, irq, NMI.
+ */

to implement

+static void dynamic_trace(const char *fmt, va_list args)

Has this __ftrace_trace_stack() code been bundled into or hidden under
a supported interface ?

would it look anything like trace_array_printk() ?

what problem is that code solving inside dynamic-debug.c ?


> Having a subsystem specific trace buffer would allow subsystem specific
> trace log permissions depending on the sensitivity of the data. But
> doesn't drm output today go to the system log which is typically world
> readable today?
>

> So I could see us supporting subsystem specific trace buffer output
> via dynamic debug here. We could add new dev_debug() variants that
> allow say a trace buffer to be supplied. So in that way subsystems
> could 'opt-out' of having their data put into the global trace buffer.
> And perhaps some subsystems we would want to allow output to both
> buffers? The subsystem specific one and the global one?
>

 * trace_array_printk - Print a message to a specific instance
 * @tr: The instance trace_array descriptor
 * @ip: The instruction pointer that this is called from.
 * @fmt: The format to print (printf format)
 *

what happens when @tr == NULL ?
It could allow up-flow of events to the global instance

> Thanks,
>
> -Jason
>
>

So I wonder, is there any conceptual utility to this ?

echo 1 > instances/foo/filter_up  # enable event upflow (or query-time merging?)

Maybe enabling this causes other files (the ones missing from
instances/foo) to magically appear
so all those filtering capacities also appear.

Re: [PATCH v10 08/10] dyndbg: add print-to-tracefs, selftest with it - RFC

[Steven Rostedt]

On Fri, 19 Nov 2021 15:46:31 -0700
jim.cromie@gmail.com wrote:


> > So I could see us supporting subsystem specific trace buffer output
> > via dynamic debug here. We could add new dev_debug() variants that
> > allow say a trace buffer to be supplied. So in that way subsystems
> > could 'opt-out' of having their data put into the global trace buffer.
> > And perhaps some subsystems we would want to allow output to both
> > buffers? The subsystem specific one and the global one?
> >  
> 
>  * trace_array_printk - Print a message to a specific instance
>  * @tr: The instance trace_array descriptor
>  * @ip: The instruction pointer that this is called from.
>  * @fmt: The format to print (printf format)
>  *
> 
> what happens when @tr == NULL ?

It does nothing, but perhaps crash the kernel.

> It could allow up-flow of events to the global instance

Absolutely not!

Then it's just a reimplementation of trace_printk(). Which I refuse to
have.

Nothing should just dump to the main instance. Once we allow that, then
everyone will be dumping there and you will no longer be able to trace
anything because it will be filled with noise.

What is allowed is an event that acts like a trace_printk() but is an
event, which you can turn off (have default off), and even pick which
instance to go to.

> 
> > Thanks,
> >
> > -Jason
> >
> >  
> 
> So I wonder, is there any conceptual utility to this ?
> 
> echo 1 > instances/foo/filter_up  # enable event upflow (or query-time merging?)
> 
> Maybe enabling this causes other files (the ones missing from
> instances/foo) to magically appear
> so all those filtering capacities also appear.


I've been busy doing other things so I haven't been keeping up with
this thread (which I need to go back and read). Perhaps it was already
stated, but I don't know why you want that.

trace-cmd can read several instances (including the top level one) and
interleave them nicely, if that is what you are looking for. So can
KernelShark.

-- Steve

Re: [PATCH v10 08/10] dyndbg: add print-to-tracefs, selftest with it - RFC

[Pekka Paalanen]

[-- Attachment #1: Type: text/plain, Size: 9317 bytes --]

On Fri, 19 Nov 2021 11:21:36 -0500
Jason Baron <jbaron@akamai.com> wrote:

> On 11/18/21 10:24 AM, Pekka Paalanen wrote:
> > On Thu, 18 Nov 2021 09:29:27 -0500
> > Jason Baron <jbaron@akamai.com> wrote:
> >   
> >> On 11/16/21 3:46 AM, Pekka Paalanen wrote:  
> >>> On Fri, 12 Nov 2021 10:08:41 -0500
> >>> Jason Baron <jbaron@akamai.com> wrote:
> >>>     
> >>>> On 11/12/21 6:49 AM, Vincent Whitchurch wrote:    
> >>>>> On Thu, Nov 11, 2021 at 03:02:04PM -0700, Jim Cromie wrote:      
> >>>>>> Sean Paul proposed, in:
> >>>>>> https://urldefense.com/v3/__https://patchwork.freedesktop.org/series/78133/__;!!GjvTz_vk!HcKnMRByYkIdyF1apqQjlN5aBIomzJR1an3YWXM6KXs0EftVMQdrewRA8Dki4A$ 
> >>>>>> drm/trace: Mirror DRM debug logs to tracefs
> >>>>>>
> >>>>>> His patchset's objective is to be able to independently steer some of
> >>>>>> the drm.debug stream to an alternate tracing destination, by splitting
> >>>>>> drm_debug_enabled() into syslog & trace flavors, and enabling them
> >>>>>> separately.  2 advantages were identified:
> >>>>>>
> >>>>>> 1- syslog is heavyweight, tracefs is much lighter
> >>>>>> 2- separate selection of enabled categories means less traffic
> >>>>>>
> >>>>>> Dynamic-Debug can do 2nd exceedingly well:
> >>>>>>
> >>>>>> A- all work is behind jump-label's NOOP, zero off cost.
> >>>>>> B- exact site selectivity, precisely the useful traffic.
> >>>>>>    can tailor enabled set interactively, at shell.
> >>>>>>
> >>>>>> Since the tracefs interface is effective for drm (the threads suggest
> >>>>>> so), adding that interface to dynamic-debug has real potential for
> >>>>>> everyone including drm.
> >>>>>>
> >>>>>> if CONFIG_TRACING:
> >>>>>>
> >>>>>> Grab Sean's trace_init/cleanup code, use it to provide tracefs
> >>>>>> available by default to all pr_debugs.  This will likely need some
> >>>>>> further per-module treatment; perhaps something reflecting hierarchy
> >>>>>> of module,file,function,line, maybe with a tuned flattening.
> >>>>>>
> >>>>>> endif CONFIG_TRACING
> >>>>>>
> >>>>>> Add a new +T flag to enable tracing, independent of +p, and add and
> >>>>>> use 3 macros: dyndbg_site_is_enabled/logging/tracing(), to encapsulate
> >>>>>> the flag checks.  Existing code treats T like other flags.      
> >>>>>
> >>>>> I posted a patchset a while ago to do something very similar, but that
> >>>>> got stalled for some reason and I unfortunately didn't follow it up:
> >>>>>
> >>>>>  https://urldefense.com/v3/__https://lore.kernel.org/lkml/20200825153338.17061-1-vincent.whitchurch@axis.com/__;!!GjvTz_vk!HcKnMRByYkIdyF1apqQjlN5aBIomzJR1an3YWXM6KXs0EftVMQdrewRGytKHPg$ 
> >>>>>
> >>>>> A key difference between that patchset and this patch (besides that
> >>>>> small fact that I used +x instead of +T) was that my patchset allowed
> >>>>> the dyndbg trace to be emitted to the main buffer and did not force them
> >>>>> to be in an instance-specific buffer.      
> >>>>
> >>>> Yes, I agree I'd prefer that we print here to the 'main' buffer - it
> >>>> seems to keep things simpler and easier to combine the output from
> >>>> different sources as you mentioned.    
> >>>
> >>> Hi,
> >>>
> >>> I'm not quite sure I understand this discussion, but I would like to
> >>> remind you all of what Sean's original work is about:
> >>>
> >>> Userspace configures DRM tracing into a flight recorder buffer (I guess
> >>> this is what you refer to "instance-specific buffer").
> >>>
> >>> Userspace runs happily for months, and then hits a problem: a failure
> >>> in the DRM sub-system most likely, e.g. an ioctl that should never
> >>> fail, failed. Userspace handles that failure by dumping the flight
> >>> recorder buffer into a file and saving or sending a bug report. The
> >>> flight recorder contents give a log of all relevant DRM in-kernel
> >>> actions leading to the unexpected failure to help developers debug it.
> >>>
> >>> I don't mind if one can additionally send the flight recorder stream to
> >>> the main buffer, but I do want the separate flight recorder buffer to
> >>> be an option so that a) unrelated things cannot flood the interesting
> >>> bits out of it, and b) the scope of collected information is relevant.
> >>>
> >>> The very reason for this work is problems that are very difficult to
> >>> reproduce in practice, either because the problem itself is triggered
> >>> very rarely and randomly, or because the end users of the system have
> >>> either no knowledge or no access to reconfigure debug logging and then
> >>> reproduce the problem with good debug logs.
> >>>
> >>> Thank you very much for pushing this work forward!
> >>>
> >>>     
> >>
> >> So I think Vincent (earlier in the thread) was saying that he finds it
> >> very helpful have dynamic debug output go to the 'main' trace buffer,
> >> while you seem to be saying you'd prefer it just go to dynamic debug
> >> specific trace buffer.  
> > 
> > Seems like we have different use cases: traditional debugging, and
> > in-production flight recorder for problem reporting. I'm not surprised
> > if they need different treatment.
> >   
> >> So we certainly can have dynamic output potentially go to both places -
> >> although I think this would mean two tracepoints? But I really wonder
> >> if we really need a separate tracing buffer for dynamic debug when
> >> what goes to the 'main' buffer can be controlled and filtered to avoid
> >> your concern around a 'flood'?  
> > 
> > If the DRM tracing goes into the main buffer, then systems in
> > production cannot have any other sub-system traced in a similar
> > fashion. To me it would feel very arrogant to say that to make use of
> > DRM flight recording, you cannot trace much or anything else.
> > 
> > The very purpose of the flight recorder is run in production all the
> > time, not in a special debugging session.
> > 
> > There is also the question of access and contents of the trace buffer.
> > Ultimately, if automatic bug reports are enabled in a system, the
> > contents of the trace buffer would be sent as-is to some bug tracking
> > system. If there is a chance to put non-DRM stuff in the trace buffer,
> > that could be a security problem.
> > 
> > My use case is Weston. When Weston encounters an unexpected problem in
> > production, something should automatically capture the DRM flight
> > recorder contents and save it alongside the Weston log. Would be really
> > nice if Weston itself could do that, but I suspect it is going to need
> > root privileges so it needs some helper daemon.
> > 
> > Maybe Sean can reiterate their use case more?
> > 
> > 
> > Thanks,
> > pq
> >   
> 
> Ok, so in this current thread the proposal was to create a "dyndbg-tracefs"
> buffer to put the dynamic debug output (including drm output from dynamic
> debug) into. And I was saying let's just put in the 'main' trace buffer
> (predicated on a dynamic debug specific tracepoint), since there seems
> to be a a use-case for that and it keeps things simpler.
> 
> But I went back to Sean's original patch, and it creates a drm specific
> trace buffer "drm" (via trace_array_get_by_name("drm")). Here:
> https://patchwork.freedesktop.org/patch/445549/?series=78133&rev=5
> 
> So I think that may be some of the confusion here? The current thread/
> proposal is not for a drm specific trace buffer...

Hi Jason,

I may very well have confused things, sorry about that. If this series
is not superseding the idea of the DRM flight recorder, then don't mind
me. It just sounded very similar and I also haven't seen new revisions
of the flight recorder in a long time.

> Having a subsystem specific trace buffer would allow subsystem specific
> trace log permissions depending on the sensitivity of the data. But
> doesn't drm output today go to the system log which is typically world
> readable today?

Yes, and that is exactly the problem. The DRM debug output is so high
traffic it would make the system log both unusable due to cruft and
slow down the whole machine. The debug output is only useful when
something went wrong, and at that point it is too late to enable
debugging. That's why a flight recorder with an over-written circular
in-memory buffer is needed.

The log being world-readable (it's not in every distribution, I
believe) only means on that one machine, but there are hopes of making
some logs truly world-readable by posting them to the internet (bug
reports).

I would be very wary of anything uploading my system logs automatically
with bug reports, both from the reporter point of view (am I exposing
things I don't want to) and from the bug report receiving service point
of view (e.g. GDPR regulations).

> So I could see us supporting subsystem specific trace buffer output
> via dynamic debug here. We could add new dev_debug() variants that
> allow say a trace buffer to be supplied. So in that way subsystems
> could 'opt-out' of having their data put into the global trace buffer.
> And perhaps some subsystems we would want to allow output to both
> buffers? The subsystem specific one and the global one?

Unfortunately the rest of the discussion goes too high over my head.


Thanks,
pq

[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 833 bytes --]

Re: [PATCH v10 08/10] dyndbg: add print-to-tracefs, selftest with it - RFC

[jim.cromie]

On Mon, Nov 22, 2021 at 2:02 AM Pekka Paalanen <ppaalanen@gmail.com> wrote:
>
> On Fri, 19 Nov 2021 11:21:36 -0500
> Jason Baron <jbaron@akamai.com> wrote:
>
> > On 11/18/21 10:24 AM, Pekka Paalanen wrote:
> > > On Thu, 18 Nov 2021 09:29:27 -0500
> > > Jason Baron <jbaron@akamai.com> wrote:
> > >
> > >> On 11/16/21 3:46 AM, Pekka Paalanen wrote:
> > >>> On Fri, 12 Nov 2021 10:08:41 -0500
> > >>> Jason Baron <jbaron@akamai.com> wrote:
> > >>>
> > >>>> On 11/12/21 6:49 AM, Vincent Whitchurch wrote:
> > >>>>> On Thu, Nov 11, 2021 at 03:02:04PM -0700, Jim Cromie wrote:
> > >>>>>> Sean Paul proposed, in:
> > >>>>>> https://urldefense.com/v3/__https://patchwork.freedesktop.org/series/78133/__;!!GjvTz_vk!HcKnMRByYkIdyF1apqQjlN5aBIomzJR1an3YWXM6KXs0EftVMQdrewRA8Dki4A$
> > >>>>>> drm/trace: Mirror DRM debug logs to tracefs
> > >>>>>>
> > >>>>>> His patchset's objective is to be able to independently steer some of
> > >>>>>> the drm.debug stream to an alternate tracing destination, by splitting
> > >>>>>> drm_debug_enabled() into syslog & trace flavors, and enabling them
> > >>>>>> separately.  2 advantages were identified:
> > >>>>>>
> > >>>>>> 1- syslog is heavyweight, tracefs is much lighter
> > >>>>>> 2- separate selection of enabled categories means less traffic
> > >>>>>>
> > >>>>>> Dynamic-Debug can do 2nd exceedingly well:
> > >>>>>>
> > >>>>>> A- all work is behind jump-label's NOOP, zero off cost.
> > >>>>>> B- exact site selectivity, precisely the useful traffic.
> > >>>>>>    can tailor enabled set interactively, at shell.
> > >>>>>>
> > >>>>>> Since the tracefs interface is effective for drm (the threads suggest
> > >>>>>> so), adding that interface to dynamic-debug has real potential for
> > >>>>>> everyone including drm.
> > >>>>>>
> > >>>>>> if CONFIG_TRACING:
> > >>>>>>
> > >>>>>> Grab Sean's trace_init/cleanup code, use it to provide tracefs
> > >>>>>> available by default to all pr_debugs.  This will likely need some
> > >>>>>> further per-module treatment; perhaps something reflecting hierarchy
> > >>>>>> of module,file,function,line, maybe with a tuned flattening.
> > >>>>>>
> > >>>>>> endif CONFIG_TRACING
> > >>>>>>
> > >>>>>> Add a new +T flag to enable tracing, independent of +p, and add and
> > >>>>>> use 3 macros: dyndbg_site_is_enabled/logging/tracing(), to encapsulate
> > >>>>>> the flag checks.  Existing code treats T like other flags.
> > >>>>>
> > >>>>> I posted a patchset a while ago to do something very similar, but that
> > >>>>> got stalled for some reason and I unfortunately didn't follow it up:
> > >>>>>
> > >>>>>  https://urldefense.com/v3/__https://lore.kernel.org/lkml/20200825153338.17061-1-vincent.whitchurch@axis.com/__;!!GjvTz_vk!HcKnMRByYkIdyF1apqQjlN5aBIomzJR1an3YWXM6KXs0EftVMQdrewRGytKHPg$
> > >>>>>
> > >>>>> A key difference between that patchset and this patch (besides that
> > >>>>> small fact that I used +x instead of +T) was that my patchset allowed
> > >>>>> the dyndbg trace to be emitted to the main buffer and did not force them
> > >>>>> to be in an instance-specific buffer.
> > >>>>
> > >>>> Yes, I agree I'd prefer that we print here to the 'main' buffer - it
> > >>>> seems to keep things simpler and easier to combine the output from
> > >>>> different sources as you mentioned.
> > >>>
> > >>> Hi,
> > >>>
> > >>> I'm not quite sure I understand this discussion, but I would like to
> > >>> remind you all of what Sean's original work is about:
> > >>>
> > >>> Userspace configures DRM tracing into a flight recorder buffer (I guess
> > >>> this is what you refer to "instance-specific buffer").
> > >>>
> > >>> Userspace runs happily for months, and then hits a problem: a failure
> > >>> in the DRM sub-system most likely, e.g. an ioctl that should never
> > >>> fail, failed. Userspace handles that failure by dumping the flight
> > >>> recorder buffer into a file and saving or sending a bug report. The
> > >>> flight recorder contents give a log of all relevant DRM in-kernel
> > >>> actions leading to the unexpected failure to help developers debug it.
> > >>>
> > >>> I don't mind if one can additionally send the flight recorder stream to
> > >>> the main buffer, but I do want the separate flight recorder buffer to
> > >>> be an option so that a) unrelated things cannot flood the interesting
> > >>> bits out of it, and b) the scope of collected information is relevant.
> > >>>
> > >>> The very reason for this work is problems that are very difficult to
> > >>> reproduce in practice, either because the problem itself is triggered
> > >>> very rarely and randomly, or because the end users of the system have
> > >>> either no knowledge or no access to reconfigure debug logging and then
> > >>> reproduce the problem with good debug logs.
> > >>>
> > >>> Thank you very much for pushing this work forward!
> > >>>
> > >>>
> > >>
> > >> So I think Vincent (earlier in the thread) was saying that he finds it
> > >> very helpful have dynamic debug output go to the 'main' trace buffer,
> > >> while you seem to be saying you'd prefer it just go to dynamic debug
> > >> specific trace buffer.
> > >
> > > Seems like we have different use cases: traditional debugging, and
> > > in-production flight recorder for problem reporting. I'm not surprised
> > > if they need different treatment.
> > >
> > >> So we certainly can have dynamic output potentially go to both places -
> > >> although I think this would mean two tracepoints? But I really wonder
> > >> if we really need a separate tracing buffer for dynamic debug when
> > >> what goes to the 'main' buffer can be controlled and filtered to avoid
> > >> your concern around a 'flood'?
> > >
> > > If the DRM tracing goes into the main buffer, then systems in
> > > production cannot have any other sub-system traced in a similar
> > > fashion. To me it would feel very arrogant to say that to make use of
> > > DRM flight recording, you cannot trace much or anything else.
> > >
> > > The very purpose of the flight recorder is run in production all the
> > > time, not in a special debugging session.
> > >
> > > There is also the question of access and contents of the trace buffer.
> > > Ultimately, if automatic bug reports are enabled in a system, the
> > > contents of the trace buffer would be sent as-is to some bug tracking
> > > system. If there is a chance to put non-DRM stuff in the trace buffer,
> > > that could be a security problem.
> > >
> > > My use case is Weston. When Weston encounters an unexpected problem in
> > > production, something should automatically capture the DRM flight
> > > recorder contents and save it alongside the Weston log. Would be really
> > > nice if Weston itself could do that, but I suspect it is going to need
> > > root privileges so it needs some helper daemon.
> > >
> > > Maybe Sean can reiterate their use case more?
> > >
> > >
> > > Thanks,
> > > pq
> > >
> >
> > Ok, so in this current thread the proposal was to create a "dyndbg-tracefs"
> > buffer to put the dynamic debug output (including drm output from dynamic
> > debug) into. And I was saying let's just put in the 'main' trace buffer
> > (predicated on a dynamic debug specific tracepoint), since there seems
> > to be a a use-case for that and it keeps things simpler.
> >
> > But I went back to Sean's original patch, and it creates a drm specific
> > trace buffer "drm" (via trace_array_get_by_name("drm")). Here:
> > https://patchwork.freedesktop.org/patch/445549/?series=78133&rev=5
> >
> > So I think that may be some of the confusion here? The current thread/
> > proposal is not for a drm specific trace buffer...
>
> Hi Jason,
>
> I may very well have confused things, sorry about that. If this series
> is not superseding the idea of the DRM flight recorder, then don't mind
> me. It just sounded very similar and I also haven't seen new revisions
> of the flight recorder in a long time.

IMO this series has clarified the requirement for a flight-recorder mode,
which seems to fit ideally in a separate instance.

> > Having a subsystem specific trace buffer would allow subsystem specific
> > trace log permissions depending on the sensitivity of the data. But
> > doesn't drm output today go to the system log which is typically world
> > readable today?
>
> Yes, and that is exactly the problem. The DRM debug output is so high
> traffic it would make the system log both unusable due to cruft and
> slow down the whole machine. The debug output is only useful when
> something went wrong, and at that point it is too late to enable
> debugging. That's why a flight recorder with an over-written circular
> in-memory buffer is needed.

Seans patch reuses enum drm_debug_category to split the tracing
stream into 10 sub-streams
- how much traffic from each ?
- are some sub-streams more valuable for post-mortem ?
- any value from further refinement of categories ?
- drop irrelevant callsites individually to reduce clutter, extend
buffer time/space ?

Re: [PATCH v10 08/10] dyndbg: add print-to-tracefs, selftest with it - RFC

[Pekka Paalanen]

[-- Attachment #1: Type: text/plain, Size: 11060 bytes --]

On Mon, 22 Nov 2021 15:42:38 -0700
jim.cromie@gmail.com wrote:

> On Mon, Nov 22, 2021 at 2:02 AM Pekka Paalanen <ppaalanen@gmail.com> wrote:
> >
> > On Fri, 19 Nov 2021 11:21:36 -0500
> > Jason Baron <jbaron@akamai.com> wrote:
> >  
> > > On 11/18/21 10:24 AM, Pekka Paalanen wrote:  
> > > > On Thu, 18 Nov 2021 09:29:27 -0500
> > > > Jason Baron <jbaron@akamai.com> wrote:
> > > >  
> > > >> On 11/16/21 3:46 AM, Pekka Paalanen wrote:  
> > > >>> On Fri, 12 Nov 2021 10:08:41 -0500
> > > >>> Jason Baron <jbaron@akamai.com> wrote:
> > > >>>  
> > > >>>> On 11/12/21 6:49 AM, Vincent Whitchurch wrote:  
> > > >>>>> On Thu, Nov 11, 2021 at 03:02:04PM -0700, Jim Cromie wrote:  
> > > >>>>>> Sean Paul proposed, in:
> > > >>>>>> https://urldefense.com/v3/__https://patchwork.freedesktop.org/series/78133/__;!!GjvTz_vk!HcKnMRByYkIdyF1apqQjlN5aBIomzJR1an3YWXM6KXs0EftVMQdrewRA8Dki4A$
> > > >>>>>> drm/trace: Mirror DRM debug logs to tracefs
> > > >>>>>>
> > > >>>>>> His patchset's objective is to be able to independently steer some of
> > > >>>>>> the drm.debug stream to an alternate tracing destination, by splitting
> > > >>>>>> drm_debug_enabled() into syslog & trace flavors, and enabling them
> > > >>>>>> separately.  2 advantages were identified:
> > > >>>>>>
> > > >>>>>> 1- syslog is heavyweight, tracefs is much lighter
> > > >>>>>> 2- separate selection of enabled categories means less traffic
> > > >>>>>>
> > > >>>>>> Dynamic-Debug can do 2nd exceedingly well:
> > > >>>>>>
> > > >>>>>> A- all work is behind jump-label's NOOP, zero off cost.
> > > >>>>>> B- exact site selectivity, precisely the useful traffic.
> > > >>>>>>    can tailor enabled set interactively, at shell.
> > > >>>>>>
> > > >>>>>> Since the tracefs interface is effective for drm (the threads suggest
> > > >>>>>> so), adding that interface to dynamic-debug has real potential for
> > > >>>>>> everyone including drm.
> > > >>>>>>
> > > >>>>>> if CONFIG_TRACING:
> > > >>>>>>
> > > >>>>>> Grab Sean's trace_init/cleanup code, use it to provide tracefs
> > > >>>>>> available by default to all pr_debugs.  This will likely need some
> > > >>>>>> further per-module treatment; perhaps something reflecting hierarchy
> > > >>>>>> of module,file,function,line, maybe with a tuned flattening.
> > > >>>>>>
> > > >>>>>> endif CONFIG_TRACING
> > > >>>>>>
> > > >>>>>> Add a new +T flag to enable tracing, independent of +p, and add and
> > > >>>>>> use 3 macros: dyndbg_site_is_enabled/logging/tracing(), to encapsulate
> > > >>>>>> the flag checks.  Existing code treats T like other flags.  
> > > >>>>>
> > > >>>>> I posted a patchset a while ago to do something very similar, but that
> > > >>>>> got stalled for some reason and I unfortunately didn't follow it up:
> > > >>>>>
> > > >>>>>  https://urldefense.com/v3/__https://lore.kernel.org/lkml/20200825153338.17061-1-vincent.whitchurch@axis.com/__;!!GjvTz_vk!HcKnMRByYkIdyF1apqQjlN5aBIomzJR1an3YWXM6KXs0EftVMQdrewRGytKHPg$
> > > >>>>>
> > > >>>>> A key difference between that patchset and this patch (besides that
> > > >>>>> small fact that I used +x instead of +T) was that my patchset allowed
> > > >>>>> the dyndbg trace to be emitted to the main buffer and did not force them
> > > >>>>> to be in an instance-specific buffer.  
> > > >>>>
> > > >>>> Yes, I agree I'd prefer that we print here to the 'main' buffer - it
> > > >>>> seems to keep things simpler and easier to combine the output from
> > > >>>> different sources as you mentioned.  
> > > >>>
> > > >>> Hi,
> > > >>>
> > > >>> I'm not quite sure I understand this discussion, but I would like to
> > > >>> remind you all of what Sean's original work is about:
> > > >>>
> > > >>> Userspace configures DRM tracing into a flight recorder buffer (I guess
> > > >>> this is what you refer to "instance-specific buffer").
> > > >>>
> > > >>> Userspace runs happily for months, and then hits a problem: a failure
> > > >>> in the DRM sub-system most likely, e.g. an ioctl that should never
> > > >>> fail, failed. Userspace handles that failure by dumping the flight
> > > >>> recorder buffer into a file and saving or sending a bug report. The
> > > >>> flight recorder contents give a log of all relevant DRM in-kernel
> > > >>> actions leading to the unexpected failure to help developers debug it.
> > > >>>
> > > >>> I don't mind if one can additionally send the flight recorder stream to
> > > >>> the main buffer, but I do want the separate flight recorder buffer to
> > > >>> be an option so that a) unrelated things cannot flood the interesting
> > > >>> bits out of it, and b) the scope of collected information is relevant.
> > > >>>
> > > >>> The very reason for this work is problems that are very difficult to
> > > >>> reproduce in practice, either because the problem itself is triggered
> > > >>> very rarely and randomly, or because the end users of the system have
> > > >>> either no knowledge or no access to reconfigure debug logging and then
> > > >>> reproduce the problem with good debug logs.
> > > >>>
> > > >>> Thank you very much for pushing this work forward!
> > > >>>
> > > >>>  
> > > >>
> > > >> So I think Vincent (earlier in the thread) was saying that he finds it
> > > >> very helpful have dynamic debug output go to the 'main' trace buffer,
> > > >> while you seem to be saying you'd prefer it just go to dynamic debug
> > > >> specific trace buffer.  
> > > >
> > > > Seems like we have different use cases: traditional debugging, and
> > > > in-production flight recorder for problem reporting. I'm not surprised
> > > > if they need different treatment.
> > > >  
> > > >> So we certainly can have dynamic output potentially go to both places -
> > > >> although I think this would mean two tracepoints? But I really wonder
> > > >> if we really need a separate tracing buffer for dynamic debug when
> > > >> what goes to the 'main' buffer can be controlled and filtered to avoid
> > > >> your concern around a 'flood'?  
> > > >
> > > > If the DRM tracing goes into the main buffer, then systems in
> > > > production cannot have any other sub-system traced in a similar
> > > > fashion. To me it would feel very arrogant to say that to make use of
> > > > DRM flight recording, you cannot trace much or anything else.
> > > >
> > > > The very purpose of the flight recorder is run in production all the
> > > > time, not in a special debugging session.
> > > >
> > > > There is also the question of access and contents of the trace buffer.
> > > > Ultimately, if automatic bug reports are enabled in a system, the
> > > > contents of the trace buffer would be sent as-is to some bug tracking
> > > > system. If there is a chance to put non-DRM stuff in the trace buffer,
> > > > that could be a security problem.
> > > >
> > > > My use case is Weston. When Weston encounters an unexpected problem in
> > > > production, something should automatically capture the DRM flight
> > > > recorder contents and save it alongside the Weston log. Would be really
> > > > nice if Weston itself could do that, but I suspect it is going to need
> > > > root privileges so it needs some helper daemon.
> > > >
> > > > Maybe Sean can reiterate their use case more?
> > > >
> > > >
> > > > Thanks,
> > > > pq
> > > >  
> > >
> > > Ok, so in this current thread the proposal was to create a "dyndbg-tracefs"
> > > buffer to put the dynamic debug output (including drm output from dynamic
> > > debug) into. And I was saying let's just put in the 'main' trace buffer
> > > (predicated on a dynamic debug specific tracepoint), since there seems
> > > to be a a use-case for that and it keeps things simpler.
> > >
> > > But I went back to Sean's original patch, and it creates a drm specific
> > > trace buffer "drm" (via trace_array_get_by_name("drm")). Here:
> > > https://patchwork.freedesktop.org/patch/445549/?series=78133&rev=5
> > >
> > > So I think that may be some of the confusion here? The current thread/
> > > proposal is not for a drm specific trace buffer...  
> >
> > Hi Jason,
> >
> > I may very well have confused things, sorry about that. If this series
> > is not superseding the idea of the DRM flight recorder, then don't mind
> > me. It just sounded very similar and I also haven't seen new revisions
> > of the flight recorder in a long time.  
> 
> IMO this series has clarified the requirement for a flight-recorder mode,
> which seems to fit ideally in a separate instance.
> 
> > > Having a subsystem specific trace buffer would allow subsystem specific
> > > trace log permissions depending on the sensitivity of the data. But
> > > doesn't drm output today go to the system log which is typically world
> > > readable today?  
> >
> > Yes, and that is exactly the problem. The DRM debug output is so high
> > traffic it would make the system log both unusable due to cruft and
> > slow down the whole machine. The debug output is only useful when
> > something went wrong, and at that point it is too late to enable
> > debugging. That's why a flight recorder with an over-written circular
> > in-memory buffer is needed.  
> 
> Seans patch reuses enum drm_debug_category to split the tracing
> stream into 10 sub-streams
> - how much traffic from each ?
> - are some sub-streams more valuable for post-mortem ?
> - any value from further refinement of categories ?
> - drop irrelevant callsites individually to reduce clutter, extend
> buffer time/space ?

I think it's hard to predict which sub-streams you are going to need
before you have a bug to debug. Hence I would err on the side of
enabling too much. This also means that better or more refined
categorisation might not be that much of help - or if it is, then are
the excluded debug messages worth having in the kernel to begin with.
Well, we're probably not that interested in GPU debugs but just
everything related to the KMS side, which on the existing categories
is... everything except half of CORE and DRIVER, maybe? Not sure.

Maybe Sean has a better idea.

My feeling is that that could mean in the order of hundreds of log
events at framerate (e.g. 60 times per second) per each enabled output
individually. And per DRM device, of course. This is with the
uninteresting GPU debugs already excluded.

Still, I don't think the flight recorder buffer would need to be
massive. I suspect it would be enough to hold a few frames' worth which
is just a split second under active operation. When something happens,
the userspace stack is likely going to stop on its tracks immediately
to collect the debug information, which means the flooding should pause
and the relevant messages don't get overwritten before we get them. In
a multi-seat system where each device is controlled by a separate
display server instance, per-device logs would help with this. OTOH,
multi-seat is not a very common use case I suppose.


Thanks,
pq

[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 833 bytes --]

Re: [PATCH v10 08/10] dyndbg: add print-to-tracefs, selftest with it - RFC

[Simon Ser]

First off, let me reiterate that this feature would be invaluable as user-space
developers. It's often pretty difficult to figure out the cause of an EINVAL,
we have to ask users to follow complicated instructions [1] to grab DRM logs.
Then have to skim through several megabytes of logs to find the error.

I have a hack [2] which just calls system("sudo dmesg") after a failed atomic
commit, it's been pretty handy. But it's really just a hack, a proper solution
would be awesome.

[1]: https://gitlab.freedesktop.org/wlroots/wlroots/-/wikis/DRM-Debugging
[2]: https://gitlab.freedesktop.org/emersion/libliftoff/-/merge_requests/61

> > > > Having a subsystem specific trace buffer would allow subsystem specific
> > > > trace log permissions depending on the sensitivity of the data. But
> > > > doesn't drm output today go to the system log which is typically world
> > > > readable today?

dmesg isn't world-readable these days, it's been changed recently-ish (last
year?) at least on my distribution (Arch). I need root to grab dmesg.

(Maybe we can we just let the DRM master process grab the logs?)

> > > Yes, and that is exactly the problem. The DRM debug output is so high
> > > traffic it would make the system log both unusable due to cruft and
> > > slow down the whole machine. The debug output is only useful when
> > > something went wrong, and at that point it is too late to enable
> > > debugging. That's why a flight recorder with an over-written circular
> > > in-memory buffer is needed.
> >
> > Seans patch reuses enum drm_debug_category to split the tracing
> > stream into 10 sub-streams
> > - how much traffic from each ?
> > - are some sub-streams more valuable for post-mortem ?
> > - any value from further refinement of categories ?
> > - drop irrelevant callsites individually to reduce clutter, extend
> > buffer time/space ?
>
> I think it's hard to predict which sub-streams you are going to need
> before you have a bug to debug. Hence I would err on the side of
> enabling too much. This also means that better or more refined
> categorisation might not be that much of help - or if it is, then are
> the excluded debug messages worth having in the kernel to begin with.
> Well, we're probably not that interested in GPU debugs but just
> everything related to the KMS side, which on the existing categories
> is... everything except half of CORE and DRIVER, maybe? Not sure.

We've been recommending drm.debug=0x19F so far (see wiki linked above).
KMS + PRIME + ATOMIC + LEASE is definitely something we want in, and
CORE + DRIVER contains other useful info. We definitely don't want VBL.

> My feeling is that that could mean in the order of hundreds of log
> events at framerate (e.g. 60 times per second) per each enabled output
> individually. And per DRM device, of course. This is with the
> uninteresting GPU debugs already excluded.

Indeed, successful KMS atomic commits already generate a lot of noise. On my
machine, setting drm.debug=0x19F and running the following command:

    sudo dmesg -w | pv >/dev/null

I get 400KiB/s when idling, and 850KiB/s when wiggling the cursor.

> Still, I don't think the flight recorder buffer would need to be
> massive. I suspect it would be enough to hold a few frames' worth which
> is just a split second under active operation. When something happens,
> the userspace stack is likely going to stop on its tracks immediately
> to collect the debug information, which means the flooding should pause
> and the relevant messages don't get overwritten before we get them. In
> a multi-seat system where each device is controlled by a separate
> display server instance, per-device logs would help with this. OTOH,
> multi-seat is not a very common use case I suppose.

There's also the case of multi-GPU where GPU B's logs could clutter GPU A's,
making it harder to understand the cause of an atomic commit failure on GPU A.
So per-device logs would be useful, but not a hard requirement for me, having
*anything* at all would already be a big win.

In my experiments linked above [2], system("sudo dmesg") after atomic commit
failure worked pretty well, and the bottom of the log contained the cause of
the failure. It was pretty useful to system("sudo dmesg -C") before performing
an atomic commit, to be able to only collect the extract of the log relevant to
the atomic commit.

Having some kind of "marker" mechanism could be pretty cool. "Mark" the log
stream before performing an atomic commit (ideally that'd just return e.g. an
uint64 offset), then on failure request the logs collected after that mark.

Re: [PATCH v10 08/10] dyndbg: add print-to-tracefs, selftest with it - RFC

[Vincent Whitchurch]

On Fri, Nov 19, 2021 at 11:46:31PM +0100, jim.cromie@gmail.com wrote:
> Vincent's code has the macro magic to define that event, which IIUC
> is what  makes it controllable by ftrace, and therefore acceptable in
> principle to Steve.
> Would there be any reason to expand his set of 2 events into dev_dbg,
> pr_debug etc varieties ?
> (ie any value to separating dev, !dev ?, maybe so
> 
> Sean's code uses trace_array_printk primarily, which is EXPORTed,
> which is a virtue.
> 
> Vincents code does
> +/*
> + * This code is heavily based on __ftrace_trace_stack().
> + *
> + * Allow 4 levels of nesting: normal, softirq, irq, NMI.
> + */
> 
> to implement
> 
> +static void dynamic_trace(const char *fmt, va_list args)
> 
> Has this __ftrace_trace_stack() code been bundled into or hidden under
> a supported interface ?
> 
> would it look anything like trace_array_printk() ?
> 
> what problem is that code solving inside dynamic-debug.c ?

I'm not sure I fully understand all of your questions, but perhaps this
thread with Steven's reply to the first version of my patchset will
answer some of them:

 https://lore.kernel.org/lkml/20200723112644.7759f82f@oasis.local.home/

Re: [PATCH v10 08/10] dyndbg: add print-to-tracefs, selftest with it - RFC

[jim.cromie]

On Fri, Nov 12, 2021 at 4:49 AM Vincent Whitchurch
<vincent.whitchurch@axis.com> wrote:
>
> On Thu, Nov 11, 2021 at 03:02:04PM -0700, Jim Cromie wrote:
> > Dynamic-Debug can do 2nd exceedingly well:
> >
> > A- all work is behind jump-label's NOOP, zero off cost.
> > B- exact site selectivity, precisely the useful traffic.
> >    can tailor enabled set interactively, at shell.
> >
> > Since the tracefs interface is effective for drm (the threads suggest
> > so), adding that interface to dynamic-debug has real potential for
> > everyone including drm.
> >
> > Add a new +T flag to enable tracing, independent of +p, and add and

>
> I posted a patchset a while ago to do something very similar, but that
> got stalled for some reason and I unfortunately didn't follow it up:
>
>  https://lore.kernel.org/lkml/20200825153338.17061-1-vincent.whitchurch@axis.com/
>
> A key difference between that patchset and this patch (besides that
> small fact that I used +x instead of +T) was that my patchset allowed
> the dyndbg trace to be emitted to the main buffer and did not force them
> to be in an instance-specific buffer.
>
> That feature is quite important at least for my use case since I often
> use dyndbg combined with function tracing, and the latter doesn't work
> on non-main instances according to Documentation/trace/ftrace.rst.
>
> For example, here's a random example of a bootargs from one of my recent
> debugging sessions:
>
>  trace_event=printk:* ftrace_filter=_mmc*,mmc*,sd*,dw_mci*,mci*
>  ftrace=function trace_buf_size=20M dyndbg="file drivers/mmc/* +x"
>

Hi Vincent,

are you planning to dust this patchset off and resubmit it ?

Ive been playing with it and learning ftrace (decade+ late),
I found your boot-line example very helpful as 1st steps
(still havent even tried the filtering)


with these adjustments (voiced partly to test my understanding)
I would support it, and rework my patchset to use it.

- change flag to -e, good mnemonics for event/trace-event
   T is good too, but uppercase, no need to go there.

- include/trace/events/dyndbg.h - separate file, not mixed with print.h
  dyndbg class, so trace_event=dyndbg:*

- 1 event type per pr_debug, dev_dbg, netdev_dbg ? ibdev_dbg ?
  with the extra args: descriptor that Steven wanted,
  probably also struct <|net|ib>dev

If youre too busy for a while, I'd eventually take a (slow) run at it.

Re: [PATCH v10 08/10] dyndbg: add print-to-tracefs, selftest with it - RFC

[Vincent Whitchurch]

On Wed, Dec 08, 2021 at 06:16:10AM +0100, jim.cromie@gmail.com wrote:
> are you planning to dust this patchset off and resubmit it ?
> 
> Ive been playing with it and learning ftrace (decade+ late),
> I found your boot-line example very helpful as 1st steps
> (still havent even tried the filtering)
> 
> 
> with these adjustments (voiced partly to test my understanding)
> I would support it, and rework my patchset to use it.
> 
> - change flag to -e, good mnemonics for event/trace-event
>    T is good too, but uppercase, no need to go there.

Any flag name works for me.

> - include/trace/events/dyndbg.h - separate file, not mixed with print.h
>   dyndbg class, so trace_event=dyndbg:*
> 
> - 1 event type per pr_debug, dev_dbg, netdev_dbg ? ibdev_dbg ?
>   with the extra args: descriptor that Steven wanted,
>   probably also struct <|net|ib>dev

For my use cases I don't see much value in having separate events for
the different debug functions, but since all of them can be easily
enabled (dyndbg:*, as you noted), that works for me too.

> If youre too busy for a while, I'd eventually take a (slow) run at it.

You're welcome to have a go.  I think you've already rebased the
patchset, but here's a diff top of v5.16-rc4 for reference.  I noticed a
bug inside the CONFIG_JUMP_LABEL handling (also present in the last
version I posted) which should be fixed as part of the diff below (I've
added a comment).  Proper tests for this, like the ones you are adding
in your patchset, would certainly be a good idea.  Thanks.

8<-------------
diff --git a/Documentation/admin-guide/dynamic-debug-howto.rst b/Documentation/admin-guide/dynamic-debug-howto.rst
index a89cfa083155..b9c4e808befc 100644
--- a/Documentation/admin-guide/dynamic-debug-howto.rst
+++ b/Documentation/admin-guide/dynamic-debug-howto.rst
@@ -228,6 +228,7 @@ of the characters::
 The flags are::
 
   p    enables the pr_debug() callsite.
+  x    enables trace to the printk:dyndbg event
   f    Include the function name in the printed message
   l    Include line number in the printed message
   m    Include module name in the printed message
diff --git a/include/linux/dynamic_debug.h b/include/linux/dynamic_debug.h
index dce631e678dd..bc21bfb0fdc6 100644
--- a/include/linux/dynamic_debug.h
+++ b/include/linux/dynamic_debug.h
@@ -27,7 +27,7 @@ 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_PRINTK	(1<<0) /* printk() a message using the format */
 #define _DPRINTK_FLAGS_INCL_MODNAME	(1<<1)
 #define _DPRINTK_FLAGS_INCL_FUNCNAME	(1<<2)
 #define _DPRINTK_FLAGS_INCL_LINENO	(1<<3)
@@ -37,8 +37,11 @@ struct _ddebug {
 	(_DPRINTK_FLAGS_INCL_MODNAME | _DPRINTK_FLAGS_INCL_FUNCNAME |\
 	 _DPRINTK_FLAGS_INCL_LINENO  | _DPRINTK_FLAGS_INCL_TID)
 
+#define _DPRINTK_FLAGS_TRACE		(1<<5)
+#define _DPRINTK_FLAGS_ENABLE		(_DPRINTK_FLAGS_PRINTK | \
+					 _DPRINTK_FLAGS_TRACE)
 #if defined DEBUG
-#define _DPRINTK_FLAGS_DEFAULT _DPRINTK_FLAGS_PRINT
+#define _DPRINTK_FLAGS_DEFAULT _DPRINTK_FLAGS_PRINTK
 #else
 #define _DPRINTK_FLAGS_DEFAULT 0
 #endif
@@ -120,10 +123,10 @@ void __dynamic_ibdev_dbg(struct _ddebug *descriptor,
 
 #ifdef DEBUG
 #define DYNAMIC_DEBUG_BRANCH(descriptor) \
-	likely(descriptor.flags & _DPRINTK_FLAGS_PRINT)
+	likely(descriptor.flags & _DPRINTK_FLAGS_ENABLE)
 #else
 #define DYNAMIC_DEBUG_BRANCH(descriptor) \
-	unlikely(descriptor.flags & _DPRINTK_FLAGS_PRINT)
+	unlikely(descriptor.flags & _DPRINTK_FLAGS_ENABLE)
 #endif
 
 #endif /* CONFIG_JUMP_LABEL */
diff --git a/include/trace/events/printk.h b/include/trace/events/printk.h
index 13d405b2fd8b..1f78bd237a91 100644
--- a/include/trace/events/printk.h
+++ b/include/trace/events/printk.h
@@ -7,7 +7,7 @@
 
 #include <linux/tracepoint.h>
 
-TRACE_EVENT(console,
+DECLARE_EVENT_CLASS(printk,
 	TP_PROTO(const char *text, size_t len),
 
 	TP_ARGS(text, len),
@@ -31,6 +31,16 @@ TRACE_EVENT(console,
 
 	TP_printk("%s", __get_str(msg))
 );
+
+DEFINE_EVENT(printk, console,
+	TP_PROTO(const char *text, size_t len),
+	TP_ARGS(text, len)
+);
+
+DEFINE_EVENT(printk, dyndbg,
+	TP_PROTO(const char *text, size_t len),
+	TP_ARGS(text, len)
+);
 #endif /* _TRACE_PRINTK_H */
 
 /* This part must be outside protection */
diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
index dd7f56af9aed..161454fa0af8 100644
--- a/lib/dynamic_debug.c
+++ b/lib/dynamic_debug.c
@@ -36,6 +36,7 @@
 #include <linux/sched.h>
 #include <linux/device.h>
 #include <linux/netdevice.h>
+#include <trace/events/printk.h>
 
 #include <rdma/ib_verbs.h>
 
@@ -86,11 +87,12 @@ 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_PRINTK, 'p' },
 	{ _DPRINTK_FLAGS_INCL_MODNAME, 'm' },
 	{ _DPRINTK_FLAGS_INCL_FUNCNAME, 'f' },
 	{ _DPRINTK_FLAGS_INCL_LINENO, 'l' },
 	{ _DPRINTK_FLAGS_INCL_TID, 't' },
+	{ _DPRINTK_FLAGS_TRACE, 'x' },
 	{ _DPRINTK_FLAGS_NONE, '_' },
 };
 
@@ -210,11 +212,23 @@ static int ddebug_change(const struct ddebug_query *query,
 			if (newflags == dp->flags)
 				continue;
 #ifdef CONFIG_JUMP_LABEL
-			if (dp->flags & _DPRINTK_FLAGS_PRINT) {
-				if (!(modifiers->flags & _DPRINTK_FLAGS_PRINT))
+			if (dp->flags & _DPRINTK_FLAGS_ENABLE) {
+				/*
+				 * The newflags check is to ensure that the
+				 * static branch doesn't get disabled in step
+				 * 3:
+				 *
+				 * (1) +pf
+				 * (2) +x
+				 * (3) -pf
+				 */
+				if (!(modifiers->flags & _DPRINTK_FLAGS_ENABLE) &&
+				    !(newflags & _DPRINTK_FLAGS_ENABLE)) {
 					static_branch_disable(&dp->key.dd_key_true);
-			} else if (modifiers->flags & _DPRINTK_FLAGS_PRINT)
+				}
+			} else if (modifiers->flags & _DPRINTK_FLAGS_ENABLE) {
 				static_branch_enable(&dp->key.dd_key_true);
+			}
 #endif
 			dp->flags = newflags;
 			v4pr_info("changed %s:%d [%s]%s =%s\n",
@@ -621,6 +635,96 @@ static char *__dynamic_emit_prefix(const struct _ddebug *desc, char *buf)
 	return buf;
 }
 
+/*
+ * This code is heavily based on __ftrace_trace_stack().
+ *
+ * Allow 4 levels of nesting: normal, softirq, irq, NMI.
+ */
+#define DYNAMIC_TRACE_NESTING	4
+
+struct dynamic_trace_buf {
+	char buf[256];
+};
+
+struct dynamic_trace_bufs {
+	struct dynamic_trace_buf bufs[DYNAMIC_TRACE_NESTING];
+};
+
+static DEFINE_PER_CPU(struct dynamic_trace_bufs, dynamic_trace_bufs);
+static DEFINE_PER_CPU(int, dynamic_trace_reserve);
+
+static void dynamic_trace(const char *fmt, va_list args)
+{
+	struct dynamic_trace_buf *buf;
+	int bufidx;
+	int len;
+
+	preempt_disable_notrace();
+
+	bufidx = __this_cpu_inc_return(dynamic_trace_reserve) - 1;
+
+	if (WARN_ON_ONCE(bufidx > DYNAMIC_TRACE_NESTING))
+		goto out;
+
+	/* For the same reasons as in __ftrace_trace_stack(). */
+	barrier();
+
+	buf = this_cpu_ptr(dynamic_trace_bufs.bufs) + bufidx;
+
+	len = vscnprintf(buf->buf, sizeof(buf->buf), fmt, args);
+	trace_dyndbg(buf->buf, len);
+
+out:
+	/* As above. */
+	barrier();
+	__this_cpu_dec(dynamic_trace_reserve);
+	preempt_enable_notrace();
+}
+
+static void dynamic_printk(unsigned int flags, const char *fmt, ...)
+{
+	if (flags & _DPRINTK_FLAGS_TRACE) {
+		va_list args;
+
+		va_start(args, fmt);
+		/*
+		 * All callers include the KERN_DEBUG prefix to keep the
+		 * vprintk case simple; strip it out for tracing.
+		 */
+		dynamic_trace(fmt + strlen(KERN_DEBUG), args);
+		va_end(args);
+	}
+
+	if (flags & _DPRINTK_FLAGS_PRINTK) {
+		va_list args;
+
+		va_start(args, fmt);
+		vprintk(fmt, args);
+		va_end(args);
+	}
+}
+
+static void dynamic_dev_printk(unsigned int flags, const struct device *dev,
+			       const char *fmt, ...)
+{
+
+	if (flags & _DPRINTK_FLAGS_TRACE) {
+		va_list args;
+
+		va_start(args, fmt);
+		dynamic_trace(fmt, args);
+		va_end(args);
+	}
+
+	if (flags & _DPRINTK_FLAGS_PRINTK) {
+		va_list args;
+
+		va_start(args, fmt);
+		dev_vprintk_emit(LOGLEVEL_DEBUG, dev, fmt, args);
+		va_end(args);
+	}
+}
+
 static inline char *dynamic_emit_prefix(struct _ddebug *desc, char *buf)
 {
 	if (unlikely(desc->flags & _DPRINTK_FLAGS_INCL_ANY))
@@ -642,7 +746,8 @@ void __dynamic_pr_debug(struct _ddebug *descriptor, const char *fmt, ...)
 	vaf.fmt = fmt;
 	vaf.va = &args;
 
-	printk(KERN_DEBUG "%s%pV", dynamic_emit_prefix(descriptor, buf), &vaf);
+	dynamic_printk(descriptor->flags, KERN_DEBUG "%s%pV",
+		       dynamic_emit_prefix(descriptor, buf), &vaf);
 
 	va_end(args);
 }
@@ -652,6 +757,7 @@ void __dynamic_dev_dbg(struct _ddebug *descriptor,
 		      const struct device *dev, const char *fmt, ...)
 {
 	struct va_format vaf;
+	unsigned int flags;
 	va_list args;
 
 	BUG_ON(!descriptor);
@@ -661,16 +767,18 @@ void __dynamic_dev_dbg(struct _ddebug *descriptor,
 
 	vaf.fmt = fmt;
 	vaf.va = &args;
+	flags = descriptor->flags;
 
 	if (!dev) {
-		printk(KERN_DEBUG "(NULL device *): %pV", &vaf);
+		dynamic_printk(flags, KERN_DEBUG "(NULL device *): %pV",
+			      &vaf);
 	} else {
 		char buf[PREFIX_SIZE] = "";
 
-		dev_printk_emit(LOGLEVEL_DEBUG, dev, "%s%s %s: %pV",
-				dynamic_emit_prefix(descriptor, buf),
-				dev_driver_string(dev), dev_name(dev),
-				&vaf);
+		dynamic_dev_printk(flags, dev, "%s%s %s: %pV",
+				   dynamic_emit_prefix(descriptor, buf),
+				   dev_driver_string(dev), dev_name(dev),
+				   &vaf);
 	}
 
 	va_end(args);
@@ -683,6 +791,7 @@ void __dynamic_netdev_dbg(struct _ddebug *descriptor,
 			  const struct net_device *dev, const char *fmt, ...)
 {
 	struct va_format vaf;
+	unsigned int flags;
 	va_list args;
 
 	BUG_ON(!descriptor);
@@ -692,22 +801,24 @@ void __dynamic_netdev_dbg(struct _ddebug *descriptor,
 
 	vaf.fmt = fmt;
 	vaf.va = &args;
+	flags = descriptor->flags;
 
 	if (dev && dev->dev.parent) {
 		char buf[PREFIX_SIZE] = "";
 
-		dev_printk_emit(LOGLEVEL_DEBUG, dev->dev.parent,
-				"%s%s %s %s%s: %pV",
-				dynamic_emit_prefix(descriptor, buf),
-				dev_driver_string(dev->dev.parent),
-				dev_name(dev->dev.parent),
-				netdev_name(dev), netdev_reg_state(dev),
-				&vaf);
+		dynamic_dev_printk(flags, dev->dev.parent,
+				   "%s%s %s %s%s: %pV",
+				   dynamic_emit_prefix(descriptor, buf),
+				   dev_driver_string(dev->dev.parent),
+				   dev_name(dev->dev.parent),
+				   netdev_name(dev), netdev_reg_state(dev),
+				   &vaf);
 	} else if (dev) {
-		printk(KERN_DEBUG "%s%s: %pV", netdev_name(dev),
-		       netdev_reg_state(dev), &vaf);
+		dynamic_printk(flags, KERN_DEBUG "%s%s: %pV",
+			       netdev_name(dev), netdev_reg_state(dev), &vaf);
 	} else {
-		printk(KERN_DEBUG "(NULL net_device): %pV", &vaf);
+		dynamic_printk(flags, KERN_DEBUG "(NULL net_device): %pV",
+			       &vaf);
 	}
 
 	va_end(args);
@@ -722,27 +833,31 @@ void __dynamic_ibdev_dbg(struct _ddebug *descriptor,
 			 const struct ib_device *ibdev, const char *fmt, ...)
 {
 	struct va_format vaf;
+	unsigned int flags;
 	va_list args;
 
 	va_start(args, fmt);
 
 	vaf.fmt = fmt;
 	vaf.va = &args;
+	flags = descriptor->flags;
 
 	if (ibdev && ibdev->dev.parent) {
 		char buf[PREFIX_SIZE] = "";
 
-		dev_printk_emit(LOGLEVEL_DEBUG, ibdev->dev.parent,
-				"%s%s %s %s: %pV",
-				dynamic_emit_prefix(descriptor, buf),
-				dev_driver_string(ibdev->dev.parent),
-				dev_name(ibdev->dev.parent),
-				dev_name(&ibdev->dev),
-				&vaf);
+		dynamic_dev_printk(flags, ibdev->dev.parent,
+				   "%s%s %s %s: %pV",
+				   dynamic_emit_prefix(descriptor, buf),
+				   dev_driver_string(ibdev->dev.parent),
+				   dev_name(ibdev->dev.parent),
+				   dev_name(&ibdev->dev),
+				   &vaf);
 	} else if (ibdev) {
-		printk(KERN_DEBUG "%s: %pV", dev_name(&ibdev->dev), &vaf);
+		dynamic_printk(flags, KERN_DEBUG "%s: %pV",
+			       dev_name(&ibdev->dev), &vaf);
 	} else {
-		printk(KERN_DEBUG "(NULL ib_device): %pV", &vaf);
+		dynamic_printk(flags, KERN_DEBUG "(NULL ib_device): %pV",
+			       &vaf);
 	}
 
 	va_end(args);