[PATCH v3] drm: Funnel drm logs to tracepoints
Steven Rostedt
rostedt at goodmis.org
Fri Dec 13 03:20:50 UTC 2019
On Thu, 12 Dec 2019 15:32:35 -0500
Sean Paul <sean at poorly.run> wrote:
>
> What about trace_printk()? It doesn't give us the control we get from using
> tracepoints and it's not meant to be left sprinkled around in code.
Not to mention that trace_printk() is not for production use (only for
developers debugging purposes).
>
> Cc: David Airlie <airlied at gmail.com>
> Cc: Daniel Vetter <daniel.vetter at ffwll.ch>
> Cc: Pekka Paalanen <ppaalanen at gmail.com>
> Cc: Joonas Lahtinen <joonas.lahtinen at linux.intel.com>
> Cc: Thomas Zimmermann <tzimmermann at suse.de>
> Cc: Rob Clark <robdclark at gmail.com>
> Cc: Ville Syrjälä <ville.syrjala at linux.intel.com>
> Acked-by: Daniel Vetter <daniel.vetter at ffwll.ch>
> Signed-off-by: Sean Paul <seanpaul at chromium.org>
> Link: https://patchwork.freedesktop.org/patch/msgid/20191010204823.195540-1-sean@poorly.run #v1
>
> Changes in v2:
> - Went with a completely different approach: https://lists.freedesktop.org/archives/dri-devel/2019-November/243230.html
>
> Changes in v3:
> - Changed commit message to be a bit less RFC-y
> - Make class_drm_category_log an actual trace class
> ---
>
> Even though we don't want it to be, this is UAPI. So here's some userspace
> code which uses it:
> https://chromium-review.googlesource.com/c/chromiumos/platform2/+/1965562
>
>
> drivers/gpu/drm/drm_print.c | 143 ++++++++++++++++++++++++++-----
> include/trace/events/drm_print.h | 116 +++++++++++++++++++++++++
> 2 files changed, 239 insertions(+), 20 deletions(-)
> create mode 100644 include/trace/events/drm_print.h
>
> diff --git a/drivers/gpu/drm/drm_print.c b/drivers/gpu/drm/drm_print.c
> index 9a25d73c155c..f591292811aa 100644
> --- a/drivers/gpu/drm/drm_print.c
> +++ b/drivers/gpu/drm/drm_print.c
> @@ -27,11 +27,15 @@
>
> #include <stdarg.h>
>
> +#include <linux/bitops.h>
> #include <linux/io.h>
> #include <linux/moduleparam.h>
> #include <linux/seq_file.h>
> #include <linux/slab.h>
>
> +#define CREATE_TRACE_POINTS
> +#include <trace/events/drm_print.h>
> +
> #include <drm/drm.h>
> #include <drm/drm_drv.h>
> #include <drm/drm_print.h>
> @@ -241,10 +245,10 @@ void drm_dev_printk(const struct device *dev, const char *level,
> struct va_format vaf;
> va_list args;
>
> - va_start(args, format);
> vaf.fmt = format;
> vaf.va = &args;
>
> + va_start(args, format);
> if (dev)
> dev_printk(level, dev, "[" DRM_NAME ":%ps] %pV",
> __builtin_return_address(0), &vaf);
> @@ -253,49 +257,145 @@ void drm_dev_printk(const struct device *dev, const char *level,
> level, __builtin_return_address(0), &vaf);
>
> va_end(args);
> +
> + va_start(args, format);
> + trace_drm_log(level, dev, &vaf);
> + va_end(args);
> }
> EXPORT_SYMBOL(drm_dev_printk);
>
> +static unsigned int drm_trace_enabled(unsigned int category)
> +{
> + unsigned int bit;
> +
> + for_each_set_bit(bit, (unsigned long*)&category, sizeof(category) * 8) {
> + switch (BIT(bit)) {
> + case DRM_UT_NONE:
> + return trace_drm_dbg_none_enabled();
> + case DRM_UT_CORE:
> + return trace_drm_dbg_core_enabled();
> + case DRM_UT_DRIVER:
> + return trace_drm_dbg_driver_enabled();
> + case DRM_UT_KMS:
> + return trace_drm_dbg_kms_enabled();
> + case DRM_UT_PRIME:
> + return trace_drm_dbg_prime_enabled();
> + case DRM_UT_ATOMIC:
> + return trace_drm_dbg_atomic_enabled();
> + case DRM_UT_VBL:
> + return trace_drm_dbg_vbl_enabled();
> + case DRM_UT_STATE:
> + return trace_drm_dbg_state_enabled();
> + case DRM_UT_LEASE:
> + return trace_drm_dbg_lease_enabled();
> + case DRM_UT_DP:
> + return trace_drm_dbg_dp_enabled();
> + default:
> + return trace_drm_dbg_unknown_enabled();
> + }
Why this double loop?
> + }
> + return false;
> +}
> +
> +static void drm_do_trace(const struct device *dev, unsigned int category,
> + struct va_format *vaf)
> +{
> + WARN_ON(hweight32(category) > 1);
> +
> + switch (category) {
> + case DRM_UT_NONE:
> + trace_drm_dbg_none(dev, vaf);
> + break;
> + case DRM_UT_CORE:
> + trace_drm_dbg_core(dev, vaf);
> + break;
> + case DRM_UT_DRIVER:
> + trace_drm_dbg_driver(dev, vaf);
> + break;
> + case DRM_UT_KMS:
> + trace_drm_dbg_kms(dev, vaf);
> + break;
> + case DRM_UT_PRIME:
> + trace_drm_dbg_prime(dev, vaf);
> + break;
> + case DRM_UT_ATOMIC:
> + trace_drm_dbg_atomic(dev, vaf);
> + break;
> + case DRM_UT_VBL:
> + trace_drm_dbg_vbl(dev, vaf);
> + break;
> + case DRM_UT_STATE:
> + trace_drm_dbg_state(dev, vaf);
> + break;
> + case DRM_UT_LEASE:
> + trace_drm_dbg_lease(dev, vaf);
> + break;
> + case DRM_UT_DP:
> + trace_drm_dbg_dp(dev, vaf);
> + break;
> + default:
> + trace_drm_dbg_unknown(dev, vaf);
> + break;
Why is there a separate trace event for each of these?
> + }
> +}
> +
> void drm_dev_dbg(const struct device *dev, unsigned int category,
> const char *format, ...)
> {
> struct va_format vaf;
> + unsigned int bit;
> va_list args;
>
> - if (!drm_debug_enabled(category))
> - return;
> -
> - va_start(args, format);
> vaf.fmt = format;
> vaf.va = &args;
>
> - if (dev)
> - dev_printk(KERN_DEBUG, dev, "[" DRM_NAME ":%ps] %pV",
> - __builtin_return_address(0), &vaf);
> - else
> - printk(KERN_DEBUG "[" DRM_NAME ":%ps] %pV",
> - __builtin_return_address(0), &vaf);
> + if (drm_debug_enabled(category)) {
> + va_start(args, format);
> + if (dev)
> + dev_printk(KERN_DEBUG, dev, "[" DRM_NAME ":%ps] %pV",
> + __builtin_return_address(0), &vaf);
> + else
> + printk(KERN_DEBUG "[" DRM_NAME ":%ps] %pV",
> + __builtin_return_address(0), &vaf);
> + va_end(args);
> + }
> +
> + if (!drm_trace_enabled(category))
> + return;
> +
> + for_each_set_bit(bit, (unsigned long*)&category, sizeof(category) * 8) {
> + va_start(args, format);
> + drm_do_trace(dev, BIT(bit), &vaf);
> + va_end(args);
I'm thinking we could find a way to move the logic here to have a
single loop.
Note, the current approach is racy. The state can change between the
"drm_trace_enabled()" and this for loop.
-- Steve
> + }
>
> - va_end(args);
> }
> EXPORT_SYMBOL(drm_dev_dbg);
>
> void drm_dbg(unsigned int category, const char *format, ...)
> {
> struct va_format vaf;
> + unsigned int bit;
> va_list args;
>
> - if (!drm_debug_enabled(category))
> - return;
> -
> - va_start(args, format);
> vaf.fmt = format;
> vaf.va = &args;
>
> - printk(KERN_DEBUG "[" DRM_NAME ":%ps] %pV",
> - __builtin_return_address(0), &vaf);
> + if (drm_debug_enabled(category)) {
> + va_start(args, format);
> + printk(KERN_DEBUG "[" DRM_NAME ":%ps] %pV",
> + __builtin_return_address(0), &vaf);
> + va_end(args);
> + }
>
> - va_end(args);
> + if (!drm_trace_enabled(category))
> + return;
> +
> + for_each_set_bit(bit, (unsigned long*)&category, sizeof(category) * 8) {
> + va_start(args, format);
> + drm_do_trace(NULL, BIT(bit), &vaf);
> + va_end(args);
> + }
> }
> EXPORT_SYMBOL(drm_dbg);
>
> @@ -304,13 +404,16 @@ void drm_err(const char *format, ...)
> struct va_format vaf;
> va_list args;
>
> - va_start(args, format);
> vaf.fmt = format;
> vaf.va = &args;
>
> + va_start(args, format);
> printk(KERN_ERR "[" DRM_NAME ":%ps] *ERROR* %pV",
> __builtin_return_address(0), &vaf);
> + va_end(args);
>
> + va_start(args, format);
> + trace_drm_err(NULL, &vaf);
> va_end(args);
> }
> EXPORT_SYMBOL(drm_err);
> diff --git a/include/trace/events/drm_print.h b/include/trace/events/drm_print.h
> new file mode 100644
> index 000000000000..862728fe0f89
> --- /dev/null
> +++ b/include/trace/events/drm_print.h
> @@ -0,0 +1,116 @@
> +// SPDX-License-Identifier: MIT
> +/*
> + * Copyright (C) 2019 Google, Inc.
> + *
> + * Authors:
> + * Sean Paul <seanpaul at chromium.org>
> + */
> +#undef TRACE_SYSTEM
> +#define TRACE_SYSTEM drm_print
> +
> +#if !defined(_TRACE_DRM_PRINT_H) || defined(TRACE_HEADER_MULTI_READ)
> +
> +#include <linux/device.h>
> +#include <linux/tracepoint.h>
> +
> +#define DRM_PRINT_MAX 256
> +
> +#define _TRACE_DRM_PRINT_H
> +
> +TRACE_EVENT(drm_log,
> + TP_PROTO(const char * level, const struct device *dev,
> + struct va_format *vaf),
> + TP_ARGS(level, dev, vaf),
> + TP_STRUCT__entry(
> + __field(const char *, level )
> + __field(const struct device *, dev )
> + __dynamic_array(char, msg, DRM_PRINT_MAX )
> + __field(int, len )
> + ),
> + TP_fast_assign(
> + __entry->level = level;
> + __entry->dev = dev;
> + __entry->len = vsnprintf(__get_str(msg), DRM_PRINT_MAX,
> + vaf->fmt, *vaf->va);
> + if (__entry->len > 0 &&
> + __get_str(msg)[__entry->len - 1] == '\n')
> + __get_str(msg)[--__entry->len] = '\0';
> + ),
> + TP_printk("%s %s %s: %s", __entry->level,
> + __entry->dev ? dev_driver_string(__entry->dev) : "(NULL):",
> + __entry->dev ? dev_name(__entry->dev) : "", __get_str(msg))
> +);
> +
> +DECLARE_EVENT_CLASS(class_drm_category_log,
> + TP_PROTO(const struct device *dev, struct va_format *vaf),
> + TP_ARGS(dev, vaf),
> + TP_STRUCT__entry(
> + __field(const struct device *, dev )
> + __dynamic_array(char, msg, DRM_PRINT_MAX )
> + __field(int, len )
> + ),
> + TP_fast_assign(
> + __entry->dev = dev;
> + __entry->len = vsnprintf(__get_str(msg), DRM_PRINT_MAX,
> + vaf->fmt, *vaf->va);
> + if (__entry->len > 0 &&
> + __get_str(msg)[__entry->len - 1] == '\n')
> + __get_str(msg)[--__entry->len] = '\0';
> + ),
> + TP_printk("%s %s%s%s",
> + __entry->dev ? dev_driver_string(__entry->dev) : "",
> + __entry->dev ? dev_name(__entry->dev) : "",
> + __entry->dev ? ": " : "", __get_str(msg))
> +);
> +DEFINE_EVENT(class_drm_category_log, drm_err,
> + TP_PROTO(const struct device *dev, struct va_format *vaf),
> + TP_ARGS(dev, vaf)
> +);
> +DEFINE_EVENT(class_drm_category_log, drm_dbg_none,
> + TP_PROTO(const struct device *dev, struct va_format *vaf),
> + TP_ARGS(dev, vaf)
> +);
> +DEFINE_EVENT(class_drm_category_log, drm_dbg_core,
> + TP_PROTO(const struct device *dev, struct va_format *vaf),
> + TP_ARGS(dev, vaf)
> +);
> +DEFINE_EVENT(class_drm_category_log, drm_dbg_driver,
> + TP_PROTO(const struct device *dev, struct va_format *vaf),
> + TP_ARGS(dev, vaf)
> +);
> +DEFINE_EVENT(class_drm_category_log, drm_dbg_kms,
> + TP_PROTO(const struct device *dev, struct va_format *vaf),
> + TP_ARGS(dev, vaf)
> +);
> +DEFINE_EVENT(class_drm_category_log, drm_dbg_prime,
> + TP_PROTO(const struct device *dev, struct va_format *vaf),
> + TP_ARGS(dev, vaf)
> +);
> +DEFINE_EVENT(class_drm_category_log, drm_dbg_atomic,
> + TP_PROTO(const struct device *dev, struct va_format *vaf),
> + TP_ARGS(dev, vaf)
> +);
> +DEFINE_EVENT(class_drm_category_log, drm_dbg_vbl,
> + TP_PROTO(const struct device *dev, struct va_format *vaf),
> + TP_ARGS(dev, vaf)
> +);
> +DEFINE_EVENT(class_drm_category_log, drm_dbg_state,
> + TP_PROTO(const struct device *dev, struct va_format *vaf),
> + TP_ARGS(dev, vaf)
> +);
> +DEFINE_EVENT(class_drm_category_log, drm_dbg_lease,
> + TP_PROTO(const struct device *dev, struct va_format *vaf),
> + TP_ARGS(dev, vaf)
> +);
> +DEFINE_EVENT(class_drm_category_log, drm_dbg_dp,
> + TP_PROTO(const struct device *dev, struct va_format *vaf),
> + TP_ARGS(dev, vaf)
> +);
> +DEFINE_EVENT(class_drm_category_log, drm_dbg_unknown,
> + TP_PROTO(const struct device *dev, struct va_format *vaf),
> + TP_ARGS(dev, vaf)
> +);
> +#endif
> +
> +/* This part must be outside protection */
> +#include <trace/define_trace.h>
More information about the dri-devel
mailing list