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

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

 




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@xxxxxxxxxxxxx>
Cc: dri-devel@xxxxxxxxxxxxxxxxxxxxx
Cc: Daniel Vetter <daniel.vetter@xxxxxxxx>
Cc: Tvrtko Ursulin <tvrtko.ursulin@xxxxxxxxx>
---
 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

_______________________________________________
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