[PATCH v4] drm/trace: Buffer DRM logs in a ringbuffer accessible via debugfs

From: Sean Paul seanpaul@chromium.org

This patch uses a ring_buffer to keep a "flight recorder" (name credit Weston) of DRM logs for a specified set of debug categories. The user writes a bitmask of debug categories to the "trace_mask" node and can read log messages from the "trace" node.

These nodes currently exist in debugfs under the dri directory. I intended on exposing all of this through tracefs originally, but the tracefs entry points are not exposed, so there's no way to create tracefs files from drivers at the moment. I think it would be a worthwhile endeavour, but one requiring more time and conversation to ensure the drm traces fit somewhere sensible.

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 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

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

Changes in v4: - Instead of [ab]using trace events and the system trace buffer, use our own ringbuffer --- --- Documentation/gpu/drm-uapi.rst | 9 + drivers/gpu/drm/Kconfig | 1 + drivers/gpu/drm/Makefile | 2 +- drivers/gpu/drm/drm_drv.c | 3 + drivers/gpu/drm/drm_print.c | 80 +++++-- drivers/gpu/drm/drm_trace.c | 376 +++++++++++++++++++++++++++++++++ include/drm/drm_print.h | 39 ++++ 7 files changed, 487 insertions(+), 23 deletions(-) create mode 100644 drivers/gpu/drm/drm_trace.c

diff --git a/Documentation/gpu/drm-uapi.rst b/Documentation/gpu/drm-uapi.rst index 56fec6ed1ad8..089eb6fd3e94 100644 --- a/Documentation/gpu/drm-uapi.rst +++ b/Documentation/gpu/drm-uapi.rst @@ -312,6 +312,15 @@ Debugfs Support .. kernel-doc:: drivers/gpu/drm/drm_debugfs.c :export:

+DRM Tracing +--------------- + +.. kernel-doc:: drivers/gpu/drm/drm_trace.c + :doc: DRM Tracing + +.. kernel-doc:: drivers/gpu/drm/drm_trace.c + :internal: + Sysfs Support =============

diff --git a/drivers/gpu/drm/Kconfig b/drivers/gpu/drm/Kconfig index d0aa6cff2e02..9d8077e87afe 100644 --- a/drivers/gpu/drm/Kconfig +++ b/drivers/gpu/drm/Kconfig @@ -14,6 +14,7 @@ menuconfig DRM select I2C select I2C_ALGOBIT select DMA_SHARED_BUFFER + select RING_BUFFER select SYNC_FILE help Kernel-level support for the Direct Rendering Infrastructure (DRI) diff --git a/drivers/gpu/drm/Makefile b/drivers/gpu/drm/Makefile index 6493088a0fdd..88b4674934e6 100644 --- a/drivers/gpu/drm/Makefile +++ b/drivers/gpu/drm/Makefile @@ -29,7 +29,7 @@ drm-$(CONFIG_DRM_PANEL) += drm_panel.o drm-$(CONFIG_OF) += drm_of.o drm-$(CONFIG_AGP) += drm_agpsupport.o drm-$(CONFIG_PCI) += drm_pci.o -drm-$(CONFIG_DEBUG_FS) += drm_debugfs.o drm_debugfs_crc.o +drm-$(CONFIG_DEBUG_FS) += drm_debugfs.o drm_debugfs_crc.o drm_trace.o drm-$(CONFIG_DRM_LOAD_EDID_FIRMWARE) += drm_edid_load.o

drm_vram_helper-y := drm_gem_vram_helper.o \ diff --git a/drivers/gpu/drm/drm_drv.c b/drivers/gpu/drm/drm_drv.c index 7c18a980cd4b..98260b9f8004 100644 --- a/drivers/gpu/drm/drm_drv.c +++ b/drivers/gpu/drm/drm_drv.c @@ -1114,6 +1114,7 @@ static const struct file_operations drm_stub_fops = { static void drm_core_exit(void) { unregister_chrdev(DRM_MAJOR, "drm"); + drm_trace_cleanup(); debugfs_remove(drm_debugfs_root); drm_sysfs_destroy(); idr_destroy(&drm_minors_idr); @@ -1135,6 +1136,8 @@ static int __init drm_core_init(void)

drm_debugfs_root = debugfs_create_dir("dri", NULL);

+ WARN_ON(drm_trace_init(drm_debugfs_root)); + ret = register_chrdev(DRM_MAJOR, "drm", &drm_stub_fops); if (ret < 0) goto error; diff --git a/drivers/gpu/drm/drm_print.c b/drivers/gpu/drm/drm_print.c index 111b932cf2a9..0ac1867937bf 100644 --- a/drivers/gpu/drm/drm_print.c +++ b/drivers/gpu/drm/drm_print.c @@ -262,21 +262,37 @@ 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; - - 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); + 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); + + va_end(args); + }

