2021-07-14 17:53:07

by Jim Cromie

[permalink] [raw]
Subject: [PATCH v3 0/5] drm: use dyndbg in drm_print

hi dri-devel,

Im pretty new in this particular playground.
Im using this to send, is it too spammy ? too --to ?
git send-email --dry-run \
--to-cmd='scripts/get_maintainer.pl --no-rolestats v3-000*.patch' \
[email protected] v3-000*.patch

drm_debug_enabled() is called a lot (by drm_dev_dbg) to do unlikely
bit-tests to selectively enable debug printing; this is a good job for
dynamic-debug, IFF it is built with JUMP_LABEL.

This patchset enables the use of dynamic-debug to avoid those
drm_debug_enabled() overheads, if CONFIG_DRM_USE_DYNAMIC_DEBUG=y.

v3: fixes missed SOB, && on BOL, commit-log tweaks
reordered patches, 1 is comment, 2 is whitespace.
dropped RFC, to see what happens.
v2: https://lore.kernel.org/lkml/[email protected]/
v1: https://lore.kernel.org/lkml/[email protected]/

Doing so creates many new pr_debug callsites,
otherwise i915 has ~120 prdbgs, and drm has just 1;

bash-5.1# modprobe i915
dyndbg: 8 debug prints in module video
dyndbg: 305 debug prints in module drm
dyndbg: 207 debug prints in module drm_kms_helper
dyndbg: 2 debug prints in module ttm
dyndbg: 1720 debug prints in module i915

On amdgpu, enabling it adds ~3200 prdbgs, currently at 56 bytes each.
So CONFIG_DRM_USE_DYNAMIC_DEBUG=y affects resource requirements.

Im running this patchset bare-metal on an i915 laptop & an amdgpu
desktop (both as loadable modules). I booted the amdgpu box with:

BOOT_IMAGE=(hd2,gpt2)/vmlinuz-5.13.0-dd7-13692-g8def25788f56 \
root=UUID=mumble ro \
rootflags=subvol=root00 rhgb \
dynamic_debug.verbose=3 main.dyndbg=+p \
amdgpu.debug=1 amdgpu.test=1 \
"amdgpu.dyndbg=format ^[ +p"

That last line enables ~1700 prdbg callsites with a format like '[DML'
etc at boot, and amdgpu.test=1 triggers 3 minutes of tests, causing
~76k prdbgs in 409 seconds, before I turned them off with:

echo module amdgpu -p > /proc/dynamic_debug/control

This is on top of master @ v5.14-rc1
Should I rebase onto something else ?

Jim Cromie (5):
drm/print: fixup spelling in a comment
drm_print.h: rewrap __DRM_DEFINE_DBG_RATELIMITED macro
drm/print: RFC add choice to use dynamic debug in drm-debug
drm/print: move conditional deref into macro defn
i915: map gvt pr_debug categories to bits in parameters/debug_gvt

Note: 3/5, 5/5 have bits that are here for POC, but belong in
dynamic_debug.c.


drivers/gpu/drm/Kconfig | 13 ++++
drivers/gpu/drm/drm_print.c | 75 +++++++++++++++++-
drivers/gpu/drm/i915/gvt/Makefile | 4 +
drivers/gpu/drm/i915/i915_params.c | 76 +++++++++++++++++++
include/drm/drm_print.h | 117 ++++++++++++++++++++---------
5 files changed, 247 insertions(+), 38 deletions(-)

--
2.31.1


2021-07-14 17:53:15

by Jim Cromie

[permalink] [raw]
Subject: [PATCH v3 1/5] drm/print: fixup spelling in a comment

s/prink/printk/ - no functional changes

Signed-off-by: Jim Cromie <[email protected]>
---
include/drm/drm_print.h | 2 +-
1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/include/drm/drm_print.h b/include/drm/drm_print.h
index 9b66be54dd16..15a089a87c22 100644
--- a/include/drm/drm_print.h
+++ b/include/drm/drm_print.h
@@ -327,7 +327,7 @@ static inline bool drm_debug_enabled(enum drm_debug_category category)
/*
* struct device based logging
*
- * Prefer drm_device based logging over device or prink based logging.
+ * Prefer drm_device based logging over device or printk based logging.
*/

__printf(3, 4)
--
2.31.1

2021-07-14 17:53:19

by Jim Cromie

[permalink] [raw]
Subject: [PATCH v3 2/5] drm_print.h: rewrap __DRM_DEFINE_DBG_RATELIMITED macro

whitespace only, to minimize the diff of a later commit.
no functional changes

Signed-off-by: Jim Cromie <[email protected]>
---
include/drm/drm_print.h | 20 ++++++++++++--------
1 file changed, 12 insertions(+), 8 deletions(-)

