[Intel-gfx] [RFC] drm: Enable dynamic debug for DRM_[DEV]_DEBUG*
Robert Bragg
robert at sixbynine.org
Wed Dec 7 19:15:46 UTC 2016
On Mon, Dec 5, 2016 at 4:31 PM, Daniel Vetter <daniel at ffwll.ch> wrote:
> On Mon, Dec 05, 2016 at 11:24:44AM +0000, Robert Bragg wrote:
> > Forgot to send to dri-devel when I first sent this out...
> >
> > The few times I've looked at using DRM_DEBUG messages, I haven't found
> > them very helpful considering how noisy some of the categories are. More
> > than once now I've preferred to go in and modify individual files to
> > affect what messages I see and re-build.
> >
> > After recently converting some of the i915_perf.c messages to use
> > DRM_DEBUG, I thought I'd see if DRM_DEBUG could be updated to have a bit
> > more fine grained control than the current category flags.
> >
> > A few things to note with this first iteration:
> >
> > - I haven't looked to see what affect the change has on linked object
> > sizes.
> >
> > - It seems like it could be nice if dynamic debug could effectively make
> > the drm_debug parameter redundant but dynamic debug doesn't give us a
> > way to categorise messages so maybe we'd want to consider including
> > categories in messages something like:
> >
> > "[drm][kms] No FB found"
> >
> > This way all kms messages could be enabled via:
> > echo "format [kms] +p" > dynamic_debug/control
> >
> > Note with this simple scheme categories would no longer be mutually
> > exclusive which could be a nice bonus.
>
> Really nice idea, and I agree that unifying drm.debug with dynamic debug
> in some way would be useful. We could implement your idea by reworking the
> existing debug helpers to auto-prepend the right string. That also opens
> up the door for much more fine-grained bucketing maybe, only challenge is
> that we should document things somewhere.
>
yup, I don't mind writing some doc updates for this if it looks worthwhile.
>
> > Since it would involve changing the output format, I wonder how
> > concerned others might be about breaking some userspace (maybe CI test
> > runners) that for some reason grep for specific messages?
>
> I think the only thing we have to keep working (somehow) is drm.debug. The
> exact output format doesn't really matter at all. Getting drm.debug to
> work when dynamic debugging is enabled probably requires exporting some
> functions, so that we can set the right ddebug options from the drm.debug
> mod-option write handler. There's special mod-option macros that allow you
> to specify write handlers, so that part is ok.
>
dynamic_debug.h exposes a macro for declaring your own dynamic debug meta
data as well as a macro for testing whether the message has been enabled.
I'm handling compatibility by using those macros so I can still test the
drm.drm_debug flags.
Handling compatibility in terms of running control queries from the kernel
would be a bit more tricky since we'd need to export some api from
dynamic_debug.c as well as adding a write handler for drm_debug. Also the
enabledness of messages is boolean not refcounted so I suppose there could
be slightly annoying interactions if mixing both - though that could be
documented.
The only disadvantage I can think of currently for not handling
compatibility in terms of running control queries is that the dynamic debug
macros can normally avoid evaluating any conditions on the cpu while a
message is disabled, based on jump labels/static branches. We were already
evaluating a condition for disabled drm debug messages though, so it seems
reasonable to continue for now.
>
> The other bit of backwards compat we imo need is that by default we should
> still keep drm.debug working, even when dynamic debugging is disabled.
> Having a third option that uses no_printk or similar (to get rid of all
> the debug strings and dead-code-eliminate all the related output code)
>
Yeah, I think the current code already handles this, but sorry if it's not
clear.
This version is #ifdefed so that if dynamic debug isn't enabled the dynamic
debug path reduces to a no_prink
I'm considering CONFIG_DYNAMIC_DEBUG being enabled or not and when enabled
I check drm_debug and the dynamic debug state, when disabled I'm just
checking the drm_debug flags and the dynamic debugs bits boil out.
In my updated patch things we re-jigged a little so pr_debug and dev_dbg
are used when CONFIG_DYNAMIC_DEBUG is not enabled, and these internally
boil down to no_printk if DEBUG is disabled. Actually we might want to
consider if that's the desired behaviour - since DRM_DEBUG wasn't
previously affected by DEBUG being defined or not.
> > --- >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 aims to maintain compatibility with controlling debug messages
> > using the drm_debug parameter. The new dynamic debug macros are called
> > by default but conditionally calling [dev_]printk if the category flag
> > is set (side stepping the dynamic debug condition in that case)
> >
> > 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 output format should be compatible, unless the _DEV macros are
> > passed a NULL dev pointer considering how the core.c dev_printk
> > implementation adds "(NULL device *)" to the message in that case while
> > the drm wrapper would fallback to a plain printk in this case.
> > Previously some of non-dev drm debug macros were defined in terms of
> > passing NULL to a dev version but that's avoided now due to this
> > difference.
> >
> > 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: Chris Wilson <chris at chris-wilson.co.uk>
> > ---
> > drivers/gpu/drm/drm_drv.c | 47 -------------
> > include/drm/drmP.h | 168 +++++++++++++++++++++++++++++-
> ----------------
> > 2 files changed, 108 insertions(+), 107 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..680f359 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,7 +130,6 @@ 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_DRIVER 0x02
> > #define DRM_UT_KMS 0x04
> > @@ -146,25 +146,22 @@ 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_FMT_PREFIX "[" DRM_NAME "] "
> > +#define _DRM_FMT_FUNC_PREFIX "[" DRM_NAME ":%s] "
> >
> > #define DRM_INFO(fmt, ...) \
> > - _DRM_PRINTK(, INFO, fmt, ##__VA_ARGS__)
> > + pr_info(_DRM_FMT_PREFIX fmt, ##__VA_ARGS__)
> > #define DRM_NOTE(fmt, ...) \
> > - _DRM_PRINTK(, NOTICE, fmt, ##__VA_ARGS__)
> > + pr_notice(_DRM_FMT_PREFIX fmt, ##__VA_ARGS__)
> > #define DRM_WARN(fmt, ...) \
> > - _DRM_PRINTK(, WARNING, fmt, ##__VA_ARGS__)
> > + pr_warn(_DRM_FMT_PREFIX fmt, ##__VA_ARGS__)
> >
> > #define DRM_INFO_ONCE(fmt, ...)
> \
> > - _DRM_PRINTK(_once, INFO, fmt, ##__VA_ARGS__)
> > + pr_info_once(_DRM_FMT_PREFIX fmt, ##__VA_ARGS__)
> > #define DRM_NOTE_ONCE(fmt, ...)
> \
> > - _DRM_PRINTK(_once, NOTICE, fmt, ##__VA_ARGS__)
> > + pr_notice_once(_DRM_FMT_PREFIX fmt, ##__VA_ARGS__)
> > #define DRM_WARN_ONCE(fmt, ...)
> \
> > - _DRM_PRINTK(_once, WARNING, fmt, ##__VA_ARGS__)
> > + pr_warn_once(_DRM_FMT_PREFIX fmt, ##__VA_ARGS__)
> >
> > /**
> > * Error output.
> > @@ -173,10 +170,11 @@ struct dma_buf_attachment;
> > * \param arg arguments
> > */
> > #define DRM_DEV_ERROR(dev, fmt, ...) \
> > - drm_dev_printk(dev, KERN_ERR, DRM_UT_NONE, __func__, " *ERROR*",\
> > - fmt, ##__VA_ARGS__)
> > + dev_err(dev, _DRM_FMT_FUNC_PREFIX "*ERROR*" fmt, __func__, \
> > + ##__VA_ARGS__)
> > #define DRM_ERROR(fmt, ...) \
> > - drm_printk(KERN_ERR, DRM_UT_NONE, fmt, ##__VA_ARGS__)
> > + pr_err(_DRM_FMT_FUNC_PREFIX "*ERROR*" fmt, __func__, \
> > + ##__VA_ARGS__)
> >
> > /**
> > * Rate limited error output. Like DRM_ERROR() but won't flood the log.
> > @@ -193,21 +191,14 @@ struct dma_buf_attachment;
> > if (__ratelimit(&_rs)) \
> > DRM_DEV_ERROR(dev, fmt, ##__VA_ARGS__); \
> > })
> > -#define DRM_ERROR_RATELIMITED(fmt, ...)
> \
> > - DRM_DEV_ERROR_RATELIMITED(NULL, fmt, ##__VA_ARGS__)
> > +#define DRM_ERROR_RATELIMITED(fmt, args...) \
> > + DRM_DEV_ERROR_RATELIMITED(NULL, fmt, ##args)
> >
> > -#define DRM_DEV_INFO(dev, fmt, ...) \
> > - drm_dev_printk(dev, KERN_INFO, DRM_UT_NONE, __func__, "", fmt, \
> > - ##__VA_ARGS__)
> > +#define DRM_DEV_INFO(dev, fmt, args...)
> \
> > + dev_info(dev, _DRM_FMT_FUNC_PREFIX fmt, __func__, ##args)
> >
> > -#define DRM_DEV_INFO_ONCE(dev, fmt, ...) \
> > -({ \
> > - static bool __print_once __read_mostly; \
> > - if (!__print_once) { \
> > - __print_once = true; \
> > - DRM_DEV_INFO(dev, fmt, ##__VA_ARGS__); \
> > - } \
> > -})
> > +#define DRM_DEV_INFO_ONCE(dev, fmt, args...) \
> > + dev_info_once(dev, _DRM_FMT_FUNC_PREFIX fmt, __func__, ##args)
> >
> > /**
> > * Debug output.
> > @@ -215,50 +206,104 @@ struct dma_buf_attachment;
> > * \param fmt printf() like format string.
> > * \param arg arguments
> > */
> > +
> > +#if defined(CONFIG_DYNAMIC_DEBUG)
> > +/* We don't use pr_debug and dev_dbg directly since we want to
> > + * maintain format compatibility with non-dynamic drm debug messages
> > + */
> > +#define _DRM_DYNAMIC_DEV_DEBUG(dev, fmt, args...) \
> > +({ \
> > + DEFINE_DYNAMIC_DEBUG_METADATA(descriptor, fmt); \
> > + if (DYNAMIC_DEBUG_BRANCH(descriptor)) \
> > + dev_printk(KERN_DEBUG, dev, fmt, ##args); \
> > +})
> > +#define _DRM_DYNAMIC_DEBUG(fmt, args...) \
> > +({ \
> > + DEFINE_DYNAMIC_DEBUG_METADATA(descriptor, fmt); \
> > + if (DYNAMIC_DEBUG_BRANCH(descriptor)) \
> > + printk(KERN_DEBUG fmt, ##args); \
> > +})
> > +#else
> > +#define _DRM_DYNAMIC_DEV_DEBUG(dev, fmt, args...) \
> > + no_printk(fmt, ##args)
> > +#define _DRM_DYNAMIC_DEBUG(fmt, args...) \
> > + no_printk(fmt, ##args)
> > +#endif
> > +
> > +/* The conditional use of pr_debug/dev_dbg here allows us to take
> > + * advantage of the kernel's dynamic debug feature by default (ref
> > + * Documentation/dynamic-debug-howto.txt) while maintaining
> > + * compatibility with using drm.drm_debug to turn on sets of messages
> > + *
> > + * Note: pr_debug and dev_dbg can't be called by a wrapper function
> > + * otherwise they can't track the __FILE__, __func__ and __LINE__
> > + * where they are called.
> > + */
> > +#define _DRM_DEV_DEBUG(dev, category, fmt, args...) \
> > +({ \
> > + if (unlikely(drm_debug & category)) { \
> > + dev_printk(KERN_DEBUG, dev, _DRM_FMT_FUNC_PREFIX fmt, \
> > + __func__, ##args); \
> > + } else { \
> > + _DRM_DYNAMIC_DEV_DEBUG(dev, _DRM_FMT_FUNC_PREFIX fmt, \
> > + __func__, ##args); \
> > + } \
> > +})
> > +#define _DRM_DEBUG(category, fmt, args...) \
> > +({ \
> > + if (unlikely(drm_debug & category)) { \
> > + printk(KERN_DEBUG _DRM_FMT_FUNC_PREFIX fmt, \
> > + __func__, ##args); \
> > + } else \
> > + _DRM_DYNAMIC_DEBUG(_DRM_FMT_FUNC_PREFIX fmt, \
> > + __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, DRM_UT_CORE, fmt, ##args)
> > +#define DRM_DEBUG(fmt, args...)
> \
> > + _DRM_DEBUG(DRM_UT_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, DRM_UT_DRIVER, fmt, ##args)
> > +#define DRM_DEBUG_DRIVER(fmt, args...)
> \
> > + _DRM_DEBUG(DRM_UT_DRIVER, 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, DRM_UT_KMS, fmt, ##args)
> > +#define DRM_DEBUG_KMS(fmt, args...) \
> > + _DRM_DEBUG(DRM_UT_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, DRM_UT_PRIME, fmt, ##args)
> > +#define DRM_DEBUG_PRIME(fmt, args...)
> \
> > + _DRM_DEBUG(DRM_UT_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, DRM_UT_ATOMIC, fmt, ##args)
> > +#define DRM_DEBUG_ATOMIC(fmt, args...)
> \
> > + _DRM_DEBUG(DRM_UT_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, DRM_UT_VBL, fmt, ##args)
> > +#define DRM_DEBUG_VBL(fmt, args...) \
> > + _DRM_DEBUG(DRM_UT_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_DEBUG(dev, DRM_UT_ ## 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_dev_printk(dev, KERN_DEBUG, DRM_UT_ ## level, \
> > - __func__, "", fmt, ##args); \
> > + _DRM_DEBUG(DRM_UT_ ## category, fmt, ##args); \
> > })
> >
> > /**
> > @@ -268,21 +313,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)
> > #define DRM_DEBUG_DRIVER_RATELIMITED(fmt, args...) \
> > - DRM_DEV_DEBUG_DRIVER_RATELIMITED(NULL, fmt, ##args)
> > + _DRM_DEV_DEFINE_DEBUG_RATELIMITED(DRIVER, fmt, ##args)
> > +
> > #define DRM_DEV_DEBUG_KMS_RATELIMITED(dev, 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)
> > #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
>
> Since I brought up some changes for the debug stuff itself, would it make
> sense to split that from the general macro rework for all the non-debug
> output, and merge that first?
>
> Another thing to look into: I think it'd be good to move all the print
> definitions into drm_print.[hc], since drmP.h is a mess, and drm_drv.c not
> really the right place. That would then also allow us to easily document
> all the variants, and put something like the intro message for this commit
> into the overview DOC: section.
> -Daniel
> --
> Daniel Vetter
> Software Engineer, Intel Corporation
> http://blog.ffwll.ch
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.freedesktop.org/archives/intel-gfx/attachments/20161207/ff4a879d/attachment-0001.html>
More information about the Intel-gfx
mailing list