On 2021-07-21 10:55, Sean Paul wrote:

From: Sean Paul seanpaul@chromium.org

This patch adds a new module parameter called drm.trace which accepts the same mask as drm.debug. When a debug category is enabled, log messages will be put in a new tracefs instance called drm for consumption.

Using the new tracefs instance will allow distros to enable drm logging in production without impacting performance or spamming the system logs.

Cc: Daniel Vetter daniel.vetter@ffwll.ch Cc: David Airlie airlied@gmail.com Cc: Jani Nikula jani.nikula@linux.intel.com Cc: Joonas Lahtinen joonas.lahtinen@linux.intel.com Cc: Pekka Paalanen ppaalanen@gmail.com Cc: Rob Clark robdclark@gmail.com Cc: Steven Rostedt rostedt@goodmis.org Cc: Thomas Zimmermann tzimmermann@suse.de Cc: Ville Syrjälä ville.syrjala@linux.intel.com Cc: Chris Wilson chris@chris-wilson.co.uk Cc: Steven Rostedt rostedt@goodmis.org Reported-by: kernel test robot lkp@intel.com # warning reported in v6 Acked-by: Pekka Paalanen pekka.paalanen@collabora.com Signed-off-by: Sean Paul seanpaul@chromium.org Link: https://patchwork.freedesktop.org/patch/msgid/20191010204823.195540-1-sean@p... #v1 Link: https://lists.freedesktop.org/archives/dri-devel/2019-November/243230.html #v2 Link: https://patchwork.freedesktop.org/patch/msgid/20191212203301.142437-1-sean@p... #v3 Link: https://patchwork.freedesktop.org/patch/msgid/20200114172155.215463-1-sean@p... #v4 Link: https://patchwork.freedesktop.org/patch/msgid/20200608210505.48519-14-sean@p... #v5 Link: https://patchwork.freedesktop.org/patch/msgid/20200818210510.49730-15-sean@p... #v6

Changes in v5: -Re-write to use trace_array and the tracefs instance support Changes in v6: -Use the new trace_array_init_printk() to initialize global trace buffers Changes in v6.5: -Fix kernel test robot warning

-Add a trace printf in __drm_err

Documentation/gpu/drm-uapi.rst | 6 + drivers/gpu/drm/drm_drv.c | 3 + drivers/gpu/drm/drm_print.c | 223 ++++++++++++++++++++++++++++----- include/drm/drm_print.h | 63 ++++++++-- 4 files changed, 255 insertions(+), 40 deletions(-)

diff --git a/Documentation/gpu/drm-uapi.rst b/Documentation/gpu/drm-uapi.rst index 7e51dd40bf6e..ce1ea39fb4b9 100644 --- a/Documentation/gpu/drm-uapi.rst +++ b/Documentation/gpu/drm-uapi.rst @@ -424,6 +424,12 @@ Debugfs Support .. kernel-doc:: drivers/gpu/drm/drm_debugfs.c :export:

+DRM Tracing +---------------

+.. kernel-doc:: drivers/gpu/drm/drm_print.c

• :doc: DRM Tracing

Sysfs Support

diff --git a/drivers/gpu/drm/drm_drv.c b/drivers/gpu/drm/drm_drv.c index 8804ec7d3215..71dc0b161b51 100644 --- a/drivers/gpu/drm/drm_drv.c +++ b/drivers/gpu/drm/drm_drv.c @@ -1034,12 +1034,15 @@ static void drm_core_exit(void) drm_sysfs_destroy(); idr_destroy(&drm_minors_idr); drm_connector_ida_destroy();

• drm_trace_cleanup();

}

