[PATCH v10 00/10 RESEND] use DYNAMIC_DEBUG to implement DRM.debug & DRM.trace

Jim Cromie
2021-11-11T22:02:18Z

Hi Jason, Greg, DRM-everyone, everyone,

resend to add more people, after rebasing on master to pick up
306589856399 drm/print: Add deprecation notes to DRM_...() functions

This patchset has 3 separate but related parts:

1. DEFINE_DYNAMIC_DEBUG_BITGRPS macro [patch 1/10]

Declares DRM.debug style bitmap, bits control pr_debugs by matching formats
Adds callback to translate bits to $cmd > dynamic_debug/control
This could obsolete EXPORT(dynamic_debug_exec_queries) not included.

/* anticipated_usage */
static struct dyndbg_desc drm_categories_map[] = {
[0] = { DRM_DBG_CAT_CORE },
[1] = { DRM_DBG_CAT_DRIVER },
[2] = { DRM_DBG_CAT_KMS },
[3] = { DRM_DBG_CAT_PRIME }, ... };

DEFINE_DYNAMIC_DEBUG_BITGRPS(debug, __drm_debug,
" bits control drm.debug categories ",
drm_categories_map);

Please consider this patch for -next/now/current:
- new interface, new code, no users to break
- allows DRM folks to consider in earnest.
- api bikeshedding to do ?
struct dyndbg_desc isnt that great a name, others too probably.

2. use (1) to reimplement drm.debug [patches 3-7]:

1st in amdgpu & i915 to control existing pr_debugs by their formats
POC for (1)
then in drm-print, for all drm.debug API users
has kernel-footprint impact:
amdgpu has ~3k pr_debugs. (120kb callsite data)
i915.ko has ~2k

avoids drm_debug_enabled(), gives NOOP savings & new flexibility.
changes drm.debug categories from enum to format-prefix-string
alters in-log format to include the format-prefix-string
Daniel Vetter liked this at -v3
https://lore.kernel.org/lkml/YPbPvm%2FxcBlTK1wq@phenom.ffwll.local/
Im sure Ive (still) missed stuff.

3. separately, Sean Paul proposed: drm.trace to mirror drm.debug to tracefs
https://patchwork.freedesktop.org/series/78133/

He argues:
tracefs is fast/lightweight compared to syslog
independent selection (of drm categories) to tracefs
gives tailored traffic w.o flooding syslog

ISTM he's correct. So it follows that write-to-tracefs is also a good
feature for dyndbg, where its then available for all pr_debug users,
including all of drm, on a per-site basis, via echo +T >control. (iff
CONFIG_TRACING).

So basically, I borg'd his:
[patch 14/14] drm/print: Add tracefs support to the drm logging helpers

Then I added a T flag, so it can be toggled from shell:

# turn on all drm's pr_debug --> tracefs
echo module drm +T > /proc/dynamic_debug/control

It appears to just work: (RFC)

The instance name is a placeholder, per-module subdirs kinda fits the
tracefs pattern, but full mod/file-basename/function/line feels like
overkill, mod/basename-func.line would flatten it nicely. RFC.

[root@gandalf dyndbg-tracefs]# pwd
/sys/kernel/tracing/instances/dyndbg-tracefs
[root@gandalf dyndbg-tracefs]# echo 1 > /sys/module/drm/parameters/trace
[root@gandalf dyndbg-tracefs]# head -n16 trace | sed -e 's/^#//'
tracer: nop

entries-in-buffer/entries-written: 405/405 #P:24

_-----=> irqs-off
/ _----=> need-resched
| / _---=> hardirq/softirq
|| / _--=> preempt-depth
||| / _-=> migrate-disable
|||| / delay
TASK-PID CPU# ||||| TIMESTAMP FUNCTION
| | | ||||| | |
<...>-2254 [000] ..... 7040.894352: __dynamic_pr_debug: drm:core: comm="gnome-shel:cs0" pid=2254, dev=0xe200, auth=1, AMDGPU_CS
<...>-2207 [015] ..... 7040.894654: __dynamic_pr_debug: drm:core: comm="gnome-shell" pid=2207, dev=0xe200, auth=1, DRM_IOCTL_MODE_ADDFB2
<...>-2207 [015] ..... 7040.995403: __dynamic_pr_debug: drm:core: comm="gnome-shell" pid=2207, dev=0xe200, auth=1, DRM_IOCTL_MODE_RMFB
<...>-2207 [015] ..... 7040.995413: __dynamic_pr_debug: drm:core: OBJ ID: 121 (2)

This is the pr-debug doing most of that logging: (from dynamic_debug/control)

drivers/gpu/drm/drm_ioctl.c:866 [drm]drm_ioctl =T "drm:core: comm=\042%s\042 pid=%d, dev=0x%lx, auth=%d, %s\012"

Turning on decoration flags changes the trace:

echo module drm format drm:core: +mflt > /proc/dynamic_debug/control

