Message-ID: <X8pY/H512EMR3bUX@intel.com>
Date:   Fri, 4 Dec 2020 17:42:52 +0200
From:   Ville Syrjälä <ville.syrjala@...ux.intel.com>
To:     Jim Cromie <jim.cromie@...il.com>
Cc:     dri-devel@...ts.freedesktop.org, linux-kernel@...r.kernel.org,
        David Airlie <airlied@...ux.ie>, jbaron@...mai.com,
        Thomas Zimmermann <tzimmermann@...e.de>
Subject: Re: [RFC PATCH 1/2] drm: RFC add choice to use dynamic debug in
 drm-debug

On Thu, Dec 03, 2020 at 08:53:17PM -0700, Jim Cromie wrote:
> drm's debug system uses distinct categories of debug messages, mapped
> to bits in drm.debug.  Currently, code does a lot of unlikely bit-mask
> checks on drm.debug (in drm_debug_enabled), we can use dynamic debug
> instead, and get all that jump_label goodness.

whatis jump_label?

One thing that bugs me about the current drm_dbg() stuff is that
it's a function, and thus we pay the cost of setting up the
arguments even when debugs are not enabled. I played around a bit
with making it a macro again with the unlikely bit check moved
into the macro. That did seem to make some of the asm a bit nicer
where the debug stuff got shoved out the main codepath, but
it did result in a slight net increase in code size. What I didn't
have time to do is check if this has any measurable speed effect
on eg. TEST_ONLY commits.

And while doing that I started to ponder if we could use something
like the alternate() instruction stuff to patch the code at runtime
in order to turn all those debug checks into nops when debugging
is not enabled. But I couldn't immediately find any generic
infrastructure for it. So now I wonder if this jump_label is something
like that?

