[Intel-gfx] [RFC v2] drm: Enable dynamic debug for DRM_[DEV]_DEBUG*
Tvrtko Ursulin
tvrtko.ursulin at linux.intel.com
Thu Dec 8 13:16:50 UTC 2016
Hi,
On 07/12/2016 18:35, 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.
To check if I got it right, that would put the prefix on debug messages
while the rest would not have it? (With the option of dropping the
prefix in general that is.)
Or you thought just removing the prefix from debug messages?
> 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.
I think prefix by default, on non-debug messages, is required. We could
perhaps make it like "drm: message", and not "[drm] message", to match
the rest of the kernel?
>
> --- >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
If I got it right from the patch the actual debug format is:
"[drm:function_name][kms] Message"
Correct? In which case I would suggest different grouping, where
category comes before the function name. For example:
"[drm:kms:function_name] Message"
I also find a lot of square braces hard to read. So the current
"[function [module]]" is not my favourite so plus points for this
initiative as well.
In general this looks like a good cleanup and improvement so ack from me.
Regards,
Tvrtko
P.S. Also eliminate DRM_NAME in this work?
>
> 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 at sixbynine.org>
> Cc: dri-devel at lists.freedesktop.org
> Cc: Daniel Vetter <daniel.vetter at ffwll.ch>
> Cc: Tvrtko Ursulin <tvrtko.ursulin at intel.com>
> ---
> 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
>
More information about the Intel-gfx
mailing list