Re: [RFC v2] drm: Enable dynamic debug for DRM_[DEV]_DEBUG*

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

 



On Wed, Dec 07, 2016 at 06:35:29PM +0000, Robert Bragg wrote:
> This is still missing corresponding documentation changes, and I haven't
> moved anything to drm_print.h yet, as suggested.
> 
> Sending out with a few functional improvements first to get agreement
> before documenting anything (changes summarised in v2: section below)
> 
> In particular, affecting the output format, I stole an idea from Tvrtko
> Ursulin to have the prefix for messages be based on the driver name,
> such as "[i915]" instead of always being "[drm]".
> 
> Depending on peoples thoughts on compatibility, we could consider
> removing the prefix given that the dynamic debug control interface has a
> way of specifying that messages should include a module name, function
> or line info like:
> 
> echo "module i915 +mfp" > dynamic_debug/control
> 
> That would enable all i915 debug messages with a module and function
> prefix.
> 
> A trade-off would be that anyone only using the drm.drm_debug interface
> to control messages would loose some information. If we really wanted we
> could have the best of both by adding a utility printing api that can
> recognise when printing due to a dynamic debug control query vs
> drm.drm_debug to conditionally add the prefix.
> 
> --- >8 --- (git am --scissors)
> 
> Dynamic debug messages (ref: Documentation/dynamic-debug-howto.txt)
> allow fine grained control over which debug messages are enabled with
> runtime control through /sysfs/kernel/debug/dynamic_debug/control
> 
> This provides more control than the current drm.drm_debug parameter
> which for some use cases is impractical to use given how chatty
> some drm debug categories are.
> 
> For example all debug messages in i915_drm.c can be enabled with:
> echo "file i915_perf.c +p" > dynamic_debug/control
> 
> This doesn't strictly maintain format compatibility with the previous
> debug messages since the category is now added as part of the prefix
> like "[drm][kms] No FB found". Adding the categories with a consistent
> format makes it possible to enable categories with a dynamic debug
> query like: echo "format [kms] +p" > dynamic_debug/control
> 
> This maintains support for enabling debug messages using the drm_debug
> parameter. If dynamic debug is not enabled via CONFIG_DYNAMIC_DEBUG the
> debug messages essentially work as before, except with the inclusion of
> categories in the format strings as described above.
> 
> This removes the drm_[dev_]printk wrappers considering that the dynamic
> debug macros are only useful if they can track the __FILE__, __func__
> and __LINE__ where they are called. The wrapper didn't seem necessary in
> the DRM_UT_NONE case with no category flag.
> 
> The non _DEV macros are no longer defined in terms of passing NULL to a
> _DEV variant to avoid have the core.c dev_printk implementation adding
> "(NULL device *)". The previous drm_[dev_]prink function used to handle
> this as a special case.
> 
> Instead of using DRM_NAME to add [drm] to the start of every message,
> the prefix is now based on module_name(THIS_MODULE) so it will be [drm]
> or e.g. [i915] for the Intel driver. Later we might consider removing
> the prefix altogether considering that the dynamic debug control
> interface has a way of optionally adding the module, function or line to
> the formatting of messages.
> 
> v2:
>     Add categories to format like "[drm][kms] No FB found"
>     Only single conditional call per message (macros expand to less code)
>     Uses __dynamic_pr_debug/dev_dbg for dynamic formatting features
>     Use module name for msg prefix like [drm] or [i915]
> 
> Signed-off-by: Robert Bragg <robert@xxxxxxxxxxxxx>
> Cc: dri-devel@xxxxxxxxxxxxxxxxxxxxx
> Cc: Daniel Vetter <daniel.vetter@xxxxxxxx>
> Cc: Tvrtko Ursulin <tvrtko.ursulin@xxxxxxxxx>

So assuming I understand it correctly - I like this 3way cascade of
dynamic debug, then printk and no_printk fallback if CONFIG_DEBUG=n for
the space concious. But I guess we do need to add a DRM Kconfig knob to
set DEBUG, at least I'm not entirely sure how that's supposed to work. Or
we might need to have our own #ifdef maze for this. Maybe we need to keep
the old drm*printk stuff for that?

Anyway, I still think this is pretty cool, if we can get some common
ground with Tvrtko's stuff and some acks and reviews then I can pull it
in.
-Daniel