diff --git a/include/drm/drm_print.h b/include/drm/drm_print.h
index 15a089a87c22..ff5ac0e88321 100644
--- a/include/drm/drm_print.h
+++ b/include/drm/drm_print.h
@@ -524,19 +524,23 @@ void __drm_err(const char *format, ...);
#define DRM_DEBUG_DP(fmt, ...) \
__drm_dbg(DRM_UT_DP, fmt, ## __VA_ARGS__)

-#define __DRM_DEFINE_DBG_RATELIMITED(category, drm, fmt, ...) \
-({ \
- static DEFINE_RATELIMIT_STATE(rs_, DEFAULT_RATELIMIT_INTERVAL, DEFAULT_RATELIMIT_BURST);\
- 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__); \
+#define __DRM_DEFINE_DBG_RATELIMITED(category, drm, fmt, ...) \
+({ \
+ static DEFINE_RATELIMIT_STATE(rs_, \
+ DEFAULT_RATELIMIT_INTERVAL, \
+ DEFAULT_RATELIMIT_BURST); \
+ 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__); \
})

#define drm_dbg_kms_ratelimited(drm, fmt, ...) \
__DRM_DEFINE_DBG_RATELIMITED(KMS, drm, fmt, ## __VA_ARGS__)

-#define DRM_DEBUG_KMS_RATELIMITED(fmt, ...) drm_dbg_kms_ratelimited(NULL, fmt, ## __VA_ARGS__)
+#define DRM_DEBUG_KMS_RATELIMITED(fmt, ...) \
+ drm_dbg_kms_ratelimited(NULL, fmt, ## __VA_ARGS__)

/*
* struct drm_device based WARNs
--
2.31.1

2021-07-14 17:53:25

by Jim Cromie

[permalink] [raw]
Subject: [PATCH v3 3/5] drm/print: RFC add choice to use dynamic debug in drm-debug

drm's debug system uses distinct categories of debug messages, encoded
in an enum (DRM_UT_<CATEGORY>), which are mapped to bits in drm.debug.
drm_debug_enabled() does a lot of unlikely bit-mask checks on
drm.debug; we can use dynamic debug instead, and get all that
static_key/jump_label goodness.

Dynamic debug has no concept of category, but we can map the DRM_UT_*
to a set of distinct prefixes; "drm:core:", "drm:kms:" etc, and
prepend them to the given formats.

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

to enable every such "prefixed" pr_debug with one query. This new
prefix changes pr_debug's output, so is user visible, but it seems
unlikely to cause trouble for log watchers; they're not relying on the
absence of class prefix strings.

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

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

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

The indirection/switchover is layered into the macro scheme:

0. A new callback on drm.debug which calls dynamic_debug_exec_queries
to map those bits to specific query/commands
dynamic_debug_exec_queries("format ^drm:kms: +p", "drm*");
here for POC, this should be in dynamic_debug.c
with a MODULE_PARAM_DEBUG_BITMAP(__drm_debug, { "prefix-1", "desc-1" }+)

1. A "converted" or "classy" DRM_UT_* map

based on: DRM_UT_* ( symbol => bit-mask )
named it: cDRM_UT_* ( symbol => format-class-prefix-string )

So cDRM_UT_* is either:
legacy: cDRM_UT_* <-- DRM_UT_* ( !CONFIG_DRM_USE_DYNAMIC_DEBUG )
enabled:
#define cDRM_UT_KMS "drm:kms: "
#define cDRM_UT_PRIME "drm:prime: "
#define cDRM_UT_ATOMIC "drm:atomic: "

DRM_UT_* are unchanged, since theyre used in drm_debug_enabled()
and elsewhere.

2. drm_dev_dbg & drm_debug are renamed (prefixed with '_')

old names are now macros, calling either:
legacy: -> to renamed fn
enabled: -> dev_dbg & pr_debug, with cDRM-prefix # format.

these names are used in a fat layer of macros (3) which supply the
category; those macros are used throughout drm code, yielding the
~2100 new prdbgs reported above.

3. names in (2) are invoked by DRM_DEBUG_<Category>, drm_dbg_<Category>.

all these macros get "converted" to use cDRM_UT_*
to get right token type for both !/!! DRM_USE_DYNAMIC_DEBUG

4. simplification of __DRM_DEFINE_DBG_RATELIMITED macro

remove DRM_UT_ ## KMS as extra indirection
pass both DRM_UT & cDRM_UT, for drm_debug_enabled & drm_dev_dbg

Signed-off-by: Jim Cromie <[email protected]>
---
drivers/gpu/drm/Kconfig | 13 +++++
drivers/gpu/drm/drm_print.c | 75 ++++++++++++++++++++++++--
include/drm/drm_print.h | 102 ++++++++++++++++++++++++++----------
3 files changed, 158 insertions(+), 32 deletions(-)

diff --git a/drivers/gpu/drm/Kconfig b/drivers/gpu/drm/Kconfig
index 7ff89690a976..e4524ccba040 100644
--- a/drivers/gpu/drm/Kconfig
+++ b/drivers/gpu/drm/Kconfig
@@ -57,6 +57,19 @@ config DRM_DEBUG_MM

If in doubt, say "N".

+config DRM_USE_DYNAMIC_DEBUG
+ bool "use dynamic debug to implement drm.debug"
+ default n
+ depends on DRM
+ depends on DYNAMIC_DEBUG || DYNAMIC_DEBUG_CORE
+ depends on JUMP_LABEL
+ help
+ The drm debug category facility does a lot of unlikely bit-field
+ tests at runtime; while cheap individually, the cost accumulates.
+ This option uses dynamic debug facility (if configured and
+ using jump_label) to avoid those runtime checks, patching
+ the kernel when those debugs are desired.
+
config DRM_DEBUG_SELFTEST
tristate "kselftests for DRM"
depends on DRM
diff --git a/drivers/gpu/drm/drm_print.c b/drivers/gpu/drm/drm_print.c
index 111b932cf2a9..e2acdfc7088b 100644
--- a/drivers/gpu/drm/drm_print.c
+++ b/drivers/gpu/drm/drm_print.c
@@ -52,8 +52,75 @@ MODULE_PARM_DESC(debug, "Enable debug output, where each bit enables a debug cat
"\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)");
+
+#ifndef CONFIG_DRM_USE_DYNAMIC_DEBUG
module_param_named(debug, __drm_debug, int, 0600);

+#else
+static char *format_class_prefixes[] = {
+ cDRM_UT_CORE,
+ cDRM_UT_DRIVER,
+ cDRM_UT_KMS,
+ cDRM_UT_PRIME,
+ cDRM_UT_ATOMIC,
+ cDRM_UT_VBL,
+ cDRM_UT_STATE,
+ cDRM_UT_LEASE,
+ cDRM_UT_DP,
+ cDRM_UT_DRMRES
+};
+
+#define OUR_QUERY_SIZE 64 /* > strlen "format '^%s' %cp" + longest prefix */
+
+static int param_set_dyndbg(const char *instr, const struct kernel_param *kp)
+{
+ unsigned int val;
+ unsigned long changes, result;
+ int rc, chgct = 0, totct = 0, bitpos;
+ char query[OUR_QUERY_SIZE];
+
+ rc = kstrtouint(instr, 0, &val);
+ if (rc) {
+ pr_err("%s: failed\n", __func__);
+ return -EINVAL;
+ }
+ result = val;
+ changes = result ^ __drm_debug;
+
+ pr_debug("changes:0x%lx from result:0x%lx\n", changes, result);
+
+ for_each_set_bit(bitpos, &changes, ARRAY_SIZE(format_class_prefixes)) {
+
+ sprintf(query, "format '^%s' %cp", format_class_prefixes[bitpos],
+ test_bit(bitpos, &result) ? '+' : '-');
+
+ chgct = dynamic_debug_exec_queries(query, "drm*");
+ if (chgct < 0) {
+ pr_err("%s: exec err:%d on: %s\n", __func__, chgct, query);
+ continue;
+ }
+ pr_debug("change ct:%d on %s\n", chgct, query);
+ totct += chgct;
+ }
+ pr_debug("total changes: %d\n", totct);
+ __drm_debug = result;
+ return 0;
+}
+
+static int param_get_dyndbg(char *buffer, const struct kernel_param *kp)
+{
+ pr_debug("debug-val:0x%x %u\n", __drm_debug, *((unsigned int *)kp->arg));
+ return scnprintf(buffer, PAGE_SIZE, "%u\n",
+ *((unsigned int *)kp->arg));
+}
+static const struct kernel_param_ops param_ops_debug = {
+ .set = param_set_dyndbg,
+ .get = param_get_dyndbg,
+};
+module_param_cb(debug, &param_ops_debug, &__drm_debug, 0644);
+
+#endif /* CONFIG_DRM_USE_DYNAMIC_DEBUG */
+
void __drm_puts_coredump(struct drm_printer *p, const char *str)
{
struct drm_print_iterator *iterator = p->arg;
@@ -256,7 +323,7 @@ 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,
+void _drm_dev_dbg(const struct device *dev, enum drm_debug_category category,
const char *format, ...)
{
struct va_format vaf;
@@ -278,9 +345,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 +364,7 @@ void __drm_dbg(enum drm_debug_category category, const char *format, ...)

va_end(args);
}
-EXPORT_SYMBOL(__drm_dbg);
+EXPORT_SYMBOL(___drm_dbg);

void __drm_err(const char *format, ...)
{
diff --git a/include/drm/drm_print.h b/include/drm/drm_print.h
index ff5ac0e88321..499fa0b35200 100644
--- a/include/drm/drm_print.h
+++ b/include/drm/drm_print.h
@@ -319,6 +319,51 @@ enum drm_debug_category {
DRM_UT_DRMRES = 0x200,
};

+#if !defined(CONFIG_DRM_USE_DYNAMIC_DEBUG)
+
+/* Use legacy drm-debug functions, and drm_debug_enabled().
+ * For cDRM_UT_* (converted category), identity map to DRM_UT_*
+ */
+#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 cDRM_UT_CORE DRM_UT_CORE
+#define cDRM_UT_DRIVER DRM_UT_DRIVER
+#define cDRM_UT_KMS DRM_UT_KMS
+#define cDRM_UT_PRIME DRM_UT_PRIME
+#define cDRM_UT_ATOMIC DRM_UT_ATOMIC
+#define cDRM_UT_VBL DRM_UT_VBL
+#define cDRM_UT_STATE DRM_UT_STATE
+#define cDRM_UT_LEASE DRM_UT_LEASE
+#define cDRM_UT_DP DRM_UT_DP
+#define cDRM_UT_DRMRES DRM_UT_DRMRES
+
+#else /* !CONFIG_DRM_USE_DYNAMIC_DEBUG */
+
+/* use dynamic_debug to avoid drm_debug_enabled().
+ * dyndbg has no category, so we prefix the format with a "class"
+ * string; cDRM_UT_* maps to those class strings
+ */
+#define __drm_dbg(cls, fmt, ...) \
+ pr_debug(cls # fmt, ##__VA_ARGS__)
+#define drm_dev_dbg(dev, cls, fmt, ...) \
+ dev_dbg(dev, cls # fmt, ##__VA_ARGS__)
+
+#define cDRM_UT_CORE "drm:core: "
+#define cDRM_UT_DRIVER "drm:drvr: "
+#define cDRM_UT_KMS "drm:kms: "
+#define cDRM_UT_PRIME "drm:prime: "
+#define cDRM_UT_ATOMIC "drm:atomic: "
+#define cDRM_UT_VBL "drm:vbl: "
+#define cDRM_UT_STATE "drm:state: "
+#define cDRM_UT_LEASE "drm:lease: "
+#define cDRM_UT_DP "drm:dp: "
+#define cDRM_UT_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,7 +379,7 @@ __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,
+void _drm_dev_dbg(const struct device *dev, enum drm_debug_category category,
const char *format, ...);

/**
@@ -383,7 +428,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, cDRM_UT_CORE, fmt, ##__VA_ARGS__)
/**
* DRM_DEV_DEBUG_DRIVER() - Debug output for vendor specific part of the driver
*
@@ -391,7 +436,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, cDRM_UT_DRIVER, fmt, ##__VA_ARGS__)
/**
* DRM_DEV_DEBUG_KMS() - Debug output for modesetting code
*
@@ -399,7 +444,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, cDRM_UT_KMS, fmt, ##__VA_ARGS__)

/*
* struct drm_device based logging
@@ -443,25 +488,25 @@ void drm_dev_dbg(const struct device *dev, enum drm_debug_category category,


#define drm_dbg_core(drm, fmt, ...) \
- drm_dev_dbg((drm) ? (drm)->dev : NULL, DRM_UT_CORE, fmt, ##__VA_ARGS__)
+ drm_dev_dbg((drm) ? (drm)->dev : NULL, cDRM_UT_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, cDRM_UT_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, cDRM_UT_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, cDRM_UT_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, cDRM_UT_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, cDRM_UT_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, cDRM_UT_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, cDRM_UT_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, cDRM_UT_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, cDRM_UT_DRMRES, fmt, ##__VA_ARGS__)


/*
@@ -471,7 +516,7 @@ void drm_dev_dbg(const struct device *dev, enum drm_debug_category category,
*/

__printf(2, 3)
-void __drm_dbg(enum drm_debug_category category, const char *format, ...);
+void ___drm_dbg(enum drm_debug_category category, const char *format, ...);
__printf(1, 2)
void __drm_err(const char *format, ...);

@@ -500,44 +545,45 @@ void __drm_err(const char *format, ...);
#define DRM_ERROR_RATELIMITED(fmt, ...) \
DRM_DEV_ERROR_RATELIMITED(NULL, fmt, ##__VA_ARGS__)

+
#define DRM_DEBUG(fmt, ...) \
- __drm_dbg(DRM_UT_CORE, fmt, ##__VA_ARGS__)
+ __drm_dbg(cDRM_UT_CORE, fmt, ##__VA_ARGS__)

#define DRM_DEBUG_DRIVER(fmt, ...) \
- __drm_dbg(DRM_UT_DRIVER, fmt, ##__VA_ARGS__)
+ __drm_dbg(cDRM_UT_DRIVER, fmt, ##__VA_ARGS__)

#define DRM_DEBUG_KMS(fmt, ...) \
- __drm_dbg(DRM_UT_KMS, fmt, ##__VA_ARGS__)
+ __drm_dbg(cDRM_UT_KMS, fmt, ##__VA_ARGS__)

#define DRM_DEBUG_PRIME(fmt, ...) \
- __drm_dbg(DRM_UT_PRIME, fmt, ##__VA_ARGS__)
+ __drm_dbg(cDRM_UT_PRIME, fmt, ##__VA_ARGS__)

#define DRM_DEBUG_ATOMIC(fmt, ...) \
- __drm_dbg(DRM_UT_ATOMIC, fmt, ##__VA_ARGS__)
+ __drm_dbg(cDRM_UT_ATOMIC, fmt, ##__VA_ARGS__)

#define DRM_DEBUG_VBL(fmt, ...) \
- __drm_dbg(DRM_UT_VBL, fmt, ##__VA_ARGS__)
+ __drm_dbg(cDRM_UT_VBL, fmt, ##__VA_ARGS__)

#define DRM_DEBUG_LEASE(fmt, ...) \
- __drm_dbg(DRM_UT_LEASE, fmt, ##__VA_ARGS__)
+ __drm_dbg(cDRM_UT_LEASE, fmt, ##__VA_ARGS__)

#define DRM_DEBUG_DP(fmt, ...) \
- __drm_dbg(DRM_UT_DP, fmt, ## __VA_ARGS__)
+ __drm_dbg(cDRM_UT_DP, fmt, ## __VA_ARGS__)

-#define __DRM_DEFINE_DBG_RATELIMITED(category, drm, fmt, ...) \
+#define __DRM_DEFINE_DBG_RATELIMITED(DRM_UT, cDRM_UT, drm, fmt, ...) \
({ \
static DEFINE_RATELIMIT_STATE(rs_, \
DEFAULT_RATELIMIT_INTERVAL, \
DEFAULT_RATELIMIT_BURST); \
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__); \
+ if (drm_debug_enabled(DRM_UT) && __ratelimit(&rs_)) \
+ drm_dev_dbg((drm_) ? (drm_)->dev : NULL, \
+ cDRM_UT, fmt, ##__VA_ARGS__); \
})

#define drm_dbg_kms_ratelimited(drm, fmt, ...) \
- __DRM_DEFINE_DBG_RATELIMITED(KMS, drm, fmt, ## __VA_ARGS__)
+ __DRM_DEFINE_DBG_RATELIMITED(DRM_UT_KMS, cDRM_UT_KMS, drm, fmt, ## __VA_ARGS__)

#define DRM_DEBUG_KMS_RATELIMITED(fmt, ...) \
drm_dbg_kms_ratelimited(NULL, fmt, ## __VA_ARGS__)
--
2.31.1

2021-07-14 17:53:49

by Jim Cromie

[permalink] [raw]
Subject: [PATCH v3 4/5] drm/print: move conditional deref into macro defn

commit 7911902129a8 ("drm/print: Handle potentially NULL drm_devices
in drm_dbg_*") added a maybe(deref) to 6 macro invocations of
drm_dev_dbg().

Commit 01ff672190bd("drm: RFC add choice to use dynamic debug in
drm-debug") then renamed that fn to _drm_dev_dbg(), and redefined
drm_dev_dbg() as a macro.

That new macro can do the maybe(deref), so the ~9 callers dont have to.

no functional changes. small word-count reduction.

Signed-off-by: Jim Cromie <[email protected]>
---
include/drm/drm_print.h | 27 +++++++++++++--------------
1 file changed, 13 insertions(+), 14 deletions(-)

diff --git a/include/drm/drm_print.h b/include/drm/drm_print.h
index 499fa0b35200..573b513e7836 100644
--- a/include/drm/drm_print.h
+++ b/include/drm/drm_print.h
@@ -326,8 +326,8 @@ enum drm_debug_category {
*/
#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_dev_dbg(drm, cls, fmt, ...) \
+ _drm_dev_dbg((drm) ? (drm)->dev : NULL, cls, fmt, ##__VA_ARGS__)

#define cDRM_UT_CORE DRM_UT_CORE
#define cDRM_UT_DRIVER DRM_UT_DRIVER
@@ -488,25 +488,25 @@ void _drm_dev_dbg(const struct device *dev, enum drm_debug_category category,


#define drm_dbg_core(drm, fmt, ...) \
- drm_dev_dbg((drm) ? (drm)->dev : NULL, cDRM_UT_CORE, fmt, ##__VA_ARGS__)
+ drm_dev_dbg(drm, cDRM_UT_CORE, fmt, ##__VA_ARGS__)
#define drm_dbg(drm, fmt, ...) \
- drm_dev_dbg((drm) ? (drm)->dev : NULL, cDRM_UT_DRIVER, fmt, ##__VA_ARGS__)
+ drm_dev_dbg(drm, cDRM_UT_DRIVER, fmt, ##__VA_ARGS__)
#define drm_dbg_kms(drm, fmt, ...) \
- drm_dev_dbg((drm) ? (drm)->dev : NULL, cDRM_UT_KMS, fmt, ##__VA_ARGS__)
+ drm_dev_dbg(drm, cDRM_UT_KMS, fmt, ##__VA_ARGS__)
#define drm_dbg_prime(drm, fmt, ...) \
- drm_dev_dbg((drm) ? (drm)->dev : NULL, cDRM_UT_PRIME, fmt, ##__VA_ARGS__)
+ drm_dev_dbg(drm, cDRM_UT_PRIME, fmt, ##__VA_ARGS__)
#define drm_dbg_atomic(drm, fmt, ...) \
- drm_dev_dbg((drm) ? (drm)->dev : NULL, cDRM_UT_ATOMIC, fmt, ##__VA_ARGS__)
+ drm_dev_dbg(drm, cDRM_UT_ATOMIC, fmt, ##__VA_ARGS__)
#define drm_dbg_vbl(drm, fmt, ...) \
- drm_dev_dbg((drm) ? (drm)->dev : NULL, cDRM_UT_VBL, fmt, ##__VA_ARGS__)
+ drm_dev_dbg(drm, cDRM_UT_VBL, fmt, ##__VA_ARGS__)
#define drm_dbg_state(drm, fmt, ...) \
- drm_dev_dbg((drm) ? (drm)->dev : NULL, cDRM_UT_STATE, fmt, ##__VA_ARGS__)
+ drm_dev_dbg(drm, cDRM_UT_STATE, fmt, ##__VA_ARGS__)
#define drm_dbg_lease(drm, fmt, ...) \
- drm_dev_dbg((drm) ? (drm)->dev : NULL, cDRM_UT_LEASE, fmt, ##__VA_ARGS__)
+ drm_dev_dbg(drm, cDRM_UT_LEASE, fmt, ##__VA_ARGS__)
#define drm_dbg_dp(drm, fmt, ...) \
- drm_dev_dbg((drm) ? (drm)->dev : NULL, cDRM_UT_DP, fmt, ##__VA_ARGS__)
+ drm_dev_dbg(drm, cDRM_UT_DP, fmt, ##__VA_ARGS__)
#define drm_dbg_drmres(drm, fmt, ...) \
- drm_dev_dbg((drm) ? (drm)->dev : NULL, cDRM_UT_DRMRES, fmt, ##__VA_ARGS__)
+ drm_dev_dbg(drm, cDRM_UT_DRMRES, fmt, ##__VA_ARGS__)


/*
@@ -578,8 +578,7 @@ void __drm_err(const char *format, ...);
const struct drm_device *drm_ = (drm); \
\
if (drm_debug_enabled(DRM_UT) && __ratelimit(&rs_)) \
- drm_dev_dbg((drm_) ? (drm_)->dev : NULL, \
- cDRM_UT, fmt, ##__VA_ARGS__); \
+ drm_dev_dbg(drm_, cDRM_UT, fmt, ##__VA_ARGS__); \
})

#define drm_dbg_kms_ratelimited(drm, fmt, ...) \
--
2.31.1

2021-07-14 17:54:23

by Jim Cromie

[permalink] [raw]
Subject: [PATCH v3 5/5] i915: map gvt pr_debug categories to bits in parameters/debug_gvt

The gvt component of this driver has ~120 pr_debugs, in 9 "classes".
Following the interface model of drm.debug, add a parameter to map
bits to these classes.

If CONFIG_DRM_USE_DYNAMIC_DEBUG=y (and CONFIG_DYNAMIC_DEBUG_CORE), add
-DDYNAMIC_DEBUG_MODULE into Makefile. TBD: maybe add a separate
CONFIG_I915_USE_DYNAMIC_DEBUG to more fully optionalize this.

In i915_params.c, add callback to map bits to queries.

TBD: the callback code should probably be moved to lib/dynamic_debug,
and given a declarative interface, with implied bit-numbering,
something like:

MOD_PARM_BITMAP_DESC(__gvt_debug,
"gvt: cmd: ", "command processing"
"gvt: core: ", "core help",
"gvt: dpy: ", "display help",
"gvt: el: ", "help",
"gvt: irq: ", "help",
"gvt: mm: ", "help",
"gvt: mmio: ", "help",
"gvt: render: ", "help",
"gvt: sched: " "help");

Signed-off-by: Jim Cromie <[email protected]>
---
drivers/gpu/drm/i915/gvt/Makefile | 4 ++
drivers/gpu/drm/i915/i915_params.c | 76 ++++++++++++++++++++++++++++++
2 files changed, 80 insertions(+)

diff --git a/drivers/gpu/drm/i915/gvt/Makefile b/drivers/gpu/drm/i915/gvt/Makefile
index ea8324abc784..846ba73b8de6 100644
--- a/drivers/gpu/drm/i915/gvt/Makefile
+++ b/drivers/gpu/drm/i915/gvt/Makefile
@@ -7,3 +7,7 @@ GVT_SOURCE := gvt.o aperture_gm.o handlers.o vgpu.o trace_points.o firmware.o \

ccflags-y += -I $(srctree)/$(src) -I $(srctree)/$(src)/$(GVT_DIR)/
i915-y += $(addprefix $(GVT_DIR)/, $(GVT_SOURCE))
+
+#ifdef CONFIG_DRM_USE_DYNAMIC_DEBUG
+ccflags-y += -DDYNAMIC_DEBUG_MODULE
+#endif
diff --git a/drivers/gpu/drm/i915/i915_params.c b/drivers/gpu/drm/i915/i915_params.c
index e07f4cfea63a..e0d13aff5274 100644
--- a/drivers/gpu/drm/i915/i915_params.c
+++ b/drivers/gpu/drm/i915/i915_params.c
@@ -265,3 +265,79 @@ void i915_params_free(struct i915_params *params)
I915_PARAMS_FOR_EACH(FREE);
#undef FREE
}
+
+/* POC for callback -> dynamic_debug_exec_queries */
+unsigned long __gvt_debug;
+EXPORT_SYMBOL(__gvt_debug);
+
+static char *format_prefix_classes[] = {
+ "gvt: cmd: ",
+ "gvt: core: ",
+ "gvt: dpy: ",
+ "gvt: el: ",
+ "gvt: irq: ",
+ "gvt: mm: ",
+ "gvt: mmio: ",
+ "gvt: render: ",
+ "gvt: sched: "
+};
+#define NUM_CLASSES ARRAY_SIZE(format_prefix_classes)
+#define OUR_QUERY_SIZE 128 /* we need about 20 */
+
+#include <linux/module.h>
+
+static int param_set_dyndbg(const char *instr, const struct kernel_param *kp)
+{
+ unsigned int val;
+ unsigned long changes, result;
+ int rc, chgct = 0, totct = 0, bitpos;
+ char query[OUR_QUERY_SIZE];
+
+ rc = kstrtouint(instr, 0, &val);
+ if (rc) {
+ pr_err("set_dyndbg: failed\n");
+ return -EINVAL;
+ }
+ result = val;
+ pr_info("set_dyndbg: result:0x%lx from %s\n", result, instr);
+
+ changes = result ^ __gvt_debug;
+
+ for_each_set_bit(bitpos, &changes, NUM_CLASSES) {
+
+ sprintf(query, "format '^%s' %cp", format_prefix_classes[bitpos],
+ test_bit(bitpos, &result) ? '+' : '-');
+
+ chgct = dynamic_debug_exec_queries(query, "i915");
+
+ pr_info("%d changes on: %s\n", chgct, query);
+ totct += chgct;
+ }
+ pr_info("total changes: %d\n", totct);
+ __gvt_debug = result;
+ return 0;
+}
+static int param_get_dyndbg(char *buffer, const struct kernel_param *kp)
+{
+ return scnprintf(buffer, PAGE_SIZE, "%u\n",
+ *((unsigned int *)kp->arg));
+}
+static const struct kernel_param_ops param_ops_dyndbg = {
+ .set = param_set_dyndbg,
+ .get = param_get_dyndbg,
+};
+
+#define info_ln(hexi, prefix) "\n\t0x" __stringify(hexi) "\t" prefix
+
+MODULE_PARM_DESC(debug_gvt, " gvt debug categories:"
+ info_ln(1, "gvt: cmd:")
+ info_ln(2, "gvt: core:")
+ info_ln(4, "gvt: dpy:")
+ info_ln(8, "gvt: el:")
+ info_ln(10, "gvt: irq:")
+ info_ln(20, "gvt: mm:")
+ info_ln(40, "gvt: mmio:")
+ info_ln(80, "gvt: render:")
+ info_ln(100, "gvt: sched:"));
+
+module_param_cb(debug_gvt, &param_ops_dyndbg, &__gvt_debug, 0644);
--
2.31.1

2021-07-20 13:10:26

by Daniel Vetter

[permalink] [raw]
Subject: Re: [PATCH v3 1/5] drm/print: fixup spelling in a comment

On Wed, Jul 14, 2021 at 11:51:34AM -0600, Jim Cromie wrote:
> s/prink/printk/ - no functional changes
>
> Signed-off-by: Jim Cromie <[email protected]>

Applied to drm-misc-next, thanks for your patch.
-Daniel

> ---
> include/drm/drm_print.h | 2 +-
> 1 file changed, 1 insertion(+), 1 deletion(-)
>
> diff --git a/include/drm/drm_print.h b/include/drm/drm_print.h
> index 9b66be54dd16..15a089a87c22 100644
> --- a/include/drm/drm_print.h
> +++ b/include/drm/drm_print.h
> @@ -327,7 +327,7 @@ static inline bool drm_debug_enabled(enum drm_debug_category category)
> /*
> * struct device based logging
> *
> - * Prefer drm_device based logging over device or prink based logging.
> + * Prefer drm_device based logging over device or printk based logging.
> */
>
> __printf(3, 4)
> --
> 2.31.1
>

--
Daniel Vetter
Software Engineer, Intel Corporation
http://blog.ffwll.ch

2021-07-20 13:37:53

by Daniel Vetter

[permalink] [raw]
Subject: Re: [PATCH v3 3/5] drm/print: RFC add choice to use dynamic debug in drm-debug

On Wed, Jul 14, 2021 at 11:51:36AM -0600, Jim Cromie wrote:
> drm's debug system uses distinct categories of debug messages, encoded
> in an enum (DRM_UT_<CATEGORY>), which are mapped to bits in drm.debug.
> drm_debug_enabled() does a lot of unlikely bit-mask checks on
> drm.debug; we can use dynamic debug instead, and get all that
> static_key/jump_label goodness.
>
> Dynamic debug has no concept of category, but we can map the DRM_UT_*
> to a set of distinct prefixes; "drm:core:", "drm:kms:" etc, and
> prepend them to the given formats.
>
> Then we can use:
> `echo module drm format ^drm:core: +p > control`
>
> to enable every such "prefixed" pr_debug with one query. This new
> prefix changes pr_debug's output, so is user visible, but it seems
> unlikely to cause trouble for log watchers; they're not relying on the
> absence of class prefix strings.
>
> This conversion yields ~2100 new callsites on my i7/i915 laptop:
>
> dyndbg: 195 debug prints in module drm_kms_helper
> dyndbg: 298 debug prints in module drm
> dyndbg: 1630 debug prints in module i915
>
> CONFIG_DRM_USE_DYNAMIC_DEBUG enables this, and is available if
> CONFIG_DYNAMIC_DEBUG or CONFIG_DYNAMIC_DEBUG_CORE is chosen, and if
> CONFIG_JUMP_LABEL is enabled; this because its required to get the
> promised optimizations.
>
> The indirection/switchover is layered into the macro scheme:
>
> 0. A new callback on drm.debug which calls dynamic_debug_exec_queries
> to map those bits to specific query/commands
> dynamic_debug_exec_queries("format ^drm:kms: +p", "drm*");
> here for POC, this should be in dynamic_debug.c
> with a MODULE_PARAM_DEBUG_BITMAP(__drm_debug, { "prefix-1", "desc-1" }+)

This is really awesome. For merging I think we need to discuss with dyn
debug folks whether they're all ok with this, but it's exported already
should should be fine.

>
> 1. A "converted" or "classy" DRM_UT_* map
>
> based on: DRM_UT_* ( symbol => bit-mask )
> named it: cDRM_UT_* ( symbol => format-class-prefix-string )
>
> So cDRM_UT_* is either:
> legacy: cDRM_UT_* <-- DRM_UT_* ( !CONFIG_DRM_USE_DYNAMIC_DEBUG )
> enabled:
> #define cDRM_UT_KMS "drm:kms: "
> #define cDRM_UT_PRIME "drm:prime: "
> #define cDRM_UT_ATOMIC "drm:atomic: "

the cDRM looks a bit funny, plus I don't eve have an idea what _UT_ means
(and git history isn't helpful either). What about just using
DRM_DBG_CLASS_ as the prefix here for these indirection macros, i.e.
DRM_DBG_CLASS_KMS.

Also would be really nice if we could make these a table or something, but
I guess with the macro magic that's not possible.

>
> DRM_UT_* are unchanged, since theyre used in drm_debug_enabled()
> and elsewhere.

I think for the production version of these we need to retire/deprecate
them, at least for drm core. Otherwise you have an annoying mismatch
between drm.debug module option and dyn debug.

>
> 2. drm_dev_dbg & drm_debug are renamed (prefixed with '_')
>
> old names are now macros, calling either:
> legacy: -> to renamed fn
> enabled: -> dev_dbg & pr_debug, with cDRM-prefix # format.
>
> these names are used in a fat layer of macros (3) which supply the
> category; those macros are used throughout drm code, yielding the
> ~2100 new prdbgs reported above.
>
> 3. names in (2) are invoked by DRM_DEBUG_<Category>, drm_dbg_<Category>.
>
> all these macros get "converted" to use cDRM_UT_*
> to get right token type for both !/!! DRM_USE_DYNAMIC_DEBUG
>
> 4. simplification of __DRM_DEFINE_DBG_RATELIMITED macro
>
> remove DRM_UT_ ## KMS as extra indirection
> pass both DRM_UT & cDRM_UT, for drm_debug_enabled & drm_dev_dbg

For merging, can we pull out the renames and reorgs from this patch, and
then maybe also the reorder the next patch in your series here to be
before the dyn debug stuff?

> Signed-off-by: Jim Cromie <[email protected]>
> ---
> drivers/gpu/drm/Kconfig | 13 +++++
> drivers/gpu/drm/drm_print.c | 75 ++++++++++++++++++++++++--
> include/drm/drm_print.h | 102 ++++++++++++++++++++++++++----------
> 3 files changed, 158 insertions(+), 32 deletions(-)

I really like this, I think you can drop the RFC. A few more things that I
think we need:

- An overview kerneldoc section which explains the interfaces and how it
all works together. Essentially your commit message with some light
markup to make it look good.

- I think it would be really good to review the driver docs for all this
and make sure it's complete. Some of the interface functions aren't
documented yet (or maybe the ones that drivers shouldn't used need more
__ prefixes to denote them as internal, dunno).

- I guess deprecation notice for drm_debug_enabled() and all that, so that
we have a consistent interface. Doing the conversion will probably
highlight the need for a bit more infrastructure and tooling, e.g. the
bigger dump functions (like edid hex dump, or also the various decode
helpers we have for dp, hdmi infoframes and all that) ideally have a
single dyn_debug label to enable all of them instead of line-by-line.
Tbh no idea how this should work, might need dyndbg work too.

- For the driver side of this we probably want a
Documentation/gpu/TODO.rst entry if it's not all easy to convert
directly.

>
> diff --git a/drivers/gpu/drm/Kconfig b/drivers/gpu/drm/Kconfig
> index 7ff89690a976..e4524ccba040 100644
> --- a/drivers/gpu/drm/Kconfig
> +++ b/drivers/gpu/drm/Kconfig
> @@ -57,6 +57,19 @@ config DRM_DEBUG_MM
>
> If in doubt, say "N".
>
> +config DRM_USE_DYNAMIC_DEBUG
> + bool "use dynamic debug to implement drm.debug"
> + default n
> + depends on DRM
> + depends on DYNAMIC_DEBUG || DYNAMIC_DEBUG_CORE
> + depends on JUMP_LABEL
> + help
> + The drm debug category facility does a lot of unlikely bit-field
> + tests at runtime; while cheap individually, the cost accumulates.
> + This option uses dynamic debug facility (if configured and
> + using jump_label) to avoid those runtime checks, patching
> + the kernel when those debugs are desired.

Can't we just make this an internal option that's enabled automatically
when dyndbg is around? Plus a comment somewhere that we really recommend
enabling dyndbg for drm. Or would this mean that in certain dyndbg
configurations we'd loose all the debug lines, which would suck?

Anyway there's a pile of details, but the big picture I really like.
Especially that we can make dyndbg seamlessly support drm.debug is really
nice.

Cheers, Daniel

> +
> config DRM_DEBUG_SELFTEST
> tristate "kselftests for DRM"
> depends on DRM
> diff --git a/drivers/gpu/drm/drm_print.c b/drivers/gpu/drm/drm_print.c
> index 111b932cf2a9..e2acdfc7088b 100644
> --- a/drivers/gpu/drm/drm_print.c
> +++ b/drivers/gpu/drm/drm_print.c
> @@ -52,8 +52,75 @@ MODULE_PARM_DESC(debug, "Enable debug output, where each bit enables a debug cat
> "\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)");
> +
> +#ifndef CONFIG_DRM_USE_DYNAMIC_DEBUG
> module_param_named(debug, __drm_debug, int, 0600);
>
> +#else
> +static char *format_class_prefixes[] = {
> + cDRM_UT_CORE,
> + cDRM_UT_DRIVER,
> + cDRM_UT_KMS,
> + cDRM_UT_PRIME,
> + cDRM_UT_ATOMIC,
> + cDRM_UT_VBL,
> + cDRM_UT_STATE,
> + cDRM_UT_LEASE,
> + cDRM_UT_DP,
> + cDRM_UT_DRMRES
> +};
> +
> +#define OUR_QUERY_SIZE 64 /* > strlen "format '^%s' %cp" + longest prefix */
> +
> +static int param_set_dyndbg(const char *instr, const struct kernel_param *kp)
> +{
> + unsigned int val;
> + unsigned long changes, result;
> + int rc, chgct = 0, totct = 0, bitpos;
> + char query[OUR_QUERY_SIZE];
> +
> + rc = kstrtouint(instr, 0, &val);
> + if (rc) {
> + pr_err("%s: failed\n", __func__);
> + return -EINVAL;
> + }
> + result = val;
> + changes = result ^ __drm_debug;
> +
> + pr_debug("changes:0x%lx from result:0x%lx\n", changes, result);
> +
> + for_each_set_bit(bitpos, &changes, ARRAY_SIZE(format_class_prefixes)) {
> +
> + sprintf(query, "format '^%s' %cp", format_class_prefixes[bitpos],
> + test_bit(bitpos, &result) ? '+' : '-');
> +
> + chgct = dynamic_debug_exec_queries(query, "drm*");
> + if (chgct < 0) {
> + pr_err("%s: exec err:%d on: %s\n", __func__, chgct, query);
> + continue;
> + }
> + pr_debug("change ct:%d on %s\n", chgct, query);
> + totct += chgct;
> + }
> + pr_debug("total changes: %d\n", totct);
> + __drm_debug = result;
> + return 0;
> +}
> +
> +static int param_get_dyndbg(char *buffer, const struct kernel_param *kp)
> +{
> + pr_debug("debug-val:0x%x %u\n", __drm_debug, *((unsigned int *)kp->arg));
> + return scnprintf(buffer, PAGE_SIZE, "%u\n",
> + *((unsigned int *)kp->arg));
> +}
> +static const struct kernel_param_ops param_ops_debug = {
> + .set = param_set_dyndbg,
> + .get = param_get_dyndbg,
> +};
> +module_param_cb(debug, &param_ops_debug, &__drm_debug, 0644);
> +
> +#endif /* CONFIG_DRM_USE_DYNAMIC_DEBUG */
> +
> void __drm_puts_coredump(struct drm_printer *p, const char *str)
> {
> struct drm_print_iterator *iterator = p->arg;
> @@ -256,7 +323,7 @@ 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,
> +void _drm_dev_dbg(const struct device *dev, enum drm_debug_category category,
> const char *format, ...)
> {
> struct va_format vaf;
> @@ -278,9 +345,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 +364,7 @@ void __drm_dbg(enum drm_debug_category category, const char *format, ...)
>
> va_end(args);
> }
> -EXPORT_SYMBOL(__drm_dbg);
> +EXPORT_SYMBOL(___drm_dbg);
>
> void __drm_err(const char *format, ...)
> {
> diff --git a/include/drm/drm_print.h b/include/drm/drm_print.h
> index ff5ac0e88321..499fa0b35200 100644
> --- a/include/drm/drm_print.h
> +++ b/include/drm/drm_print.h
> @@ -319,6 +319,51 @@ enum drm_debug_category {
> DRM_UT_DRMRES = 0x200,
> };
>
> +#if !defined(CONFIG_DRM_USE_DYNAMIC_DEBUG)
> +
> +/* Use legacy drm-debug functions, and drm_debug_enabled().
> + * For cDRM_UT_* (converted category), identity map to DRM_UT_*
> + */
> +#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 cDRM_UT_CORE DRM_UT_CORE
> +#define cDRM_UT_DRIVER DRM_UT_DRIVER
> +#define cDRM_UT_KMS DRM_UT_KMS
> +#define cDRM_UT_PRIME DRM_UT_PRIME
> +#define cDRM_UT_ATOMIC DRM_UT_ATOMIC
> +#define cDRM_UT_VBL DRM_UT_VBL
> +#define cDRM_UT_STATE DRM_UT_STATE
> +#define cDRM_UT_LEASE DRM_UT_LEASE
> +#define cDRM_UT_DP DRM_UT_DP
> +#define cDRM_UT_DRMRES DRM_UT_DRMRES
> +
> +#else /* !CONFIG_DRM_USE_DYNAMIC_DEBUG */
> +
> +/* use dynamic_debug to avoid drm_debug_enabled().
> + * dyndbg has no category, so we prefix the format with a "class"
> + * string; cDRM_UT_* maps to those class strings
> + */
> +#define __drm_dbg(cls, fmt, ...) \
> + pr_debug(cls # fmt, ##__VA_ARGS__)
> +#define drm_dev_dbg(dev, cls, fmt, ...) \
> + dev_dbg(dev, cls # fmt, ##__VA_ARGS__)
> +
> +#define cDRM_UT_CORE "drm:core: "
> +#define cDRM_UT_DRIVER "drm:drvr: "
> +#define cDRM_UT_KMS "drm:kms: "
> +#define cDRM_UT_PRIME "drm:prime: "
> +#define cDRM_UT_ATOMIC "drm:atomic: "
> +#define cDRM_UT_VBL "drm:vbl: "
> +#define cDRM_UT_STATE "drm:state: "
> +#define cDRM_UT_LEASE "drm:lease: "
> +#define cDRM_UT_DP "drm:dp: "
> +#define cDRM_UT_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,7 +379,7 @@ __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,
> +void _drm_dev_dbg(const struct device *dev, enum drm_debug_category category,
> const char *format, ...);
>
> /**
> @@ -383,7 +428,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, cDRM_UT_CORE, fmt, ##__VA_ARGS__)
> /**
> * DRM_DEV_DEBUG_DRIVER() - Debug output for vendor specific part of the driver
> *
> @@ -391,7 +436,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, cDRM_UT_DRIVER, fmt, ##__VA_ARGS__)
> /**
> * DRM_DEV_DEBUG_KMS() - Debug output for modesetting code
> *
> @@ -399,7 +444,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, cDRM_UT_KMS, fmt, ##__VA_ARGS__)
>
> /*
> * struct drm_device based logging
> @@ -443,25 +488,25 @@ void drm_dev_dbg(const struct device *dev, enum drm_debug_category category,
>
>
> #define drm_dbg_core(drm, fmt, ...) \
> - drm_dev_dbg((drm) ? (drm)->dev : NULL, DRM_UT_CORE, fmt, ##__VA_ARGS__)
> + drm_dev_dbg((drm) ? (drm)->dev : NULL, cDRM_UT_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, cDRM_UT_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, cDRM_UT_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, cDRM_UT_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, cDRM_UT_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, cDRM_UT_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, cDRM_UT_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, cDRM_UT_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, cDRM_UT_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, cDRM_UT_DRMRES, fmt, ##__VA_ARGS__)
>
>
> /*
> @@ -471,7 +516,7 @@ void drm_dev_dbg(const struct device *dev, enum drm_debug_category category,
> */
>
> __printf(2, 3)
> -void __drm_dbg(enum drm_debug_category category, const char *format, ...);
> +void ___drm_dbg(enum drm_debug_category category, const char *format, ...);
> __printf(1, 2)
> void __drm_err(const char *format, ...);
>
> @@ -500,44 +545,45 @@ void __drm_err(const char *format, ...);
> #define DRM_ERROR_RATELIMITED(fmt, ...) \
> DRM_DEV_ERROR_RATELIMITED(NULL, fmt, ##__VA_ARGS__)
>
> +
> #define DRM_DEBUG(fmt, ...) \
> - __drm_dbg(DRM_UT_CORE, fmt, ##__VA_ARGS__)
> + __drm_dbg(cDRM_UT_CORE, fmt, ##__VA_ARGS__)
>
> #define DRM_DEBUG_DRIVER(fmt, ...) \
> - __drm_dbg(DRM_UT_DRIVER, fmt, ##__VA_ARGS__)
> + __drm_dbg(cDRM_UT_DRIVER, fmt, ##__VA_ARGS__)
>
> #define DRM_DEBUG_KMS(fmt, ...) \
> - __drm_dbg(DRM_UT_KMS, fmt, ##__VA_ARGS__)
> + __drm_dbg(cDRM_UT_KMS, fmt, ##__VA_ARGS__)
>
> #define DRM_DEBUG_PRIME(fmt, ...) \
> - __drm_dbg(DRM_UT_PRIME, fmt, ##__VA_ARGS__)
> + __drm_dbg(cDRM_UT_PRIME, fmt, ##__VA_ARGS__)
>
> #define DRM_DEBUG_ATOMIC(fmt, ...) \
> - __drm_dbg(DRM_UT_ATOMIC, fmt, ##__VA_ARGS__)
> + __drm_dbg(cDRM_UT_ATOMIC, fmt, ##__VA_ARGS__)
>
> #define DRM_DEBUG_VBL(fmt, ...) \
> - __drm_dbg(DRM_UT_VBL, fmt, ##__VA_ARGS__)
> + __drm_dbg(cDRM_UT_VBL, fmt, ##__VA_ARGS__)
>
> #define DRM_DEBUG_LEASE(fmt, ...) \
> - __drm_dbg(DRM_UT_LEASE, fmt, ##__VA_ARGS__)
> + __drm_dbg(cDRM_UT_LEASE, fmt, ##__VA_ARGS__)
>
> #define DRM_DEBUG_DP(fmt, ...) \
> - __drm_dbg(DRM_UT_DP, fmt, ## __VA_ARGS__)
> + __drm_dbg(cDRM_UT_DP, fmt, ## __VA_ARGS__)
>
> -#define __DRM_DEFINE_DBG_RATELIMITED(category, drm, fmt, ...) \
> +#define __DRM_DEFINE_DBG_RATELIMITED(DRM_UT, cDRM_UT, drm, fmt, ...) \
> ({ \
> static DEFINE_RATELIMIT_STATE(rs_, \
> DEFAULT_RATELIMIT_INTERVAL, \
> DEFAULT_RATELIMIT_BURST); \
> 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__); \
> + if (drm_debug_enabled(DRM_UT) && __ratelimit(&rs_)) \
> + drm_dev_dbg((drm_) ? (drm_)->dev : NULL, \
> + cDRM_UT, fmt, ##__VA_ARGS__); \
> })
>
> #define drm_dbg_kms_ratelimited(drm, fmt, ...) \
> - __DRM_DEFINE_DBG_RATELIMITED(KMS, drm, fmt, ## __VA_ARGS__)
> + __DRM_DEFINE_DBG_RATELIMITED(DRM_UT_KMS, cDRM_UT_KMS, drm, fmt, ## __VA_ARGS__)
>
> #define DRM_DEBUG_KMS_RATELIMITED(fmt, ...) \
> drm_dbg_kms_ratelimited(NULL, fmt, ## __VA_ARGS__)
> --
> 2.31.1
>

--
Daniel Vetter
Software Engineer, Intel Corporation
http://blog.ffwll.ch

2021-07-22 19:41:12

by Jim Cromie

[permalink] [raw]
Subject: Re: [PATCH v3 3/5] drm/print: RFC add choice to use dynamic debug in drm-debug

Thanks for the feedback!


On Tue, Jul 20, 2021 at 9:29 AM Daniel Vetter <[email protected]> wrote:
>
> On Wed, Jul 14, 2021 at 11:51:36AM -0600, Jim Cromie wrote:
> > drm's debug system uses distinct categories of debug messages, encoded
> > in an enum (DRM_UT_<CATEGORY>), which are mapped to bits in drm.debug.
> > drm_debug_enabled() does a lot of unlikely bit-mask checks on
> > drm.debug; we can use dynamic debug instead, and get all that
> > static_key/jump_label goodness.
> >
> > Dynamic debug has no concept of category, but we can map the DRM_UT_*
> > to a set of distinct prefixes; "drm:core:", "drm:kms:" etc, and
> > prepend them to the given formats.
> >
> > Then we can use:
> > `echo module drm format ^drm:core: +p > control`
> >
> > to enable every such "prefixed" pr_debug with one query. This new
> > prefix changes pr_debug's output, so is user visible, but it seems
> > unlikely to cause trouble for log watchers; they're not relying on the
> > absence of class prefix strings.
> >
> > This conversion yields ~2100 new callsites on my i7/i915 laptop:
> >
> > dyndbg: 195 debug prints in module drm_kms_helper
> > dyndbg: 298 debug prints in module drm
> > dyndbg: 1630 debug prints in module i915
> >
> > CONFIG_DRM_USE_DYNAMIC_DEBUG enables this, and is available if
> > CONFIG_DYNAMIC_DEBUG or CONFIG_DYNAMIC_DEBUG_CORE is chosen, and if
> > CONFIG_JUMP_LABEL is enabled; this because its required to get the
> > promised optimizations.
> >
> > The indirection/switchover is layered into the macro scheme:
> >
> > 0. A new callback on drm.debug which calls dynamic_debug_exec_queries
> > to map those bits to specific query/commands
> > dynamic_debug_exec_queries("format ^drm:kms: +p", "drm*");
> > here for POC, this should be in dynamic_debug.c
> > with a MODULE_PARAM_DEBUG_BITMAP(__drm_debug, { "prefix-1", "desc-1" }+)
>
> This is really awesome. For merging I think we need to discuss with dyn
> debug folks whether they're all ok with this, but it's exported already
> should should be fine.
>

Yay. FWIW, Im to blame for that export, with this use case in mind.
That said, I dont know if that macro can be written as I described,
but if not, then { BIT(0), "prefix-0", "description-0" }, { BIT(1)
.... } should work.
If its been done elsewhere, Id copy it, or imitate it.





> >
> > 1. A "converted" or "classy" DRM_UT_* map
> >
> > based on: DRM_UT_* ( symbol => bit-mask )
> > named it: cDRM_UT_* ( symbol => format-class-prefix-string )
> >
> > So cDRM_UT_* is either:
> > legacy: cDRM_UT_* <-- DRM_UT_* ( !CONFIG_DRM_USE_DYNAMIC_DEBUG )
> > enabled:
> > #define cDRM_UT_KMS "drm:kms: "
> > #define cDRM_UT_PRIME "drm:prime: "
> > #define cDRM_UT_ATOMIC "drm:atomic: "
>
> the cDRM looks a bit funny, plus I don't eve have an idea what _UT_ means
> (and git history isn't helpful either). What about just using
> DRM_DBG_CLASS_ as the prefix here for these indirection macros, i.e.
> DRM_DBG_CLASS_KMS.
>

yes.


> Also would be really nice if we could make these a table or something, but
> I guess with the macro magic that's not possible.
>

not obvious to me, I'll watch for an opportunity.

> >
> > DRM_UT_* are unchanged, since theyre used in drm_debug_enabled()
> > and elsewhere.
>
> I think for the production version of these we need to retire/deprecate
> them, at least for drm core. Otherwise you have an annoying mismatch
> between drm.debug module option and dyn debug.
>

I will look at renaming it : __drm_debug_enabled
and making a macro for the old name.
so enabled, it would end up like
if (unlikely(1) && ... )

drivers/gpu/drm/drm_atomic_uapi.c
1457: if (drm_debug_enabled(DRM_UT_STATE))

drivers/gpu/drm/drm_dp_mst_topology.c
1358: if (unlikely(ret == -EIO) && drm_debug_enabled(DRM_UT_DP)) {
2875: if (unlikely(ret) && drm_debug_enabled(DRM_UT_DP)) {
2919: if (drm_debug_enabled(DRM_UT_DP)) {


> >
> > 2. drm_dev_dbg & drm_debug are renamed (prefixed with '_')
> >
> > old names are now macros, calling either:
> > legacy: -> to renamed fn
> > enabled: -> dev_dbg & pr_debug, with cDRM-prefix # format.
> >
> > these names are used in a fat layer of macros (3) which supply the
> > category; those macros are used throughout drm code, yielding the
> > ~2100 new prdbgs reported above.
> >
> > 3. names in (2) are invoked by DRM_DEBUG_<Category>, drm_dbg_<Category>.
> >
> > all these macros get "converted" to use cDRM_UT_*
> > to get right token type for both !/!! DRM_USE_DYNAMIC_DEBUG
> >
> > 4. simplification of __DRM_DEFINE_DBG_RATELIMITED macro
> >
> > remove DRM_UT_ ## KMS as extra indirection
> > pass both DRM_UT & cDRM_UT, for drm_debug_enabled & drm_dev_dbg
>
> For merging, can we pull out the renames and reorgs from this patch, and
> then maybe also the reorder the next patch in your series here to be
> before the dyn debug stuff?
>

I will drop the 4. RATELIMITED tweaks.
FWIW, I have semi-working code to implement rate limiting
in dynamic debug, controlled by `+r > control`
which would touch this anyway.

wrt reordering 4/5, can you clarify ?
the i915 changes are 1/2 POC, so I'll assume you mean after getting 0.
into dyndbg

> > Signed-off-by: Jim Cromie <[email protected]>
> > ---
> > drivers/gpu/drm/Kconfig | 13 +++++
> > drivers/gpu/drm/drm_print.c | 75 ++++++++++++++++++++++++--
> > include/drm/drm_print.h | 102 ++++++++++++++++++++++++++----------
> > 3 files changed, 158 insertions(+), 32 deletions(-)
>
> I really like this, I think you can drop the RFC. A few more things that I
> think we need:
>
> - An overview kerneldoc section which explains the interfaces and how it
> all works together. Essentially your commit message with some light
> markup to make it look good.

into include/drm/drm_print.h ?

>
> - I think it would be really good to review the driver docs for all this
> and make sure it's complete. Some of the interface functions aren't
> documented yet (or maybe the ones that drivers shouldn't used need more
> __ prefixes to denote them as internal, dunno).
>

I will look, but I dont have the experience here to make these
qualitative judgements

Also, I renamed drm_dev_dbg to _drm_dev_dbg, with a single underscore.
I'm now thinking this is reserved, and __ prefix is better (legal)
This isnt quite the same is lower-level implementation detail,
since it adds a CONFIG dependent alternative impl.
But I'll do this unless you have a better name

> - I guess deprecation notice for drm_debug_enabled() and all that, so that
> we have a consistent interface. Doing the conversion will probably
> highlight the need for a bit more infrastructure and tooling, e.g. the
> bigger dump functions (like edid hex dump, or also the various decode
> helpers we have for dp, hdmi infoframes and all that) ideally have a
> single dyn_debug label to enable all of them instead of line-by-line.
> Tbh no idea how this should work, might need dyndbg work too.
>

macrofying drm_debug_enabled() might work for this set.
possibly with different prefixes, forex: "drmx:*" or "drm:misc:"

> - For the driver side of this we probably want a
> Documentation/gpu/TODO.rst entry if it's not all easy to convert
> directly.

so there are 32 uses of drm_debug_enabled(DRM_UT_*)
and just 1 used in drm_dev_dbg (with category as arg)
I'll try to macrofy it, see if it will handle the 32 cases.

>
> >
> > diff --git a/drivers/gpu/drm/Kconfig b/drivers/gpu/drm/Kconfig
> > index 7ff89690a976..e4524ccba040 100644
> > --- a/drivers/gpu/drm/Kconfig
> > +++ b/drivers/gpu/drm/Kconfig
> > @@ -57,6 +57,19 @@ config DRM_DEBUG_MM
> >
> > If in doubt, say "N".
> >
> > +config DRM_USE_DYNAMIC_DEBUG
> > + bool "use dynamic debug to implement drm.debug"
> > + default n
> > + depends on DRM
> > + depends on DYNAMIC_DEBUG || DYNAMIC_DEBUG_CORE
> > + depends on JUMP_LABEL
> > + help
> > + The drm debug category facility does a lot of unlikely bit-field
> > + tests at runtime; while cheap individually, the cost accumulates.
> > + This option uses dynamic debug facility (if configured and
> > + using jump_label) to avoid those runtime checks, patching
> > + the kernel when those debugs are desired.
>
> Can't we just make this an internal option that's enabled automatically
> when dyndbg is around? Plus a comment somewhere that we really recommend
> enabling dyndbg for drm. Or would this mean that in certain dyndbg
> configurations we'd loose all the debug lines, which would suck?
>

We could indeed, I took the cautious approach.
keeping the CONFIG simplifies comparing DRM_USE_DD=y/n builds,
and changing default later is easy, and probably should have some numbers
about instructions saved and obj size increase.


> Anyway there's a pile of details, but the big picture I really like.
> Especially that we can make dyndbg seamlessly support drm.debug is really
> nice.
>
> Cheers, Daniel
>

thanks, Jim

2021-07-27 13:56:56

by Sean Paul

[permalink] [raw]
Subject: Re: [Intel-gfx] [PATCH v3 3/5] drm/print: RFC add choice to use dynamic debug in drm-debug

On Tue, Jul 20, 2021 at 03:29:34PM +0200, Daniel Vetter wrote:
> On Wed, Jul 14, 2021 at 11:51:36AM -0600, Jim Cromie wrote:
> > drm's debug system uses distinct categories of debug messages, encoded
> > in an enum (DRM_UT_<CATEGORY>), which are mapped to bits in drm.debug.
> > drm_debug_enabled() does a lot of unlikely bit-mask checks on
> > drm.debug; we can use dynamic debug instead, and get all that
> > static_key/jump_label goodness.

Hi Jim,
Thanks for your patches! Daniel pointed me at them in response to my drm_trace
patchset (https://patchwork.freedesktop.org/series/78133/). I'd love to get your
input on it. I think the 2 sets are mostly compatible, we'd just need to keep
drm_dev_dbg and do the CONFIG check in the function beside the trace_enabled
checks.

> >
> > Dynamic debug has no concept of category, but we can map the DRM_UT_*
> > to a set of distinct prefixes; "drm:core:", "drm:kms:" etc, and
> > prepend them to the given formats.
> >
> > Then we can use:
> > `echo module drm format ^drm:core: +p > control`
> >
> > to enable every such "prefixed" pr_debug with one query. This new
> > prefix changes pr_debug's output, so is user visible, but it seems
> > unlikely to cause trouble for log watchers; they're not relying on the
> > absence of class prefix strings.
> >
> > This conversion yields ~2100 new callsites on my i7/i915 laptop:
> >
> > dyndbg: 195 debug prints in module drm_kms_helper
> > dyndbg: 298 debug prints in module drm
> > dyndbg: 1630 debug prints in module i915
> >
> > CONFIG_DRM_USE_DYNAMIC_DEBUG enables this, and is available if
> > CONFIG_DYNAMIC_DEBUG or CONFIG_DYNAMIC_DEBUG_CORE is chosen, and if
> > CONFIG_JUMP_LABEL is enabled; this because its required to get the
> > promised optimizations.
> >
> > The indirection/switchover is layered into the macro scheme:
> >
> > 0. A new callback on drm.debug which calls dynamic_debug_exec_queries
> > to map those bits to specific query/commands
> > dynamic_debug_exec_queries("format ^drm:kms: +p", "drm*");
> > here for POC, this should be in dynamic_debug.c
> > with a MODULE_PARAM_DEBUG_BITMAP(__drm_debug, { "prefix-1", "desc-1" }+)
>
> This is really awesome.


Agreed, this is a very clever way of merging the 2 worlds!


> For merging I think we need to discuss with dyn
> debug folks whether they're all ok with this, but it's exported already
> should should be fine.

I wonder if this is a good time to reconsider our drm categories. IMO they're
overly broad and it's hard to get the right information without subscribing to
the firehose. It seems like dyndbg might be a good opportunity to unlock
subcategories of log messages.

More concretely, on CrOS we can't subscribe to atomic or state categories since
they're too noisy. However if there was a "fail" subcategory which dumped
state/atomic logs on check failures, that would be really compelling. Something
like:

drm:atomic:fail vs. drm:atomic

Both would be picked up if (drm.debug & DRM_DBG_ATOMIC), however it would allow
dyndbg-aware clients to get better logs without having a huge table of
individual log signatures.

I'm not sure how tightly we'd want to control the subcategories. It could be
strict like the categories spelled out in drm_print.h, or an open prefix arg to
drm_dev_dbg. I suspect we'd want the former, but would want to be careful to
provide enough flexibility to properly

Of course, none of this needs to be decided to land this initial support, it can
be bolted on later easily enough (I think).


>
> >
> > 1. A "converted" or "classy" DRM_UT_* map
> >
> > based on: DRM_UT_* ( symbol => bit-mask )
> > named it: cDRM_UT_* ( symbol => format-class-prefix-string )
> >
> > So cDRM_UT_* is either:
> > legacy: cDRM_UT_* <-- DRM_UT_* ( !CONFIG_DRM_USE_DYNAMIC_DEBUG )
> > enabled:
> > #define cDRM_UT_KMS "drm:kms: "
> > #define cDRM_UT_PRIME "drm:prime: "
> > #define cDRM_UT_ATOMIC "drm:atomic: "
>
> the cDRM looks a bit funny, plus I don't eve have an idea what _UT_ means
> (and git history isn't helpful either). What about just using
> DRM_DBG_CLASS_ as the prefix here for these indirection macros, i.e.
> DRM_DBG_CLASS_KMS.
>
> Also would be really nice if we could make these a table or something, but
> I guess with the macro magic that's not possible.
>
> >
> > DRM_UT_* are unchanged, since theyre used in drm_debug_enabled()
> > and elsewhere.
>
> I think for the production version of these we need to retire/deprecate
> them, at least for drm core. Otherwise you have an annoying mismatch
> between drm.debug module option and dyn debug.
>
> >
> > 2. drm_dev_dbg & drm_debug are renamed (prefixed with '_')
> >
> > old names are now macros, calling either:
> > legacy: -> to renamed fn
> > enabled: -> dev_dbg & pr_debug, with cDRM-prefix # format.
> >
> > these names are used in a fat layer of macros (3) which supply the
> > category; those macros are used throughout drm code, yielding the
> > ~2100 new prdbgs reported above.
> >
> > 3. names in (2) are invoked by DRM_DEBUG_<Category>, drm_dbg_<Category>.
> >
> > all these macros get "converted" to use cDRM_UT_*
> > to get right token type for both !/!! DRM_USE_DYNAMIC_DEBUG
> >
> > 4. simplification of __DRM_DEFINE_DBG_RATELIMITED macro
> >
> > remove DRM_UT_ ## KMS as extra indirection
> > pass both DRM_UT & cDRM_UT, for drm_debug_enabled & drm_dev_dbg
>
> For merging, can we pull out the renames and reorgs from this patch, and
> then maybe also the reorder the next patch in your series here to be
> before the dyn debug stuff?
>
> > Signed-off-by: Jim Cromie <[email protected]>
> > ---
> > drivers/gpu/drm/Kconfig | 13 +++++
> > drivers/gpu/drm/drm_print.c | 75 ++++++++++++++++++++++++--
> > include/drm/drm_print.h | 102 ++++++++++++++++++++++++++----------
> > 3 files changed, 158 insertions(+), 32 deletions(-)
>
> I really like this, I think you can drop the RFC. A few more things that I
> think we need:
>
> - An overview kerneldoc section which explains the interfaces and how it
> all works together. Essentially your commit message with some light
> markup to make it look good.
>
> - I think it would be really good to review the driver docs for all this
> and make sure it's complete. Some of the interface functions aren't
> documented yet (or maybe the ones that drivers shouldn't used need more
> __ prefixes to denote them as internal, dunno).
>
> - I guess deprecation notice for drm_debug_enabled() and all that, so that
> we have a consistent interface. Doing the conversion will probably
> highlight the need for a bit more infrastructure and tooling, e.g. the
> bigger dump functions (like edid hex dump, or also the various decode
> helpers we have for dp, hdmi infoframes and all that) ideally have a
> single dyn_debug label to enable all of them instead of line-by-line.
> Tbh no idea how this should work, might need dyndbg work too.

Yeah, this is going to be tricky.

We'll probably need to enumerate these fully and if the process of gathering
the data is simple or already done in the course of the function, just avoid the
drm_debug_enabled() call with a CONFIG_DRM_DYNDBG check.

If the debug_enabled call gates a HW access, we probably need to query dyndbg
for the prefix the logs are associated with before gathering the log contents.

Sean
>
> - For the driver side of this we probably want a
> Documentation/gpu/TODO.rst entry if it's not all easy to convert
> directly.
>
> >
> > diff --git a/drivers/gpu/drm/Kconfig b/drivers/gpu/drm/Kconfig
> > index 7ff89690a976..e4524ccba040 100644
> > --- a/drivers/gpu/drm/Kconfig
> > +++ b/drivers/gpu/drm/Kconfig
> > @@ -57,6 +57,19 @@ config DRM_DEBUG_MM
> >
> > If in doubt, say "N".
> >
> > +config DRM_USE_DYNAMIC_DEBUG
> > + bool "use dynamic debug to implement drm.debug"
> > + default n
> > + depends on DRM
> > + depends on DYNAMIC_DEBUG || DYNAMIC_DEBUG_CORE
> > + depends on JUMP_LABEL
> > + help
> > + The drm debug category facility does a lot of unlikely bit-field
> > + tests at runtime; while cheap individually, the cost accumulates.
> > + This option uses dynamic debug facility (if configured and
> > + using jump_label) to avoid those runtime checks, patching
> > + the kernel when those debugs are desired.
>
> Can't we just make this an internal option that's enabled automatically
> when dyndbg is around? Plus a comment somewhere that we really recommend
> enabling dyndbg for drm. Or would this mean that in certain dyndbg
> configurations we'd loose all the debug lines, which would suck?
>
> Anyway there's a pile of details, but the big picture I really like.
> Especially that we can make dyndbg seamlessly support drm.debug is really
> nice.
>
> Cheers, Daniel
>
> > +
> > config DRM_DEBUG_SELFTEST
> > tristate "kselftests for DRM"
> > depends on DRM
> > diff --git a/drivers/gpu/drm/drm_print.c b/drivers/gpu/drm/drm_print.c
> > index 111b932cf2a9..e2acdfc7088b 100644
> > --- a/drivers/gpu/drm/drm_print.c
> > +++ b/drivers/gpu/drm/drm_print.c
> > @@ -52,8 +52,75 @@ MODULE_PARM_DESC(debug, "Enable debug output, where each bit enables a debug cat
> > "\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)");
> > +
> > +#ifndef CONFIG_DRM_USE_DYNAMIC_DEBUG
> > module_param_named(debug, __drm_debug, int, 0600);
> >
> > +#else
> > +static char *format_class_prefixes[] = {
> > + cDRM_UT_CORE,
> > + cDRM_UT_DRIVER,
> > + cDRM_UT_KMS,
> > + cDRM_UT_PRIME,
> > + cDRM_UT_ATOMIC,
> > + cDRM_UT_VBL,
> > + cDRM_UT_STATE,
> > + cDRM_UT_LEASE,
> > + cDRM_UT_DP,
> > + cDRM_UT_DRMRES
> > +};
> > +
> > +#define OUR_QUERY_SIZE 64 /* > strlen "format '^%s' %cp" + longest prefix */
> > +
> > +static int param_set_dyndbg(const char *instr, const struct kernel_param *kp)
> > +{
> > + unsigned int val;
> > + unsigned long changes, result;
> > + int rc, chgct = 0, totct = 0, bitpos;
> > + char query[OUR_QUERY_SIZE];
> > +
> > + rc = kstrtouint(instr, 0, &val);
> > + if (rc) {
> > + pr_err("%s: failed\n", __func__);
> > + return -EINVAL;
> > + }
> > + result = val;
> > + changes = result ^ __drm_debug;
> > +
> > + pr_debug("changes:0x%lx from result:0x%lx\n", changes, result);
> > +
> > + for_each_set_bit(bitpos, &changes, ARRAY_SIZE(format_class_prefixes)) {
> > +
> > + sprintf(query, "format '^%s' %cp", format_class_prefixes[bitpos],
> > + test_bit(bitpos, &result) ? '+' : '-');
> > +
> > + chgct = dynamic_debug_exec_queries(query, "drm*");
> > + if (chgct < 0) {
> > + pr_err("%s: exec err:%d on: %s\n", __func__, chgct, query);
> > + continue;
> > + }
> > + pr_debug("change ct:%d on %s\n", chgct, query);
> > + totct += chgct;
> > + }
> > + pr_debug("total changes: %d\n", totct);
> > + __drm_debug = result;
> > + return 0;
> > +}
> > +
> > +static int param_get_dyndbg(char *buffer, const struct kernel_param *kp)
> > +{
> > + pr_debug("debug-val:0x%x %u\n", __drm_debug, *((unsigned int *)kp->arg));
> > + return scnprintf(buffer, PAGE_SIZE, "%u\n",
> > + *((unsigned int *)kp->arg));
> > +}
> > +static const struct kernel_param_ops param_ops_debug = {
> > + .set = param_set_dyndbg,
> > + .get = param_get_dyndbg,
> > +};
> > +module_param_cb(debug, &param_ops_debug, &__drm_debug, 0644);
> > +
> > +#endif /* CONFIG_DRM_USE_DYNAMIC_DEBUG */
> > +
> > void __drm_puts_coredump(struct drm_printer *p, const char *str)
> > {
> > struct drm_print_iterator *iterator = p->arg;
> > @@ -256,7 +323,7 @@ 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,
> > +void _drm_dev_dbg(const struct device *dev, enum drm_debug_category category,
> > const char *format, ...)
> > {
> > struct va_format vaf;
> > @@ -278,9 +345,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 +364,7 @@ void __drm_dbg(enum drm_debug_category category, const char *format, ...)
> >
> > va_end(args);
> > }
> > -EXPORT_SYMBOL(__drm_dbg);
> > +EXPORT_SYMBOL(___drm_dbg);
> >
> > void __drm_err(const char *format, ...)
> > {
> > diff --git a/include/drm/drm_print.h b/include/drm/drm_print.h
> > index ff5ac0e88321..499fa0b35200 100644
> > --- a/include/drm/drm_print.h
> > +++ b/include/drm/drm_print.h
> > @@ -319,6 +319,51 @@ enum drm_debug_category {
> > DRM_UT_DRMRES = 0x200,
> > };
> >
> > +#if !defined(CONFIG_DRM_USE_DYNAMIC_DEBUG)
> > +
> > +/* Use legacy drm-debug functions, and drm_debug_enabled().
> > + * For cDRM_UT_* (converted category), identity map to DRM_UT_*
> > + */
> > +#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 cDRM_UT_CORE DRM_UT_CORE
> > +#define cDRM_UT_DRIVER DRM_UT_DRIVER
> > +#define cDRM_UT_KMS DRM_UT_KMS
> > +#define cDRM_UT_PRIME DRM_UT_PRIME
> > +#define cDRM_UT_ATOMIC DRM_UT_ATOMIC
> > +#define cDRM_UT_VBL DRM_UT_VBL
> > +#define cDRM_UT_STATE DRM_UT_STATE
> > +#define cDRM_UT_LEASE DRM_UT_LEASE
> > +#define cDRM_UT_DP DRM_UT_DP
> > +#define cDRM_UT_DRMRES DRM_UT_DRMRES
> > +
> > +#else /* !CONFIG_DRM_USE_DYNAMIC_DEBUG */
> > +
> > +/* use dynamic_debug to avoid drm_debug_enabled().
> > + * dyndbg has no category, so we prefix the format with a "class"
> > + * string; cDRM_UT_* maps to those class strings
> > + */
> > +#define __drm_dbg(cls, fmt, ...) \
> > + pr_debug(cls # fmt, ##__VA_ARGS__)
> > +#define drm_dev_dbg(dev, cls, fmt, ...) \
> > + dev_dbg(dev, cls # fmt, ##__VA_ARGS__)
> > +
> > +#define cDRM_UT_CORE "drm:core: "
> > +#define cDRM_UT_DRIVER "drm:drvr: "
> > +#define cDRM_UT_KMS "drm:kms: "
> > +#define cDRM_UT_PRIME "drm:prime: "
> > +#define cDRM_UT_ATOMIC "drm:atomic: "
> > +#define cDRM_UT_VBL "drm:vbl: "
> > +#define cDRM_UT_STATE "drm:state: "
> > +#define cDRM_UT_LEASE "drm:lease: "
> > +#define cDRM_UT_DP "drm:dp: "
> > +#define cDRM_UT_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,7 +379,7 @@ __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,
> > +void _drm_dev_dbg(const struct device *dev, enum drm_debug_category category,
> > const char *format, ...);
> >
> > /**
> > @@ -383,7 +428,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, cDRM_UT_CORE, fmt, ##__VA_ARGS__)
> > /**
> > * DRM_DEV_DEBUG_DRIVER() - Debug output for vendor specific part of the driver
> > *
> > @@ -391,7 +436,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, cDRM_UT_DRIVER, fmt, ##__VA_ARGS__)
> > /**
> > * DRM_DEV_DEBUG_KMS() - Debug output for modesetting code
> > *
> > @@ -399,7 +444,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, cDRM_UT_KMS, fmt, ##__VA_ARGS__)
> >
> > /*
> > * struct drm_device based logging
> > @@ -443,25 +488,25 @@ void drm_dev_dbg(const struct device *dev, enum drm_debug_category category,
> >
> >
> > #define drm_dbg_core(drm, fmt, ...) \
> > - drm_dev_dbg((drm) ? (drm)->dev : NULL, DRM_UT_CORE, fmt, ##__VA_ARGS__)
> > + drm_dev_dbg((drm) ? (drm)->dev : NULL, cDRM_UT_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, cDRM_UT_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, cDRM_UT_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, cDRM_UT_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, cDRM_UT_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, cDRM_UT_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, cDRM_UT_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, cDRM_UT_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, cDRM_UT_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, cDRM_UT_DRMRES, fmt, ##__VA_ARGS__)
> >
> >
> > /*
> > @@ -471,7 +516,7 @@ void drm_dev_dbg(const struct device *dev, enum drm_debug_category category,
> > */
> >
> > __printf(2, 3)
> > -void __drm_dbg(enum drm_debug_category category, const char *format, ...);
> > +void ___drm_dbg(enum drm_debug_category category, const char *format, ...);
> > __printf(1, 2)
> > void __drm_err(const char *format, ...);
> >
> > @@ -500,44 +545,45 @@ void __drm_err(const char *format, ...);
> > #define DRM_ERROR_RATELIMITED(fmt, ...) \
> > DRM_DEV_ERROR_RATELIMITED(NULL, fmt, ##__VA_ARGS__)
> >
> > +
> > #define DRM_DEBUG(fmt, ...) \
> > - __drm_dbg(DRM_UT_CORE, fmt, ##__VA_ARGS__)
> > + __drm_dbg(cDRM_UT_CORE, fmt, ##__VA_ARGS__)
> >
> > #define DRM_DEBUG_DRIVER(fmt, ...) \
> > - __drm_dbg(DRM_UT_DRIVER, fmt, ##__VA_ARGS__)
> > + __drm_dbg(cDRM_UT_DRIVER, fmt, ##__VA_ARGS__)
> >
> > #define DRM_DEBUG_KMS(fmt, ...) \
> > - __drm_dbg(DRM_UT_KMS, fmt, ##__VA_ARGS__)
> > + __drm_dbg(cDRM_UT_KMS, fmt, ##__VA_ARGS__)
> >
> > #define DRM_DEBUG_PRIME(fmt, ...) \
> > - __drm_dbg(DRM_UT_PRIME, fmt, ##__VA_ARGS__)
> > + __drm_dbg(cDRM_UT_PRIME, fmt, ##__VA_ARGS__)
> >
> > #define DRM_DEBUG_ATOMIC(fmt, ...) \
> > - __drm_dbg(DRM_UT_ATOMIC, fmt, ##__VA_ARGS__)
> > + __drm_dbg(cDRM_UT_ATOMIC, fmt, ##__VA_ARGS__)
> >
> > #define DRM_DEBUG_VBL(fmt, ...) \
> > - __drm_dbg(DRM_UT_VBL, fmt, ##__VA_ARGS__)
> > + __drm_dbg(cDRM_UT_VBL, fmt, ##__VA_ARGS__)
> >
> > #define DRM_DEBUG_LEASE(fmt, ...) \
> > - __drm_dbg(DRM_UT_LEASE, fmt, ##__VA_ARGS__)
> > + __drm_dbg(cDRM_UT_LEASE, fmt, ##__VA_ARGS__)
> >
> > #define DRM_DEBUG_DP(fmt, ...) \
> > - __drm_dbg(DRM_UT_DP, fmt, ## __VA_ARGS__)
> > + __drm_dbg(cDRM_UT_DP, fmt, ## __VA_ARGS__)
> >
> > -#define __DRM_DEFINE_DBG_RATELIMITED(category, drm, fmt, ...) \
> > +#define __DRM_DEFINE_DBG_RATELIMITED(DRM_UT, cDRM_UT, drm, fmt, ...) \
> > ({ \
> > static DEFINE_RATELIMIT_STATE(rs_, \
> > DEFAULT_RATELIMIT_INTERVAL, \
> > DEFAULT_RATELIMIT_BURST); \
> > 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__); \
> > + if (drm_debug_enabled(DRM_UT) && __ratelimit(&rs_)) \
> > + drm_dev_dbg((drm_) ? (drm_)->dev : NULL, \
> > + cDRM_UT, fmt, ##__VA_ARGS__); \
> > })
> >
> > #define drm_dbg_kms_ratelimited(drm, fmt, ...) \
> > - __DRM_DEFINE_DBG_RATELIMITED(KMS, drm, fmt, ## __VA_ARGS__)
> > + __DRM_DEFINE_DBG_RATELIMITED(DRM_UT_KMS, cDRM_UT_KMS, drm, fmt, ## __VA_ARGS__)
> >
> > #define DRM_DEBUG_KMS_RATELIMITED(fmt, ...) \
> > drm_dbg_kms_ratelimited(NULL, fmt, ## __VA_ARGS__)
> > --
> > 2.31.1
> >
>
> --
> Daniel Vetter
> Software Engineer, Intel Corporation
> http://blog.ffwll.ch
> _______________________________________________
> Intel-gfx mailing list
> [email protected]
> https://lists.freedesktop.org/mailman/listinfo/intel-gfx

--
Sean Paul, Software Engineer, Google / Chromium OS

2021-07-27 14:04:45

by Sean Paul

[permalink] [raw]
Subject: Re: [Intel-gfx] [PATCH v3 3/5] drm/print: RFC add choice to use dynamic debug in drm-debug

On Thu, Jul 22, 2021 at 11:20 AM Sean Paul <[email protected]> wrote:
>

Reply-all fail. Adding everyone else back to my response.

> On Tue, Jul 20, 2021 at 03:29:34PM +0200, Daniel Vetter wrote:
> > On Wed, Jul 14, 2021 at 11:51:36AM -0600, Jim Cromie wrote:
> > > drm's debug system uses distinct categories of debug messages, encoded
> > > in an enum (DRM_UT_<CATEGORY>), which are mapped to bits in drm.debug.
> > > drm_debug_enabled() does a lot of unlikely bit-mask checks on
> > > drm.debug; we can use dynamic debug instead, and get all that
> > > static_key/jump_label goodness.
>
> Hi Jim,
> Thanks for your patches! Daniel pointed me at them in response to my drm_trace
> patchset (https://patchwork.freedesktop.org/series/78133/). I'd love to get your
> input on it. I think the 2 sets are mostly compatible, we'd just need to keep
> drm_dev_dbg and do the CONFIG check in the function beside the trace_enabled
> checks.
>
> > >
> > > Dynamic debug has no concept of category, but we can map the DRM_UT_*
> > > to a set of distinct prefixes; "drm:core:", "drm:kms:" etc, and
> > > prepend them to the given formats.
> > >
> > > Then we can use:
> > > `echo module drm format ^drm:core: +p > control`
> > >
> > > to enable every such "prefixed" pr_debug with one query. This new
> > > prefix changes pr_debug's output, so is user visible, but it seems
> > > unlikely to cause trouble for log watchers; they're not relying on the
> > > absence of class prefix strings.
> > >
> > > This conversion yields ~2100 new callsites on my i7/i915 laptop:
> > >
> > > dyndbg: 195 debug prints in module drm_kms_helper
> > > dyndbg: 298 debug prints in module drm
> > > dyndbg: 1630 debug prints in module i915
> > >
> > > CONFIG_DRM_USE_DYNAMIC_DEBUG enables this, and is available if
> > > CONFIG_DYNAMIC_DEBUG or CONFIG_DYNAMIC_DEBUG_CORE is chosen, and if
> > > CONFIG_JUMP_LABEL is enabled; this because its required to get the
> > > promised optimizations.
> > >
> > > The indirection/switchover is layered into the macro scheme:
> > >
> > > 0. A new callback on drm.debug which calls dynamic_debug_exec_queries
> > > to map those bits to specific query/commands
> > > dynamic_debug_exec_queries("format ^drm:kms: +p", "drm*");
> > > here for POC, this should be in dynamic_debug.c
> > > with a MODULE_PARAM_DEBUG_BITMAP(__drm_debug, { "prefix-1", "desc-1" }+)
> >
> > This is really awesome.
>
>
> Agreed, this is a very clever way of merging the 2 worlds!
>
>
> > For merging I think we need to discuss with dyn
> > debug folks whether they're all ok with this, but it's exported already
> > should should be fine.
>
> I wonder if this is a good time to reconsider our drm categories. IMO they're
> overly broad and it's hard to get the right information without subscribing to
> the firehose. It seems like dyndbg might be a good opportunity to unlock
> subcategories of log messages.
>
> More concretely, on CrOS we can't subscribe to atomic or state categories since
> they're too noisy. However if there was a "fail" subcategory which dumped
> state/atomic logs on check failures, that would be really compelling. Something
> like:
>
> drm:atomic:fail vs. drm:atomic
>
> Both would be picked up if (drm.debug & DRM_DBG_ATOMIC), however it would allow
> dyndbg-aware clients to get better logs without having a huge table of
> individual log signatures.
>
> I'm not sure how tightly we'd want to control the subcategories. It could be
> strict like the categories spelled out in drm_print.h, or an open prefix arg to
> drm_dev_dbg. I suspect we'd want the former, but would want to be careful to
> provide enough flexibility to properly
>
> Of course, none of this needs to be decided to land this initial support, it can
> be bolted on later easily enough (I think).
>
>
> >
> > >
> > > 1. A "converted" or "classy" DRM_UT_* map
> > >
> > > based on: DRM_UT_* ( symbol => bit-mask )
> > > named it: cDRM_UT_* ( symbol => format-class-prefix-string )
> > >
> > > So cDRM_UT_* is either:
> > > legacy: cDRM_UT_* <-- DRM_UT_* ( !CONFIG_DRM_USE_DYNAMIC_DEBUG )
> > > enabled:
> > > #define cDRM_UT_KMS "drm:kms: "
> > > #define cDRM_UT_PRIME "drm:prime: "
> > > #define cDRM_UT_ATOMIC "drm:atomic: "
> >
> > the cDRM looks a bit funny, plus I don't eve have an idea what _UT_ means
> > (and git history isn't helpful either). What about just using
> > DRM_DBG_CLASS_ as the prefix here for these indirection macros, i.e.
> > DRM_DBG_CLASS_KMS.
> >
> > Also would be really nice if we could make these a table or something, but
> > I guess with the macro magic that's not possible.
> >
> > >
> > > DRM_UT_* are unchanged, since theyre used in drm_debug_enabled()
> > > and elsewhere.
> >
> > I think for the production version of these we need to retire/deprecate
> > them, at least for drm core. Otherwise you have an annoying mismatch
> > between drm.debug module option and dyn debug.
> >
> > >
> > > 2. drm_dev_dbg & drm_debug are renamed (prefixed with '_')
> > >
> > > old names are now macros, calling either:
> > > legacy: -> to renamed fn
> > > enabled: -> dev_dbg & pr_debug, with cDRM-prefix # format.
> > >
> > > these names are used in a fat layer of macros (3) which supply the
> > > category; those macros are used throughout drm code, yielding the
> > > ~2100 new prdbgs reported above.
> > >
> > > 3. names in (2) are invoked by DRM_DEBUG_<Category>, drm_dbg_<Category>.
> > >
> > > all these macros get "converted" to use cDRM_UT_*
> > > to get right token type for both !/!! DRM_USE_DYNAMIC_DEBUG
> > >
> > > 4. simplification of __DRM_DEFINE_DBG_RATELIMITED macro
> > >
> > > remove DRM_UT_ ## KMS as extra indirection
> > > pass both DRM_UT & cDRM_UT, for drm_debug_enabled & drm_dev_dbg
> >
> > For merging, can we pull out the renames and reorgs from this patch, and
> > then maybe also the reorder the next patch in your series here to be
> > before the dyn debug stuff?
> >
> > > Signed-off-by: Jim Cromie <[email protected]>
> > > ---
> > > drivers/gpu/drm/Kconfig | 13 +++++
> > > drivers/gpu/drm/drm_print.c | 75 ++++++++++++++++++++++++--
> > > include/drm/drm_print.h | 102 ++++++++++++++++++++++++++----------
> > > 3 files changed, 158 insertions(+), 32 deletions(-)
> >
> > I really like this, I think you can drop the RFC. A few more things that I
> > think we need:
> >
> > - An overview kerneldoc section which explains the interfaces and how it
> > all works together. Essentially your commit message with some light
> > markup to make it look good.
> >
> > - I think it would be really good to review the driver docs for all this
> > and make sure it's complete. Some of the interface functions aren't
> > documented yet (or maybe the ones that drivers shouldn't used need more
> > __ prefixes to denote them as internal, dunno).
> >
> > - I guess deprecation notice for drm_debug_enabled() and all that, so that
> > we have a consistent interface. Doing the conversion will probably
> > highlight the need for a bit more infrastructure and tooling, e.g. the
> > bigger dump functions (like edid hex dump, or also the various decode
> > helpers we have for dp, hdmi infoframes and all that) ideally have a
> > single dyn_debug label to enable all of them instead of line-by-line.
> > Tbh no idea how this should work, might need dyndbg work too.
>
> Yeah, this is going to be tricky.
>
> We'll probably need to enumerate these fully and if the process of gathering
> the data is simple or already done in the course of the function, just avoid the
> drm_debug_enabled() call with a CONFIG_DRM_DYNDBG check.
>
> If the debug_enabled call gates a HW access, we probably need to query dyndbg
> for the prefix the logs are associated with before gathering the log contents.
>
> Sean
> >
> > - For the driver side of this we probably want a
> > Documentation/gpu/TODO.rst entry if it's not all easy to convert
> > directly.
> >
> > >
> > > diff --git a/drivers/gpu/drm/Kconfig b/drivers/gpu/drm/Kconfig
> > > index 7ff89690a976..e4524ccba040 100644
> > > --- a/drivers/gpu/drm/Kconfig
> > > +++ b/drivers/gpu/drm/Kconfig
> > > @@ -57,6 +57,19 @@ config DRM_DEBUG_MM
> > >
> > > If in doubt, say "N".
> > >
> > > +config DRM_USE_DYNAMIC_DEBUG
> > > + bool "use dynamic debug to implement drm.debug"
> > > + default n
> > > + depends on DRM
> > > + depends on DYNAMIC_DEBUG || DYNAMIC_DEBUG_CORE
> > > + depends on JUMP_LABEL
> > > + help
> > > + The drm debug category facility does a lot of unlikely bit-field
> > > + tests at runtime; while cheap individually, the cost accumulates.
> > > + This option uses dynamic debug facility (if configured and
> > > + using jump_label) to avoid those runtime checks, patching
> > > + the kernel when those debugs are desired.
> >
> > Can't we just make this an internal option that's enabled automatically
> > when dyndbg is around? Plus a comment somewhere that we really recommend
> > enabling dyndbg for drm. Or would this mean that in certain dyndbg
> > configurations we'd loose all the debug lines, which would suck?
> >
> > Anyway there's a pile of details, but the big picture I really like.
> > Especially that we can make dyndbg seamlessly support drm.debug is really
> > nice.
> >
> > Cheers, Daniel
> >
> > > +
> > > config DRM_DEBUG_SELFTEST
> > > tristate "kselftests for DRM"
> > > depends on DRM
> > > diff --git a/drivers/gpu/drm/drm_print.c b/drivers/gpu/drm/drm_print.c
> > > index 111b932cf2a9..e2acdfc7088b 100644
> > > --- a/drivers/gpu/drm/drm_print.c
> > > +++ b/drivers/gpu/drm/drm_print.c
> > > @@ -52,8 +52,75 @@ MODULE_PARM_DESC(debug, "Enable debug output, where each bit enables a debug cat
> > > "\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)");
> > > +
> > > +#ifndef CONFIG_DRM_USE_DYNAMIC_DEBUG
> > > module_param_named(debug, __drm_debug, int, 0600);
> > >
> > > +#else
> > > +static char *format_class_prefixes[] = {
> > > + cDRM_UT_CORE,
> > > + cDRM_UT_DRIVER,
> > > + cDRM_UT_KMS,
> > > + cDRM_UT_PRIME,
> > > + cDRM_UT_ATOMIC,
> > > + cDRM_UT_VBL,
> > > + cDRM_UT_STATE,
> > > + cDRM_UT_LEASE,
> > > + cDRM_UT_DP,
> > > + cDRM_UT_DRMRES
> > > +};
> > > +
> > > +#define OUR_QUERY_SIZE 64 /* > strlen "format '^%s' %cp" + longest prefix */
> > > +
> > > +static int param_set_dyndbg(const char *instr, const struct kernel_param *kp)
> > > +{
> > > + unsigned int val;
> > > + unsigned long changes, result;
> > > + int rc, chgct = 0, totct = 0, bitpos;
> > > + char query[OUR_QUERY_SIZE];
> > > +
> > > + rc = kstrtouint(instr, 0, &val);
> > > + if (rc) {
> > > + pr_err("%s: failed\n", __func__);
> > > + return -EINVAL;
> > > + }
> > > + result = val;
> > > + changes = result ^ __drm_debug;
> > > +
> > > + pr_debug("changes:0x%lx from result:0x%lx\n", changes, result);
> > > +
> > > + for_each_set_bit(bitpos, &changes, ARRAY_SIZE(format_class_prefixes)) {
> > > +
> > > + sprintf(query, "format '^%s' %cp", format_class_prefixes[bitpos],
> > > + test_bit(bitpos, &result) ? '+' : '-');
> > > +
> > > + chgct = dynamic_debug_exec_queries(query, "drm*");
> > > + if (chgct < 0) {
> > > + pr_err("%s: exec err:%d on: %s\n", __func__, chgct, query);
> > > + continue;
> > > + }
> > > + pr_debug("change ct:%d on %s\n", chgct, query);
> > > + totct += chgct;
> > > + }
> > > + pr_debug("total changes: %d\n", totct);
> > > + __drm_debug = result;
> > > + return 0;
> > > +}
> > > +
> > > +static int param_get_dyndbg(char *buffer, const struct kernel_param *kp)
> > > +{
> > > + pr_debug("debug-val:0x%x %u\n", __drm_debug, *((unsigned int *)kp->arg));
> > > + return scnprintf(buffer, PAGE_SIZE, "%u\n",
> > > + *((unsigned int *)kp->arg));
> > > +}
> > > +static const struct kernel_param_ops param_ops_debug = {
> > > + .set = param_set_dyndbg,
> > > + .get = param_get_dyndbg,
> > > +};
> > > +module_param_cb(debug, &param_ops_debug, &__drm_debug, 0644);
> > > +
> > > +#endif /* CONFIG_DRM_USE_DYNAMIC_DEBUG */
> > > +
> > > void __drm_puts_coredump(struct drm_printer *p, const char *str)
> > > {
> > > struct drm_print_iterator *iterator = p->arg;
> > > @@ -256,7 +323,7 @@ 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,
> > > +void _drm_dev_dbg(const struct device *dev, enum drm_debug_category category,
> > > const char *format, ...)
> > > {
> > > struct va_format vaf;
> > > @@ -278,9 +345,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 +364,7 @@ void __drm_dbg(enum drm_debug_category category, const char *format, ...)
> > >
> > > va_end(args);
> > > }
> > > -EXPORT_SYMBOL(__drm_dbg);
> > > +EXPORT_SYMBOL(___drm_dbg);
> > >
> > > void __drm_err(const char *format, ...)
> > > {
> > > diff --git a/include/drm/drm_print.h b/include/drm/drm_print.h
> > > index ff5ac0e88321..499fa0b35200 100644
> > > --- a/include/drm/drm_print.h
> > > +++ b/include/drm/drm_print.h
> > > @@ -319,6 +319,51 @@ enum drm_debug_category {
> > > DRM_UT_DRMRES = 0x200,
> > > };
> > >
> > > +#if !defined(CONFIG_DRM_USE_DYNAMIC_DEBUG)
> > > +
> > > +/* Use legacy drm-debug functions, and drm_debug_enabled().
> > > + * For cDRM_UT_* (converted category), identity map to DRM_UT_*
> > > + */
> > > +#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 cDRM_UT_CORE DRM_UT_CORE
> > > +#define cDRM_UT_DRIVER DRM_UT_DRIVER
> > > +#define cDRM_UT_KMS DRM_UT_KMS
> > > +#define cDRM_UT_PRIME DRM_UT_PRIME
> > > +#define cDRM_UT_ATOMIC DRM_UT_ATOMIC
> > > +#define cDRM_UT_VBL DRM_UT_VBL
> > > +#define cDRM_UT_STATE DRM_UT_STATE
> > > +#define cDRM_UT_LEASE DRM_UT_LEASE
> > > +#define cDRM_UT_DP DRM_UT_DP
> > > +#define cDRM_UT_DRMRES DRM_UT_DRMRES
> > > +
> > > +#else /* !CONFIG_DRM_USE_DYNAMIC_DEBUG */
> > > +
> > > +/* use dynamic_debug to avoid drm_debug_enabled().
> > > + * dyndbg has no category, so we prefix the format with a "class"
> > > + * string; cDRM_UT_* maps to those class strings
> > > + */
> > > +#define __drm_dbg(cls, fmt, ...) \
> > > + pr_debug(cls # fmt, ##__VA_ARGS__)
> > > +#define drm_dev_dbg(dev, cls, fmt, ...) \
> > > + dev_dbg(dev, cls # fmt, ##__VA_ARGS__)
> > > +
> > > +#define cDRM_UT_CORE "drm:core: "
> > > +#define cDRM_UT_DRIVER "drm:drvr: "
> > > +#define cDRM_UT_KMS "drm:kms: "
> > > +#define cDRM_UT_PRIME "drm:prime: "
> > > +#define cDRM_UT_ATOMIC "drm:atomic: "
> > > +#define cDRM_UT_VBL "drm:vbl: "
> > > +#define cDRM_UT_STATE "drm:state: "
> > > +#define cDRM_UT_LEASE "drm:lease: "
> > > +#define cDRM_UT_DP "drm:dp: "
> > > +#define cDRM_UT_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,7 +379,7 @@ __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,
> > > +void _drm_dev_dbg(const struct device *dev, enum drm_debug_category category,
> > > const char *format, ...);
> > >
> > > /**
> > > @@ -383,7 +428,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, cDRM_UT_CORE, fmt, ##__VA_ARGS__)
> > > /**
> > > * DRM_DEV_DEBUG_DRIVER() - Debug output for vendor specific part of the driver
> > > *
> > > @@ -391,7 +436,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, cDRM_UT_DRIVER, fmt, ##__VA_ARGS__)
> > > /**
> > > * DRM_DEV_DEBUG_KMS() - Debug output for modesetting code
> > > *
> > > @@ -399,7 +444,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, cDRM_UT_KMS, fmt, ##__VA_ARGS__)
> > >
> > > /*
> > > * struct drm_device based logging
> > > @@ -443,25 +488,25 @@ void drm_dev_dbg(const struct device *dev, enum drm_debug_category category,
> > >
> > >
> > > #define drm_dbg_core(drm, fmt, ...) \
> > > - drm_dev_dbg((drm) ? (drm)->dev : NULL, DRM_UT_CORE, fmt, ##__VA_ARGS__)
> > > + drm_dev_dbg((drm) ? (drm)->dev : NULL, cDRM_UT_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, cDRM_UT_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, cDRM_UT_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, cDRM_UT_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, cDRM_UT_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, cDRM_UT_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, cDRM_UT_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, cDRM_UT_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, cDRM_UT_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, cDRM_UT_DRMRES, fmt, ##__VA_ARGS__)
> > >
> > >
> > > /*
> > > @@ -471,7 +516,7 @@ void drm_dev_dbg(const struct device *dev, enum drm_debug_category category,
> > > */
> > >
> > > __printf(2, 3)
> > > -void __drm_dbg(enum drm_debug_category category, const char *format, ...);
> > > +void ___drm_dbg(enum drm_debug_category category, const char *format, ...);
> > > __printf(1, 2)
> > > void __drm_err(const char *format, ...);
> > >
> > > @@ -500,44 +545,45 @@ void __drm_err(const char *format, ...);
> > > #define DRM_ERROR_RATELIMITED(fmt, ...) \
> > > DRM_DEV_ERROR_RATELIMITED(NULL, fmt, ##__VA_ARGS__)
> > >
> > > +
> > > #define DRM_DEBUG(fmt, ...) \
> > > - __drm_dbg(DRM_UT_CORE, fmt, ##__VA_ARGS__)
> > > + __drm_dbg(cDRM_UT_CORE, fmt, ##__VA_ARGS__)
> > >
> > > #define DRM_DEBUG_DRIVER(fmt, ...) \
> > > - __drm_dbg(DRM_UT_DRIVER, fmt, ##__VA_ARGS__)
> > > + __drm_dbg(cDRM_UT_DRIVER, fmt, ##__VA_ARGS__)
> > >
> > > #define DRM_DEBUG_KMS(fmt, ...) \
> > > - __drm_dbg(DRM_UT_KMS, fmt, ##__VA_ARGS__)
> > > + __drm_dbg(cDRM_UT_KMS, fmt, ##__VA_ARGS__)
> > >
> > > #define DRM_DEBUG_PRIME(fmt, ...) \
> > > - __drm_dbg(DRM_UT_PRIME, fmt, ##__VA_ARGS__)
> > > + __drm_dbg(cDRM_UT_PRIME, fmt, ##__VA_ARGS__)
> > >
> > > #define DRM_DEBUG_ATOMIC(fmt, ...) \
> > > - __drm_dbg(DRM_UT_ATOMIC, fmt, ##__VA_ARGS__)
> > > + __drm_dbg(cDRM_UT_ATOMIC, fmt, ##__VA_ARGS__)
> > >
> > > #define DRM_DEBUG_VBL(fmt, ...) \
> > > - __drm_dbg(DRM_UT_VBL, fmt, ##__VA_ARGS__)
> > > + __drm_dbg(cDRM_UT_VBL, fmt, ##__VA_ARGS__)
> > >
> > > #define DRM_DEBUG_LEASE(fmt, ...) \
> > > - __drm_dbg(DRM_UT_LEASE, fmt, ##__VA_ARGS__)
> > > + __drm_dbg(cDRM_UT_LEASE, fmt, ##__VA_ARGS__)
> > >
> > > #define DRM_DEBUG_DP(fmt, ...) \
> > > - __drm_dbg(DRM_UT_DP, fmt, ## __VA_ARGS__)
> > > + __drm_dbg(cDRM_UT_DP, fmt, ## __VA_ARGS__)
> > >
> > > -#define __DRM_DEFINE_DBG_RATELIMITED(category, drm, fmt, ...) \
> > > +#define __DRM_DEFINE_DBG_RATELIMITED(DRM_UT, cDRM_UT, drm, fmt, ...) \
> > > ({ \
> > > static DEFINE_RATELIMIT_STATE(rs_, \
> > > DEFAULT_RATELIMIT_INTERVAL, \
> > > DEFAULT_RATELIMIT_BURST); \
> > > 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__); \
> > > + if (drm_debug_enabled(DRM_UT) && __ratelimit(&rs_)) \
> > > + drm_dev_dbg((drm_) ? (drm_)->dev : NULL, \
> > > + cDRM_UT, fmt, ##__VA_ARGS__); \
> > > })
> > >
> > > #define drm_dbg_kms_ratelimited(drm, fmt, ...) \
> > > - __DRM_DEFINE_DBG_RATELIMITED(KMS, drm, fmt, ## __VA_ARGS__)
> > > + __DRM_DEFINE_DBG_RATELIMITED(DRM_UT_KMS, cDRM_UT_KMS, drm, fmt, ## __VA_ARGS__)
> > >
> > > #define DRM_DEBUG_KMS_RATELIMITED(fmt, ...) \
> > > drm_dbg_kms_ratelimited(NULL, fmt, ## __VA_ARGS__)
> > > --
> > > 2.31.1
> > >
> >
> > --
> > Daniel Vetter
> > Software Engineer, Intel Corporation
> > http://blog.ffwll.ch
> > _______________________________________________
> > Intel-gfx mailing list
> > [email protected]
> > https://lists.freedesktop.org/mailman/listinfo/intel-gfx
>
> --
> Sean Paul, Software Engineer, Google / Chromium OS

2021-07-28 21:24:30

by Jim Cromie

[permalink] [raw]
Subject: Re: [Intel-gfx] [PATCH v3 3/5] drm/print: RFC add choice to use dynamic debug in drm-debug

On Tue, Jul 27, 2021 at 10:03 AM Sean Paul <[email protected]> wrote:
>
> On Thu, Jul 22, 2021 at 11:20 AM Sean Paul <[email protected]> wrote:
> >
>
> Reply-all fail. Adding everyone else back to my response.
>
> > On Tue, Jul 20, 2021 at 03:29:34PM +0200, Daniel Vetter wrote:
> > > On Wed, Jul 14, 2021 at 11:51:36AM -0600, Jim Cromie wrote:
> > > > drm's debug system uses distinct categories of debug messages, encoded
> > > > in an enum (DRM_UT_<CATEGORY>), which are mapped to bits in drm.debug.
> > > > drm_debug_enabled() does a lot of unlikely bit-mask checks on
> > > > drm.debug; we can use dynamic debug instead, and get all that
> > > > static_key/jump_label goodness.
> >
> > Hi Jim,
> > Thanks for your patches! Daniel pointed me at them in response to my drm_trace
> > patchset (https://patchwork.freedesktop.org/series/78133/). I'd love to get your
> > input on it. I think the 2 sets are mostly compatible, we'd just need to keep
> > drm_dev_dbg and do the CONFIG check in the function beside the trace_enabled
> > checks.
> >
> > > >
> > > > Dynamic debug has no concept of category, but we can map the DRM_UT_*
> > > > to a set of distinct prefixes; "drm:core:", "drm:kms:" etc, and
> > > > prepend them to the given formats.
> > > >
> > > > Then we can use:
> > > > `echo module drm format ^drm:core: +p > control`
> > > >
> > > > to enable every such "prefixed" pr_debug with one query. This new
> > > > prefix changes pr_debug's output, so is user visible, but it seems
> > > > unlikely to cause trouble for log watchers; they're not relying on the
> > > > absence of class prefix strings.
> > > >
> > > > This conversion yields ~2100 new callsites on my i7/i915 laptop:
> > > >
> > > > dyndbg: 195 debug prints in module drm_kms_helper
> > > > dyndbg: 298 debug prints in module drm
> > > > dyndbg: 1630 debug prints in module i915
> > > >
> > > > CONFIG_DRM_USE_DYNAMIC_DEBUG enables this, and is available if
> > > > CONFIG_DYNAMIC_DEBUG or CONFIG_DYNAMIC_DEBUG_CORE is chosen, and if
> > > > CONFIG_JUMP_LABEL is enabled; this because its required to get the
> > > > promised optimizations.
> > > >
> > > > The indirection/switchover is layered into the macro scheme:
> > > >
> > > > 0. A new callback on drm.debug which calls dynamic_debug_exec_queries
> > > > to map those bits to specific query/commands
> > > > dynamic_debug_exec_queries("format ^drm:kms: +p", "drm*");
> > > > here for POC, this should be in dynamic_debug.c
> > > > with a MODULE_PARAM_DEBUG_BITMAP(__drm_debug, { "prefix-1", "desc-1" }+)
> > >
> > > This is really awesome.
> >
> >
> > Agreed, this is a very clever way of merging the 2 worlds!
> >
> >
> > > For merging I think we need to discuss with dyn
> > > debug folks whether they're all ok with this, but it's exported already
> > > should should be fine.
> >
> > I wonder if this is a good time to reconsider our drm categories. IMO they're
> > overly broad and it's hard to get the right information without subscribing to
> > the firehose. It seems like dyndbg might be a good opportunity to unlock
> > subcategories of log messages.
> >
> > More concretely, on CrOS we can't subscribe to atomic or state categories since
> > they're too noisy. However if there was a "fail" subcategory which dumped
> > state/atomic logs on check failures, that would be really compelling. Something
> > like:
> >
> > drm:atomic:fail vs. drm:atomic
> >

YES

> > Both would be picked up if (drm.debug & DRM_DBG_ATOMIC), however it would allow
> > dyndbg-aware clients to get better logs without having a huge table of
> > individual log signatures.
> >
> > I'm not sure how tightly we'd want to control the subcategories. It could be
> > strict like the categories spelled out in drm_print.h, or an open prefix arg to
> > drm_dev_dbg. I suspect we'd want the former, but would want to be careful to
> > provide enough flexibility to properly

formalizing categories and subcategories is where the
practical selectivity of format ^prefix is determined.

While endless bikeshedding is a possible downside,
there are a few subtleties to note, so we can pick a harmonious 3-color scheme:

"drm:kms: " and "drm:kms:" are different (2nd, w/o trailing space,
allows subcats)
"drm:kms" is also different (includes "drm:kmsmart", whatever that would be)
"drm.kms" again. dot names anyone ?

ASIDE(s):

"drm:kms" and "drm:kms*" are different,
the latter does not work as you might reasonably expect.
This is because

commit 578b1e0701af34f9ef69daabda4431f1e8501109
Author: Changbin Du <[email protected]>
Date: Thu Jan 23 15:54:14 2014 -0800

dynamic_debug: add wildcard support to filter files/functions/modules

Add wildcard '*'(matches zero or more characters) and '?' (matches one
character) support when qurying debug flags.

specifically left format out of the wildcarded query terms.
And that was rational since the format search was already special
(floating substring, not exact match or basename match)
and format foobar should work analogously to grep foobar, ie w/o wildcards.
while an implied "format *foobar*" is possible, I dont like the
regex-iness implied in that 1st '*'

(2)

dyndbg is extremely agnostic about prefixes used by authors/subsystems

"1:", "2:", "3:" is a lot like the original: void dev_printk(const
char *level, ..).
w/o the trailing colon, even more so (I will be checking what it does!)
"Lo:", "Mid:", "Hi:" was proposed in a patchset once, and is usable today.

some unification of explicit wildcard chars * & ? and format floating
substr seems practical,
with it, prefix matching could handle complicated error message regimes.
Specifically, http return codes like 100, 200, 400, 404 etc would work.

/ASIDE


In any case, lets not try to over-control the categories & optional
subcategories,
at least not with lots of structure. Afterall, only code review will
prevent something like:

pr_debug("%s: blah blah\n", hex(sha1))
(queries on it are highly selective, but not organized)

IMO, its potentially useful to be able to add ad-hoc categories,
review and taste can moderate the ad-hockery,
"drm:misc:" seems a reasonable catch-all, esp with 3rd level
selectivity possible

Consider Sean's example: "drm:atomic:fail", and variations:

"drm:atomic:ok" - not as useful, unless we wanted a counter.
I dont think we need to rule it out.
to the extent that theres a traceable event here (success)
theres some utility to be able to put something of a label on it.

"drm:atomic:fail-%s" - we could have a dictionary of reasons,
(with open dictionary, neologisms allowed, any reason not to?)


> >
> > Of course, none of this needs to be decided to land this initial support, it can
> > be bolted on later easily enough (I think).
> >

I think so too, one such revisit...

Eventually, the "drm:" part of the prefix may become sufficiently unnecessary
that we could drop it in the name of log brevity.
The selectivity lost to "format ^prefix" is recovered by adding
"module drm*" or similar,
so somemod.foobar's use of pr_debug("atomic: blabla") would be excluded,

Or a flag-day, where we swap over to drm.dot.naming.
Doing so modestly improves the use of ':' for a log-entry field separator.
(though probably not a material improvement, structured logs are
better for this)

2022-03-06 01:34:32

by Jim Cromie

[permalink] [raw]
Subject: Re: [PATCH v3 3/5] drm/print: RFC add choice to use dynamic debug in drm-debug

From: Daniel Vetter <[email protected]>


Hi Daniel, everyone,

Ive substantially updated this patchset,
and I thought it useful to reply here.

Im noting the biggest changes in context below, trimming heavily otherwize.

Also, Ive lost the msg in my gmail-cloud, so this lacks
the usual "Daniel said: " attribution, and the "> " marks.
Ive prefixed "< " to 1st line of my replies where it helps.

The current patchset is here:

https://patchwork.freedesktop.org/series/100290/
https://lore.kernel.org/lkml/[email protected]/

Its "failing" patchwork CI cuz of a macro warning in dyndbg, which
would be nice for CI to "pass" because its out of DRM tree, and
subject to a separate review process, and in the meantime, it would be
nice to see it under test.


Going item by item:

On Wed, Jul 14, 2021 at 11:51:36AM -0600, Jim Cromie wrote:
> drm's debug system uses distinct categories of debug messages, encoded
> in an enum (DRM_UT_<CATEGORY>),

enum is now renumbered to 0-15 (fits in 4 bits)
drm_debug_enabled() does BIT(cat)
15 is unclassed/reserved

> Dynamic debug has no concept of category, but we can map the DRM_UT_*

now it has "class" keyword, and class_id:4 field.

#> echo module drm class 1 +p > control # 1=DRM_UT_KMS iirc

This interface is unused yet, DRM is its A-1 customer, are you shopping ?
Since its unused, it cannot break anything not using it :-)

> CONFIG_DRM_USE_DYNAMIC_DEBUG enables this, and is available if

still true.

> The indirection/switchover is layered into the macro scheme:

Heres where the biggest DRM centric changes (vs old) are:

The cDRM_UT_* => prefix-string mapping is gone; while it worked, it
made the literal format strings config dependent, and was more
complicated to explain. Fitting category into class_id is much
cleaner.

old way replaced drm*dbg with pr_debug (at surface level)
new way adapts drm*dbg to reuse the class-Factory macro under pr_debug.

This loses pr_debug's log-decorating feature, but DRM has its own
conventions, and extra decorations are unlikely to really add anything.
OTOH, drm could re-use those flags to optionalize some of its conventions.

> 0. A new callback on drm.debug which calls dynamic_debug_exec_queries

now in dyndbg, where it belonged. now just uses class query inside.


This is really awesome. For merging I think we need to discuss with dyn
debug folks whether they're all ok with this, but it's exported already
should should be fine.

< Your (fresh) endorsement should help :-)
Particularly, the new dyndbg features need a user.

>
> 1. A "converted" or "classy" DRM_UT_* map
>

repeating, 2nd map is gone, DRM_UT_* is merely renumbered.

> DRM_UT_* are unchanged, since theyre used in drm_debug_enabled()
> and elsewhere.

I think for the production version of these we need to retire/deprecate
them, at least for drm core. Otherwise you have an annoying mismatch
between drm.debug module option and dyn debug.

< I think this isnt relevant now, since symbols are preserved.

Also, the __drm_debug var is used directly by the CLASSBITS macro,
(and therefore the callbacks), so /sys/module/drm/parameters/debug is
preserved at an ABI-ish level. (__drm_debug now ulong, to work with BIT)

>
> 2. drm_dev_dbg & drm_debug are renamed (prefixed with '_')
>
> old names are now macros, calling either:
> legacy: -> to renamed fn
> enabled: -> dev_dbg & pr_debug, with cDRM-prefix # format.
>

For merging, can we pull out the renames and reorgs from this patch, and
then maybe also the reorder the next patch in your series here to be
before the dyn debug stuff?

< the above adaptation is re-adapted to use dyndbg's new class-Factory
macro, other stuff is gone.


> Signed-off-by: Jim Cromie <[email protected]>
> ---
> drivers/gpu/drm/Kconfig | 13 +++++
> drivers/gpu/drm/drm_print.c | 75 ++++++++++++++++++++++++--
> include/drm/drm_print.h | 102 ++++++++++++++++++++++++++----------
> 3 files changed, 158 insertions(+), 32 deletions(-)

update - drm parts are slightly smaller now :-)

[jimc@frodo wk-next]$ git diff --stat master
Documentation/admin-guide/dynamic-debug-howto.rst | 7 +++++
drivers/gpu/drm/Kconfig | 12 ++++++++
drivers/gpu/drm/Makefile | 2 ++
drivers/gpu/drm/drm_print.c | 56 ++++++++++++++++++++++------------
include/drm/drm_print.h | 80 +++++++++++++++++++++++++++++
include/linux/dynamic_debug.h | 113 +++++++++++++++++++++++++++++
lib/dynamic_debug.c | 140 +++++++++++++++++++++++++++++
7 files changed, 323 insertions(+), 87 deletions(-)


I really like this, I think you can drop the RFC. A few more things that I
think we need:

- An overview kerneldoc section which explains the interfaces and how it
all works together. Essentially your commit message with some light
markup to make it look good.

< not sure anything worth documenting has survived.

- I think it would be really good to review the driver docs for all this
and make sure it's complete. Some of the interface functions aren't
documented yet (or maybe the ones that drivers shouldn't used need more
__ prefixes to denote them as internal, dunno).

- I guess deprecation notice for drm_debug_enabled() and all that, so that
we have a consistent interface. Doing the conversion will probably

< this keeps drm_debug_enabled(), and __drm_debug, so those users are fine.
__drm_debug_enabled() is optimized version for macro-wrapped sites

highlight the need for a bit more infrastructure and tooling, e.g. the
bigger dump functions (like edid hex dump, or also the various decode
helpers we have for dp, hdmi infoframes and all that) ideally have a
single dyn_debug label to enable all of them instead of line-by-line.
Tbh no idea how this should work, might need dyndbg work too.

< Factory-macros should help here, havent looked.

- For the driver side of this we probably want a
Documentation/gpu/TODO.rst entry if it's not all easy to convert
directly.


> +config DRM_USE_DYNAMIC_DEBUG
> + bool "use dynamic debug to implement drm.debug"
> + default n
> + depends on DRM
> + depends on DYNAMIC_DEBUG || DYNAMIC_DEBUG_CORE
> + depends on JUMP_LABEL
> + help
> + The drm debug category facility does a lot of unlikely bit-field
> + tests at runtime; while cheap individually, the cost accumulates.
> + This option uses dynamic debug facility (if configured and
> + using jump_label) to avoid those runtime checks, patching
> + the kernel when those debugs are desired.

Can't we just make this an internal option that's enabled automatically
when dyndbg is around? Plus a comment somewhere that we really recommend
enabling dyndbg for drm. Or would this mean that in certain dyndbg
configurations we'd loose all the debug lines, which would suck?

< I have 'default y' now.

WRT losing debug lines, I cant think how, but it raises a thought; cuz
drm.debug uses .class_id, the mod,func,file info isnt needed to
support queries (other than ad-hoc at >control), drm could drop them.
Its already lost pr_debug's optional mod.func.ln prefix, and cannot
use them for that. (but Im foreshadowing, see bottom)


Anyway there's a pile of details, but the big picture I really like.
Especially that we can make dyndbg seamlessly support drm.debug is really
nice.

Cheers, Daniel


< Wait, theres more ! (here comes the tease) :-D

0. this patchset and others below are at:

ghlinux-ro https://github.com/jimc/linux.git (fetch)

lkp-robot <[email protected]> has been helping a lot.

1. dd-drm branch - this patchset

commit 46a5bd89e47d0f7e4ad63b4f574815f01d4290a0
(HEAD -> dd-drm, ghlinux/dd-drm, ghlinux-ro/dd-drm)

passing robot tests.

2. dyn-drm-trc branch - on top of 1.dd-drm

commit 0473a8ecdb15ec0e63644b77da575905c5851462
(ghlinux/dyn-drm-trc, ghlinux-ro/dyn-drm-trc, dyn-drm-trc)

It starts with Vincent Whitchurch's patch:
https://lore.kernel.org/lkml/[email protected]/

which (oversimplifying) added a trace-event and called it from
pr_debug, and which met with some approval from Steve Rostedt.

It then recapitulates those changes in drm_*dbg.

3. dd-diet-next - on top of 2.dyn-drm-trc.

passes lkp-robot tests, but still problematic

This splits struct _ddebug in 2, then de-duplicates the _ddebug_site
records (containing repetitive module,filename,function). In my
fedora-ish config kernel containing ~3100 callsites in builtin
modules, I see ~40% reduction in 24/64 of the full data footprint.
Id expect a little more in modules, due to higher prdbgs/fns ratio.

forex: (69% compression here)
dyndbg: 3883 debug prints in module amdgpu (in 1190 functions)

Its incomplete 2x: needs some union-fu, and more work to drop the
.site pointer. This would drop 8/40 from struct _ddebug, recover another 8/56 of total footprint.

A noteworthy side-effect of this is that it becomes practical to drop
all _ddebug_site data for modules which don't need/want it.

DRM (in 2.dyn-drm-trc) is such a user; it gets the control it needs
using .class_id, and has no log-decoration facility which would use
the 3 fields. It should just get lots of "_na_"s in cat control.

Dyndbg can be easily fixed to not apply query-commands which specify
those terms to callsites which do not have the data.


Clearly, getting to here is gonna be a many-step process.
DRM buy-in will certainly help :-)


Cheers, Jim