> 
> RFC: dynamic debug has no concept of category, but we can do without
> one if we can prepend a class-prefix to each printk format.  Then we
> can use "format ^prefix" to select the whole category with one query.
> This is a log-facing and user visible change, 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 laptop:
> 
>   dyndbg: 195 debug prints in module drm_kms_helper
>   dyndbg: 298 debug prints in module drm
>   dyndbg: 1630 debug prints in module i915
> 
> Since this change has wide-ranging effects (many drm drivers, with
> many callsites, and kernel image growth), and most vendors don't
> enable DYNAMIC_DEBUG, we supplement the existing mechanism, adding
> CONFIG_DRM_USE_DYNAMIC_DEBUG to enable the new one.
> 
> The indirection/switchover has a few parts:
> 
> 1 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*");
> 
> 2 a "converted" or "classy" DRM_UT_* map
>   similar to DRM_UT_* ( symbol => bit-mask )
>   named it  cDRM_UT_* ( symbol => format-class-prefix-string )
> 
>   cDRM_UT_* is either ( CONFIG_DRM_USE_DYNAMIC_DEBUG )
>   legacy: cDRM_UT_* <-- DRM_UT_*
>   enabled:
>   +#define cDRM_UT_KMS    "drm:kms: "
>   +#define cDRM_UT_PRIME  "drm:prime: "
>   +#define cDRM_UT_ATOMIC "drm:atomic: "
> 
>   these are similar to "gvt: cmd:" in i915/gvt
>   and effectively a replacement for DRM_NAME
>   please bikeshed on keys, values. latter are log-facing.
> 
> 3 drm_dev_dbg & drm_debug are renamed (prefixed with '_')
>   old names are now macros, which are ifdefd
>   legacy:  -> to renamed fn
>   enabled: -> dev_dbg & pr_debug, after prepending prefix to format.
> 
> 4 names in (2) are called from DRM_DEBUG_<Category> and drm_dbg_<Category>.
>   all these get "converted" to use cDRM_UT_*, to get right token type.
> 
> RFC: for dynamic debug, category is a source-facing addition;
> something like pr_debug_cat(cat, ...) would do it, iff cat is a
> compile-time const.  Note that cat isn't needed in the printing, it
> would be saved into a new field in struct _ddebug, and used only for
> callsite selection, activation and control.
> 
> Signed-off-by: Jim Cromie <jim.cromie@...il.com>
> ---
>  drivers/gpu/drm/Kconfig     | 13 ++++++
>  drivers/gpu/drm/drm_print.c | 75 ++++++++++++++++++++++++++++--
>  include/drm/drm_print.h     | 92 +++++++++++++++++++++++++++----------
>  3 files changed, 153 insertions(+), 27 deletions(-)
> 
> diff --git a/drivers/gpu/drm/Kconfig b/drivers/gpu/drm/Kconfig
> index 147d61b9674e..854bc1ad21fb 100644
> --- a/drivers/gpu/drm/Kconfig
> +++ b/drivers/gpu/drm/Kconfig
> @@ -54,6 +54,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
> +	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 f32d179e139d..2bd5c38aa100 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, implying 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 format with a class-string,
> + * and alter cDRM_UT_* to provide 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
>   *
> @@ -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)->dev, DRM_UT_CORE, fmt, ##__VA_ARGS__)
> +	drm_dev_dbg((drm)->dev, cDRM_UT_CORE, fmt, ##__VA_ARGS__)
>  #define drm_dbg(drm, fmt, ...)						\
> -	drm_dev_dbg((drm)->dev, DRM_UT_DRIVER, fmt, ##__VA_ARGS__)
> +	drm_dev_dbg((drm)->dev, cDRM_UT_DRIVER, fmt, ##__VA_ARGS__)
>  #define drm_dbg_kms(drm, fmt, ...)					\
> -	drm_dev_dbg((drm)->dev, DRM_UT_KMS, fmt, ##__VA_ARGS__)
> +	drm_dev_dbg((drm)->dev, cDRM_UT_KMS, fmt, ##__VA_ARGS__)
>  #define drm_dbg_prime(drm, fmt, ...)					\
> -	drm_dev_dbg((drm)->dev, DRM_UT_PRIME, fmt, ##__VA_ARGS__)
> +	drm_dev_dbg((drm)->dev, cDRM_UT_PRIME, fmt, ##__VA_ARGS__)
>  #define drm_dbg_atomic(drm, fmt, ...)					\
> -	drm_dev_dbg((drm)->dev, DRM_UT_ATOMIC, fmt, ##__VA_ARGS__)
> +	drm_dev_dbg((drm)->dev, cDRM_UT_ATOMIC, fmt, ##__VA_ARGS__)
>  #define drm_dbg_vbl(drm, fmt, ...)					\
> -	drm_dev_dbg((drm)->dev, DRM_UT_VBL, fmt, ##__VA_ARGS__)
> +	drm_dev_dbg((drm)->dev, cDRM_UT_VBL, fmt, ##__VA_ARGS__)
>  #define drm_dbg_state(drm, fmt, ...)					\
> -	drm_dev_dbg((drm)->dev, DRM_UT_STATE, fmt, ##__VA_ARGS__)
> +	drm_dev_dbg((drm)->dev, cDRM_UT_STATE, fmt, ##__VA_ARGS__)
>  #define drm_dbg_lease(drm, fmt, ...)					\
> -	drm_dev_dbg((drm)->dev, DRM_UT_LEASE, fmt, ##__VA_ARGS__)
> +	drm_dev_dbg((drm)->dev, cDRM_UT_LEASE, fmt, ##__VA_ARGS__)
>  #define drm_dbg_dp(drm, fmt, ...)					\
> -	drm_dev_dbg((drm)->dev, DRM_UT_DP, fmt, ##__VA_ARGS__)
> +	drm_dev_dbg((drm)->dev, cDRM_UT_DP, fmt, ##__VA_ARGS__)
>  #define drm_dbg_drmres(drm, fmt, ...)					\
> -	drm_dev_dbg((drm)->dev, DRM_UT_DRMRES, fmt, ##__VA_ARGS__)
> +	drm_dev_dbg((drm)->dev, 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,29 +545,30 @@ void __drm_err(const char *format, ...);
>  #define DRM_ERROR_RATELIMITED(fmt, ...)					\
>  	DRM_DEV_ERROR_RATELIMITED(NULL, fmt, ##__VA_ARGS__)
>  
> +
>  #define DRM_DEBUG(fmt, ...)						\
> -	__drm_dbg(DRM_UT_CORE, fmt, ##__VA_ARGS__)
> +	__drm_dbg(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_DEBUG_KMS_RATELIMITED(fmt, ...)				\
> @@ -531,7 +577,7 @@ void __drm_err(const char *format, ...);
>  				      DEFAULT_RATELIMIT_INTERVAL,       \
>  				      DEFAULT_RATELIMIT_BURST);         \
>  	if (__ratelimit(&_rs))						\
> -		drm_dev_dbg(NULL, DRM_UT_KMS, fmt, ##__VA_ARGS__);	\
> +		drm_dev_dbg(NULL, cDRM_UT_KMS, fmt, ##__VA_ARGS__);	\
>  })
>  
>  /*
> -- 
> 2.28.0
> 
> _______________________________________________
> dri-devel mailing list
> dri-devel@...ts.freedesktop.org
> https://lists.freedesktop.org/mailman/listinfo/dri-devel

-- 
Ville Syrjälä
Intel

Powered by blists - more mailing lists