> ---
>  drivers/gpu/drm/drm_drv.c |  47 -----------
>  include/drm/drmP.h        | 202 +++++++++++++++++++++++++++++-----------------
>  2 files changed, 127 insertions(+), 122 deletions(-)
> 
> diff --git a/drivers/gpu/drm/drm_drv.c b/drivers/gpu/drm/drm_drv.c
> index f74b7d0..25d00aa 100644
> --- a/drivers/gpu/drm/drm_drv.c
> +++ b/drivers/gpu/drm/drm_drv.c
> @@ -65,53 +65,6 @@ static struct idr drm_minors_idr;
>  
>  static struct dentry *drm_debugfs_root;
>  
> -#define DRM_PRINTK_FMT "[" DRM_NAME ":%s]%s %pV"
> -
> -void drm_dev_printk(const struct device *dev, const char *level,
> -		    unsigned int category, const char *function_name,
> -		    const char *prefix, const char *format, ...)
> -{
> -	struct va_format vaf;
> -	va_list args;
> -
> -	if (category != DRM_UT_NONE && !(drm_debug & category))
> -		return;
> -
> -	va_start(args, format);
> -	vaf.fmt = format;
> -	vaf.va = &args;
> -
> -	if (dev)
> -		dev_printk(level, dev, DRM_PRINTK_FMT, function_name, prefix,
> -			   &vaf);
> -	else
> -		printk("%s" DRM_PRINTK_FMT, level, function_name, prefix, &vaf);
> -
> -	va_end(args);
> -}
> -EXPORT_SYMBOL(drm_dev_printk);
> -
> -void drm_printk(const char *level, unsigned int category,
> -		const char *format, ...)
> -{
> -	struct va_format vaf;
> -	va_list args;
> -
> -	if (category != DRM_UT_NONE && !(drm_debug & category))
> -		return;
> -
> -	va_start(args, format);
> -	vaf.fmt = format;
> -	vaf.va = &args;
> -
> -	printk("%s" "[" DRM_NAME ":%ps]%s %pV",
> -	       level, __builtin_return_address(0),
> -	       strcmp(level, KERN_ERR) == 0 ? " *ERROR*" : "", &vaf);
> -
> -	va_end(args);
> -}
> -EXPORT_SYMBOL(drm_printk);
> -
>  /*
>   * DRM Minors
>   * A DRM device can provide several char-dev interfaces on the DRM-Major. Each
> diff --git a/include/drm/drmP.h b/include/drm/drmP.h
> index a9cfd33..0416114 100644
> --- a/include/drm/drmP.h
> +++ b/include/drm/drmP.h
> @@ -58,6 +58,7 @@
>  #include <linux/vmalloc.h>
>  #include <linux/workqueue.h>
>  #include <linux/dma-fence.h>
> +#include <linux/dynamic_debug.h>
>  
>  #include <asm/mman.h>
>  #include <asm/pgalloc.h>
> @@ -129,15 +130,22 @@ struct dma_buf_attachment;
>   * run-time by echoing the debug value in its sysfs node:
>   *   # echo 0xf > /sys/module/drm/parameters/debug
>   */
> -#define DRM_UT_NONE		0x00
>  #define DRM_UT_CORE 		0x01
> +#define _DRM_UT_core		0x01
>  #define DRM_UT_DRIVER		0x02
> +#define _DRM_UT_drv		0x02
>  #define DRM_UT_KMS		0x04
> +#define _DRM_UT_kms		0x04
>  #define DRM_UT_PRIME		0x08
> +#define _DRM_UT_prime		0x08
>  #define DRM_UT_ATOMIC		0x10
> +#define _DRM_UT_atomic		0x10
>  #define DRM_UT_VBL		0x20
> +#define _DRM_UT_vbl		0x20
>  #define DRM_UT_STATE		0x40
>  
> +#define _DRM_PREFIX module_name(THIS_MODULE)
> +
>  /***********************************************************************/
>  /** \name DRM template customization defaults */
>  /*@{*/
> @@ -146,25 +154,19 @@ struct dma_buf_attachment;
>  /** \name Macros to make printk easier */
>  /*@{*/
>  
> -#define _DRM_PRINTK(once, level, fmt, ...)				\
> -	do {								\
> -		printk##once(KERN_##level "[" DRM_NAME "] " fmt,	\
> -			     ##__VA_ARGS__);				\
> -	} while (0)
> -
> -#define DRM_INFO(fmt, ...)						\
> -	_DRM_PRINTK(, INFO, fmt, ##__VA_ARGS__)
> -#define DRM_NOTE(fmt, ...)						\
> -	_DRM_PRINTK(, NOTICE, fmt, ##__VA_ARGS__)
> -#define DRM_WARN(fmt, ...)						\
> -	_DRM_PRINTK(, WARNING, fmt, ##__VA_ARGS__)
> -
> -#define DRM_INFO_ONCE(fmt, ...)						\
> -	_DRM_PRINTK(_once, INFO, fmt, ##__VA_ARGS__)
> -#define DRM_NOTE_ONCE(fmt, ...)						\
> -	_DRM_PRINTK(_once, NOTICE, fmt, ##__VA_ARGS__)
> -#define DRM_WARN_ONCE(fmt, ...)						\
> -	_DRM_PRINTK(_once, WARNING, fmt, ##__VA_ARGS__)
> +#define DRM_INFO(fmt, args...)						\
> +	pr_info("[%s] " fmt, _DRM_PREFIX, ##args)
> +#define DRM_NOTE(fmt, args...)						\
> +	pr_notice("[%s] " fmt, _DRM_PREFIX, ##args)
> +#define DRM_WARN(fmt, args...)						\
> +	pr_warn("[%s] " fmt, _DRM_PREFIX, ##args)
> +
> +#define DRM_INFO_ONCE(fmt, args...)					\
> +	pr_info_once("[%s] " fmt, _DRM_PREFIX, ##args)
> +#define DRM_NOTE_ONCE(fmt, args...)					\
> +	pr_notice_once("[%s] " fmt, _DRM_PREFIX, ##args)
> +#define DRM_WARN_ONCE(fmt, args...)					\
> +	pr_warn_once("[%s] " fmt, _DRM_PREFIX, ##args)
>  
>  /**
>   * Error output.
> @@ -172,11 +174,10 @@ struct dma_buf_attachment;
>   * \param fmt printf() like format string.
>   * \param arg arguments
>   */
> -#define DRM_DEV_ERROR(dev, fmt, ...)					\
> -	drm_dev_printk(dev, KERN_ERR, DRM_UT_NONE, __func__, " *ERROR*",\
> -		       fmt, ##__VA_ARGS__)
> -#define DRM_ERROR(fmt, ...)						\
> -	drm_printk(KERN_ERR, DRM_UT_NONE, fmt,	##__VA_ARGS__)
> +#define DRM_DEV_ERROR(dev, fmt, args...)				\
> +	dev_err(dev, "[%s:%s]*ERROR*" fmt, _DRM_PREFIX, __func__, ##args)
> +#define DRM_ERROR(fmt, args...)						\
> +	pr_err("[%s:%s]*ERROR*" fmt, _DRM_PREFIX, __func__, ##args)
>  
>  /**
>   * Rate limited error output.  Like DRM_ERROR() but won't flood the log.
> @@ -184,81 +185,129 @@ struct dma_buf_attachment;
>   * \param fmt printf() like format string.
>   * \param arg arguments
>   */
> -#define DRM_DEV_ERROR_RATELIMITED(dev, fmt, ...)			\
> +#define DRM_DEV_ERROR_RATELIMITED(dev, fmt, args...)			\
>  ({									\
>  	static DEFINE_RATELIMIT_STATE(_rs,				\
>  				      DEFAULT_RATELIMIT_INTERVAL,	\
>  				      DEFAULT_RATELIMIT_BURST);		\
>  									\
>  	if (__ratelimit(&_rs))						\
> -		DRM_DEV_ERROR(dev, fmt, ##__VA_ARGS__);			\
> +		DRM_DEV_ERROR(dev, fmt, ##args);			\
>  })
> -#define DRM_ERROR_RATELIMITED(fmt, ...)					\
> -	DRM_DEV_ERROR_RATELIMITED(NULL, fmt, ##__VA_ARGS__)
> -
> -#define DRM_DEV_INFO(dev, fmt, ...)					\
> -	drm_dev_printk(dev, KERN_INFO, DRM_UT_NONE, __func__, "", fmt,	\
> -		       ##__VA_ARGS__)
> -
> -#define DRM_DEV_INFO_ONCE(dev, fmt, ...)				\
> +#define DRM_ERROR_RATELIMITED(fmt, args...)				\
>  ({									\
> -	static bool __print_once __read_mostly;				\
> -	if (!__print_once) {						\
> -		__print_once = true;					\
> -		DRM_DEV_INFO(dev, fmt, ##__VA_ARGS__);			\
> -	}								\
> +	static DEFINE_RATELIMIT_STATE(_rs,				\
> +				      DEFAULT_RATELIMIT_INTERVAL,	\
> +				      DEFAULT_RATELIMIT_BURST);		\
> +									\
> +	if (__ratelimit(&_rs))						\
> +		DRM_ERROR(fmt, ##args);					\
>  })
>  
> +#define DRM_DEV_INFO(dev, fmt, args...)					\
> +	dev_info(dev, "[%s:%s] " fmt, _DRM_PREFIX, __func__, ##args)
> +
> +#define DRM_DEV_INFO_ONCE(dev, fmt, args...)				\
> +	dev_info_once(dev, "[%s:%s] " fmt, _DRM_PREFIX, __func__, ##args)
> +
>  /**
>   * Debug output.
>   *
>   * \param fmt printf() like format string.
>   * \param arg arguments
>   */
> +
> +#if defined(CONFIG_DYNAMIC_DEBUG)
> +#define DRM_DEF_DYN_DEBUG_DATA(name, fmt)				\
> +	DEFINE_DYNAMIC_DEBUG_METADATA(name, fmt);
> +#define DRM_DYN_DEBUG_BRANCH(descriptor)				\
> +	DYNAMIC_DEBUG_BRANCH(descriptor)
> +
> +#define __drm_dyn_dev_dbg(descriptor, dev, fmt, args...)		\
> +	__dynamic_dev_dbg(descriptor, dev, fmt, ##args)
> +#define __drm_dyn_pr_debug(descriptor, fmt, args...)			\
> +	__dynamic_pr_debug(descriptor, fmt, ##args)
> +#else
> +#define DRM_DEF_DYN_DEBUG_DATA(name, fmt)	do {} while(0)
> +#define DRM_DYN_DEBUG_BRANCH(descriptor)	0
> +
> +#define __drm_dyn_dev_dbg(descriptor, dev, fmt, args...)		\
> +	dev_dbg(dev, fmt, ##args)
> +#define __drm_dyn_pr_debug(descriptor, fmt, args...)			\
> +	pr_debug(fmt, ##args)
> +#endif
> +
> +/* If modifying, note the duplication of the format strings for the
> + * dynamic debug meta data and for passing to printk. We don't
> + * deref descriptor->format to handle building without
> + * CONFIG_DYNAMIC_DEBUG
> + */
> +#define _DRM_DEV_DEBUG(dev, cat, fmt, args...)				\
> +({									\
> +	DRM_DEF_DYN_DEBUG_DATA(descriptor, "[%s:%s]["#cat"] " fmt);	\
> +	if (DRM_DYN_DEBUG_BRANCH(descriptor) ||				\
> +	    unlikely(drm_debug & _DRM_UT_##cat)) {			\
> +		__drm_dyn_dev_dbg(&descriptor, dev,			\
> +				  "[%s:%s]["#cat"] " fmt,		\
> +				  _DRM_PREFIX, __func__, ##args);	\
> +	}								\
> +})
> +#define _DRM_DEBUG(cat, fmt, args...)					\
> +({									\
> +	DRM_DEF_DYN_DEBUG_DATA(descriptor, "[%s:%s]["#cat"] " fmt);	\
> +	if (DRM_DYN_DEBUG_BRANCH(descriptor) ||				\
> +	    unlikely(drm_debug & _DRM_UT_##cat)) {			\
> +		__drm_dyn_pr_debug(&descriptor,				\
> +				   "[%s:%s]["#cat"] " fmt,		\
> +				   _DRM_PREFIX, __func__, ##args);	\
> +	}								\
> +})
> +
>  #define DRM_DEV_DEBUG(dev, fmt, args...)				\
> -	drm_dev_printk(dev, KERN_DEBUG, DRM_UT_CORE, __func__, "", fmt,	\
> -		       ##args)
> -#define DRM_DEBUG(fmt, ...)						\
> -	drm_printk(KERN_DEBUG, DRM_UT_CORE, fmt, ##__VA_ARGS__)
> +	_DRM_DEV_DEBUG(dev, core, fmt, ##args)
> +#define DRM_DEBUG(fmt, args...)						\
> +	_DRM_DEBUG(core, fmt, ##args)
>  
>  #define DRM_DEV_DEBUG_DRIVER(dev, fmt, args...)				\
> -	drm_dev_printk(dev, KERN_DEBUG, DRM_UT_DRIVER, __func__, "",	\
> -		       fmt, ##args)
> -#define DRM_DEBUG_DRIVER(fmt, ...)					\
> -	drm_printk(KERN_DEBUG, DRM_UT_DRIVER, fmt, ##__VA_ARGS__)
> +	_DRM_DEV_DEBUG(dev, drv, fmt, ##args)
> +#define DRM_DEBUG_DRIVER(fmt, args...)					\
> +	_DRM_DEBUG(drv, fmt, ##args)
>  
>  #define DRM_DEV_DEBUG_KMS(dev, fmt, args...)				\
> -	drm_dev_printk(dev, KERN_DEBUG, DRM_UT_KMS, __func__, "", fmt,	\
> -		       ##args)
> -#define DRM_DEBUG_KMS(fmt, ...)					\
> -	drm_printk(KERN_DEBUG, DRM_UT_KMS, fmt, ##__VA_ARGS__)
> +	_DRM_DEV_DEBUG(dev, kms, fmt, ##args)
> +#define DRM_DEBUG_KMS(fmt, args...)					\
> +	_DRM_DEBUG(kms, fmt, ##args)
>  
>  #define DRM_DEV_DEBUG_PRIME(dev, fmt, args...)				\
> -	drm_dev_printk(dev, KERN_DEBUG, DRM_UT_PRIME, __func__, "",	\
> -		       fmt, ##args)
> -#define DRM_DEBUG_PRIME(fmt, ...)					\
> -	drm_printk(KERN_DEBUG, DRM_UT_PRIME, fmt, ##__VA_ARGS__)
> +	_DRM_DEV_DEBUG(dev, prime, fmt, ##args)
> +#define DRM_DEBUG_PRIME(fmt, args...)					\
> +	_DRM_DEBUG(prime, fmt, ##args)
>  
>  #define DRM_DEV_DEBUG_ATOMIC(dev, fmt, args...)				\
> -	drm_dev_printk(dev, KERN_DEBUG, DRM_UT_ATOMIC, __func__, "",	\
> -		       fmt, ##args)
> -#define DRM_DEBUG_ATOMIC(fmt, ...)					\
> -	drm_printk(KERN_DEBUG, DRM_UT_ATOMIC, fmt, ##__VA_ARGS__)
> +	_DRM_DEV_DEBUG(dev, atomic, fmt, ##args)
> +#define DRM_DEBUG_ATOMIC(fmt, args...)					\
> +	_DRM_DEBUG(atomic, fmt, ##args)
>  
>  #define DRM_DEV_DEBUG_VBL(dev, fmt, args...)				\
> -	drm_dev_printk(dev, KERN_DEBUG, DRM_UT_VBL, __func__, "", fmt,	\
> -		       ##args)
> -#define DRM_DEBUG_VBL(fmt, ...)					\
> -	drm_printk(KERN_DEBUG, DRM_UT_VBL, fmt, ##__VA_ARGS__)
> +	_DRM_DEV_DEBUG(dev, vbl, fmt, ##args)
> +#define DRM_DEBUG_VBL(fmt, args...)					\
> +	_DRM_DEBUG(vbl, fmt, ##args)
>  
> -#define _DRM_DEV_DEFINE_DEBUG_RATELIMITED(dev, level, fmt, args...)	\
> +#define _DRM_DEV_DEFINE_DEBUG_RATELIMITED(dev, category, fmt, args...)	\
>  ({									\
>  	static DEFINE_RATELIMIT_STATE(_rs,				\
>  				      DEFAULT_RATELIMIT_INTERVAL,	\
>  				      DEFAULT_RATELIMIT_BURST);		\
>  	if (__ratelimit(&_rs))						\
> -		drm_dev_printk(dev, KERN_DEBUG, DRM_UT_ ## level,	\
> -			       __func__, "", fmt, ##args);		\
> +		_DRM_DEV_DEBUG(dev, category, fmt, ##args);		\
> +})
> +#define _DRM_DEFINE_DEBUG_RATELIMITED(category, fmt, args...)	\
> +({									\
> +	static DEFINE_RATELIMIT_STATE(_rs,				\
> +				      DEFAULT_RATELIMIT_INTERVAL,	\
> +				      DEFAULT_RATELIMIT_BURST);		\
> +	if (__ratelimit(&_rs))						\
> +		_DRM_DEBUG(category, fmt, ##args);			\
>  })
>  
>  /**
> @@ -268,21 +317,24 @@ struct dma_buf_attachment;
>   * \param arg arguments
>   */
>  #define DRM_DEV_DEBUG_RATELIMITED(dev, fmt, args...)			\
> -	DEV__DRM_DEFINE_DEBUG_RATELIMITED(dev, CORE, fmt, ##args)
> +	_DRM_DEFINE_DEBUG_RATELIMITED(dev, core, fmt, ##args)
>  #define DRM_DEBUG_RATELIMITED(fmt, args...)				\
> -	DRM_DEV_DEBUG_RATELIMITED(NULL, fmt, ##args)
> +	_DRM_DEFINE_DEBUG_RATELIMITED(core, fmt, ##args)
> +
>  #define DRM_DEV_DEBUG_DRIVER_RATELIMITED(dev, fmt, args...)		\
> -	_DRM_DEV_DEFINE_DEBUG_RATELIMITED(dev, DRIVER, fmt, ##args)
> +	_DRM_DEV_DEFINE_DEBUG_RATELIMITED(dev, drv, fmt, ##args)
>  #define DRM_DEBUG_DRIVER_RATELIMITED(fmt, args...)			\
> -	DRM_DEV_DEBUG_DRIVER_RATELIMITED(NULL, fmt, ##args)
> +	_DRM_DEV_DEFINE_DEBUG_RATELIMITED(drv, fmt, ##args)
> +
>  #define DRM_DEV_DEBUG_KMS_RATELIMITED(dev, fmt, args...)		\
> -	_DRM_DEV_DEFINE_DEBUG_RATELIMITED(dev, KMS, fmt, ##args)
> +	_DRM_DEV_DEFINE_DEBUG_RATELIMITED(dev, kms, fmt, ##args)
>  #define DRM_DEBUG_KMS_RATELIMITED(fmt, args...)				\
> -	DRM_DEV_DEBUG_KMS_RATELIMITED(NULL, fmt, ##args)
> +	_DRM_DEFINE_DEBUG_RATELIMITED(kms, fmt, ##args)
> +
>  #define DRM_DEV_DEBUG_PRIME_RATELIMITED(dev, fmt, args...)		\
> -	_DRM_DEV_DEFINE_DEBUG_RATELIMITED(dev, PRIME, fmt, ##args)
> +	_DRM_DEV_DEFINE_DEBUG_RATELIMITED(dev, prime, fmt, ##args)
>  #define DRM_DEBUG_PRIME_RATELIMITED(fmt, args...)			\
> -	DRM_DEV_DEBUG_PRIME_RATELIMITED(NULL, fmt, ##args)
> +	_DRM_DEFINE_DEBUG_RATELIMITED(prime, fmt, ##args)
>  
>  /* Format strings and argument splitters to simplify printing
>   * various "complex" objects
> -- 
> 2.10.2
> 

-- 
Daniel Vetter
Software Engineer, Intel Corporation
http://blog.ffwll.ch
_______________________________________________
dri-devel mailing list
dri-devel@xxxxxxxxxxxxxxxxxxxxx
https://lists.freedesktop.org/mailman/listinfo/dri-devel




[Index of Archives]     [Linux DRI Users]     [Linux Intel Graphics]     [Linux USB Devel]     [Video for Linux]     [Linux Audio Users]     [Yosemite News]     [Linux Kernel]     [Linux SCSI]     [XFree86]     [Linux USB Devel]     [Video for Linux]     [Linux Audio Users]     [Linux Kernel]     [Linux SCSI]     [XFree86]
  Powered by Linux