Re: [PATCH v2 26/27] dyndbg: 4 new trace-events: pr_debug, dev_dbg, drm_{,dev}debug

2022-06-29 Thread Steven Rostedt


Sorry for the late review. I finally got some time to look at this.

On Mon, 16 May 2022 16:56:39 -0600
Jim Cromie  wrote:


> diff --git a/include/trace/events/drm.h b/include/trace/events/drm.h
> new file mode 100644
> index ..6de80dd68620
> --- /dev/null
> +++ b/include/trace/events/drm.h
> @@ -0,0 +1,68 @@
> +/* 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 
> +
> +/* 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)
> + __dynamic_array(char, msg, 256)
> + ),
> +
> + TP_fast_assign(
> + int len;
> +
> + __entry->drm_debug_category = drm_debug_category;
> + vsnprintf(__get_str(msg), 256, vaf->fmt, *vaf->va);
> +
> + len = strlen(__get_str(msg));
> + if (len > 0 && (__get_str(msg)[len - 1] == '\n'))
> + len -= 1;
> + __get_str(msg)[len] = 0;
> + ),
> +
> + 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)
> + __dynamic_array(char, msg, 256)

You do not want to hardcode the 256 here. That will cause 256 bytes to be
reserved on the buffer, and you will not get that back. Might as well make
it a static array, as you also add 4 bytes to for the offset and size.

I think you want (haven't tested it)

__dynamic_array(char, msg, get_msg_size(vaf))

Where you have:

static unsigned int get_msg_size(struct va_format *vaf)
{
va_list aq;
unsigned int ret;

va_copy(aq, vaf->va);
ret = vsnprintf(NULL, 0, vaf->fmt, aq);
va_end(aq);

return min(ret + 1, 256);
}

What is in the last parameter of __dynamic_array() is used to calculate the
size needed to store the dynamic array.

Hmm, looking at other users of __dynamic_array(), this appears to be a
constant problem. I need to document this better.

-- Steve


> + ),
> +
> + TP_fast_assign(
> + int len;
> +
> + __entry->drm_debug_category = drm_debug_category;
> + __entry->dev = dev;
> + vsnprintf(__get_str(msg), 256, vaf->fmt, *vaf->va);
> +
> + len = strlen(__get_str(msg));
> + if (len > 0 && (__get_str(msg)[len - 1] == '\n'))
> + len -= 1;
> + __get_str(msg)[len] = 0;
> + ),
> +
> + TP_printk("cat:%d, %s %s", __entry->drm_debug_category,
> +   dev_name(__entry->dev), __get_str(msg))
> +);
> +
> +#endif /* _TRACE_DRM_H */
> +


[PATCH v2 26/27] dyndbg: 4 new trace-events: pr_debug, dev_dbg, drm_{, dev}debug

2022-05-16 Thread Jim Cromie
ddebug_trace() currently issues a single printk:console event.
Replace that, adding include/trace/events/dyndbg.h, which defines 2
new events:

- dyndbg:prdbg  - from trace_prdbg()  - if !dev
- dyndbg:devdbg - from trace_devdbg() - if !!dev

This links the legacy pr_debug API to tracefs, via dyndbg, allowing
pr_debug()s etc to add just a little more user-context to the
trace-logs, and then at users option, less syslog.

The 2 new trace_*() calls accept their caller's args respectively,
keeping the available info w/o alteration; we can't improve on
transparency.  The args:

 1- struct _ddebug *descriptor, giving tracefs all of dyndbg's info.
 2- struct device *dev, used by trace_devdbg(), if !!dev

The trace_*() calls need the descriptor arg, the callchain prototypes
above them are extended to provide it.

The existing category param in this callchain is partially redundant;
when descriptor is available, it has the class_id.

dev_dbg(desc, dev...), if dev is true, issues a trace_devdbg(),
otherwise trace_prdbg().  This way we dont consume buffer space
storing nulls.  Otherwise the events are equivalent.

Also add include/trace/events/drm.h, to create 2 events for use in
drm_dbg() and drm_devdbg(), and call them.  This recapitulates the
changes described above, connecting 3-10K drm.debug callsites to
tracefs.

Signed-off-by: Jim Cromie 
---
 drivers/gpu/drm/drm_print.c   |  9 +
 include/trace/events/drm.h| 68 
 include/trace/events/dyndbg.h | 74 +++
 lib/dynamic_debug.c   | 73 +-
 4 files changed, 188 insertions(+), 36 deletions(-)
 create mode 100644 include/trace/events/drm.h
 create mode 100644 include/trace/events/dyndbg.h

diff --git a/drivers/gpu/drm/drm_print.c b/drivers/gpu/drm/drm_print.c
index 63125a507577..9afb676bda4d 100644
--- a/drivers/gpu/drm/drm_print.c
+++ b/drivers/gpu/drm/drm_print.c
@@ -34,6 +34,9 @@
 #include 
 #include 
 
+#define CREATE_TRACE_POINTS
+#include 
+
 /*
  * __drm_debug: Enable debug output.
  * Bitmask of DRM_UT_x. See include/drm/drm_print.h for details.
@@ -283,10 +286,14 @@ void __drm_dev_dbg(struct _ddebug *desc, const struct 
device *dev,
if (desc->flags & _DPRINTK_FLAGS_PRINTK)
dev_printk(KERN_DEBUG, dev, "[" DRM_NAME ":%ps] %pV",
   __builtin_return_address(0), );
+   if (desc->flags & _DPRINTK_FLAGS_TRACE)
+   trace_drm_devdbg(dev, category, );
} else {
if (desc->flags & _DPRINTK_FLAGS_PRINTK)
printk(KERN_DEBUG "[" DRM_NAME ":%ps] %pV",
   __builtin_return_address(0), );
+   if (desc->flags & _DPRINTK_FLAGS_TRACE)
+   trace_drm_debug(category, );
}
va_end(args);
 }
@@ -307,6 +314,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), );
 
+   trace_drm_debug(category, );
+
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 ..6de80dd68620
--- /dev/null
+++ b/include/trace/events/drm.h
@@ -0,0 +1,68 @@
+/* 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 
+
+/* 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)
+   __dynamic_array(char, msg, 256)
+   ),
+
+   TP_fast_assign(
+   int len;
+
+   __entry->drm_debug_category = drm_debug_category;
+   vsnprintf(__get_str(msg), 256, vaf->fmt, *vaf->va);
+
+   len = strlen(__get_str(msg));
+   if (len > 0 && (__get_str(msg)[len - 1] == '\n'))
+   len -= 1;
+   __get_str(msg)[len] = 0;
+   ),
+
+   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)
+   __dynamic_array(char, msg, 256)
+   ),
+
+   TP_fast_assign(
+   int len;
+
+   __entry->drm_debug_category = drm_debug_category;
+