static int __init drm_core_init(void) { int ret;

• drm_trace_init();

Can we move the drm_trace_init() to drm_dev_register()? The reason is while creating the tracefs node, I think its useful to have the drm device id to support multiple DRM devices. So while creating the tracefs node, we can do something like trace_array_get_by_name("drm_<device_id");

Then usermode will just read all the traces from /instances/drm_***

• drm_connector_ida_init(); idr_init(&drm_minors_idr); drm_memcpy_init_early();

diff --git a/drivers/gpu/drm/drm_print.c b/drivers/gpu/drm/drm_print.c index 4d984a01b3a3..64d9a724c2df 100644 --- a/drivers/gpu/drm/drm_print.c +++ b/drivers/gpu/drm/drm_print.c @@ -31,6 +31,7 @@ #include <linux/moduleparam.h> #include <linux/seq_file.h> #include <linux/slab.h> +#include <linux/trace.h>

#include <drm/drm.h> #include <drm/drm_drv.h> @@ -43,17 +44,34 @@ unsigned int __drm_debug_syslog; EXPORT_SYMBOL(__drm_debug_syslog);

-MODULE_PARM_DESC(debug, "Enable debug output, where each bit enables a debug category.\n" -"\t\tBit 0 (0x01) will enable CORE messages (drm core code)\n" -"\t\tBit 1 (0x02) will enable DRIVER messages (drm controller code)\n" -"\t\tBit 2 (0x04) will enable KMS messages (modesetting code)\n" -"\t\tBit 3 (0x08) will enable PRIME messages (prime code)\n" -"\t\tBit 4 (0x10) will enable ATOMIC messages (atomic code)\n" -"\t\tBit 5 (0x20) will enable VBL messages (vblank code)\n" -"\t\tBit 7 (0x80) will enable LEASE messages (leasing code)\n" -"\t\tBit 8 (0x100) will enable DP messages (displayport code)"); +/*

• • __drm_debug_trace: Enable debug output in drm tracing instance.
• • Bitmask of DRM_UT_x. See include/drm/drm_print.h for details.
• */

+unsigned int __drm_debug_trace; +EXPORT_SYMBOL(__drm_debug_trace);

+#define DEBUG_PARM_DESC(dst) \ +"Enable debug output to " dst ", where each bit enables a debug category.\n" \ +"\t\tBit 0 (0x01) will enable CORE messages (drm core code)\n" \ +"\t\tBit 1 (0x02) will enable DRIVER messages (drm controller code)\n" \ +"\t\tBit 2 (0x04) will enable KMS messages (modesetting code)\n" \ +"\t\tBit 3 (0x08) will enable PRIME messages (prime code)\n" \ +"\t\tBit 4 (0x10) will enable ATOMIC messages (atomic code)\n" \ +"\t\tBit 5 (0x20) will enable VBL messages (vblank code)\n" \ +"\t\tBit 7 (0x80) will enable LEASE messages (leasing code)\n" \ +"\t\tBit 8 (0x100) will enable DP messages (displayport code)"

This is certainly a great start. Moving forward a bit, is there a possibility to subcatergorize even further? Like plane, crtc, connector etc?

+MODULE_PARM_DESC(debug, DEBUG_PARM_DESC("syslog")); module_param_named(debug, __drm_debug_syslog, int, 0600);

+MODULE_PARM_DESC(trace, DEBUG_PARM_DESC("tracefs")); +module_param_named(trace, __drm_debug_trace, int, 0600);

+#ifdef CONFIG_TRACING +struct trace_array *trace_arr; +#endif

void __drm_puts_coredump(struct drm_printer *p, const char *str) { struct drm_print_iterator *iterator = p->arg; @@ -166,6 +184,20 @@ void __drm_printfn_debug_syslog(struct drm_printer *p, struct va_format *vaf) } EXPORT_SYMBOL(__drm_printfn_debug_syslog);

+void __drm_printfn_trace(struct drm_printer *p, struct va_format *vaf) +{

• drm_trace_printf("%s %pV", p->prefix, vaf);

+} +EXPORT_SYMBOL(__drm_printfn_trace);

+void __drm_printfn_debug_syslog_and_trace(struct drm_printer *p,

• 			   struct va_format *vaf)
  

+{

• pr_debug("%s %pV", p->prefix, vaf);
• drm_trace_printf("%s %pV", p->prefix, vaf);

+} +EXPORT_SYMBOL(__drm_printfn_debug_syslog_and_trace);

void __drm_printfn_err(struct drm_printer *p, struct va_format *vaf) { pr_err("*ERROR* %s %pV", p->prefix, vaf); @@ -246,6 +278,14 @@ 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;
• drm_trace_printf("%s%s[" DRM_NAME ":%ps] %pV",

• 	 dev ? dev_name(dev) : "",dev ? " " : "",
  

• 	 __builtin_return_address(0), &vaf);
  

• va_end(args);
• va_start(args, format); vaf.fmt = format; vaf.va = &args;

@@ -267,21 +307,30 @@ void drm_dev_dbg(const struct device *dev, enum drm_debug_category category, struct va_format vaf; va_list args;

• if (!drm_debug_enabled(category))

• return;
  

• if (drm_debug_syslog_enabled(category)) {

• va_start(args, format);
  

• vaf.fmt = format;
  

• vaf.va = &args;
  
  

• 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 (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);
  

• }

• va_end(args);

• if (drm_debug_trace_enabled(category)) {

• va_start(args, format);
  

• vaf.fmt = format;
  

• vaf.va = &args;
  

• drm_trace_printf("%s%s[" DRM_NAME ":%ps] %pV",
  

• 		 dev ? dev_name(dev) : "", dev ? " " : "",
  

• 		 __builtin_return_address(0), &vaf);
  

• va_end(args);
  

• }

} EXPORT_SYMBOL(drm_dev_dbg);

@@ -290,17 +339,25 @@ void __drm_dbg(enum drm_debug_category category, const char *format, ...) struct va_format vaf; va_list args;

• if (!drm_debug_enabled(category))

• return;
  

• if (drm_debug_syslog_enabled(category)) {

• va_start(args, format);
  

• vaf.fmt = format;
  

• vaf.va = &args;
  
  

• va_start(args, format);
• vaf.fmt = format;
• vaf.va = &args;

• printk(KERN_DEBUG "[" DRM_NAME ":%ps] %pV",
  

• __builtin_return_address(0), &vaf);
  
  

• printk(KERN_DEBUG "[" DRM_NAME ":%ps] %pV",

•       __builtin_return_address(0), &vaf);
  

• va_end(args);
  

• }

• va_end(args);

• if (drm_debug_trace_enabled(category)) {

• va_start(args, format);
  

• vaf.fmt = format;
  

• vaf.va = &args;
  

• drm_trace_printf("[" DRM_NAME ":%ps] %pV",
  

• 		 __builtin_return_address(0), &vaf);
  

• va_end(args);
  

• }

} EXPORT_SYMBOL(__drm_dbg);

@@ -317,6 +374,13 @@ void __drm_err(const char *format, ...) __builtin_return_address(0), &vaf);