- va_end(args); + if (drm_trace_enabled(category)) { + va_start(args, format); + vaf.fmt = format; + vaf.va = &args; + + if (dev) + drm_dev_trace_printf(dev, "[%ps] %pV", + __builtin_return_address(0), + &vaf); + else + drm_trace_printf("[%ps] %pV", + __builtin_return_address(0), + &vaf); + + va_end(args); + } } EXPORT_SYMBOL(drm_dev_dbg);

@@ -285,17 +301,28 @@ void __drm_dbg(enum drm_debug_category category, const char *format, ...) struct va_format vaf; va_list args;

- if (!drm_debug_enabled(category)) - return;

- va_start(args, format); - vaf.fmt = format; - vaf.va = &args; + if (drm_debug_enabled(category)) { + 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_trace_enabled(category)) { + va_start(args, format); + vaf.fmt = format; + vaf.va = &args; + + drm_trace_printf("[%ps] %pV", __builtin_return_address(0), + &vaf); + + va_end(args); + } } EXPORT_SYMBOL(__drm_dbg);

@@ -312,6 +339,15 @@ 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("[%ps] *ERROR* %pV", __builtin_return_address(0), + &vaf); + + va_end(args); } EXPORT_SYMBOL(__drm_err);

diff --git a/drivers/gpu/drm/drm_trace.c b/drivers/gpu/drm/drm_trace.c new file mode 100644 index 000000000000..0e7cf342d1d9 --- /dev/null +++ b/drivers/gpu/drm/drm_trace.c @@ -0,0 +1,376 @@ +/* SPDX-License-Identifier: MIT */ +/* + * Copyright (C) 2020 Google, Inc. + * + * Authors: + * Sean Paul seanpaul@chromium.org + */ + +#include <linux/cpumask.h> +#include <linux/debugfs.h> +#include <linux/kernel.h> +#include <linux/ring_buffer.h> +#include <linux/slab.h> +#include <linux/stat.h> + +#include <drm/drm_device.h> +#include <drm/drm_print.h> + +#define DRM_TRACE_MAX_LEN 256 + +/** + * 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, write a DRM debug category mask (this is a bitmask of + * &drm_debug_category values) to the trace_mask file: + * :: + * + * eg: echo 0x106 > /sys/kernel/debug/dri/trace_mask + * + * 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/debug/dri/trace + * + * Considerations + * ************** + * 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. + * + * New traces can not be added to the trace buffer while it is being read. If + * this proves to be a problem, it can be mitigated by making a copy of the + * buffer on start of read. Since DRM trace is not meant to be continuously + * read, this loss is acceptable. + * + * The timestamps on logs are CPU-local. As such, log messages from different + * CPUs may have slightly different ideas about time. + * + * Since each CPU has its own buffer, they won't all overflow at the same rate. + * This means that messages from a particularly active CPU could be dropped + * while an inactive CPU might have much older log messages. So don't be fooled + * if you seem to be missing log messages when you see a switch between CPUs in + * the logs. + * + * Internals + * ********* + * The DRM Tracing functions are intentionally unexported, they are not meant to + * be used by drivers directly. The reasons are twofold: + * + * 1. All messages going to traces should also go to the console logs. This + * ensures users can choose their logging medium without fear they're losing + * messages. + * 2. Writing directly to the trace skips category filtering, resulting in trace + * spam. + */ + +struct drm_trace_info { + struct ring_buffer *buffer; + struct dentry *debugfs; + struct dentry *debugfs_mask; + enum drm_debug_category category_mask; +}; +static struct drm_trace_info drm_trace; + +struct drm_trace_seq_iter { + loff_t pos; + cpumask_var_t cpu_mask; + int cpu; + u64 ts; +}; + +static void *drm_trace_seq_start(struct seq_file *seq_file, loff_t *pos) +{ + struct drm_trace_info *info = seq_file->private; + struct drm_trace_seq_iter *iter; + int cpu; + + iter = kzalloc(sizeof(*iter), GFP_KERNEL); + if (!iter) + return NULL; + + if (!zalloc_cpumask_var(&iter->cpu_mask, GFP_KERNEL)) + return NULL; + + /* + * TODO: We could do better than stopping record for the entirety of the + * read session. + */ + ring_buffer_record_off(info->buffer); + + /* + * pos is only used as a means of determining whether we're at the start + * of the virtual file, or continuing a read. We don't want to skip over + * log lines since that's not a meaningful thing to do. + */ + iter->pos = *pos; + + iter->cpu = -1; + + /* + * There's no way to extract the ring buffer's cpumask, so we'll try + * every possible cpu and skip the invalid entries. + */ + for_each_possible_cpu(cpu) { + if (ring_buffer_entries_cpu(info->buffer, cpu)) + cpumask_set_cpu(cpu, iter->cpu_mask); + } + + return iter; +} + +static void *drm_trace_seq_next(struct seq_file *seq_file, void *data, + loff_t *pos) +{ + struct drm_trace_info *info = seq_file->private; + struct drm_trace_seq_iter *iter = data; + int cpu; + + *pos = ++iter->pos; + iter->cpu = -1; + iter->ts = 0; + + /* Find the oldest event across our cpu_mask */ + for_each_cpu(cpu, iter->cpu_mask) { + u64 ts; + + if (!ring_buffer_peek(info->buffer, cpu, &ts, NULL)) { + cpumask_clear_cpu(cpu, iter->cpu_mask); + continue; + } + if (iter->cpu == -1 || ts < iter->ts) { + iter->ts = ts; + iter->cpu = cpu; + } + } + if (iter->cpu == -1) + return NULL; + + return iter; +} + +static void drm_trace_seq_stop(struct seq_file *seq_file, void *data) +{ + struct drm_trace_info *info = seq_file->private; + struct drm_trace_seq_iter *iter = data; + + free_cpumask_var(iter->cpu_mask); + kfree(iter); + + ring_buffer_record_on(info->buffer); +} + +static int drm_trace_seq_show(struct seq_file *seq_file, void *data) +{ + struct drm_trace_info *info = seq_file->private; + struct drm_trace_seq_iter *iter = data; + struct ring_buffer_event *event; + u64 ts, usec; + + if (iter->pos == 0) { + seq_printf(seq_file, "[%3s %12s] %s\n", "cpu", "timestamp", + "message"); + return 0; + } else if (iter->cpu == -1) { + /* This happens when we start a session with position > 0 */ + return SEQ_SKIP; + } + + event = ring_buffer_consume(info->buffer, iter->cpu, &ts, NULL); + + ts += 500; + /* ts converts from ns->us */ + do_div(ts, 1000); + /* ts converts from us->s */ + usec = do_div(ts, USEC_PER_SEC); + + seq_printf(seq_file, "[%3u %5llu.%06llu] %s", iter->cpu, ts, usec, + (const char *)ring_buffer_event_data(event)); + + return 0; +} + +static const struct seq_operations drm_trace_sops = { + .start = drm_trace_seq_start, + .next = drm_trace_seq_next, + .stop = drm_trace_seq_stop, + .show = drm_trace_seq_show +}; + +static int drm_trace_fop_open(struct inode *inode, struct file *file) +{ + struct seq_file *seq_file; + int ret; + + ret = seq_open(file, &drm_trace_sops); + if (ret) + return ret; + + seq_file = (struct seq_file *)file->private_data; + seq_file->private = inode->i_private; /* this is drm_trace_info */ + + return 0; +} + +static const struct file_operations drm_trace_fops = { + .open = drm_trace_fop_open, + .read = seq_read, + .llseek = seq_lseek, + .release = seq_release, +}; + +/** + * drm_trace_init - initializes tracing for drm core + * @debugfs_root: the dentry for drm core's debugfs root + * + * This function is called on drm core init. It is responsible for initializing + * drm tracing. This function must be matched by a call to drm_trace_cleanup(). + * + * Returns: 0 on success, -errno on failure + */ +int drm_trace_init(struct dentry *debugfs_root) +{ + struct drm_trace_info *info = &drm_trace; + int ret; + + info->buffer = ring_buffer_alloc(PAGE_SIZE * 2, RB_FL_OVERWRITE); + if (!info->buffer) + return -ENOMEM; + + info->debugfs_mask = debugfs_create_u32("trace_mask", + S_IFREG | S_IRUGO | S_IWUSR, + debugfs_root, + &info->category_mask); + if (IS_ERR(info->debugfs)) { + ret = PTR_ERR(info->debugfs); + goto err_debugfs_mask; + } + + info->debugfs = debugfs_create_file("trace", S_IFREG | S_IRUGO, + debugfs_root, info, + &drm_trace_fops); + if (IS_ERR(info->debugfs)) { + ret = PTR_ERR(info->debugfs); + goto err_debugfs; + } + + return 0; + +err_debugfs_mask: + debugfs_remove(info->debugfs_mask); +err_debugfs: + ring_buffer_free(info->buffer); + return ret; +} + +/** + * drm_trace_cleanup - cleans up tracing for drm core + * + * This function is responsible for cleaning up anything that was previously + * initialized in drm_trace_init() + */ +void drm_trace_cleanup() +{ + struct drm_trace_info *info = &drm_trace; + + debugfs_remove(info->debugfs); + debugfs_remove(info->debugfs_mask); + ring_buffer_free(info->buffer); + memset(info, 0, sizeof(*info)); +} + +/** + * drm_trace_enabled - check if a debug category has traces enabled + * @category: the debug category to check + * + * Returns true if the given category has drm traces enabled, false otherwise. + */ +bool drm_trace_enabled(enum drm_debug_category category) +{ + return READ_ONCE(drm_trace.category_mask) & category; +} + +static int drm_trace_write(const void *data, unsigned int len) +{ + struct drm_trace_info *info = &drm_trace; + struct ring_buffer_event *event; + void *event_body; + + event = ring_buffer_lock_reserve(info->buffer, len); + if (!event) + return -ENOMEM; + + event_body = ring_buffer_event_data(event); + memcpy(event_body, data, len); + + return ring_buffer_unlock_commit(info->buffer, event); +} + +/** + * drm_trace_printf - adds an entry to the drm trace + * @format: printf format of the message to add to the trace + * + * This function adds a new entry in the drm trace. + */ +void drm_trace_printf(const char *format, ...) +{ + char buf[DRM_TRACE_MAX_LEN]; + va_list args; + int ret; + + va_start(args, format); + ret = vsnprintf(buf, sizeof(buf), format, args); + va_end(args); + + if (ret < 0) + return; + else if (ret >= sizeof(buf)) + ret = sizeof(buf) - 1; + + drm_trace_write(buf, ret + 1); +} + +/** + * drm_dev_trace_printf - adds an entry to the drm trace + * @dev: pointer to device so we can print the name + * @format: printf format of the message to add to the trace + * + * This function adds a new entry in the drm trace. + */ +void drm_dev_trace_printf(const struct device *dev, const char *format, ...) +{ + char buf[DRM_TRACE_MAX_LEN]; + struct va_format vaf; + va_list args; + int ret; + + va_start(args, format); + vaf.fmt = format; + vaf.va = &args; + ret = snprintf(buf, sizeof(buf), "%s %s: %pV", dev_driver_string(dev), + dev_name(dev), &vaf); + va_end(args); + + if (ret < 0) + return; + else if (ret >= sizeof(buf)) + ret = sizeof(buf) - 1; + + drm_trace_write(buf, ret + 1); +} diff --git a/include/drm/drm_print.h b/include/drm/drm_print.h index 8f99d389792d..1f3dae7150f0 100644 --- a/include/drm/drm_print.h +++ b/include/drm/drm_print.h @@ -320,6 +320,45 @@ static inline bool drm_debug_enabled(enum drm_debug_category category) return unlikely(__drm_debug & category); }

+#ifdef CONFIG_DEBUG_FS + +int drm_trace_init(struct dentry *debugfs_root); +bool drm_trace_enabled(enum drm_debug_category category); +__printf(1, 2) +void drm_trace_printf(const char *format, ...); +__printf(2, 3) +void drm_dev_trace_printf(const struct device *dev, const char *format, ...); +void drm_trace_cleanup(void); + +#else + +static inline int drm_trace_init(struct dentry *debugfs_root) +{ + return 0; +} + +static inline bool drm_trace_enabled(enum drm_debug_category category) +{ + return false; +} + +__printf(1, 2) +static inline void drm_trace_printf(const char *format, ...) +{ +} + +__printf(2, 3) +static inline void drm_dev_trace_printf(const struct device *dev, + const char *format, ...) +{ +} + +static inline void drm_trace_cleanup(void) +{ +} + +#endif + /* * struct device based logging *