TASK-PID CPU# ||||| TIMESTAMP FUNCTION
| | | ||||| | |
<...>-2254 [003] ..... 15980.936660: __dynamic_pr_debug: [2254] drm:drm_ioctl:866: drm:core: comm="gnome-shel:cs0" pid=2254, dev=0xe200, auth=1, AMDGPU_CS
<...>-2207 [015] ..... 15980.936966: __dynamic_pr_debug: [2207] drm:drm_ioctl:866: drm:core: comm="gnome-shell" pid=2207, dev=0xe200, auth=1, DRM_IOCTL_MODE_ADDFB2
<...>-2207 [015] ..... 15981.037727: __dynamic_pr_debug: [2207] drm:drm_ioctl:866: drm:core: comm="gnome-shell" pid=2207, dev=0xe200, auth=1, DRM_IOCTL_MODE_RMFB
<...>-2207 [015] ..... 15981.037739: __dynamic_pr_debug: [2207] drm:drm_mode_object_put:195: drm:core: OBJ ID: 124 (2)
<...>-2207 [015] ..... 15981.037742: __dynamic_pr_debug: [2207] drm:drm_mode_object_put:195: drm:core: OBJ ID: 124 (1)

The FUNCTION could stand tweaking (to match the callsite in the
control file, cited above), or perhaps replaced by the 'mfl'
decorations; the 't' flag is redundant for trace. Meh.

SELFTEST

A previous version of this patchset added test_dynamic_debug.ko, but
it relied upon code I ripped out when I made tracefs available by
default (without modules having to register 1st). So it fails 10/29
tests, which counted +T sites executed, via side effect.

TODO: userspace selftest

# to set expected tracing activity
echo module test_dynamic_debug function do_debugging +T > control

# run do_debugging function (todo: add sysfs knob)
echo 2 > /sys/module/test-dynamic-debug/parameters/run_me

If thats wrapped in the right trace_on, trace_pipe, etc incantations,
the +T enabled pr_debugs in do_debugging() can be counted, compared
against expectations, and passed or failed.

change since v9:
. patch confict against drm-misc resolved
. s/CATEGORIES/BITGRPS/ in 1/10 - keep name generic: bitmap + groups
. CATEGORIES is drm term, use it there only
. fix api friction wrt drm.trace knob
2 separate macros: DEFINE_DYNAMIC_DEBUG_{LOG,TRACE}_GROUPS - JBaron

v9: https://patchwork.freedesktop.org/series/96327/
v8: https://patchwork.freedesktop.org/series/93914/
https://lore.kernel.org/lkml/20210915163957.2949166-1-jim.cromie@gmail.com/

The major change since v8 is that +T now works for all users, if
CONFIG_TRACING=y, otherwise it complains/errors.

SUMMARY

- drm as dyndbg user adds almost 9k callsites to kernel running this patchset
substantial footprint
substantial source of pr-debug-trace events (not all, but some useful)

[jimc@gandalf wk-next]$ wc /proc/dynamic_debug/control
8927 71062 1099699 /proc/dynamic_debug/control
[jimc@gandalf wk-next]$ uname -a
Linux gandalf 5.15.0-rh2-12144-g5d5db04dfb0c #3 SMP PREEMPT Thu Nov 11 10:5

- pr_debug as event provider
using exported trace_array_printk
cheap with JUMP_LABEL
precise, ad-hoc or organized callsite enablement
callsite descriptor is in its interface, so are VARARGS
inspectable, extensible wo api churn,
iff trace_array_printk can do it.

Jim Cromie (10):
dyndbg: add DEFINE_DYNAMIC_DEBUG_BITGRPS macro and callbacks
drm: fix doc grammar
amdgpu: use dyndbg.BITGRPS to control existing pr_debugs
i915/gvt: trim spaces from pr_debug "gvt: core:" prefixes
i915/gvt: use dyndbg.BITGRPS for existing pr_debugs
drm_print: add choice to use dynamic debug in drm-debug
drm_print: instrument drm_debug_enabled
dyndbg: add print-to-tracefs, selftest with it - RFC
dyndbg: create DEFINE_DYNAMIC_DEBUG_LOG|TRACE_GROUPS
drm: use DEFINE_DYNAMIC_DEBUG_TRACE_GROUPS in 3 places

.../admin-guide/dynamic-debug-howto.rst | 7 +-
MAINTAINERS | 1 +
drivers/gpu/drm/Kconfig | 26 ++
drivers/gpu/drm/Makefile | 2 +
drivers/gpu/drm/amd/amdgpu/Makefile | 2 +
.../gpu/drm/amd/display/dc/core/dc_debug.c | 55 ++++-
drivers/gpu/drm/drm_print.c | 62 +++--
drivers/gpu/drm/i915/Makefile | 2 +
drivers/gpu/drm/i915/gvt/debug.h | 18 +-
drivers/gpu/drm/i915/intel_gvt.c | 47 ++++
include/drm/drm_drv.h | 2 +-
include/drm/drm_print.h | 182 +++++++++++---
include/linux/dynamic_debug.h | 88 ++++++-
lib/Kconfig.debug | 11 +
lib/Makefile | 1 +
lib/dynamic_debug.c | 203 ++++++++++++++--
lib/test_dynamic_debug.c | 222 ++++++++++++++++++
17 files changed, 843 insertions(+), 88 deletions(-)
create mode 100644 lib/test_dynamic_debug.c

--
2.31.1