va_end(args);

• va_start(args, format);
• vaf.fmt = format;
• vaf.va = &args;
• drm_trace_printf("[" DRM_NAME ":%ps] *ERROR* %pV",

• 		__builtin_return_address(0), &vaf);
  

• va_end(args);

} EXPORT_SYMBOL(__drm_err);

@@ -347,3 +411,104 @@ void drm_print_regset32(struct drm_printer *p, struct debugfs_regset32 *regset) } } EXPORT_SYMBOL(drm_print_regset32);

+/**

• • DOC: DRM Tracing
• • *tl;dr* DRM tracing is a lightweight alternative to traditional DRM

debug

• • logging.
• • While DRM logging is quite convenient when reproducing a specific

issue, it

• • doesn't help when something goes wrong unexpectedly. There are a

couple

• • reasons why one does not want to enable DRM logging at all times:
• • 1. We don't want to overwhelm syslog with drm spam, others have to

use it too

• • 2. Console logging is slow
• • DRM tracing aims to solve both these problems.
• • To use DRM tracing, set the drm.trace module parameter (via

cmdline or sysfs)

• • to a DRM debug category mask (this is a bitmask of

&drm_debug_category

• • values):
• • ::
• • eg: echo 0x106 > /sys/module/drm/parameters/trace
• • Once active, all log messages in the specified categories will be

written to

• • the DRM trace. Once at capacity, the trace will overwrite old

messages with

• • new ones. At any point, one can read the trace file to extract the

previous N

• • DRM messages:
• • ::
• • eg: cat /sys/kernel/tracing/instances/drm/trace
• • Considerations

• ---

• • The trace is subsystem wide, so if you have multiple devices

active, they

• • will be adding logs to the same trace.
• • The contents of the DRM Trace are **not** considered UABI. **DO

NOT depend on

• • the values of these traces in your userspace.** These traces are

intended for

• • entertainment purposes only. The contents of these logs carry no

warranty,

• • expressed or implied.
• */

