[PATCH v3 34/41] dyndbg: add 2 trace-events: drm_{,dev}debug

From: Jim Cromie <jim.cromie@gmail.com>
To: jbaron@akamai.com
Cc: nouveau@lists.freedesktop.org, intel-gfx@lists.freedesktop.org,
	amd-gfx@lists.freedesktop.org, dri-devel@lists.freedesktop.org
Subject: [PATCH v3 34/41] dyndbg: add 2 trace-events: drm_{,dev}debug
Date: Mon, 18 Jul 2022 00:36:29 -0600	[thread overview]
Message-ID: <20220718063641.9179-46-jim.cromie@gmail.com> (raw)
In-Reply-To: <20220718063641.9179-1-jim.cromie@gmail.com>

Add include/trace/events/drm.h, with 2 new events: drm_debug() &
drm_devdbg(), and call them from drm_dbg() & drm_dev_dbg().  This is
easy, cuz the callers already build the vaf that the callee wants.

This allows the 3-5k drm.debug/on-dyndbg callsites to independently
(re-)direct messages to tracefs, not just syslog.  ISTM this is good;
debug traffic can be sent (just) to the tool where it can be best
used.  Over time, I'd expect to see less traffic to syslog.

NOTE: The message formats for the 2 events are both sub-optimal.
(both have event-name too)

drm_devdbg: TP_printk("cat:%d, %s %s", __entry->drm_debug_category,

  "cat:%d" should be "%s", but the classnames arent really in-scope
  here.  Maybe the events-decl-header should be under drm somewhere,
  so that class-names are available.

  It would also be nice to replace the event-name with the classname,
  as the names are highly client centric.

drm_dbg: TP_printk("%s", __get_str(msg))

  same as above.

NB:

The existing category param in this callchain is partially redundant;
when descriptor is available, it has the callsite's class_id.  If
later, CONFIG_DRM_USE_DYNAMIC_DEBUG:=y (hardwired), then category can
be dropped here, since the descriptor will always be available.

Also, if combined with header-move (or maybe its expanding inclusion
by lib/dynamic_debug), we could add the optional flags prefix, by
exposing dynamic_emit_prefix.  And perhaps this could be done only in
TP_printk, to save work while writing to the ring-buffer.

Signed-off-by: Jim Cromie <jim.cromie@gmail.com>
---
 drivers/gpu/drm/drm_print.c | 25 ++++++++++++-----
 include/trace/events/drm.h  | 54 +++++++++++++++++++++++++++++++++++++
 2 files changed, 72 insertions(+), 7 deletions(-)
 create mode 100644 include/trace/events/drm.h

diff --git a/drivers/gpu/drm/drm_print.c b/drivers/gpu/drm/drm_print.c
index 92f3f45e410c..9fb0b8e40dca 100644
--- a/drivers/gpu/drm/drm_print.c
+++ b/drivers/gpu/drm/drm_print.c
@@ -35,6 +35,9 @@
 #include <drm/drm_drv.h>
 #include <drm/drm_print.h>
 
+#define CREATE_TRACE_POINTS
+#include <trace/events/drm.h>
+
 /*
  * __drm_debug: Enable debug output.
  * Bitmask of DRM_UT_x. See include/drm/drm_print.h for details.
@@ -293,13 +296,19 @@ void __drm_dev_dbg(struct _ddebug *desc, const struct device *dev,
 	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) {
+		if (desc->flags & _DPRINTK_FLAGS_PRINTK)
+			dev_printk(KERN_DEBUG, dev, "[" DRM_NAME ":%ps] %pV",
+				   __builtin_return_address(0), &vaf);
+		if (desc->flags & _DPRINTK_FLAGS_TRACE)
+			trace_drm_devdbg(dev, category, &vaf);
+	} else {
+		if (desc->flags & _DPRINTK_FLAGS_PRINTK)
+			printk(KERN_DEBUG "[" DRM_NAME ":%ps] %pV",
+			       __builtin_return_address(0), &vaf);
+		if (desc->flags & _DPRINTK_FLAGS_TRACE)
+			trace_drm_debug(category, &vaf);
+	}
 	va_end(args);
 }
 EXPORT_SYMBOL(__drm_dev_dbg);
@@ -319,6 +328,8 @@ void ___drm_dbg(struct _ddebug *desc, enum drm_debug_category category, const ch
 	printk(KERN_DEBUG "[" DRM_NAME ":%ps] %pV",
 	       __builtin_return_address(0), &vaf);
 
+	trace_drm_debug(category, &vaf);
+
 	va_end(args);
 }
 EXPORT_SYMBOL(___drm_dbg);
diff --git a/include/trace/events/drm.h b/include/trace/events/drm.h
new file mode 100644
index 000000000000..589fa1e1f2c2
--- /dev/null
+++ b/include/trace/events/drm.h
@@ -0,0 +1,54 @@
+/* SPDX-License-Identifier: GPL-2.0 */
+#undef TRACE_SYSTEM
+#define TRACE_SYSTEM drm
+
+#if !defined(_TRACE_DRM_H) || defined(TRACE_HEADER_MULTI_READ)
+#define _TRACE_DRM_H
+
+#include <linux/tracepoint.h>
+
+/* drm_debug() was called, pass its args */
+TRACE_EVENT(drm_debug,
+	    TP_PROTO(int drm_debug_category, struct va_format *vaf),
+
+	    TP_ARGS(drm_debug_category, vaf),
+
+	    TP_STRUCT__entry(
+		    __field(int, drm_debug_category)
+		    __vstring(msg, vaf->fmt, vaf->va)
+		    ),
+
+	    TP_fast_assign(
+		    __entry->drm_debug_category = drm_debug_category;
+		    __assign_vstr(msg, vaf->fmt, vaf->va);
+		    ),
+
+	    TP_printk("%s", __get_str(msg))
+);
+
+/* drm_devdbg() was called, pass its args, preserving order */
+TRACE_EVENT(drm_devdbg,
+	    TP_PROTO(const struct device *dev, int drm_debug_category, struct va_format *vaf),
+
+	    TP_ARGS(dev, drm_debug_category, vaf),
+
+	    TP_STRUCT__entry(
+		    __field(const struct device*, dev)
+		    __field(int, drm_debug_category)
+		    __vstring(msg, vaf->fmt, vaf->va)
+		    ),
+
+	    TP_fast_assign(
+		    __entry->drm_debug_category = drm_debug_category;
+		    __entry->dev = dev;
+		    __assign_vstr(msg, vaf->fmt, vaf->va);
+		    ),
+
+	    TP_printk("cat:%d, %s %s", __entry->drm_debug_category,
+		      dev_name(__entry->dev), __get_str(msg))
+);
+
+#endif /* _TRACE_DRM_H */
+
+/* This part must be outside protection */
+#include <trace/define_trace.h>
-- 
2.36.1

