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

Message

Jim Cromie Nov. 11, 2021, 10:01 p.m. UTC

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/[e-mail]/
   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/[e-mail]/

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