+#ifdef CONFIG_TRACING

+/**

• • drm_trace_init - initializes the drm trace array
• • This function fetches (or creates) the drm trace array. This

should be called

• • once on drm subsystem creation and matched with

drm_trace_cleanup().

• */

+void drm_trace_init(void) +{

• int ret;
• trace_arr = trace_array_get_by_name("drm");
• if (!trace_arr)

• return;
  

• ret = trace_array_init_printk(trace_arr);
• if (ret)

• drm_trace_cleanup();
  

+} +EXPORT_SYMBOL(drm_trace_init);

+/**

• • drm_trace_printf - adds an entry to the drm tracefs instance
• • @format: printf format of the message to add to the trace
• • This function adds a new entry in the drm tracefs instance
• */

+void drm_trace_printf(const char *format, ...) +{

• struct va_format vaf;
• va_list args;
• va_start(args, format);
• vaf.fmt = format;
• vaf.va = &args;
• trace_array_printk(trace_arr, _THIS_IP_, "%pV", &vaf);
• va_end(args);

+}

+/**

• • drm_trace_cleanup - destroys the drm trace array
• • This function destroys the drm trace array created with

drm_trace_init. This

• • should be called once on drm subsystem close and matched with
• • drm_trace_init().
• */

+void drm_trace_cleanup(void) +{

• if (trace_arr) {

• trace_array_put(trace_arr);
  

• trace_array_destroy(trace_arr);
  

• trace_arr = NULL;
  

• }

+} +EXPORT_SYMBOL(drm_trace_cleanup); +#endif \ No newline at end of file diff --git a/include/drm/drm_print.h b/include/drm/drm_print.h index af31beeb82a1..4609a2f4a425 100644 --- a/include/drm/drm_print.h +++ b/include/drm/drm_print.h @@ -36,12 +36,13 @@

/* Do *not* use outside of drm_print.[ch]! */ extern unsigned int __drm_debug_syslog; +extern unsigned int __drm_debug_trace;

/**

• DOC: print
• A simple wrapper for dev_printk(), seq_printf(), etc. Allows same

• • debug code to be used for both debugfs and printk logging.

• • debug code to be used for debugfs, printk and tracefs logging.
  • For example::

@@ -86,6 +87,9 @@ void __drm_printfn_seq_file(struct drm_printer *p, struct va_format *vaf); void __drm_puts_seq_file(struct drm_printer *p, const char *str); void __drm_printfn_info(struct drm_printer *p, struct va_format *vaf); void __drm_printfn_debug_syslog(struct drm_printer *p, struct va_format *vaf); +void __drm_printfn_trace(struct drm_printer *p, struct va_format *vaf); +void __drm_printfn_debug_syslog_and_trace(struct drm_printer *p,

• 			   struct va_format *vaf);
  

void __drm_printfn_err(struct drm_printer *p, struct va_format *vaf); void __drm_printfn_noop(struct drm_printer *p, struct va_format *vaf);

@@ -219,7 +223,8 @@ static inline struct drm_printer drm_info_printer(struct device *dev) }

/**

• • drm_debug_printer - construct a &drm_printer that outputs to

pr_debug()

• • drm_debug_printer - construct a &drm_printer that outputs to

pr_debug() and

• • drm tracefs
  • @prefix: debug output prefix
  • RETURNS:

@@ -228,7 +233,7 @@ static inline struct drm_printer drm_info_printer(struct device *dev) static inline struct drm_printer drm_debug_printer(const char *prefix) { struct drm_printer p = {

• .printfn = __drm_printfn_debug_syslog,
  

• .printfn = __drm_printfn_debug_syslog_and_trace,
  

  .prefix = prefix }; return p;

@@ -254,14 +259,14 @@ static inline struct drm_printer drm_err_printer(const char *prefix)

• enum drm_debug_category - The DRM debug categories
• Each of the DRM debug logging macros use a specific category, and

the logging

• • is filtered by the drm.debug module parameter. This enum specifies

the values

• • for the interface.

• • is filtered by the drm.debug and drm.trace module parameters. This

enum

• • specifies the values for the interface.
  • Each DRM_DEBUG_<CATEGORY> macro logs to DRM_UT_<CATEGORY> category,

except

• DRM_DEBUG() logs to DRM_UT_CORE.

• • Enabling verbose debug messages is done through the drm.debug

parameter, each

• • category being enabled by a bit:

• • Enabling verbose debug messages is done through the drm.debug and

drm.trace

• • parameters, each category being enabled by a bit:
  • • drm.debug=0x1 will enable CORE messages
  • • drm.debug=0x2 will enable DRIVER messages

@@ -270,10 +275,14 @@ static inline struct drm_printer drm_err_printer(const char *prefix)

• • drm.debug=0x1ff will enable all messages
• An interesting feature is that it's possible to enable verbose

logging at

• • run-time by echoing the debug value in its sysfs node::

• • run-time by echoing the debug category value in its sysfs node::
• • # For syslog logging:
  • # echo 0xf > /sys/module/drm/parameters/debug
• • # For tracefs logging:
• • # echo 0xf > /sys/module/drm/parameters/trace
• */

enum drm_debug_category { /** @@ -325,14 +334,20 @@ static inline bool drm_debug_syslog_enabled(enum drm_debug_category category) return unlikely(__drm_debug_syslog & category); }

+static inline bool drm_debug_trace_enabled(enum drm_debug_category category) +{

• return unlikely(__drm_debug_trace & category);

+}

static inline bool drm_debug_enabled(enum drm_debug_category category) {

• return drm_debug_syslog_enabled(category);

• return drm_debug_syslog_enabled(category) ||

•       drm_debug_trace_enabled(category);
  

}

/**

• drm_debug_category_printer - construct a &drm_printer that outputs

to

• • pr_debug() if enabled for the given category.

• • pr_debug() and/or the drm tracefs instance if enabled for the

given category.

• @category: the DRM_UT_* message category this message belongs to
• @prefix: trace output prefix

@@ -347,8 +362,13 @@ drm_debug_category_printer(enum drm_debug_category category, .prefix = prefix };

• if (drm_debug_syslog_enabled(category)) {

• if (drm_debug_syslog_enabled(category) &&

•    drm_debug_trace_enabled(category)) {
  

• p.printfn = __drm_printfn_debug_syslog_and_trace;
  

• } else if (drm_debug_syslog_enabled(category)) { p.printfn = __drm_printfn_debug_syslog;
• } else if (drm_debug_trace_enabled(category)) {

• p.printfn = __drm_printfn_trace;
  

  } else { WARN(1, "Debug category %d is inactive.", category); p.printfn = __drm_printfn_noop;

@@ -357,6 +377,27 @@ drm_debug_category_printer(enum drm_debug_category category, return p; }

+#ifdef CONFIG_TRACING +void drm_trace_init(void); +__printf(1, 2) +void drm_trace_printf(const char *format, ...); +void drm_trace_cleanup(void); +#else +static inline void drm_trace_init(void) +{ +}

+__printf(1, 2) +static inline void drm_trace_printf(const char *format, ...) +{ +}

+static inline void drm_trace_cleanup(void) +{ +} +#endif

/*

• struct device based logging