2022-05-17 00:25:23

by Jim Cromie

[permalink] [raw]
Subject: [RFC PATCH v2 00/27] DRM.debug on DYNAMIC_DEBUG, add trace events

DRM.debug API is 23 macros, issuing 10 exclusive categories of debug
messages. By rough count, they are used 5140 times in the kernel.
These all call drm_dbg or drm_devdbg, which call drm_debug_enabled(),
which checks bits in global __drm_debug. Some of these are page-flips
and vblanks, and get called often.

DYNAMIC_DEBUG (with CONFIG_JUMP_LABEL) is built to avoid this kind of
work, with NOOPd jump/callsites.

This patchset is RFC because:
- it touches 2.5 subsystems: dyndbg, drm, tracefs (new events)
- dyndbg class support is built for drm, needs it for validation
- new api, used by drm
- big memory impact, with 5100 new pr-debug callsites.
- drm class bikeshedding opportunities
- others, names etc.

DYNAMIC_DEBUG:

Adapt to directly represent 32 exclusive classes / categories.
All existing users get _CLASS_DFLT:31, reserving 0-30 for opt-in.

dynamic_debug_register_classes(): Tells dyndbg that caller/client is
using .class_id's 0..N, and wants them exposed and manipulatable with
names: DRM_UT_KMS etc.

Client invokes DYNAMIC_DEBUG_CLASSES to define the name->id map,
then registers it during its initialization.

Then, when a dyndbg command-query has "class FOO":

echo class DRM_UT_KMS +p > /proc/dynamic_debug/control

ddebug_change() will 1st ddebug_validate_classname() for each module,
using its registered class-maps; only modules which know DRM_UT_KMS
will get those callsite adjustments. This "protects" each module's
class-id space, unlike "class 4" query syntax.

Add bitmap support for:
echo 0x02 > /sys/module/drm/parameters/debug

Add symbolic bitmap, because we have the class-names:
echo +DRM_UT_KMS,+DRM_UT_ATOMIC > /sys/module/drm/parameters/debug

Add test_dynamic_debug, to prove out the API.

which is (used 3x to prove class-id ranges):
- DYNAMIC_DEBUG_CLASSES(var, ... [3 class-name-literals each])
- dynamic_debug_register_classes(var)
- dynamic_debug_unregister_classes(var)
also (6x):
+module_param_cb(<node-name>, &param_ops_dyndbg_classes, /[pt][123]_bitmap/, 0600);

Bits 0,1,2 of each of the 6 bitmaps control the 3 named classes in
each of 3 groups, toggling their p,T bits respectively.

RFC:

dynamic_debug_register_classes() cannot act early enough to be in
effect at module-load. So this will not work as you'd reasonably
expect:

modprobe test_dynamic_debug dyndbg='+pfm; class FOO +pfmlt'

The 1st query:+pfm will be enabled during load, but in the 2nd query,
"class FOO" will be unknown at load time. Early class enablement
would be nice. DYNAMIC_DEBUG_CLASSES is a static initializer, which
is certainly early enough, but Im missing a trick, suggestions?

Wildcarding on classname is possible, maybe useful:

echo +DRM_UT_\* > /sys/module/drm/parameters/debug

If contemplated in earnest, it should consider the difference between
"DRM_*" and "*_KMS", wrt observing across class hierarchies, as well
as decide whether that echo means 1st match, or all matching names.

__pr_debug_cls(cls, fmt,...) is just for testing, drm doesnt need it.


DRM adaptation:

Basically, these patches add another layer of macro indirection, which
by CONFIG_DRM_USE_DYNAMIC_DEBUG=y, wraps drm_*dbg() in dyndbg's callsite
Factory macro, and adds the new descriptor arg to the funcs.

With these patches, drm.debugs appear as controllable *pr-dbg* callsites:

[ 11.804352] dyndbg: register_classes: drm
[ 11.920715] dyndbg: 234 debug prints in module drm_kms_helper
[ 11.932135] dyndbg: 2 debug prints in module ttm
[ 11.936119] dyndbg: 8 debug prints in module video
[ 12.537543] dyndbg: 1756 debug prints in module i915
[ 12.555045] dyndbg: register_classes: i915
[ 12.666727] AMD-Vi: AMD IOMMUv2 functionality not available on this ..
[ 13.735310] dyndbg: 3859 debug prints in module amdgpu

amdgpu's large count includes:
582 direct uses/mentions of pr_debug
43 defns of DC_LOG_*, which use either pr_debug or DRM_DEBUG_*
~1000 uses of DC_LOG_*
1116 uses of dml_print in drivers/gpu/drm/amd
15 drm_dbg_\\w+ drivers/gpu/drm/amd
273 DRM_DEBUG_\\w+ drivers/gpu/drm/amd

i915 has:
1072 drm_dbg_\\w+ drivers/gpu/drm/i915/ | wc -l
200 DRM_DEBUG_\\w+ drivers/gpu/drm/i915/
46 pr_debug drivers/gpu/drm/i915/
144 gvt_dbg_\\w+ drivers/gpu/drm/i915/gvt, using pr_debug

This impacts the data footprint, so everything new/drm is dependent on
DRM_USE_DYNAMIC_DEBUG=y.

RFC for DRM:

- decoration flags "fmlt" do not work on drm_*dbg().
(drm_*dbg() dont use pr_debug, they *become* one flavor of them)
this could (should?) be added, and maybe tailored for drm.
some of the device prefixes are very long, a "d" flag could optionalize them.

- api use needs review wrt drm life-cycle.
enum drm_debug_category and DYNAMIC_DEBUG_CLASSES could be together?

- class-names could stand review, perhaps extension
"drm:core:" etc have appeared (maybe just from me)
or a "plan" to look at it later

- i915 & amdgpu have pr_debugs (DC_LOG_*, gvt_dbg_*) that have
class-ish prefixes that are separate from, but similar to DRM_UT_*,
and could stand review and possible unification with reformed or
extended drm categories.

- the change to enum drm_debug_category from bitmask values to 0..31
means that we foreclose this possiblility:

drm_dbg(DRM_UT_CORE|DRM_UT_KMS, "wierd double-cat experiment");

- nouveau has very few drm.debug calls,
has NV_DEBUG, VMM_DEBUG, nvkm_printk_, I havent looked deeply.

DYNDBG/DRM -> TRACEFS

My 1st try was motivated by Sean Paul's patch - DRM.trace:
https://patchwork.freedesktop.org/patch/445549/?series=78133&rev=5

Those used trace_printk, so were not good for upstream.

Vincent Whitchurch's code:
https://lore.kernel.org/lkml/[email protected]/

added similar features, by sending printk:console events from dyndbg.
It met with a good reception from Steve Rostedt, so I re-started with
that.

The biggest addition (from UI viewpoint) is 4 new trace-events, 2 each
from dyndbg (pr_debug, dev_dbg) and drm (drm_dbg, drm_dev_dbg); 2 have
dev, other 2 avoid storing nulls. Im unsure that 4 distinctions is
valuable, but it seemed most obvious to reflect them straight thru to
tracefs.

RFC: the event/message formats are a bit of a mash-up;

in /sys/kernel/tracing:
drm/drm_debug/format:print fmt: "%s", __get_str(msg)
drm/drm_devdbg/format:print fmt: "cat:%d, %s %s", \
REC->drm_debug_category, dev_name(REC->dev), __get_str(msg)

The 1st prints just the mesg itself, 2nd prints category as int;
it'd be better if DRM.class-name replaced (not just augmented) the
event-name "drm_devdbg" in the trace, is that possible ?

dyndbg/prdbg/format:
print fmt: "%s.%s %s", REC->desc->modname, REC->desc->function, __get_str(msg)
dyndbg/devdbg/format:
print fmt: "%s.%s %s", REC->desc->modname, REC->desc->function, __get_str(msg)

These add a prefix string similar to dyndbg's decorations, except they
don't use dyndbg's "fmlt" decoration flags.

There are also 3 vblank trace-events already,
declared in: drivers/gpu/drm/drm_trace.h
15:TRACE_EVENT(drm_vblank_event,
35:TRACE_EVENT(drm_vblank_event_queued,
52:TRACE_EVENT(drm_vblank_event_delivered,

STATUS

kernel-test-robot tested this patchset (on 5.18-rc6).
github:[jimc:blead] BUILD SUCCESS 6c59e52ac81dd81ac7da4522a5e15b7ac488d5b5
May 15, 2022, 8:39 AM (1 day ago)


Ive been testing, mostly on virtme, mostly with this:
#!/bin/bash

# test class FOO handling of dynamic-debug

alias lmt='modprobe test_dynamic_debug dyndbg=+pmf'
alias rmt='rmmod test_dynamic_debug'
alias look='grep test_dynamic_debug /proc/dynamic_debug/control'

lookfor() {
grep $1 /proc/dynamic_debug/control
}

vx() {
echo $* > /sys/module/dynamic_debug/parameters/verbose
}

# amdgpu has ~2200 pr-debugs (before drm-debug-on-dyndbg),
# use them to prove modprobe <mod> dyndbg=+p works

test_param_dyndbg() {

modprobe amdgpu dyndbg=+pfm
let count=$(grep =pmf /proc/dynamic_debug/control | grep amdgpu | wc -l)

if [ $count -gt 200 ] ; then
echo amdgpu has $count pr-dbgs
return 0
else
echo failed $count
return -1
fi
}
out=$(test_param_dyndbg)
echo out:$out $?
[ $? -eq 0 ] || exit $?

qry_cmd() {
echo "QCMD: $* >control" >&2
echo $* > /proc/dynamic_debug/control
}

# enable dyndbg tracing
dynable() {
grep -P \\d $SKT/events/dyndbg/{.,*}/enable
echo 1 > $SKT/events/dyndbg/enable
grep -P \\d $SKT/events/dyndbg/{.,*}/enable
}

# enable drm tracing
drmable() {
grep -P \\d $SKT/events/drm/{.,*}/enable
echo 1 > $SKT/events/drm/enable
grep -P \\d $SKT/events/drm/{.,*}/enable
}

function doit() {
cat /sys/module/test_dynamic_debug/parameters/do_prints
}

# test class FOO behavior of test_dynamic_debug module
ttest_module__() {
flg=$1
dmesg -C
modprobe test_dynamic_debug dyndbg=+pfm
doit

for cls in FOO BAR BUZZ; do
qry_cmd module test_dynamic_debug class $cls $flg
doit
done
doit

for cls in Foo Bar Buzz; do
qry_cmd module test_dynamic_debug class $cls $flg
doit
done
doit

for cls in bing bong boom; do
qry_cmd module test_dynamic_debug class $cls $flg
doit
done
doit

dmesg | grep class
}

ttest_module() {

ttest_module__ +p
ttest_module__ -p

#ttest_module__ +T
#ttest_module__ -T
}

#dynable
#drmable

ttest_module
grep test_dyn /proc/dynamic_debug/control


# use/test bitmaps

set_tddm_() {
val=$1;
knob=$2;
echo "TDDM: $val >$knob" >&2
echo $val > /sys/module/test_dynamic_debug/parameters/$knob
cat /sys/module/test_dynamic_debug/parameters/$knob
}

CLS_1="FOO -FOO +FOO -FOO BAR -BAR +BAR -BAR BUZZ -BUZZ +BUZZ -BUZZ"
CLS_2=" Foo Bar Buzz -Foo -Bar -Buzz +Foo +Bar +Buzz -Foo -Bar -Buzz"
CLS_3=" bing bong boom -bing -bong -boom +bing +bong +boom -bing -bong -boom"

tddm_sysnode_classes__() {
targ=$1
shift
cls=$*
for bitsym in $cls;
do
set_tddm_ $bitsym $targ
done
}

# work all 3 sysfs bitmaps

for sysnode in c1_syslog_bits c2_syslog_bits c3_syslog_bits;
do
for val in 0 1 2 4 8 0;
do
tddm_sysnode_classes__ $sysnode $val
done
done

tddm_sysnode_classes__ c1_syslog_bits $CLS_1
tddm_sysnode_classes__ c2_syslog_bits $CLS_2
tddm_sysnode_classes__ c3_syslog_bits $CLS_3

echo "show unknown: c3-names on c1-knob" >&2
tddm_sysnode_classes__ c1_trace_bits $CLS_3

echo "flags look inverted" >&2
tddm_sysnode_classes__ c1_syslog_bits $CLS_1

CLS_1_=FOO,-FOO,+FOO,-FOO,BAR,-BAR,+BAR,-BAR,BUZZ,-BUZZ,+BUZZ,-BUZZ
CLS_2_=Foo,Bar,Buzz,-Foo,-Bar,-Buzz,+Foo,+Bar,+Buzz,-Foo,-Bar,-Buzz
# leading err doesnt wreck the rest
CLS_3_=,bing,bong,boom,-bing,-bong,-boom,+bing,+bong,+boom,-bing,-bong,-boom

tddm_sysnode_classes__ c1_syslog_bits $CLS_1_
tddm_sysnode_classes__ c2_syslog_bits $CLS_2_
tddm_sysnode_classes__ c3_syslog_bits $CLS_3_


Cc: Sean Paul <[email protected]>
Cc: Daniel Vetter <[email protected]>
Cc: David Airlie <[email protected]>
Cc: Jani Nikula <[email protected]>
Cc: Joonas Lahtinen <[email protected]>
Cc: Pekka Paalanen <[email protected]>
Cc: Rob Clark <[email protected]>
Cc: Steven Rostedt <[email protected]>
Cc: Thomas Zimmermann <[email protected]>
Cc: Ville Syrjälä <[email protected]>
Cc: Chris Wilson <[email protected]>
Cc: Steven Rostedt <[email protected]>

Jim Cromie (27):
dyndbg: fix static_branch manipulation
dyndbg: show both old and new in change-info
dyndbg: fix module.dyndbg handling
dyndbg: drop EXPORTed dynamic_debug_exec_queries
dyndbg: add exclusive class_id to pr_debug callsites
dyndbg: add dynamic_debug_(un)register_classes
dyndbg: validate class FOO on module
dyndbg: add drm.debug style bitmap support
Doc/dyndbg: document new class class_name query support
dyndbg: let query-modname override defaulting modname
dyndbg: support symbolic class-names in bitmap
dyndbg: change zero-or-one classes-map to maps list
dyndbg: add __pr_debug_cls(class, fmt, ...)
dyndbg: add test_dynamic_debug module
drm: POC drm on dyndbg - map class-names to drm_debug_category's
drm/print: POC drm on dyndbg - use bitmap
drm_print: condense enum drm_debug_category
drm_print: interpose drm_*dbg with forwarding macros
drm_print: wrap drm_*_dbg in dyndbg descriptor factory macro
drm_print: refine drm_debug_enabled for jump-label
drm_print: prefer bare printk KERN_DEBUG on generic fn
drm_print: add _ddebug desc to drm_*dbg prototypes
dyndbg: add _DPRINTK_FLAGS_ENABLED
dyndbg: add _DPRINTK_FLAGS_TRACE
dyndbg: add write-events-to-tracefs code
dyndbg: 4 new trace-events: pr_debug, dev_dbg, drm_{,dev}debug
dyndbg/drm: POC add tracebits sysfs-knob

.../admin-guide/dynamic-debug-howto.rst | 12 +
MAINTAINERS | 1 +
drivers/gpu/drm/Kconfig | 12 +
drivers/gpu/drm/Makefile | 2 +
drivers/gpu/drm/amd/amdgpu/amdgpu_drv.c | 3 +
drivers/gpu/drm/drm_drv.c | 5 +
drivers/gpu/drm/drm_print.c | 69 ++-
drivers/gpu/drm/i915/i915_module.c | 11 +
drivers/gpu/drm/nouveau/nouveau_drm.c | 4 +
include/drm/drm_drv.h | 26 +
include/drm/drm_print.h | 84 ++-
include/linux/dynamic_debug.h | 136 ++++-
include/trace/events/drm.h | 68 +++
include/trace/events/dyndbg.h | 74 +++
lib/Kconfig.debug | 11 +
lib/Makefile | 1 +
lib/dynamic_debug.c | 487 +++++++++++++++---
lib/test_dynamic_debug.c | 172 +++++++
18 files changed, 1049 insertions(+), 129 deletions(-)
create mode 100644 include/trace/events/drm.h
create mode 100644 include/trace/events/dyndbg.h
create mode 100644 lib/test_dynamic_debug.c

--
2.35.1



2022-05-17 00:59:20

by Jim Cromie

[permalink] [raw]
Subject: [PATCH v2 09/27] Doc/dyndbg: document new class class_name query support

The added paragraph is slightly process oriented, rather than in
language of guarantees; I thought the implications were clear enough.

It does perhaps undersell the selectivity gained with string
class_names; only drm/* would sanely register DRM_UT_CORE etc, so
doing multiple "module {drm*,amdgpu,i915}" queries is unnecessary.

Signed-off-by: Jim Cromie <[email protected]>
---
Documentation/admin-guide/dynamic-debug-howto.rst | 11 +++++++++++
1 file changed, 11 insertions(+)

diff --git a/Documentation/admin-guide/dynamic-debug-howto.rst b/Documentation/admin-guide/dynamic-debug-howto.rst
index a89cfa083155..01ca6f635dcc 100644
--- a/Documentation/admin-guide/dynamic-debug-howto.rst
+++ b/Documentation/admin-guide/dynamic-debug-howto.rst
@@ -35,6 +35,7 @@ Dynamic debug has even more useful features:
- line number (including ranges of line numbers)
- module name
- format string
+ - class string (as known by each module)

* Provides a debugfs control file: ``<debugfs>/dynamic_debug/control``
which can be read to display the complete list of known debug
@@ -142,6 +143,7 @@ against. Possible keywords are:::
'file' string |
'module' string |
'format' string |
+ 'class' string |
'line' line-range

line-range ::= lineno |
@@ -203,6 +205,15 @@ format
format "nfsd: SETATTR" // a neater way to match a format with whitespace
format 'nfsd: SETATTR' // yet another way to match a format with whitespace

+class
+ The given class_name is validated against each module, which may
+ have registered a list of known class_names. If the class_name is
+ found for a module, callsite matching and adjustment proceeds.
+ Examples::
+
+ class DRM_UT_KMS # unless DRM wants different
+ class JUNK # silent non-match
+
line
The given line number or range of line numbers is compared
against the line number of each ``pr_debug()`` callsite. A single
--
2.35.3


2022-05-17 00:59:41

by Jim Cromie

[permalink] [raw]
Subject: [PATCH v2 21/27] drm_print: prefer bare printk KERN_DEBUG on generic fn

drm_print.c calls pr_debug() just once, from __drm_printfn_debug(),
which is a generic/service fn. The callsite is compile-time enabled
by DEBUG in both DYNAMIC_DEBUG=y/n builds.

For dyndbg builds, reverting this callsite back to bare printk is
correcting a few anti-features:

1- callsite is generic, serves multiple drm users.
its hardwired on currently
could accidentally: #> echo -p > /proc/dynamic_debug/control

2- optional "decorations" by dyndbg are unhelpful/misleading
they describe only the generic site, not end users

IOW, 1,2 are unhelpful at best, and possibly confusing.

reverting yields a nominal data and text shrink:

text data bss dec hex filename
462583 36604 54592 553779 87333 /kernel/drivers/gpu/drm/drm.ko
462515 36532 54592 553639 872a7 -dirty/kernel/drivers/gpu/drm/drm.ko

Signed-off-by: Jim Cromie <[email protected]>
---
drivers/gpu/drm/drm_print.c | 5 ++---
1 file changed, 2 insertions(+), 3 deletions(-)

diff --git a/drivers/gpu/drm/drm_print.c b/drivers/gpu/drm/drm_print.c
index 22b7ab1c5c40..1b11a15366b7 100644
--- a/drivers/gpu/drm/drm_print.c
+++ b/drivers/gpu/drm/drm_print.c
@@ -23,8 +23,6 @@
* Rob Clark <[email protected]>
*/

-#define DEBUG /* for pr_debug() */
-
#include <linux/stdarg.h>

#include <linux/io.h>
@@ -172,7 +170,8 @@ EXPORT_SYMBOL(__drm_printfn_info);

void __drm_printfn_debug(struct drm_printer *p, struct va_format *vaf)
{
- pr_debug("%s %pV", p->prefix, vaf);
+ /* pr_debug callsite decorations are unhelpful here */
+ printk(KERN_DEBUG "%s %pV", p->prefix, vaf);
}
EXPORT_SYMBOL(__drm_printfn_debug);

--
2.35.3


2022-05-17 01:07:35

by Jim Cromie

[permalink] [raw]
Subject: [PATCH v2 22/27] drm_print: add _ddebug desc to drm_*dbg prototypes

Add a struct _ddebug ptr to drm_dbg() and drm_dev_dbg() protos, and
upgrade their callers - the interposed macros added recently, to use
_dynamic_func_call_no_desc(); ie drop the '_no_desc', since the
factory macro's callees (these 2 functions) are now expecting the arg.

This makes those functions controllable like pr_debug(). It also
means that they don't get to use the decorations implemented by
pr_debug(). DRM already has standards for logging/messaging; tossing
optional decorations on top may not help.

For CONFIG_DRM_USE_DYNAMIC_DEBUG=N, just pass null.

Note: desc->class_id is redundant with category parameter, but its
availability is dependent on desc.

Signed-off-by: Jim Cromie <[email protected]>
---
drivers/gpu/drm/drm_print.c | 23 +++++++++++++----------
include/drm/drm_print.h | 22 +++++++++++-----------
2 files changed, 24 insertions(+), 21 deletions(-)

diff --git a/drivers/gpu/drm/drm_print.c b/drivers/gpu/drm/drm_print.c
index 1b11a15366b7..1752b40b0189 100644
--- a/drivers/gpu/drm/drm_print.c
+++ b/drivers/gpu/drm/drm_print.c
@@ -265,8 +265,8 @@ void drm_dev_printk(const struct device *dev, const char *level,
}
EXPORT_SYMBOL(drm_dev_printk);

-void __drm_dev_dbg(const struct device *dev, enum drm_debug_category category,
- const char *format, ...)
+void __drm_dev_dbg(struct _ddebug *desc, const struct device *dev,
+ enum drm_debug_category category, const char *format, ...)
{
struct va_format vaf;
va_list args;
@@ -274,22 +274,25 @@ void __drm_dev_dbg(const struct device *dev, enum drm_debug_category category,
if (!__drm_debug_enabled(category))
return;

+ /* we know we are printing for either syslog, tracefs, or both */
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 (dev) {
+ if (desc->flags && _DPRINTK_FLAGS_PRINT)
+ dev_printk(KERN_DEBUG, dev, "[" DRM_NAME ":%ps] %pV",
+ __builtin_return_address(0), &vaf);
+ } else {
+ if (desc->flags && _DPRINTK_FLAGS_PRINT)
+ printk(KERN_DEBUG "[" DRM_NAME ":%ps] %pV",
+ __builtin_return_address(0), &vaf);
+ }
va_end(args);
}
EXPORT_SYMBOL(__drm_dev_dbg);

-void ___drm_dbg(enum drm_debug_category category, const char *format, ...)
+void ___drm_dbg(struct _ddebug *desc, enum drm_debug_category category, const char *format, ...)
{
struct va_format vaf;
va_list args;
diff --git a/include/drm/drm_print.h b/include/drm/drm_print.h
index ccd177236ab3..fc0f2f6c2b91 100644
--- a/include/drm/drm_print.h
+++ b/include/drm/drm_print.h
@@ -366,9 +366,9 @@ static inline bool drm_debug_enabled(enum drm_debug_category category)
__printf(3, 4)
void drm_dev_printk(const struct device *dev, const char *level,
const char *format, ...);
-__printf(3, 4)
-void __drm_dev_dbg(const struct device *dev, enum drm_debug_category category,
- const char *format, ...);
+__printf(4, 5)
+void __drm_dev_dbg(struct _ddebug *desc, const struct device *dev,
+ enum drm_debug_category category, const char *format, ...);

/**
* DRM_DEV_ERROR() - Error output.
@@ -418,11 +418,11 @@ void __drm_dev_dbg(const struct device *dev, enum drm_debug_category category,

#if !defined(CONFIG_DRM_USE_DYNAMIC_DEBUG)
#define drm_dev_dbg(dev, cat, fmt, ...) \
- __drm_dev_dbg(dev, cat, fmt, ##__VA_ARGS__)
+ __drm_dev_dbg(NULL, dev, cat, fmt, ##__VA_ARGS__)
#else
#define drm_dev_dbg(dev, cat, fmt, ...) \
- _dynamic_func_call_no_desc(fmt, __drm_dev_dbg, \
- dev, cat, fmt, ##__VA_ARGS__)
+ _dynamic_func_call_cls(cat, fmt, __drm_dev_dbg, \
+ dev, cat, fmt, ##__VA_ARGS__)
#endif

/**
@@ -525,17 +525,17 @@ void __drm_dev_dbg(const struct device *dev, enum drm_debug_category category,
* Prefer drm_device based logging over device or prink based logging.
*/

-__printf(2, 3)
-void ___drm_dbg(enum drm_debug_category category, const char *format, ...);
+__printf(3, 4)
+void ___drm_dbg(struct _ddebug *desc, enum drm_debug_category category, const char *format, ...);
__printf(1, 2)
void __drm_err(const char *format, ...);

#if !defined(CONFIG_DRM_USE_DYNAMIC_DEBUG)
-#define __drm_dbg(fmt, ...) ___drm_dbg(fmt, ##__VA_ARGS__)
+#define __drm_dbg(fmt, ...) ___drm_dbg(NULL, fmt, ##__VA_ARGS__)
#else
#define __drm_dbg(cat, fmt, ...) \
- _dynamic_func_call_no_desc(fmt, ___drm_dbg, \
- cat, fmt, ##__VA_ARGS__)
+ _dynamic_func_call_cls(cat, fmt, ___drm_dbg, \
+ cat, fmt, ##__VA_ARGS__)
#endif

/* Macros to make printk easier */
--
2.35.3


2022-05-17 01:07:59

by Jim Cromie

[permalink] [raw]
Subject: [PATCH v2 07/27] dyndbg: validate class FOO on module

Add module-to-class validation, in

#> echo class DRM_UT_KMS +p > /proc/dynamic_debug/control

If a query has "class FOO", ddebug_validate_classname (called from
ddebug_change) requires that FOO is known to module X, otherwize X is
skipped entirely.

The choice of FOO is highly selective, giving isolation and/or
coordinated sharing of FOOs. For example, only DRM modules should
know and respond to DRM_UT_KMS.

So this, combined with module's opt-in declaration of known classes,
effectively privatizes the .class_id space for each module (or
coordinated set of modules).

Ignoring a bad query, with dynamic_debug.verbose=3:
(lots of modules will not know other module's classes)

bash-5.1# echo module drm class FOO +p > /proc/dynamic_debug/control
[ 54.507983] dyndbg: read 24 bytes from userspace
[ 54.509549] dyndbg: query 0: "module drm class FOO +p" mod:*
[ 54.511502] dyndbg: split into words: "module" "drm" "class" "FOO" "+p"
[ 54.513672] dyndbg: op='+'
[ 54.514575] dyndbg: flags=0x1
[ 54.515547] dyndbg: *flagsp=0x1 *maskp=0xffffffff
[ 54.517112] dyndbg: parsed: func="" file="" module="drm" format="" lineno=0-0 class=FOO
[ 54.519707] dyndbg: class: drm.FOO unknown
[ 54.521302] dyndbg: no matches for query
[ 54.522581] dyndbg: no-match: func="" file="" module="drm" format="" lineno=0-0 class=FOO
[ 54.525236] dyndbg: processed 1 queries, with 0 matches, 0 errs

Also add a new column to control-file output, displaying the
class-name when its not default. If a module has pr_debugs with
non-default .class_id's, and has not registered them, "<unregistered>"
is issued.

Signed-off-by: Jim Cromie <[email protected]>
---
. split out validate_classnames()
---
lib/dynamic_debug.c | 70 +++++++++++++++++++++++++++++++++++++++------
1 file changed, 62 insertions(+), 8 deletions(-)

diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
index 8f600c13048a..b1aaf8893cdf 100644
--- a/lib/dynamic_debug.c
+++ b/lib/dynamic_debug.c
@@ -56,6 +56,7 @@ struct ddebug_query {
const char *module;
const char *function;
const char *format;
+ const char *class_string;
unsigned int first_lineno, last_lineno;
};

@@ -136,13 +137,40 @@ static void vpr_info_dq(const struct ddebug_query *query, const char *msg)
fmtlen--;
}

- v3pr_info("%s: func=\"%s\" file=\"%s\" module=\"%s\" format=\"%.*s\" lineno=%u-%u\n",
- msg,
- query->function ?: "",
- query->filename ?: "",
- query->module ?: "",
- fmtlen, query->format ?: "",
- query->first_lineno, query->last_lineno);
+ v3pr_info("%s: func=\"%s\" file=\"%s\" module=\"%s\" format=\"%.*s\" lineno=%u-%u class=%s\n",
+ msg,
+ query->function ?: "",
+ query->filename ?: "",
+ query->module ?: "",
+ fmtlen, query->format ?: "",
+ query->first_lineno, query->last_lineno, query->class_string);
+}
+
+/* return <0 if class-name is unknown/invalid, 0..CLASS_DFLT otherwise */
+static int ddebug_validate_classname(struct ddebug_table *dt, const char *class_string)
+{
+ int query_class = -ENOENT;
+ int idx;
+
+ if (!class_string)
+ /* all queries w/o class given work only on default class */
+ return _DPRINTK_CLASS_DFLT;
+
+ /*
+ * XXX single list will need to be a for-list
+ * so that modules can have 2 sets of class-decls
+ */
+ if (!dt->map)
+ return -ENOENT;
+
+ idx = match_string(dt->map->classes, dt->map->length, class_string);
+ if (idx < 0) {
+ v3pr_info("class: %s.%s unknown\n", dt->mod_name, class_string);
+ return -ENOENT;
+ }
+ query_class = idx + dt->map->base;
+
+ return query_class;
}

/*
@@ -159,6 +187,7 @@ static int ddebug_change(const struct ddebug_query *query,
unsigned int newflags;
unsigned int nfound = 0;
struct flagsbuf fbuf, nbuf;
+ int query_class;

/* search for matching ddebugs */
mutex_lock(&ddebug_lock);
@@ -169,9 +198,18 @@ static int ddebug_change(const struct ddebug_query *query,
!match_wildcard(query->module, dt->mod_name))
continue;

+ /* validate class-string against module's known classes */
+ query_class = ddebug_validate_classname(dt, query->class_string);
+ if (query_class < 0)
+ continue;
+
for (i = 0; i < dt->num_ddebugs; i++) {
struct _ddebug *dp = &dt->ddebugs[i];

+ /* match against query-class, either valid input or default */
+ if (query_class != dp->class_id)
+ continue;
+
/* match against the source filename */
if (query->filename &&
!match_wildcard(query->filename, dp->filename) &&
@@ -424,6 +462,8 @@ static int ddebug_parse_query(char *words[], int nwords,
} else if (!strcmp(keyword, "line")) {
if (parse_linerange(query, arg))
return -EINVAL;
+ } else if (!strcmp(keyword, "class")) {
+ rc = check_set(&query->class_string, arg, "class");
} else {
pr_err("unknown keyword \"%s\"\n", keyword);
return -EINVAL;
@@ -851,6 +891,13 @@ static void *ddebug_proc_next(struct seq_file *m, void *p, loff_t *pos)
return dp;
}

+static const char *ddebug_class_name(struct ddebug_iter *iter, struct _ddebug *dp)
+{
+ if (iter->table->map)
+ return iter->table->map->classes[dp->class_id];
+ return NULL;
+}
+
/*
* Seq_ops show method. Called several times within a read()
* call from userspace, with ddebug_lock held. Formats the
@@ -862,6 +909,7 @@ static int ddebug_proc_show(struct seq_file *m, void *p)
struct ddebug_iter *iter = m->private;
struct _ddebug *dp = p;
struct flagsbuf flags;
+ char const *class;

if (p == SEQ_START_TOKEN) {
seq_puts(m,
@@ -874,7 +922,13 @@ static int ddebug_proc_show(struct seq_file *m, void *p)
iter->table->mod_name, dp->function,
ddebug_describe_flags(dp->flags, &flags));
seq_escape(m, dp->format, "\t\r\n\"");
- seq_puts(m, "\"\n");
+ seq_puts(m, "\"");
+
+ if (dp->class_id != _DPRINTK_CLASS_DFLT) {
+ class = ddebug_class_name(iter, dp);
+ seq_printf(m, " class:%s", class ?: "<unregistered>");
+ }
+ seq_puts(m, "\n");

return 0;
}
--
2.35.3


2022-05-17 01:13:47

by Jim Cromie

[permalink] [raw]
Subject: [PATCH v2 20/27] drm_print: refine drm_debug_enabled for jump-label

In order to use dynamic-debug's jump-label optimization in drm-debug,
its clarifying to refine drm_debug_enabled into 3 uses:

1. drm_debug_enabled - legacy, public
2. __drm_debug_enabled - optimized for dyndbg jump-label enablement.
3. _drm_debug_enabled - pr_debug instrumented, observable

1. The legacy version always checks the bits.

2. is privileged, for use by __drm_dbg(), __drm_dev_dbg(), which do an
early return unless the category is enabled (free of call/NOOP side
effects). For dyndbg builds, debug callsites are selectively
"pre-enabled", so __drm_debug_enabled() short-circuits to true there.
Remaining callers of 1 may be able to use 2, case by case.

3. is 1st wrapped in a macro, with a pr_debug, which reports each
usage in /proc/dynamic_debug/control, making it observable in the
logs. The macro lets the pr_debug see the real caller, not an inline
function.

When plugged into 1, it identified ~10 remaining callers of the
function, leading to the follow-on cleanup patch, and would allow
activating the pr_debugs, estimating the callrate, and the potential
savings by using the wrapper macro. It is unused ATM, but it fills
out the picture.

Signed-off-by: Jim Cromie <[email protected]>
---
drivers/gpu/drm/drm_print.c | 4 ++--
include/drm/drm_print.h | 28 ++++++++++++++++++++++++++++
2 files changed, 30 insertions(+), 2 deletions(-)

diff --git a/drivers/gpu/drm/drm_print.c b/drivers/gpu/drm/drm_print.c
index 5192533794a2..22b7ab1c5c40 100644
--- a/drivers/gpu/drm/drm_print.c
+++ b/drivers/gpu/drm/drm_print.c
@@ -272,7 +272,7 @@ 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))
+ if (!__drm_debug_enabled(category))
return;

va_start(args, format);
@@ -295,7 +295,7 @@ void ___drm_dbg(enum drm_debug_category category, const char *format, ...)
struct va_format vaf;
va_list args;

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

va_start(args, format);
diff --git a/include/drm/drm_print.h b/include/drm/drm_print.h
index 5c39bacac2b3..ccd177236ab3 100644
--- a/include/drm/drm_print.h
+++ b/include/drm/drm_print.h
@@ -324,11 +324,39 @@ enum drm_debug_category {
DRM_UT_DRMRES
};

+/*
+ * 3 name flavors of drm_debug_enabled:
+ * drm_debug_enabled - public/legacy, always checks bits
+ * _drm_debug_enabled - instrumented to observe call-rates, est overheads.
+ * __drm_debug_enabled - privileged - knows jump-label state, can short-circuit
+ */
static inline bool drm_debug_enabled(enum drm_debug_category category)
{
return unlikely(__drm_debug & BIT(category));
}

+/*
+ * Wrap fn in macro, so that the pr_debug sees the actual caller, not
+ * the inline fn. Using this name creates a callsite entry / control
+ * point in /proc/dynamic_debug/control.
+ */
+#define _drm_debug_enabled(category) \
+ ({ \
+ pr_debug("todo: maybe avoid via dyndbg\n"); \
+ drm_debug_enabled(category); \
+ })
+
+#if defined(CONFIG_DRM_USE_DYNAMIC_DEBUG)
+/*
+ * dyndbg is wrapping the drm.debug API, so as to avoid the runtime
+ * bit-test overheads of drm_debug_enabled() in those api calls.
+ * In this case, executed callsites are known enabled, so true.
+ */
+#define __drm_debug_enabled(category) true
+#else
+#define __drm_debug_enabled(category) drm_debug_enabled(category)
+#endif
+
/*
* struct device based logging
*
--
2.35.3


2022-05-17 01:23:42

by Jim Cromie

[permalink] [raw]
Subject: [PATCH v2 04/27] dyndbg: drop EXPORTed dynamic_debug_exec_queries

This exported fn is unused, and is effectively obsoleted by a
forthcoming commit, so remove it.

The export was added to let drm control pr_debugs, as part of using
them to avoid drm_debug_enabled overheads. But following patches
implement the drm.debug interface, and adapt drm to just use it, so
nobody will never need the export.

This also drops the CONFIG_DYNAMIC_DEBUG=N stub-func, and its
pr_warn(), which I avoided in 2012, then added in 2020 :-/

Fixes: a2d375eda771 ("dyndbg: refine export, rename to dynamic_debug_exec_queries()")
Fixes: 4c0d77828d4f ("dyndbg: export ddebug_exec_queries")
Signed-off-by: Jim Cromie <[email protected]>
---
include/linux/dynamic_debug.h | 8 --------
lib/dynamic_debug.c | 29 -----------------------------
2 files changed, 37 deletions(-)

diff --git a/include/linux/dynamic_debug.h b/include/linux/dynamic_debug.h
index f30b01aa9fa4..dd20e825c36f 100644
--- a/include/linux/dynamic_debug.h
+++ b/include/linux/dynamic_debug.h
@@ -55,9 +55,6 @@ struct _ddebug {

#if defined(CONFIG_DYNAMIC_DEBUG_CORE)

-/* exported for module authors to exercise >control */
-int dynamic_debug_exec_queries(const char *query, const char *modname);
-
int ddebug_add_module(struct _ddebug *tab, unsigned int n,
const char *modname);
extern int ddebug_remove_module(const char *mod_name);
@@ -221,11 +218,6 @@ static inline int ddebug_dyndbg_module_param_cb(char *param, char *val,
rowsize, groupsize, buf, len, ascii); \
} while (0)

-static inline int dynamic_debug_exec_queries(const char *query, const char *modname)
-{
- pr_warn("kernel not built with CONFIG_DYNAMIC_DEBUG_CORE\n");
- return 0;
-}

#endif /* !CONFIG_DYNAMIC_DEBUG_CORE */

diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
index ca2a28f1d51c..cdc0b03b1148 100644
--- a/lib/dynamic_debug.c
+++ b/lib/dynamic_debug.c
@@ -555,35 +555,6 @@ static int ddebug_exec_queries(char *query, const char *modname)
return nfound;
}

-/**
- * dynamic_debug_exec_queries - select and change dynamic-debug prints
- * @query: query-string described in admin-guide/dynamic-debug-howto
- * @modname: string containing module name, usually &module.mod_name
- *
- * This uses the >/proc/dynamic_debug/control reader, allowing module
- * authors to modify their dynamic-debug callsites. The modname is
- * canonically struct module.mod_name, but can also be null or a
- * module-wildcard, for example: "drm*".
- */
-int dynamic_debug_exec_queries(const char *query, const char *modname)
-{
- int rc;
- char *qry; /* writable copy of query */
-
- if (!query) {
- pr_err("non-null query/command string expected\n");
- return -EINVAL;
- }
- qry = kstrndup(query, PAGE_SIZE, GFP_KERNEL);
- if (!qry)
- return -ENOMEM;
-
- rc = ddebug_exec_queries(qry, modname);
- kfree(qry);
- return rc;
-}
-EXPORT_SYMBOL_GPL(dynamic_debug_exec_queries);
-
#define PREFIX_SIZE 64

static int remaining(int wrote)
--
2.35.3


2022-05-17 01:28:43

by Jim Cromie

[permalink] [raw]
Subject: [PATCH v2 27/27] dyndbg/drm: POC add tracebits sysfs-knob

clone DRM.debug interface to DRM.tracebits: ie map bits to
drm-debug-categories, except this interface enables messages to
tracefs, not to syslog.

This reuses dyndbg's register-classes API to add the new sysfs-knob:

drm_drv.h:

[A] 2nd use of DYNAMIC_DEBUG_CLASSES(drm_trace_classes), which
declares and initializes a known-classes map with the same literal
classnames as in the 1st use. This "shares" the classnames for both
sysfs-knobs, which is necessary because they're manipulating a shared
dyndbg callsite, toggling "p" and "T" flags respectively.

This incurs a tiny waste of constant strings, but its worth it for the
simpler declarative macro.

drm_print.c:

1- declare and export a 2nd bit-vector: __drm_trace, like __drm_debug

2- declare and init a struct ddebug_classes_bitmap_param with:
__drm_trace [1], drm_trace_classes [A].

3- module_param_cb([2]) - does the sysfs part

drm_drv.c:

register and unregister [A], and missed unregister on drm_debug_classes.

Signed-off-by: Jim Cromie <[email protected]>
---
drivers/gpu/drm/drm_drv.c | 3 +++
drivers/gpu/drm/drm_print.c | 10 ++++++++++
include/drm/drm_drv.h | 14 +++++++++++++-
3 files changed, 26 insertions(+), 1 deletion(-)

diff --git a/drivers/gpu/drm/drm_drv.c b/drivers/gpu/drm/drm_drv.c
index 16683fb169aa..ad141c5e29ca 100644
--- a/drivers/gpu/drm/drm_drv.c
+++ b/drivers/gpu/drm/drm_drv.c
@@ -1039,6 +1039,8 @@ static void drm_core_exit(void)
drm_sysfs_destroy();
idr_destroy(&drm_minors_idr);
drm_connector_ida_destroy();
+ dynamic_debug_unregister_classes(&drm_debug_classes);
+ dynamic_debug_unregister_classes(&drm_trace_classes);
}

static int __init drm_core_init(void)
@@ -1046,6 +1048,7 @@ static int __init drm_core_init(void)
int ret;

dynamic_debug_register_classes(&drm_debug_classes);
+ dynamic_debug_register_classes(&drm_trace_classes);

drm_connector_ida_init();
idr_init(&drm_minors_idr);
diff --git a/drivers/gpu/drm/drm_print.c b/drivers/gpu/drm/drm_print.c
index 9afb676bda4d..970b6dd46c42 100644
--- a/drivers/gpu/drm/drm_print.c
+++ b/drivers/gpu/drm/drm_print.c
@@ -44,6 +44,9 @@
unsigned long __drm_debug;
EXPORT_SYMBOL(__drm_debug);

+unsigned long __drm_trace;
+EXPORT_SYMBOL(__drm_trace);
+
MODULE_PARM_DESC(debug, "Enable debug output, where each bit enables a debug category.\n"
"\t\tBit 0 (0x01) will enable CORE messages (drm core code)\n"
"\t\tBit 1 (0x02) will enable DRIVER messages (drm controller code)\n"
@@ -63,6 +66,13 @@ static struct ddebug_classes_bitmap_param drm_debug_bitmap = {
.map = &drm_debug_classes,
};
module_param_cb(debug, &param_ops_dyndbg_classes, &drm_debug_bitmap, 0600);
+
+static struct ddebug_classes_bitmap_param drm_trace_bitmap = {
+ .bits = &__drm_trace,
+ .flags = "T",
+ .map = &drm_trace_classes,
+};
+module_param_cb(tracecats, &param_ops_dyndbg_classes, &drm_trace_bitmap, 0600);
#endif

void __drm_puts_coredump(struct drm_printer *p, const char *str)
diff --git a/include/drm/drm_drv.h b/include/drm/drm_drv.h
index c2ffe12161b8..596de0addfd5 100644
--- a/include/drm/drm_drv.h
+++ b/include/drm/drm_drv.h
@@ -45,7 +45,19 @@ struct drm_printer;
struct sg_table;

/* these must comport with enum drm_debug_category values */
-DYNAMIC_DEBUG_CLASSES(drm_debug_classes, "*", 0,
+DYNAMIC_DEBUG_CLASSES(drm_debug_classes, 0,
+ "DRM_UT_CORE",
+ "DRM_UT_DRIVER",
+ "DRM_UT_KMS",
+ "DRM_UT_PRIME",
+ "DRM_UT_ATOMIC",
+ "DRM_UT_VBL",
+ "DRM_UT_STATE",
+ "DRM_UT_LEASE",
+ "DRM_UT_DP",
+ "DRM_UT_DRMRES");
+
+DYNAMIC_DEBUG_CLASSES(drm_trace_classes, 0,
"DRM_UT_CORE",
"DRM_UT_DRIVER",
"DRM_UT_KMS",
--
2.35.3


2022-05-17 01:38:23

by Jim Cromie

[permalink] [raw]
Subject: [PATCH v2 23/27] dyndbg: add _DPRINTK_FLAGS_ENABLED

Distinguish the condition: _DPRINTK_FLAGS_ENABLED from the bit:
_DPRINTK_FLAGS_PRINT (and define former as latter), in preparation to
add another bit next: _DPRINTK_FLAGS_TRACE

And change JUMP_LABEL code block to use the more general
_DPRINTK_FLAGS_ENABLED symbol. Also add a 'K' to get new symbol
_DPRINTK_FLAGS_PRINTK, in order to break any stale uses.

CC: [email protected]
Signed-off-by: Jim Cromie <[email protected]>
---
drivers/gpu/drm/drm_print.c | 4 ++--
include/linux/dynamic_debug.h | 10 ++++++----
lib/dynamic_debug.c | 8 ++++----
3 files changed, 12 insertions(+), 10 deletions(-)

diff --git a/drivers/gpu/drm/drm_print.c b/drivers/gpu/drm/drm_print.c
index 1752b40b0189..77b56399147a 100644
--- a/drivers/gpu/drm/drm_print.c
+++ b/drivers/gpu/drm/drm_print.c
@@ -280,11 +280,11 @@ void __drm_dev_dbg(struct _ddebug *desc, const struct device *dev,
vaf.va = &args;

if (dev) {
- if (desc->flags && _DPRINTK_FLAGS_PRINT)
+ if (desc->flags && _DPRINTK_FLAGS_PRINTK)
dev_printk(KERN_DEBUG, dev, "[" DRM_NAME ":%ps] %pV",
__builtin_return_address(0), &vaf);
} else {
- if (desc->flags && _DPRINTK_FLAGS_PRINT)
+ if (desc->flags && _DPRINTK_FLAGS_PRINTK)
printk(KERN_DEBUG "[" DRM_NAME ":%ps] %pV",
__builtin_return_address(0), &vaf);
}
diff --git a/include/linux/dynamic_debug.h b/include/linux/dynamic_debug.h
index abf43e28d8d3..0a81a3582281 100644
--- a/include/linux/dynamic_debug.h
+++ b/include/linux/dynamic_debug.h
@@ -32,7 +32,7 @@ struct _ddebug {
* writes commands to <debugfs>/dynamic_debug/control
*/
#define _DPRINTK_FLAGS_NONE 0
-#define _DPRINTK_FLAGS_PRINT (1<<0) /* printk() a message using the format */
+#define _DPRINTK_FLAGS_PRINTK (1 << 0) /* printk() a message using the format */
#define _DPRINTK_FLAGS_INCL_MODNAME (1<<1)
#define _DPRINTK_FLAGS_INCL_FUNCNAME (1<<2)
#define _DPRINTK_FLAGS_INCL_LINENO (1<<3)
@@ -42,8 +42,10 @@ struct _ddebug {
(_DPRINTK_FLAGS_INCL_MODNAME | _DPRINTK_FLAGS_INCL_FUNCNAME |\
_DPRINTK_FLAGS_INCL_LINENO | _DPRINTK_FLAGS_INCL_TID)

+#define _DPRINTK_FLAGS_ENABLED _DPRINTK_FLAGS_PRINTK
+
#if defined DEBUG
-#define _DPRINTK_FLAGS_DEFAULT _DPRINTK_FLAGS_PRINT
+#define _DPRINTK_FLAGS_DEFAULT _DPRINTK_FLAGS_PRINTK
#else
#define _DPRINTK_FLAGS_DEFAULT 0
#endif
@@ -161,10 +163,10 @@ void __dynamic_ibdev_dbg(struct _ddebug *descriptor,

#ifdef DEBUG
#define DYNAMIC_DEBUG_BRANCH(descriptor) \
- likely(descriptor.flags & _DPRINTK_FLAGS_PRINT)
+ likely(descriptor.flags & _DPRINTK_FLAGS_ENABLED)
#else
#define DYNAMIC_DEBUG_BRANCH(descriptor) \
- unlikely(descriptor.flags & _DPRINTK_FLAGS_PRINT)
+ unlikely(descriptor.flags & _DPRINTK_FLAGS_ENABLED)
#endif

#endif /* CONFIG_JUMP_LABEL */
diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
index f9c5bbf9d43b..5682ee477677 100644
--- a/lib/dynamic_debug.c
+++ b/lib/dynamic_debug.c
@@ -87,7 +87,7 @@ static inline const char *trim_prefix(const char *path)
}

static struct { unsigned flag:8; char opt_char; } opt_array[] = {
- { _DPRINTK_FLAGS_PRINT, 'p' },
+ { _DPRINTK_FLAGS_PRINTK, 'p' },
{ _DPRINTK_FLAGS_INCL_MODNAME, 'm' },
{ _DPRINTK_FLAGS_INCL_FUNCNAME, 'f' },
{ _DPRINTK_FLAGS_INCL_LINENO, 'l' },
@@ -238,10 +238,10 @@ static int ddebug_change(const struct ddebug_query *query,
if (newflags == dp->flags)
continue;
#ifdef CONFIG_JUMP_LABEL
- if (dp->flags & _DPRINTK_FLAGS_PRINT) {
- if (!(newflags & _DPRINTK_FLAGS_PRINT))
+ if (dp->flags & _DPRINTK_FLAGS_ENABLED) {
+ if (!(newflags & _DPRINTK_FLAGS_ENABLED))
static_branch_disable(&dp->key.dd_key_true);
- } else if (newflags & _DPRINTK_FLAGS_PRINT) {
+ } else if (newflags & _DPRINTK_FLAGS_ENABLED) {
static_branch_enable(&dp->key.dd_key_true);
}
#endif
--
2.35.3


2022-05-17 01:53:05

by Jim Cromie

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

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 <[email protected]>
---
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 <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.
@@ -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), &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);
}
@@ -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), &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..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 <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)
+ __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;
+ __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 */
+
+/* This part must be outside protection */
+#include <trace/define_trace.h>
diff --git a/include/trace/events/dyndbg.h b/include/trace/events/dyndbg.h
new file mode 100644
index 000000000000..e19fcb56566c
--- /dev/null
+++ b/include/trace/events/dyndbg.h
@@ -0,0 +1,74 @@
+/* SPDX-License-Identifier: GPL-2.0 */
+#undef TRACE_SYSTEM
+#define TRACE_SYSTEM dyndbg
+
+#if !defined(_TRACE_DYNDBG_H) || defined(TRACE_HEADER_MULTI_READ)
+#define _TRACE_DYNDBG_H
+
+#include <linux/tracepoint.h>
+
+/* capture pr_debug() callsite descriptor and message */
+TRACE_EVENT(prdbg,
+ TP_PROTO(const struct _ddebug *desc, const char *text, size_t len),
+
+ TP_ARGS(desc, text, len),
+
+ TP_STRUCT__entry(
+ __field(const struct _ddebug *, desc)
+ __dynamic_array(char, msg, len + 1)
+ ),
+
+ TP_fast_assign(
+ __entry->desc = desc;
+ /*
+ * Each trace entry is printed in a new line.
+ * If the msg finishes with '\n', cut it off
+ * to avoid blank lines in the trace.
+ */
+ if (len > 0 && (text[len - 1] == '\n'))
+ len -= 1;
+
+ memcpy(__get_str(msg), text, len);
+ __get_str(msg)[len] = 0;
+ ),
+
+ TP_printk("%s.%s %s", __entry->desc->modname,
+ __entry->desc->function, __get_str(msg))
+);
+
+/* capture dev_dbg() callsite descriptor, device, and message */
+TRACE_EVENT(devdbg,
+ TP_PROTO(const struct _ddebug *desc, const struct device *dev,
+ const char *text, size_t len),
+
+ TP_ARGS(desc, dev, text, len),
+
+ TP_STRUCT__entry(
+ __field(const struct _ddebug *, desc)
+ __field(const struct device *, dev)
+ __dynamic_array(char, msg, len + 1)
+ ),
+
+ TP_fast_assign(
+ __entry->desc = desc;
+ __entry->dev = (struct device *) dev;
+ /*
+ * Each trace entry is printed in a new line.
+ * If the msg finishes with '\n', cut it off
+ * to avoid blank lines in the trace.
+ */
+ if (len > 0 && (text[len - 1] == '\n'))
+ len -= 1;
+
+ memcpy(__get_str(msg), text, len);
+ __get_str(msg)[len] = 0;
+ ),
+
+ TP_printk("%s.%s %s", __entry->desc->modname,
+ __entry->desc->function, __get_str(msg))
+);
+
+#endif /* _TRACE_DYNDBG_H */
+
+/* This part must be outside protection */
+#include <trace/define_trace.h>
diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
index 81cfe6e21d15..a97ca94a266a 100644
--- a/lib/dynamic_debug.c
+++ b/lib/dynamic_debug.c
@@ -36,7 +36,9 @@
#include <linux/sched.h>
#include <linux/device.h>
#include <linux/netdevice.h>
-#include <trace/events/printk.h>
+
+#define CREATE_TRACE_POINTS
+#include <trace/events/dyndbg.h>

#include <rdma/ib_verbs.h>

@@ -790,7 +792,9 @@ struct ddebug_trace_bufs {
static DEFINE_PER_CPU(struct ddebug_trace_bufs, ddebug_trace_bufs);
static DEFINE_PER_CPU(int, ddebug_trace_reserve);

-static void ddebug_trace(const char *fmt, va_list args)
+__printf(3, 0)
+static void ddebug_trace(struct _ddebug *desc, const struct device *dev,
+ const char *fmt, va_list args)
{
struct ddebug_trace_buf *buf;
int bufidx;
@@ -809,7 +813,11 @@ static void ddebug_trace(const char *fmt, va_list args)
buf = this_cpu_ptr(ddebug_trace_bufs.bufs) + bufidx;

len = vscnprintf(buf->buf, sizeof(buf->buf), fmt, args);
- trace_console(buf->buf, len);
+
+ if (!dev)
+ trace_prdbg(desc, buf->buf, len);
+ else
+ trace_devdbg(desc, dev, buf->buf, len);

out:
/* As above. */
@@ -819,9 +827,9 @@ static void ddebug_trace(const char *fmt, va_list args)
}

__printf(2, 3)
-static void ddebug_printk(unsigned int flags, const char *fmt, ...)
+static void ddebug_printk(struct _ddebug *desc, const char *fmt, ...)
{
- if (flags & _DPRINTK_FLAGS_TRACE) {
+ if (desc->flags & _DPRINTK_FLAGS_TRACE) {
va_list args;

va_start(args, fmt);
@@ -829,11 +837,11 @@ static void ddebug_printk(unsigned int flags, const char *fmt, ...)
* All callers include the KERN_DEBUG prefix to keep the
* vprintk case simple; strip it out for tracing.
*/
- ddebug_trace(fmt + strlen(KERN_DEBUG), args);
+ ddebug_trace(desc, NULL, fmt + strlen(KERN_DEBUG), args);
va_end(args);
}

- if (flags & _DPRINTK_FLAGS_PRINTK) {
+ if (desc->flags & _DPRINTK_FLAGS_PRINTK) {
va_list args;

va_start(args, fmt);
@@ -843,19 +851,19 @@ static void ddebug_printk(unsigned int flags, const char *fmt, ...)
}

__printf(3, 4)
-static void ddebug_dev_printk(unsigned int flags, const struct device *dev,
+static void ddebug_dev_printk(struct _ddebug *desc, const struct device *dev,
const char *fmt, ...)
{

- if (flags & _DPRINTK_FLAGS_TRACE) {
+ if (desc->flags & _DPRINTK_FLAGS_TRACE) {
va_list args;

va_start(args, fmt);
- ddebug_trace(fmt, args);
+ ddebug_trace(desc, dev, fmt, args);
va_end(args);
}

- if (flags & _DPRINTK_FLAGS_PRINTK) {
+ if (desc->flags & _DPRINTK_FLAGS_PRINTK) {
va_list args;

va_start(args, fmt);
@@ -878,7 +886,7 @@ void __dynamic_pr_debug(struct _ddebug *descriptor, const char *fmt, ...)
vaf.fmt = fmt;
vaf.va = &args;

- ddebug_printk(descriptor->flags, KERN_DEBUG "%s%pV",
+ ddebug_printk(descriptor, KERN_DEBUG "%s%pV",
dynamic_emit_prefix(descriptor, buf), &vaf);

va_end(args);
@@ -889,7 +897,6 @@ void __dynamic_dev_dbg(struct _ddebug *descriptor,
const struct device *dev, const char *fmt, ...)
{
struct va_format vaf;
- unsigned int flags;
va_list args;

BUG_ON(!descriptor);
@@ -899,15 +906,14 @@ void __dynamic_dev_dbg(struct _ddebug *descriptor,

vaf.fmt = fmt;
vaf.va = &args;
- flags = descriptor->flags;

if (!dev) {
- ddebug_printk(flags, KERN_DEBUG "(NULL device *): %pV",
- &vaf);
+ ddebug_printk(descriptor, KERN_DEBUG "(NULL device *): %pV",
+ &vaf);
} else {
char buf[PREFIX_SIZE] = "";

- ddebug_dev_printk(flags, dev, "%s%s %s: %pV",
+ ddebug_dev_printk(descriptor, dev, "%s%s %s: %pV",
dynamic_emit_prefix(descriptor, buf),
dev_driver_string(dev), dev_name(dev),
&vaf);
@@ -923,7 +929,6 @@ void __dynamic_netdev_dbg(struct _ddebug *descriptor,
const struct net_device *dev, const char *fmt, ...)
{
struct va_format vaf;
- unsigned int flags;
va_list args;

BUG_ON(!descriptor);
@@ -933,24 +938,22 @@ void __dynamic_netdev_dbg(struct _ddebug *descriptor,

vaf.fmt = fmt;
vaf.va = &args;
- flags = descriptor->flags;

if (dev && dev->dev.parent) {
char buf[PREFIX_SIZE] = "";

- ddebug_dev_printk(flags, dev->dev.parent,
- "%s%s %s %s%s: %pV",
- dynamic_emit_prefix(descriptor, buf),
- dev_driver_string(dev->dev.parent),
- dev_name(dev->dev.parent),
- netdev_name(dev), netdev_reg_state(dev),
- &vaf);
+ ddebug_dev_printk(descriptor, dev->dev.parent,
+ "%s%s %s %s%s: %pV",
+ dynamic_emit_prefix(descriptor, buf),
+ dev_driver_string(dev->dev.parent),
+ dev_name(dev->dev.parent),
+ netdev_name(dev), netdev_reg_state(dev),
+ &vaf);
} else if (dev) {
- ddebug_printk(flags, KERN_DEBUG "%s%s: %pV",
- netdev_name(dev), netdev_reg_state(dev), &vaf);
+ ddebug_dev_printk(descriptor, &dev->dev, KERN_DEBUG "%s%s: %pV",
+ netdev_name(dev), netdev_reg_state(dev), &vaf);
} else {
- ddebug_printk(flags, KERN_DEBUG "(NULL net_device): %pV",
- &vaf);
+ ddebug_printk(descriptor, KERN_DEBUG "(NULL net_device): %pV", &vaf);
}

va_end(args);
@@ -966,18 +969,16 @@ void __dynamic_ibdev_dbg(struct _ddebug *descriptor,
{
struct va_format vaf;
va_list args;
- unsigned int flags;

va_start(args, fmt);

vaf.fmt = fmt;
vaf.va = &args;
- flags = descriptor->flags;

if (ibdev && ibdev->dev.parent) {
char buf[PREFIX_SIZE] = "";

- ddebug_dev_printk(flags, ibdev->dev.parent,
+ ddebug_dev_printk(descriptor, ibdev->dev.parent,
"%s%s %s %s: %pV",
dynamic_emit_prefix(descriptor, buf),
dev_driver_string(ibdev->dev.parent),
@@ -985,10 +986,10 @@ void __dynamic_ibdev_dbg(struct _ddebug *descriptor,
dev_name(&ibdev->dev),
&vaf);
} else if (ibdev) {
- ddebug_printk(flags, KERN_DEBUG "%s: %pV",
- dev_name(&ibdev->dev), &vaf);
+ ddebug_dev_printk(descriptor, &ibdev->dev, KERN_DEBUG "%s: %pV",
+ dev_name(&ibdev->dev), &vaf);
} else {
- ddebug_printk(flags, KERN_DEBUG "(NULL ip_device): %pV", &vaf);
+ ddebug_printk(descriptor, KERN_DEBUG "(NULL ip_device): %pV", &vaf);
}

va_end(args);
--
2.35.3


2022-05-17 01:58:21

by Jim Cromie

[permalink] [raw]
Subject: [PATCH v2 14/27] dyndbg: add test_dynamic_debug module

Demonstrate dyndbg's "class FOO" and bitmap-to-classes support. This
support is meant to plug into drm.debug system, and largely replace
the use of drm_debug_enabled(category) with JUMP_LABELs.

Recap:
#> echo class DRM_UT_CORE +p > /proc/dynamic_debug/control

This is made "safe" because dyndbg skips it for any modules which
don't know that class (havent called dynamic_debug_register_classes).

Other modules may use the same .class_id for a separate classified
debug scheme.

Use the API:

- DYNAMIC_DEBUG_CLASSES(_var, classes), to declare static _var by name
- dynamic_debug_register_classes(_var)
- dynamic_debug_unregister_classes(_var)

Use these 3 times; with base = 0,8,16 respectively, to demonstrate the
segmenting of the module's .class_id range [0..30]

For each of those 3 class-name-sets, add 2 sysfs-node-bitmaps, one
each for p-syslog, and T-tracefs, the latter will work once dyndbg
gets that patchset.

#> modprobe test_dynamic_debug dyndbg=+pfm
#> cat /sys/module/test_dynamic_debug/parameters/do_prints
#> echo class FOO +pf > /proc/dynamic_debug/control
#> echo class Foo +pfm > /proc/dynamic_debug/control
#> cat /sys/module/test_dynamic_debug/parameters/do_prints

RFC:

This use case exposes a weak point in the api; the 2nd query command
given in the dyndbg option will not work like the 1st:

#> modprobe test_dynamic_debug dyndbg='+pfm; class FOO +pfm'

This is because the option is processed early in module-load, well
before the registration can attach the class-map to the module's
ddebug_table entry.

Signed-off-by: Jim Cromie <[email protected]>
---
MAINTAINERS | 1 +
lib/Kconfig.debug | 11 +++
lib/Makefile | 1 +
lib/test_dynamic_debug.c | 172 +++++++++++++++++++++++++++++++++++++++
4 files changed, 185 insertions(+)
create mode 100644 lib/test_dynamic_debug.c

diff --git a/MAINTAINERS b/MAINTAINERS
index e8c52d0192a6..bf615853be47 100644
--- a/MAINTAINERS
+++ b/MAINTAINERS
@@ -6918,6 +6918,7 @@ M: Jason Baron <[email protected]>
S: Maintained
F: include/linux/dynamic_debug.h
F: lib/dynamic_debug.c
+F: lib/test_dynamic_debug.c

DYNAMIC INTERRUPT MODERATION
M: Tal Gilboa <[email protected]>
diff --git a/lib/Kconfig.debug b/lib/Kconfig.debug
index 075cd25363ac..c88d691d3df1 100644
--- a/lib/Kconfig.debug
+++ b/lib/Kconfig.debug
@@ -2601,6 +2601,17 @@ config TEST_STATIC_KEYS

If unsure, say N.

+config TEST_DYNAMIC_DEBUG
+ tristate "Test DYNAMIC_DEBUG"
+ depends on m
+ depends on DYNAMIC_DEBUG
+ help
+ This module registers a tracer callback to count enabled
+ pr_debugs in a 'do_debugging' function, then alters their
+ enablements, calls the function, and compares counts.
+
+ If unsure, say N.
+
config TEST_KMOD
tristate "kmod stress tester"
depends on m
diff --git a/lib/Makefile b/lib/Makefile
index 6b9ffc1bd1ee..e5727fbbfc7d 100644
--- a/lib/Makefile
+++ b/lib/Makefile
@@ -82,6 +82,7 @@ obj-$(CONFIG_TEST_SORT) += test_sort.o
obj-$(CONFIG_TEST_USER_COPY) += test_user_copy.o
obj-$(CONFIG_TEST_STATIC_KEYS) += test_static_keys.o
obj-$(CONFIG_TEST_STATIC_KEYS) += test_static_key_base.o
+obj-$(CONFIG_TEST_DYNAMIC_DEBUG) += test_dynamic_debug.o
obj-$(CONFIG_TEST_PRINTF) += test_printf.o
obj-$(CONFIG_TEST_SCANF) += test_scanf.o
obj-$(CONFIG_TEST_BITMAP) += test_bitmap.o
diff --git a/lib/test_dynamic_debug.c b/lib/test_dynamic_debug.c
new file mode 100644
index 000000000000..65c37ba6c0da
--- /dev/null
+++ b/lib/test_dynamic_debug.c
@@ -0,0 +1,172 @@
+// SPDX-License-Identifier: GPL-2.0-only
+/*
+ * Kernel module for testing dynamic_debug
+ *
+ * Authors:
+ * Jim Cromie <[email protected]>
+ */
+
+#define pr_fmt(fmt) "test_dd: " fmt
+
+#include <linux/module.h>
+
+static void do_prints(void); /* device under test */
+
+/* run tests by reading or writing sysfs node */
+
+int param_set_do_prints(const char *instr, const struct kernel_param *kp)
+{
+ do_prints();
+ return 0;
+}
+EXPORT_SYMBOL(param_set_do_prints);
+
+int param_get_do_prints(char *buffer, const struct kernel_param *kp)
+{
+ do_prints();
+ return scnprintf(buffer, PAGE_SIZE, "did do_prints\n");
+}
+EXPORT_SYMBOL(param_get_do_prints);
+
+const struct kernel_param_ops param_ops_do_prints = {
+ .set = param_set_do_prints,
+ .get = param_get_do_prints,
+};
+EXPORT_SYMBOL(param_ops_do_prints);
+
+module_param_cb(do_prints, &param_ops_do_prints, NULL, 0600);
+
+/*
+ * Declare 3 groups of classes, with different .class_id[] ranges,
+ * each with 2 sysfs-node bitmaps controlling p,T flags respectively
+ * for those named classes. This example is rather more involved than
+ * anyone will likely use.
+
+ * The T-bitmap sysfs-node functionality will need a few patches which
+ * add trace-events to dyndbg.
+
+ * Rules:
+ * - enum symbols must match/correlate with class-name strings
+ * - base must equal enum's 1st value
+ */
+
+enum cat1 { FOO, BAR, BUZZ };
+DYNAMIC_DEBUG_CLASSES(ddt_classes1, 0,
+ "FOO", "BAR", "BUZZ");
+
+unsigned long bits_1p, bits_1t;
+EXPORT_SYMBOL(bits_1p);
+EXPORT_SYMBOL(bits_1t);
+
+static struct ddebug_classes_bitmap_param p1_bitmap = {
+ .bits = &bits_1p,
+ .flags = "p",
+ .map = &ddt_classes1
+};
+module_param_cb(c1_syslog_bits, &param_ops_dyndbg_classes, &p1_bitmap, 0600);
+
+static struct ddebug_classes_bitmap_param t1_bitmap = {
+ .bits = &bits_1t,
+ .flags = "T",
+ .map = &ddt_classes1
+};
+module_param_cb(c1_trace_bits, &param_ops_dyndbg_classes, &t1_bitmap, 0600);
+
+
+enum cat2 { Foo = 8, Bar, Buzz };
+DYNAMIC_DEBUG_CLASSES(ddt_classes2, 8,
+ "Foo", "Bar", "Buzz");
+
+unsigned long bits_2p, bits_2t;
+EXPORT_SYMBOL(bits_2p);
+EXPORT_SYMBOL(bits_2t);
+
+static struct ddebug_classes_bitmap_param p2_bitmap = {
+ .bits = &bits_2p,
+ .flags = "p",
+ .map = &ddt_classes2
+};
+module_param_cb(c2_syslog_bits, &param_ops_dyndbg_classes, &p2_bitmap, 0600);
+
+static struct ddebug_classes_bitmap_param t2_bitmap = {
+ .bits = &bits_2t,
+ .flags = "T",
+ .map = &ddt_classes2
+};
+module_param_cb(c2_trace_bits, &param_ops_dyndbg_classes, &t2_bitmap, 0600);
+
+
+enum cat3 { bing = 16, bong, boom };
+DYNAMIC_DEBUG_CLASSES(ddt_classes3, 16,
+ "bing", "bong", "boom");
+
+unsigned long bits_3p, bits_3t;
+EXPORT_SYMBOL(bits_3p);
+EXPORT_SYMBOL(bits_3t);
+
+static struct ddebug_classes_bitmap_param p3_bitmap = {
+ .bits = &bits_3p,
+ .flags = "p",
+ .map = &ddt_classes3
+};
+module_param_cb(c3_syslog_bits, &param_ops_dyndbg_classes, &p3_bitmap, 0600);
+
+static struct ddebug_classes_bitmap_param t3_bitmap = {
+ .bits = &bits_3t,
+ .flags = "T",
+ .map = &ddt_classes3
+};
+module_param_cb(c3_trace_bits, &param_ops_dyndbg_classes, &t3_bitmap, 0600);
+
+static void do_prints(void)
+{
+ /* raw integer classes */
+ __pr_debug_cls(0, "class 0");
+ __pr_debug_cls(1, "class 1");
+ __pr_debug_cls(2, "class 2");
+
+ /* enum ints */
+ __pr_debug_cls(FOO, "class FOO");
+ __pr_debug_cls(BAR, "class BAR");
+ __pr_debug_cls(BUZZ, "class BUZZ");
+
+ __pr_debug_cls(Foo, "class Foo");
+ __pr_debug_cls(Bar, "class Bar");
+ __pr_debug_cls(Buzz, "class Buzz");
+
+ __pr_debug_cls(bing, "class bing");
+ __pr_debug_cls(bong, "class bong");
+ __pr_debug_cls(boom, "class boom");
+}
+
+static int __init test_dynamic_debug_init(void)
+{
+ pr_debug("module-init\n");
+ /*
+ * these are too late to enable class FOO at module load time:
+ * #> modprobe test_dynamic_debug dyndbg='class FOO +p'
+ */
+ dynamic_debug_register_classes(&ddt_classes1);
+ dynamic_debug_register_classes(&ddt_classes2);
+ dynamic_debug_register_classes(&ddt_classes3);
+
+ do_prints();
+
+ pr_debug("module-init done\n");
+ return 0;
+}
+
+static void __exit test_dynamic_debug_exit(void)
+{
+ dynamic_debug_unregister_classes(&ddt_classes1);
+ dynamic_debug_unregister_classes(&ddt_classes2);
+ dynamic_debug_unregister_classes(&ddt_classes3);
+
+ pr_debug("module-exit\n");
+}
+
+module_init(test_dynamic_debug_init);
+module_exit(test_dynamic_debug_exit);
+
+MODULE_AUTHOR("Jim Cromie <[email protected]>");
+MODULE_LICENSE("GPL");
--
2.35.3


2022-05-17 01:58:28

by Jim Cromie

[permalink] [raw]
Subject: [PATCH v2 03/27] dyndbg: fix module.dyndbg handling

For CONFIG_DYNAMIC_DEBUG=N, the ddebug_dyndbg_module_param_cb()
stub-fn is too permissive:

bash-5.1# modprobe drm JUNKdyndbg
bash-5.1# modprobe drm dyndbgJUNK
[ 42.933220] dyndbg param is supported only in CONFIG_DYNAMIC_DEBUG builds
[ 42.937484] ACPI: bus type drm_connector registered

This caused no ill effects, because unknown parameters are either
ignored by default (with an "unknown parameter" warning, see below),
or ignored because dyndbg allows its no-effect use on non-dyndbg builds.

That said, the code has an explicit feedback message, which should be
issued accurately. Fix with strcmp, for exact param-name match.

Here is fixed behavior:

bash-5.1# modprobe drm dyndbgJUNK
[ 20.127473] drm: unknown parameter 'dyndbgJUNK' ignored
[ 20.128835] ACPI: bus type drm_connector registered
bash-5.1# rmmod drm
[ 37.961656] ACPI: bus type drm_connector unregistered
bash-5.1# modprobe drm dyndbg
[ 42.933220] dyndbg param is supported only in CONFIG_DYNAMIC_DEBUG builds
[ 42.937484] ACPI: bus type drm_connector registered

Reported-by: Rasmus Villemoes <[email protected]>
Signed-off-by: Jim Cromie <[email protected]>
---
include/linux/dynamic_debug.h | 2 +-
1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/include/linux/dynamic_debug.h b/include/linux/dynamic_debug.h
index dce631e678dd..f30b01aa9fa4 100644
--- a/include/linux/dynamic_debug.h
+++ b/include/linux/dynamic_debug.h
@@ -201,7 +201,7 @@ static inline int ddebug_remove_module(const char *mod)
static inline int ddebug_dyndbg_module_param_cb(char *param, char *val,
const char *modname)
{
- if (strstr(param, "dyndbg")) {
+ if (!strcmp(param, "dyndbg")) {
/* avoid pr_warn(), which wants pr_fmt() fully defined */
printk(KERN_WARNING "dyndbg param is supported only in "
"CONFIG_DYNAMIC_DEBUG builds\n");
--
2.35.3


2022-05-17 02:40:37

by Jim Cromie

[permalink] [raw]
Subject: [PATCH v2 24/27] dyndbg: add _DPRINTK_FLAGS_TRACE

add new flag, and OR it into _DPRINTK_FLAGS_ENABLED definition

CC: [email protected]
Signed-off-by: Jim Cromie <[email protected]>
---
include/linux/dynamic_debug.h | 4 +++-
1 file changed, 3 insertions(+), 1 deletion(-)

diff --git a/include/linux/dynamic_debug.h b/include/linux/dynamic_debug.h
index 0a81a3582281..7581fe79980a 100644
--- a/include/linux/dynamic_debug.h
+++ b/include/linux/dynamic_debug.h
@@ -42,7 +42,9 @@ struct _ddebug {
(_DPRINTK_FLAGS_INCL_MODNAME | _DPRINTK_FLAGS_INCL_FUNCNAME |\
_DPRINTK_FLAGS_INCL_LINENO | _DPRINTK_FLAGS_INCL_TID)

-#define _DPRINTK_FLAGS_ENABLED _DPRINTK_FLAGS_PRINTK
+#define _DPRINTK_FLAGS_TRACE (1 << 5)
+#define _DPRINTK_FLAGS_ENABLED (_DPRINTK_FLAGS_PRINTK | \
+ _DPRINTK_FLAGS_TRACE)

#if defined DEBUG
#define _DPRINTK_FLAGS_DEFAULT _DPRINTK_FLAGS_PRINTK
--
2.35.3


2022-05-17 02:59:47

by Jim Cromie

[permalink] [raw]
Subject: [PATCH v2 02/27] dyndbg: show both old and new in change-info

print "old -> new" flag values in the info("change") message.

no functional change.

Signed-off-by: Jim Cromie <[email protected]>
---
lib/dynamic_debug.c | 11 ++++++-----
1 file changed, 6 insertions(+), 5 deletions(-)

diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
index a56c1286ffa4..ca2a28f1d51c 100644
--- a/lib/dynamic_debug.c
+++ b/lib/dynamic_debug.c
@@ -156,7 +156,7 @@ static int ddebug_change(const struct ddebug_query *query,
struct ddebug_table *dt;
unsigned int newflags;
unsigned int nfound = 0;
- struct flagsbuf fbuf;
+ struct flagsbuf fbuf, nbuf;

/* search for matching ddebugs */
mutex_lock(&ddebug_lock);
@@ -217,11 +217,12 @@ static int ddebug_change(const struct ddebug_query *query,
static_branch_enable(&dp->key.dd_key_true);
}
#endif
+ v4pr_info("changed %s:%d [%s]%s %s -> %s\n",
+ trim_prefix(dp->filename), dp->lineno,
+ dt->mod_name, dp->function,
+ ddebug_describe_flags(dp->flags, &fbuf),
+ ddebug_describe_flags(newflags, &nbuf));
dp->flags = newflags;
- v4pr_info("changed %s:%d [%s]%s =%s\n",
- trim_prefix(dp->filename), dp->lineno,
- dt->mod_name, dp->function,
- ddebug_describe_flags(dp->flags, &fbuf));
}
}
mutex_unlock(&ddebug_lock);
--
2.35.3


2022-05-17 03:06:11

by Jim Cromie

[permalink] [raw]
Subject: [PATCH v2 12/27] dyndbg: change zero-or-one classes-map to maps list

Upgrade single classes-map to list of them:

This allows multiple DYNAMIC_DEBUG_CLASSES(class-map)s per module,
using _base to segment the 0..30 classid space.

alter struct ddebug table:
replace .classes (a &map) with maps (list-head)

dynamic_debug_register_classes(map) - adds new map to maps list.

dynamic_debug_unregister_classes(map) - deletes map after ID-check.

ddebug_validate_classname() - check all maps in list before failing.

ddebug_class_name() - which supports ```cat control``` now walks maps
list, finds the map whose sub-range of .class_id's spans the one in
the callsite, and returns that class-name.

Signed-off-by: Jim Cromie <[email protected]>
---
. split out validate_classnames()
. fold in fixes for multi class-maps
---
lib/dynamic_debug.c | 76 +++++++++++++++++++++++++++++++--------------
1 file changed, 52 insertions(+), 24 deletions(-)

diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
index 8e1b9159e881..f9c5bbf9d43b 100644
--- a/lib/dynamic_debug.c
+++ b/lib/dynamic_debug.c
@@ -43,10 +43,8 @@ extern struct _ddebug __start___dyndbg[];
extern struct _ddebug __stop___dyndbg[];

struct ddebug_table {
- struct list_head link;
+ struct list_head link, maps;
const char *mod_name;
- /* a module can have multiple class-sets eventually, but not yet */
- struct ddebug_known_classes_map const *map;
unsigned int num_ddebugs;
struct _ddebug *ddebugs;
};
@@ -149,28 +147,18 @@ static void vpr_info_dq(const struct ddebug_query *query, const char *msg)
/* return <0 if class-name is unknown/invalid, 0..CLASS_DFLT otherwise */
static int ddebug_validate_classname(struct ddebug_table *dt, const char *class_string)
{
- int query_class = -ENOENT;
+ struct ddebug_known_classes_map *map;
int idx;

if (!class_string)
- /* all queries w/o class given work only on default class */
return _DPRINTK_CLASS_DFLT;

- /*
- * XXX single list will need to be a for-list
- * so that modules can have 2 sets of class-decls
- */
- if (!dt->map)
- return -ENOENT;
-
- idx = match_string(dt->map->classes, dt->map->length, class_string);
- if (idx < 0) {
- v3pr_info("class: %s.%s unknown\n", dt->mod_name, class_string);
- return -ENOENT;
+ list_for_each_entry(map, &dt->maps, link) {
+ idx = match_string(map->classes, map->length, class_string);
+ if (idx >= 0)
+ return idx + map->base;
}
- query_class = idx + dt->map->base;
-
- return query_class;
+ return -ENOENT;
}

/*
@@ -1032,8 +1020,14 @@ static void *ddebug_proc_next(struct seq_file *m, void *p, loff_t *pos)

static const char *ddebug_class_name(struct ddebug_iter *iter, struct _ddebug *dp)
{
- if (iter->table->map)
- return iter->table->map->classes[dp->class_id];
+ struct ddebug_known_classes_map *map;
+
+ list_for_each_entry(map, &iter->table->maps, link) {
+ if (dp->class_id < map->base ||
+ dp->class_id >= map->base + map->length)
+ continue;
+ return map->classes[dp->class_id - map->base];
+ }
return NULL;
}

@@ -1124,6 +1118,7 @@ int dynamic_debug_register_classes(struct ddebug_known_classes_map *map)
struct ddebug_table *dt;
int rc = -ENOENT;

+ INIT_LIST_HEAD(&map->link);
mutex_lock(&ddebug_lock);
#ifdef CONFIG_MODULES
if (map->mod) {
@@ -1131,7 +1126,7 @@ int dynamic_debug_register_classes(struct ddebug_known_classes_map *map)
list_for_each_entry(dt, &ddebug_tables, link) {
if (dt->mod_name == map->mod->name) {
rc = 0;
- dt->map = map;
+ list_add(&map->link, &dt->maps);
break;
}
}
@@ -1142,7 +1137,7 @@ int dynamic_debug_register_classes(struct ddebug_known_classes_map *map)
list_for_each_entry(dt, &ddebug_tables, link) {
if (!strcmp(dt->mod_name, map->mod_name)) {
rc = 0;
- dt->map = map;
+ list_add(&map->link, &dt->maps);
break;
}
}
@@ -1159,8 +1154,38 @@ EXPORT_SYMBOL(dynamic_debug_register_classes);

void dynamic_debug_unregister_classes(struct ddebug_known_classes_map *map)
{
- vpr_info("unregister_classes: %s\n", map->mod_name);
+ int rc = -ENOENT;
+
+ mutex_lock(&ddebug_lock);
+#ifdef CONFIG_MODULES
+ if (map->mod) {
+ struct ddebug_known_classes_map *dmap;
+ struct ddebug_table *dt;
+
+ list_for_each_entry(dt, &ddebug_tables, link) {
+ if (dt->mod_name != map->mod->name)
+ continue;
+ list_for_each_entry(dmap, &dt->maps, link) {
+ if (dmap != map)
+ continue;
+ rc = 0;
+ list_del(&map->link);
+ break;
+ }
+ }
+ }
+#endif
+ if (!map->mod) {
+ pr_err("shouldn't be unloading a builtin module: %s\n",
+ map->mod_name);
+ }
+ mutex_unlock(&ddebug_lock);
+ if (rc)
+ pr_warn("unregister_classes: module %s not found\n", map->mod_name);
+ else
+ vpr_info("unregister_classes: %s\n", map->mod_name);
}
+EXPORT_SYMBOL(dynamic_debug_unregister_classes);

/*
* Allocate a new ddebug_table for the given module
@@ -1186,6 +1211,9 @@ int ddebug_add_module(struct _ddebug *tab, unsigned int n,
dt->num_ddebugs = n;
dt->ddebugs = tab;

+ INIT_LIST_HEAD(&dt->link);
+ INIT_LIST_HEAD(&dt->maps);
+
mutex_lock(&ddebug_lock);
list_add(&dt->link, &ddebug_tables);
mutex_unlock(&ddebug_lock);
--
2.35.3


2022-05-17 03:15:58

by Jim Cromie

[permalink] [raw]
Subject: [PATCH v2 16/27] drm/print: POC drm on dyndbg - use bitmap

POC: adapt drm_print to use/test the bitmap callback support.

with dynamic_debug.verbose=1:

bash-5.1# echo 1 > /sys/module/drm/parameters/debug
[ 33.697039] dyndbg: set_dyndbg_classes: new 0x1 current 0x0
[ 33.697571] dyndbg: query 0: "class DRM_UT_CORE +p" mod:*
[ 33.698072] dyndbg: no matches for query
[ 33.698498] dyndbg: total matches: 0
bash-5.1# echo 2 > /sys/module/drm/parameters/debug
[ 46.687012] dyndbg: set_dyndbg_classes: new 0x2 current 0x1
[ 46.687655] dyndbg: query 0: "class DRM_UT_CORE -p" mod:*
[ 46.688280] dyndbg: no matches for query
[ 46.688632] dyndbg: query 0: "class DRM_UT_DRIVER +p" mod:*
[ 46.689122] dyndbg: no matches for query
[ 46.689441] dyndbg: total matches: 0

This changes typeof __drm_debug to unsigned long from unsigned int,
which dyndbg requires so it can use BIT().

It is currently dependent on CONFIG_DYNAMIC_DEBUG_CORE, which is only
aproximately correct, it will need proper DRM dependence too.

Signed-off-by: Jim Cromie <[email protected]>
---
drivers/gpu/drm/drm_print.c | 14 ++++++++++++--
include/drm/drm_print.h | 3 ++-
2 files changed, 14 insertions(+), 3 deletions(-)

diff --git a/drivers/gpu/drm/drm_print.c b/drivers/gpu/drm/drm_print.c
index f783d4963d4b..e49ffda0a47e 100644
--- a/drivers/gpu/drm/drm_print.c
+++ b/drivers/gpu/drm/drm_print.c
@@ -40,7 +40,7 @@
* __drm_debug: Enable debug output.
* Bitmask of DRM_UT_x. See include/drm/drm_print.h for details.
*/
-unsigned int __drm_debug;
+unsigned long __drm_debug;
EXPORT_SYMBOL(__drm_debug);

MODULE_PARM_DESC(debug, "Enable debug output, where each bit enables a debug category.\n"
@@ -52,7 +52,17 @@ MODULE_PARM_DESC(debug, "Enable debug output, where each bit enables a debug cat
"\t\tBit 5 (0x20) will enable VBL messages (vblank code)\n"
"\t\tBit 7 (0x80) will enable LEASE messages (leasing code)\n"
"\t\tBit 8 (0x100) will enable DP messages (displayport code)");
-module_param_named(debug, __drm_debug, int, 0600);
+
+#if !defined(CONFIG_DYNAMIC_DEBUG_CORE)
+module_param_named(debug, __drm_debug, ulong, 0600);
+#else
+static struct ddebug_classes_bitmap_param drm_debug_bitmap = {
+ .bits = &__drm_debug,
+ .flags = "p",
+ .map = &drm_debug_classes,
+};
+module_param_cb(debug, &param_ops_dyndbg_classes, &drm_debug_bitmap, 0600);
+#endif

void __drm_puts_coredump(struct drm_printer *p, const char *str)
{
diff --git a/include/drm/drm_print.h b/include/drm/drm_print.h
index 5b7eedb0f477..0597137bac75 100644
--- a/include/drm/drm_print.h
+++ b/include/drm/drm_print.h
@@ -31,11 +31,12 @@
#include <linux/seq_file.h>
#include <linux/device.h>
#include <linux/debugfs.h>
+#include <linux/dynamic_debug.h>

#include <drm/drm.h>

/* Do *not* use outside of drm_print.[ch]! */
-extern unsigned int __drm_debug;
+extern unsigned long __drm_debug;

/**
* DOC: print
--
2.35.3


2022-05-17 03:23:31

by Jim Cromie

[permalink] [raw]
Subject: [PATCH v2 25/27] dyndbg: add write-events-to-tracefs code

adds: ddebug_trace()
uses trace_console() temporarily to issue printk:console event
uses internal-ish __ftrace_trace_stack code:
4-context buffer stack, barriers per Steve Rostedt

call it from new funcs:
ddebug_printk() - print to both syslog/tracefs
ddebug_dev_printk() - dev-print to both syslog/tracefs

These handle both _DPRINTK_FLAGS_PRINTK and _DPRINTK_FLAGS_TRACE
cases, allowing to vsnprintf the message once and use it for both,
skipping past the KERN_DEBUG character for tracing.

Finally, adjust the callers: __ddebug_{pr_debug,{,net,ib}dev_dbg},
replacing printk and dev_printk with the new funcs above.

The _DPRINTK_FLAGS_TRACE flag character is 'T', so the following finds
all callsites enabled for tracing:

grep -P =p?T /proc/dynamic_debug/control

This patch,~1,~2 are basically copies of:
https://lore.kernel.org/lkml/[email protected]/

with a few differences:

- s/dynamic_/ddebug_/ on Vincent's additions
- __printf attrs on the _printk funcs
- reuses trace_console() event, not adding a new "printk:dyndbg" event.
next patch replaces this with 2 new events

CC: [email protected]
Signed-off-by: Jim Cromie <[email protected]>
---
.../admin-guide/dynamic-debug-howto.rst | 1 +
drivers/gpu/drm/drm_print.c | 4 +-
lib/dynamic_debug.c | 156 +++++++++++++++---
3 files changed, 133 insertions(+), 28 deletions(-)

diff --git a/Documentation/admin-guide/dynamic-debug-howto.rst b/Documentation/admin-guide/dynamic-debug-howto.rst
index 01ca6f635dcc..b8c6772b88ac 100644
--- a/Documentation/admin-guide/dynamic-debug-howto.rst
+++ b/Documentation/admin-guide/dynamic-debug-howto.rst
@@ -239,6 +239,7 @@ of the characters::
The flags are::

p enables the pr_debug() callsite.
+ T enables callsite to issue a dyndbg:* trace-event
f Include the function name in the printed message
l Include line number in the printed message
m Include module name in the printed message
diff --git a/drivers/gpu/drm/drm_print.c b/drivers/gpu/drm/drm_print.c
index 77b56399147a..63125a507577 100644
--- a/drivers/gpu/drm/drm_print.c
+++ b/drivers/gpu/drm/drm_print.c
@@ -280,11 +280,11 @@ void __drm_dev_dbg(struct _ddebug *desc, const struct device *dev,
vaf.va = &args;

if (dev) {
- if (desc->flags && _DPRINTK_FLAGS_PRINTK)
+ if (desc->flags & _DPRINTK_FLAGS_PRINTK)
dev_printk(KERN_DEBUG, dev, "[" DRM_NAME ":%ps] %pV",
__builtin_return_address(0), &vaf);
} else {
- if (desc->flags && _DPRINTK_FLAGS_PRINTK)
+ if (desc->flags & _DPRINTK_FLAGS_PRINTK)
printk(KERN_DEBUG "[" DRM_NAME ":%ps] %pV",
__builtin_return_address(0), &vaf);
}
diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
index 5682ee477677..81cfe6e21d15 100644
--- a/lib/dynamic_debug.c
+++ b/lib/dynamic_debug.c
@@ -36,6 +36,7 @@
#include <linux/sched.h>
#include <linux/device.h>
#include <linux/netdevice.h>
+#include <trace/events/printk.h>

#include <rdma/ib_verbs.h>

@@ -88,6 +89,7 @@ static inline const char *trim_prefix(const char *path)

static struct { unsigned flag:8; char opt_char; } opt_array[] = {
{ _DPRINTK_FLAGS_PRINTK, 'p' },
+ { _DPRINTK_FLAGS_TRACE, 'T' },
{ _DPRINTK_FLAGS_INCL_MODNAME, 'm' },
{ _DPRINTK_FLAGS_INCL_FUNCNAME, 'f' },
{ _DPRINTK_FLAGS_INCL_LINENO, 'l' },
@@ -770,6 +772,98 @@ static inline char *dynamic_emit_prefix(struct _ddebug *desc, char *buf)
return buf;
}

+/*
+ * This code is heavily based on __ftrace_trace_stack().
+ *
+ * Allow 4 levels of nesting: normal, softirq, irq, NMI.
+ */
+#define DYNAMIC_TRACE_NESTING 4
+
+struct ddebug_trace_buf {
+ char buf[256];
+};
+
+struct ddebug_trace_bufs {
+ struct ddebug_trace_buf bufs[DYNAMIC_TRACE_NESTING];
+};
+
+static DEFINE_PER_CPU(struct ddebug_trace_bufs, ddebug_trace_bufs);
+static DEFINE_PER_CPU(int, ddebug_trace_reserve);
+
+static void ddebug_trace(const char *fmt, va_list args)
+{
+ struct ddebug_trace_buf *buf;
+ int bufidx;
+ int len;
+
+ preempt_disable_notrace();
+
+ bufidx = __this_cpu_inc_return(ddebug_trace_reserve) - 1;
+
+ if (WARN_ON_ONCE(bufidx > DYNAMIC_TRACE_NESTING))
+ goto out;
+
+ /* For the same reasons as in __ftrace_trace_stack(). */
+ barrier();
+
+ buf = this_cpu_ptr(ddebug_trace_bufs.bufs) + bufidx;
+
+ len = vscnprintf(buf->buf, sizeof(buf->buf), fmt, args);
+ trace_console(buf->buf, len);
+
+out:
+ /* As above. */
+ barrier();
+ __this_cpu_dec(ddebug_trace_reserve);
+ preempt_enable_notrace();
+}
+
+__printf(2, 3)
+static void ddebug_printk(unsigned int flags, const char *fmt, ...)
+{
+ if (flags & _DPRINTK_FLAGS_TRACE) {
+ va_list args;
+
+ va_start(args, fmt);
+ /*
+ * All callers include the KERN_DEBUG prefix to keep the
+ * vprintk case simple; strip it out for tracing.
+ */
+ ddebug_trace(fmt + strlen(KERN_DEBUG), args);
+ va_end(args);
+ }
+
+ if (flags & _DPRINTK_FLAGS_PRINTK) {
+ va_list args;
+
+ va_start(args, fmt);
+ vprintk(fmt, args);
+ va_end(args);
+ }
+}
+
+__printf(3, 4)
+static void ddebug_dev_printk(unsigned int flags, const struct device *dev,
+ const char *fmt, ...)
+{
+
+ if (flags & _DPRINTK_FLAGS_TRACE) {
+ va_list args;
+
+ va_start(args, fmt);
+ ddebug_trace(fmt, args);
+ va_end(args);
+ }
+
+ if (flags & _DPRINTK_FLAGS_PRINTK) {
+ va_list args;
+
+ va_start(args, fmt);
+ dev_vprintk_emit(LOGLEVEL_DEBUG, dev, fmt, args);
+ va_end(args);
+ }
+}
+
void __dynamic_pr_debug(struct _ddebug *descriptor, const char *fmt, ...)
{
va_list args;
@@ -784,16 +878,18 @@ void __dynamic_pr_debug(struct _ddebug *descriptor, const char *fmt, ...)
vaf.fmt = fmt;
vaf.va = &args;

- printk(KERN_DEBUG "%s%pV", dynamic_emit_prefix(descriptor, buf), &vaf);
+ ddebug_printk(descriptor->flags, KERN_DEBUG "%s%pV",
+ dynamic_emit_prefix(descriptor, buf), &vaf);

va_end(args);
}
EXPORT_SYMBOL(__dynamic_pr_debug);

void __dynamic_dev_dbg(struct _ddebug *descriptor,
- const struct device *dev, const char *fmt, ...)
+ const struct device *dev, const char *fmt, ...)
{
struct va_format vaf;
+ unsigned int flags;
va_list args;

BUG_ON(!descriptor);
@@ -803,16 +899,18 @@ void __dynamic_dev_dbg(struct _ddebug *descriptor,

vaf.fmt = fmt;
vaf.va = &args;
+ flags = descriptor->flags;

if (!dev) {
- printk(KERN_DEBUG "(NULL device *): %pV", &vaf);
+ ddebug_printk(flags, KERN_DEBUG "(NULL device *): %pV",
+ &vaf);
} else {
char buf[PREFIX_SIZE] = "";

- dev_printk_emit(LOGLEVEL_DEBUG, dev, "%s%s %s: %pV",
- dynamic_emit_prefix(descriptor, buf),
- dev_driver_string(dev), dev_name(dev),
- &vaf);
+ ddebug_dev_printk(flags, dev, "%s%s %s: %pV",
+ dynamic_emit_prefix(descriptor, buf),
+ dev_driver_string(dev), dev_name(dev),
+ &vaf);
}

va_end(args);
@@ -825,6 +923,7 @@ void __dynamic_netdev_dbg(struct _ddebug *descriptor,
const struct net_device *dev, const char *fmt, ...)
{
struct va_format vaf;
+ unsigned int flags;
va_list args;

BUG_ON(!descriptor);
@@ -834,22 +933,24 @@ void __dynamic_netdev_dbg(struct _ddebug *descriptor,

vaf.fmt = fmt;
vaf.va = &args;
+ flags = descriptor->flags;

if (dev && dev->dev.parent) {
char buf[PREFIX_SIZE] = "";

- dev_printk_emit(LOGLEVEL_DEBUG, dev->dev.parent,
- "%s%s %s %s%s: %pV",
- dynamic_emit_prefix(descriptor, buf),
- dev_driver_string(dev->dev.parent),
- dev_name(dev->dev.parent),
- netdev_name(dev), netdev_reg_state(dev),
- &vaf);
+ ddebug_dev_printk(flags, dev->dev.parent,
+ "%s%s %s %s%s: %pV",
+ dynamic_emit_prefix(descriptor, buf),
+ dev_driver_string(dev->dev.parent),
+ dev_name(dev->dev.parent),
+ netdev_name(dev), netdev_reg_state(dev),
+ &vaf);
} else if (dev) {
- printk(KERN_DEBUG "%s%s: %pV", netdev_name(dev),
- netdev_reg_state(dev), &vaf);
+ ddebug_printk(flags, KERN_DEBUG "%s%s: %pV",
+ netdev_name(dev), netdev_reg_state(dev), &vaf);
} else {
- printk(KERN_DEBUG "(NULL net_device): %pV", &vaf);
+ ddebug_printk(flags, KERN_DEBUG "(NULL net_device): %pV",
+ &vaf);
}

va_end(args);
@@ -865,26 +966,29 @@ void __dynamic_ibdev_dbg(struct _ddebug *descriptor,
{
struct va_format vaf;
va_list args;
+ unsigned int flags;

va_start(args, fmt);

vaf.fmt = fmt;
vaf.va = &args;
+ flags = descriptor->flags;

if (ibdev && ibdev->dev.parent) {
char buf[PREFIX_SIZE] = "";

- dev_printk_emit(LOGLEVEL_DEBUG, ibdev->dev.parent,
- "%s%s %s %s: %pV",
- dynamic_emit_prefix(descriptor, buf),
- dev_driver_string(ibdev->dev.parent),
- dev_name(ibdev->dev.parent),
- dev_name(&ibdev->dev),
- &vaf);
+ ddebug_dev_printk(flags, ibdev->dev.parent,
+ "%s%s %s %s: %pV",
+ dynamic_emit_prefix(descriptor, buf),
+ dev_driver_string(ibdev->dev.parent),
+ dev_name(ibdev->dev.parent),
+ dev_name(&ibdev->dev),
+ &vaf);
} else if (ibdev) {
- printk(KERN_DEBUG "%s: %pV", dev_name(&ibdev->dev), &vaf);
+ ddebug_printk(flags, KERN_DEBUG "%s: %pV",
+ dev_name(&ibdev->dev), &vaf);
} else {
- printk(KERN_DEBUG "(NULL ib_device): %pV", &vaf);
+ ddebug_printk(flags, KERN_DEBUG "(NULL ip_device): %pV", &vaf);
}

va_end(args);
--
2.35.3


2022-05-17 03:31:01

by Jim Cromie

[permalink] [raw]
Subject: [PATCH v2 10/27] dyndbg: let query-modname override defaulting modname

dyndbg's control-parser: ddebug_parse_query(), requires that search
terms: module, func, file, lineno, are not used 2x in a query; a thing
cannot be named both foo and bar (not even wildcards, no OR is
contemplated).

Amend the treatment of module; while still enforcing the 2x rule on
it, set the default module at end, if none was given in the query
itself, so the preset doesn't spoil the check.

Background:

ddebug_parse_query() got a modname arg to support boot-args with
compound queries, all with "module aMod" added by default.

aMod.dyndbg="func foo +p; func bar +p"

With default module at end, this becomes possible; "module *" in the
query overrides the default "module aMod".

aMod.dyndbg="module * class FOO +p"

This means aMod can modify (by explicit means) any FOO class'd
pr_debugs in other modules. It is intended for use by DRM, which
generally would want sub-system wide coordination.

Signed-off-by: Jim Cromie <[email protected]>
---
lib/dynamic_debug.c | 11 +++++++----
1 file changed, 7 insertions(+), 4 deletions(-)

diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
index b67bf9efec07..42dce2e76014 100644
--- a/lib/dynamic_debug.c
+++ b/lib/dynamic_debug.c
@@ -425,10 +425,6 @@ static int ddebug_parse_query(char *words[], int nwords,
return -EINVAL;
}

- if (modname)
- /* support $modname.dyndbg=<multiple queries> */
- query->module = modname;
-
for (i = 0; i < nwords; i += 2) {
char *keyword = words[i];
char *arg = words[i+1];
@@ -471,6 +467,13 @@ static int ddebug_parse_query(char *words[], int nwords,
if (rc)
return rc;
}
+ if (!query->module && modname)
+ /*
+ * support $modname.dyndbg=<multiple queries>,
+ * allowing query.module to override $modname
+ */
+ query->module = modname;
+
vpr_info_dq(query, "parsed");
return 0;
}
--
2.35.3


2022-05-17 03:33:55

by Jim Cromie

[permalink] [raw]
Subject: [PATCH v2 18/27] drm_print: interpose drm_*dbg with forwarding macros

change drm_dev_dbg & drm_dbg to macros, which forward to the renamed
functions (with __ prefix added).

Those functions sit below the categorized layer of macros implementing
the DRM debug.category API, and implement most of it. These are good
places to insert dynamic-debug jump-label mechanics, which will allow
DRM to avoid the runtime cost of drm_debug_enabled().

no functional changes.

memory cost baseline: (unchanged)
bash-5.1# drms_load
[ 9.220389] dyndbg: 1 debug prints in module drm
[ 9.224426] ACPI: bus type drm_connector registered
[ 9.302192] dyndbg: 2 debug prints in module ttm
[ 9.305033] dyndbg: 8 debug prints in module video
[ 9.627563] dyndbg: 127 debug prints in module i915
[ 9.721505] AMD-Vi: AMD IOMMUv2 functionality not available on this system - This is not a bug.
[ 10.091345] dyndbg: 2196 debug prints in module amdgpu
[ 10.106589] [drm] amdgpu kernel modesetting enabled.
[ 10.107270] amdgpu: CRAT table not found
[ 10.107926] amdgpu: Virtual CRAT table created for CPU
[ 10.108398] amdgpu: Topology: Add CPU node
[ 10.168507] dyndbg: 3 debug prints in module wmi
[ 10.329587] dyndbg: 3 debug prints in module nouveau

Signed-off-by: Jim Cromie <[email protected]>
---
drivers/gpu/drm/drm_print.c | 10 +++++-----
include/drm/drm_print.h | 9 +++++++--
2 files changed, 12 insertions(+), 7 deletions(-)

diff --git a/drivers/gpu/drm/drm_print.c b/drivers/gpu/drm/drm_print.c
index e49ffda0a47e..e77b49c7725b 100644
--- a/drivers/gpu/drm/drm_print.c
+++ b/drivers/gpu/drm/drm_print.c
@@ -266,8 +266,8 @@ void drm_dev_printk(const struct device *dev, const char *level,
}
EXPORT_SYMBOL(drm_dev_printk);

-void drm_dev_dbg(const struct device *dev, enum drm_debug_category category,
- const char *format, ...)
+void __drm_dev_dbg(const struct device *dev, enum drm_debug_category category,
+ const char *format, ...)
{
struct va_format vaf;
va_list args;
@@ -288,9 +288,9 @@ void drm_dev_dbg(const struct device *dev, enum drm_debug_category category,

va_end(args);
}
-EXPORT_SYMBOL(drm_dev_dbg);
+EXPORT_SYMBOL(__drm_dev_dbg);

-void __drm_dbg(enum drm_debug_category category, const char *format, ...)
+void ___drm_dbg(enum drm_debug_category category, const char *format, ...)
{
struct va_format vaf;
va_list args;
@@ -307,7 +307,7 @@ void __drm_dbg(enum drm_debug_category category, const char *format, ...)

va_end(args);
}
-EXPORT_SYMBOL(__drm_dbg);
+EXPORT_SYMBOL(___drm_dbg);

void __drm_err(const char *format, ...)
{
diff --git a/include/drm/drm_print.h b/include/drm/drm_print.h
index a157485bf573..383feb0d34fe 100644
--- a/include/drm/drm_print.h
+++ b/include/drm/drm_print.h
@@ -339,7 +339,7 @@ __printf(3, 4)
void drm_dev_printk(const struct device *dev, const char *level,
const char *format, ...);
__printf(3, 4)
-void drm_dev_dbg(const struct device *dev, enum drm_debug_category category,
+void __drm_dev_dbg(const struct device *dev, enum drm_debug_category category,
const char *format, ...);

/**
@@ -388,6 +388,9 @@ void drm_dev_dbg(const struct device *dev, enum drm_debug_category category,
} \
})

+#define drm_dev_dbg(dev, cat, fmt, ...) \
+ __drm_dev_dbg(dev, cat, fmt, ##__VA_ARGS__)
+
/**
* DRM_DEV_DEBUG() - Debug output for generic drm code
*
@@ -489,10 +492,12 @@ void drm_dev_dbg(const struct device *dev, enum drm_debug_category category,
*/

__printf(2, 3)
-void __drm_dbg(enum drm_debug_category category, const char *format, ...);
+void ___drm_dbg(enum drm_debug_category category, const char *format, ...);
__printf(1, 2)
void __drm_err(const char *format, ...);

+#define __drm_dbg(fmt, ...) ___drm_dbg(fmt, ##__VA_ARGS__)
+
/* Macros to make printk easier */

#define _DRM_PRINTK(once, level, fmt, ...) \
--
2.35.3


2022-05-17 03:34:28

by Jim Cromie

[permalink] [raw]
Subject: [PATCH v2 01/27] dyndbg: fix static_branch manipulation

In https://lore.kernel.org/lkml/[email protected]/

Vincent's patch commented on, and worked around, a bug toggling
static_branch's, when a 2nd PRINTK-ish flag was added. The bug
results in a premature static_branch_disable when the 1st of 2 flags
was disabled.

The cited commit computed newflags, but then in the JUMP_LABEL block,
failed to use that result, instead using just one of the terms in it.
Using newflags instead made the code work properly.

This is Vincents test-case, reduced. It needs the 2nd flag to
demonstrate the bug, but it's explanatory here.

pt_test() {
echo 5 > /sys/module/dynamic_debug/verbose

site="module tcp" # just one callsite
echo " $site =_ " > /proc/dynamic_debug/control # clear it

# A B ~A ~B
for flg in +T +p "-T #broke here" -p; do
echo " $site $flg " > /proc/dynamic_debug/control
done;

# A B ~B ~A
for flg in +T +p "-p #broke here" -T; do
echo " $site $flg " > /proc/dynamic_debug/control
done
}
pt_test

Fixes: 84da83a6ffc0 dyndbg: combine flags & mask into a struct, simplify with it
CC: [email protected]
Signed-off-by: Jim Cromie <[email protected]>
Acked-by: Jason Baron <[email protected]>
---
.drop @stable, no exposed bug.
.add jbaron ack
---
lib/dynamic_debug.c | 5 +++--
1 file changed, 3 insertions(+), 2 deletions(-)

diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
index dd7f56af9aed..a56c1286ffa4 100644
--- a/lib/dynamic_debug.c
+++ b/lib/dynamic_debug.c
@@ -211,10 +211,11 @@ static int ddebug_change(const struct ddebug_query *query,
continue;
#ifdef CONFIG_JUMP_LABEL
if (dp->flags & _DPRINTK_FLAGS_PRINT) {
- if (!(modifiers->flags & _DPRINTK_FLAGS_PRINT))
+ if (!(newflags & _DPRINTK_FLAGS_PRINT))
static_branch_disable(&dp->key.dd_key_true);
- } else if (modifiers->flags & _DPRINTK_FLAGS_PRINT)
+ } else if (newflags & _DPRINTK_FLAGS_PRINT) {
static_branch_enable(&dp->key.dd_key_true);
+ }
#endif
dp->flags = newflags;
v4pr_info("changed %s:%d [%s]%s =%s\n",
--
2.35.3


2022-05-17 05:35:15

by Jim Cromie

[permalink] [raw]
Subject: [PATCH v2 17/27] drm_print: condense enum drm_debug_category

enum drm_debug_category has 10 categories, but is initialized with
bitmasks which require 10 bits of underlying storage. By using
natural enumeration, and moving the BIT(cat) into drm_debug_enabled(),
the enum fits in 4 bits, allowing the category to be represented
directly in pr_debug callsites, via the ddebug.class_id field.

While this slightly pessimizes the bit-test in drm_debug_enabled(),
using dyndbg with JUMP_LABEL will avoid the function entirely.

NOTE: this change forecloses the possibility of doing:

drm_dbg(DRM_UT_CORE|DRM_UT_KMS, "weird 2-cat experiment")

but thats already strongly implied by the use of the enum itself; its
not a normal enum if it can be 2 values simultaneously.

Signed-off-by: Jim Cromie <[email protected]>
---
include/drm/drm_print.h | 22 +++++++++++-----------
1 file changed, 11 insertions(+), 11 deletions(-)

diff --git a/include/drm/drm_print.h b/include/drm/drm_print.h
index 0597137bac75..a157485bf573 100644
--- a/include/drm/drm_print.h
+++ b/include/drm/drm_print.h
@@ -284,49 +284,49 @@ enum drm_debug_category {
* @DRM_UT_CORE: Used in the generic drm code: drm_ioctl.c, drm_mm.c,
* drm_memory.c, ...
*/
- DRM_UT_CORE = 0x01,
+ DRM_UT_CORE,
/**
* @DRM_UT_DRIVER: Used in the vendor specific part of the driver: i915,
* radeon, ... macro.
*/
- DRM_UT_DRIVER = 0x02,
+ DRM_UT_DRIVER,
/**
* @DRM_UT_KMS: Used in the modesetting code.
*/
- DRM_UT_KMS = 0x04,
+ DRM_UT_KMS,
/**
* @DRM_UT_PRIME: Used in the prime code.
*/
- DRM_UT_PRIME = 0x08,
+ DRM_UT_PRIME,
/**
* @DRM_UT_ATOMIC: Used in the atomic code.
*/
- DRM_UT_ATOMIC = 0x10,
+ DRM_UT_ATOMIC,
/**
* @DRM_UT_VBL: Used for verbose debug message in the vblank code.
*/
- DRM_UT_VBL = 0x20,
+ DRM_UT_VBL,
/**
* @DRM_UT_STATE: Used for verbose atomic state debugging.
*/
- DRM_UT_STATE = 0x40,
+ DRM_UT_STATE,
/**
* @DRM_UT_LEASE: Used in the lease code.
*/
- DRM_UT_LEASE = 0x80,
+ DRM_UT_LEASE,
/**
* @DRM_UT_DP: Used in the DP code.
*/
- DRM_UT_DP = 0x100,
+ DRM_UT_DP,
/**
* @DRM_UT_DRMRES: Used in the drm managed resources code.
*/
- DRM_UT_DRMRES = 0x200,
+ DRM_UT_DRMRES
};

static inline bool drm_debug_enabled(enum drm_debug_category category)
{
- return unlikely(__drm_debug & category);
+ return unlikely(__drm_debug & BIT(category));
}

/*
--
2.35.3


2022-05-17 08:29:51

by Jim Cromie

[permalink] [raw]
Subject: [PATCH v2 05/27] dyndbg: add exclusive class_id to pr_debug callsites

DRM issues ~10 exclusive categories of debug messages; to represent
this directly in dyndbg, add a new field: struct _ddebug.class_id:5.

We only need 4 bits for drm, and with that reserved, we have 2 to
spare on 32 bit builds; lets take one extra (5 bits total), and keep a
spare bit. 32 classes-per-bitmap is a practical usability limit
anyway with a bitmap interface:

#> echo 0x012345678 > /sys/module/drm/parameters/debug

All existing callsites are initialized with _DPRINTK_CLASS_DFLT, which
is 2^5-1. This reserves 0-30 for use in new categorized/class'd
pr_debugs, which fits perfectly with natural enums (ints: 0..N).

To achieve this, DEFINE_DYNAMIC_DEBUG_METADATA_CLS(cls,...) is added,
and DEFINE_DYNAMIC_DEBUG_METADATA is altered to call it with the
default. The factory macro chain between there and pr_debug is
adjusted similarly.

No behavior change.

Signed-off-by: Jim Cromie <[email protected]>
---
include/linux/dynamic_debug.h | 54 ++++++++++++++++++++++++++---------
1 file changed, 41 insertions(+), 13 deletions(-)

diff --git a/include/linux/dynamic_debug.h b/include/linux/dynamic_debug.h
index dd20e825c36f..39550fefcf0f 100644
--- a/include/linux/dynamic_debug.h
+++ b/include/linux/dynamic_debug.h
@@ -6,6 +6,8 @@
#include <linux/jump_label.h>
#endif

+#include <linux/build_bug.h>
+
/*
* An instance of this structure is created in a special
* ELF section at every dynamic debug callsite. At runtime,
@@ -21,6 +23,9 @@ struct _ddebug {
const char *filename;
const char *format;
unsigned int lineno:18;
+#define CLS_BITS 5
+ unsigned int class_id:CLS_BITS;
+#define _DPRINTK_CLASS_DFLT ((1 << CLS_BITS) - 1)
/*
* The flags field controls the behaviour at the callsite.
* The bits here are changed dynamically when the user
@@ -84,7 +89,7 @@ void __dynamic_ibdev_dbg(struct _ddebug *descriptor,
const struct ib_device *ibdev,
const char *fmt, ...);

-#define DEFINE_DYNAMIC_DEBUG_METADATA(name, fmt) \
+#define DEFINE_DYNAMIC_DEBUG_METADATA_CLS(name, cls, fmt) \
static struct _ddebug __aligned(8) \
__section("__dyndbg") name = { \
.modname = KBUILD_MODNAME, \
@@ -93,8 +98,14 @@ void __dynamic_ibdev_dbg(struct _ddebug *descriptor,
.format = (fmt), \
.lineno = __LINE__, \
.flags = _DPRINTK_FLAGS_DEFAULT, \
+ .class_id = cls, \
_DPRINTK_KEY_INIT \
- }
+ }; \
+ BUILD_BUG_ON_MSG(cls > _DPRINTK_CLASS_DFLT, \
+ "classid value overflow")
+
+#define DEFINE_DYNAMIC_DEBUG_METADATA(name, fmt) \
+ DEFINE_DYNAMIC_DEBUG_METADATA_CLS(name, _DPRINTK_CLASS_DFLT, fmt)

#ifdef CONFIG_JUMP_LABEL

@@ -125,18 +136,26 @@ void __dynamic_ibdev_dbg(struct _ddebug *descriptor,

#endif /* CONFIG_JUMP_LABEL */

-#define __dynamic_func_call(id, fmt, func, ...) do { \
- DEFINE_DYNAMIC_DEBUG_METADATA(id, fmt); \
- if (DYNAMIC_DEBUG_BRANCH(id)) \
- func(&id, ##__VA_ARGS__); \
+#define __dynamic_func_call_cls(id, cls, fmt, func, ...) do { \
+ DEFINE_DYNAMIC_DEBUG_METADATA_CLS(id, cls, fmt); \
+ if (DYNAMIC_DEBUG_BRANCH(id)) \
+ func(&id, ##__VA_ARGS__); \
} while (0)

-#define __dynamic_func_call_no_desc(id, fmt, func, ...) do { \
- DEFINE_DYNAMIC_DEBUG_METADATA(id, fmt); \
- if (DYNAMIC_DEBUG_BRANCH(id)) \
- func(__VA_ARGS__); \
+#define __dynamic_func_call_no_desc_cls(id, cls, fmt, func, ...) do { \
+ DEFINE_DYNAMIC_DEBUG_METADATA_CLS(id, cls, fmt); \
+ if (DYNAMIC_DEBUG_BRANCH(id)) \
+ func(__VA_ARGS__); \
} while (0)

+#define __dynamic_func_call(id, fmt, func, ...) \
+ __dynamic_func_call_cls(id, _DPRINTK_CLASS_DFLT, \
+ fmt, func, ##__VA_ARGS__)
+
+#define __dynamic_func_call_no_desc(id, fmt, func, ...) \
+ __dynamic_func_call_no_desc_cls(id, _DPRINTK_CLASS_DFLT, \
+ fmt, func, ##__VA_ARGS__)
+
/*
* "Factory macro" for generating a call to func, guarded by a
* DYNAMIC_DEBUG_BRANCH. The dynamic debug descriptor will be
@@ -145,15 +164,24 @@ void __dynamic_ibdev_dbg(struct _ddebug *descriptor,
* the varargs. Note that fmt is repeated in invocations of this
* macro.
*/
+#define _dynamic_func_call_cls(cls, fmt, func, ...) \
+ __dynamic_func_call_cls(__UNIQUE_ID(ddebug), cls, fmt, func, ##__VA_ARGS__)
#define _dynamic_func_call(fmt, func, ...) \
- __dynamic_func_call(__UNIQUE_ID(ddebug), fmt, func, ##__VA_ARGS__)
+ _dynamic_func_call_cls(_DPRINTK_CLASS_DFLT, fmt, func, ##__VA_ARGS__)
+
/*
* A variant that does the same, except that the descriptor is not
* passed as the first argument to the function; it is only called
* with precisely the macro's varargs.
*/
-#define _dynamic_func_call_no_desc(fmt, func, ...) \
- __dynamic_func_call_no_desc(__UNIQUE_ID(ddebug), fmt, func, ##__VA_ARGS__)
+#define _dynamic_func_call_no_desc_cls(fmt, cat, func, ...) \
+ __dynamic_func_call_no_desc_cls(__UNIQUE_ID(ddebug), cat, \
+ fmt, func, ##__VA_ARGS__)
+
+#define _dynamic_func_call_no_desc(fmt, func, ...) \
+ __dynamic_func_call_no_desc_cls(__UNIQUE_ID(ddebug), \
+ _DPRINTK_CLASS_DFLT, \
+ fmt, func, ##__VA_ARGS__)

#define dynamic_pr_debug(fmt, ...) \
_dynamic_func_call(fmt, __dynamic_pr_debug, \
--
2.35.3


2022-05-17 08:48:26

by Jim Cromie

[permalink] [raw]
Subject: [PATCH v2 08/27] dyndbg: add drm.debug style bitmap support

Add kernel_param_ops and callbacks to implement a bitmap in a
sysfs-node. IE, add these:

- int param_set_dyndbg_classes()
- int param_get_dyndbg_classes()
- struct kernel_param_ops param_ops_dyndbg_classes

Following the model of kernel/params.c STANDARD_PARAM_DEFS, these are
non-static and exported.

get/set use an augmented kernel_param; the arg refs a new struct
dyndbg_classes_param, initialized by the macro, containing:

BITS: a pointer to the user module's ulong holding the bits/state.
By ref'g the client's bit-state, we coordinate with existing code that
uses it, so it works unchanged; for example drm_debug_enabled(). The
change to ulong allows use of BIT() etc.

FLAGS: dyndbg.flags toggled by bit-changes. Usually just "p".

MAP: a pointer to struct ddebug_known_classes, which maps those
class-names to pr_debug.class_ids 0..N.

Using the sys-node, with dynamic_debug.verbose=1:

bash-5.1# echo 1 > /sys/module/drm/parameters/debug
[ 29.821298] dyndbg: set_dyndbg_classes: new 0x1 current 0x0
[ 29.822841] dyndbg: query 0: "class DRM_UT_CORE +p" mod:*
[ 29.824348] dyndbg: no matches for query
[ 29.825428] dyndbg: total matches: 0

Signed-off-by: Jim Cromie <[email protected]>
---
include/linux/dynamic_debug.h | 17 ++++++++
lib/dynamic_debug.c | 81 +++++++++++++++++++++++++++++++++++
2 files changed, 98 insertions(+)

diff --git a/include/linux/dynamic_debug.h b/include/linux/dynamic_debug.h
index 328722ba2d8e..e9e6d0f503f3 100644
--- a/include/linux/dynamic_debug.h
+++ b/include/linux/dynamic_debug.h
@@ -85,6 +85,11 @@ struct ddebug_known_classes_map {
.classes = { __VA_ARGS__ } \
}

+struct ddebug_classes_bitmap_param {
+ unsigned long *bits;
+ char flags[8];
+ const struct ddebug_known_classes_map *map;
+};

#if defined(CONFIG_DYNAMIC_DEBUG_CORE)

@@ -237,6 +242,10 @@ void __dynamic_ibdev_dbg(struct _ddebug *descriptor,
int dynamic_debug_register_classes(struct ddebug_known_classes_map *map);
void dynamic_debug_unregister_classes(struct ddebug_known_classes_map *map);

+struct kernel_param;
+int param_set_dyndbg_classes(const char *instr, const struct kernel_param *kp);
+int param_get_dyndbg_classes(char *buffer, const struct kernel_param *kp);
+
#else /* !CONFIG_DYNAMIC_DEBUG_CORE */

#include <linux/string.h>
@@ -283,6 +292,14 @@ static inline int dynamic_debug_register_classes(const struct ddebug_known_class
static inline void dynamic_debug_unregister_classes(struct ddebug_known_classes_map *map)
{}

+struct kernel_param;
+static inline int param_set_dyndbg_classes(const char *instr, const struct kernel_param *kp)
+{ return 0; }
+static inline int param_get_dyndbg_classes(char *buffer, const struct kernel_param *kp)
+{ return 0; }
+
#endif /* !CONFIG_DYNAMIC_DEBUG_CORE */

+extern const struct kernel_param_ops param_ops_dyndbg_classes;
+
#endif
diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
index b1aaf8893cdf..b67bf9efec07 100644
--- a/lib/dynamic_debug.c
+++ b/lib/dynamic_debug.c
@@ -597,6 +597,87 @@ static int ddebug_exec_queries(char *query, const char *modname)
return nfound;
}

+static int do_callback_changes(const struct ddebug_classes_bitmap_param *dcp,
+ int bitpos, unsigned long *inbits)
+{
+#define QUERY_SIZE 128
+ char query[QUERY_SIZE];
+ int matches;
+
+ snprintf(query, QUERY_SIZE, "class %s %c%s", dcp->map->classes[bitpos],
+ test_bit(bitpos, inbits) ? '+' : '-', dcp->flags);
+
+ matches = ddebug_exec_queries(query, NULL);
+
+ v2pr_info("bit-%d: %d matches on class:%s\n", bitpos,
+ matches, dcp->map->classes[bitpos]);
+
+ return matches;
+}
+
+/**
+ * param_set_dyndbg_classes - bits => categories >control setter
+ * @instr: string echo>d to sysfs
+ * @kp: kp->arg has state: bits, map
+ *
+ * Enable/disable prdbgs by their "category", as specified in the
+ * arguments to DEFINE_DYNAMIC_DEBUG_CLASSES.
+ *
+ * Returns: 0 or <0 if error.
+ */
+int param_set_dyndbg_classes(const char *instr, const struct kernel_param *kp)
+{
+ const struct ddebug_classes_bitmap_param *dcp = kp->arg;
+ unsigned long inbits;
+ int rc, i, totct = 0;
+
+ if (!dcp || !dcp->map) {
+ pr_err("set_dyndbg_classes: no bits=>queries map\n");
+ return -EINVAL;
+ }
+ rc = kstrtoul(instr, 0, &inbits);
+ if (rc) {
+ pr_err("set_dyndbg_classes: expecting bits/integer\n");
+ return -EINVAL;
+ }
+ vpr_info("set_dyndbg_classes: new 0x%lx current 0x%lx\n", inbits, *dcp->bits);
+
+ for (i = 0; i < dcp->map->length; i++) {
+
+ if (test_bit(i, &inbits) == test_bit(i, dcp->bits))
+ continue;
+
+ totct += do_callback_changes(dcp, i, &inbits);
+ }
+ *dcp->bits = inbits;
+ vpr_info("total matches: %d\n", totct);
+ return 0;
+}
+EXPORT_SYMBOL(param_set_dyndbg_classes);
+
+/**
+ * param_get_dyndbg_classes - classes reader
+ * @buffer: string description of controlled bits -> classes
+ * @kp: kp->arg has state: bits, map
+ *
+ * Reads last written bits, underlying prdbg state may have changed since.
+ * Returns: #chars written or <0 on error
+ */
+int param_get_dyndbg_classes(char *buffer, const struct kernel_param *kp)
+{
+ const struct ddebug_classes_bitmap_param *p = kp->arg;
+ unsigned long val = *p->bits;
+
+ return scnprintf(buffer, PAGE_SIZE, "0x%lx\n", val);
+}
+EXPORT_SYMBOL(param_get_dyndbg_classes);
+
+const struct kernel_param_ops param_ops_dyndbg_classes = {
+ .set = param_set_dyndbg_classes,
+ .get = param_get_dyndbg_classes,
+};
+EXPORT_SYMBOL(param_ops_dyndbg_classes);
+
#define PREFIX_SIZE 64

static int remaining(int wrote)
--
2.35.3


2022-05-17 08:48:44

by Jim Cromie

[permalink] [raw]
Subject: [PATCH v2 19/27] drm_print: wrap drm_*_dbg in dyndbg descriptor factory macro

For CONFIG_DRM_USE_DYNAMIC_DEBUG=y, wrap __drm_dbg() & __drm_dev_dbg()
in one of dyndbg's Factory macros: _dynamic_func_call_no_desc().

Next, those functions are adapted to accept a descriptor arg, and we
drop the _no_desc suffix, then the (~4000) drm.debug callsites will be
controllable by their class-names:

#> echo class DRM_UT_ATOMIC +p > /proc/dynamic_debug/control

CONFIG_DRM_USE_DYNAMIC_DEBUG=y/n is configurable because of the .data
footprint cost of per-callsite control; 56 bytes/site * ~2k for i915,
~4k callsites for amdgpu. This is large enough that a kernel builder
might not want it.

Signed-off-by: Jim Cromie <[email protected]>
---
drivers/gpu/drm/Kconfig | 12 ++++++++++++
drivers/gpu/drm/Makefile | 2 ++
drivers/gpu/drm/drm_print.c | 2 +-
include/drm/drm_print.h | 12 ++++++++++++
4 files changed, 27 insertions(+), 1 deletion(-)

diff --git a/drivers/gpu/drm/Kconfig b/drivers/gpu/drm/Kconfig
index f1422bee3dcc..5ab31753c25d 100644
--- a/drivers/gpu/drm/Kconfig
+++ b/drivers/gpu/drm/Kconfig
@@ -63,6 +63,18 @@ config DRM_DEBUG_MM

If in doubt, say "N".

+config DRM_USE_DYNAMIC_DEBUG
+ bool "use dynamic debug to implement drm.debug"
+ default y
+ depends on DRM
+ depends on DYNAMIC_DEBUG || DYNAMIC_DEBUG_CORE
+ depends on JUMP_LABEL
+ help
+ Use dynamic-debug to avoid drm_debug_enabled() runtime overheads.
+ Due to callsite counts in DRM drivers (~4k in amdgpu) and 56
+ bytes per callsite, the .data costs can be substantial, and
+ are therefore configurable.
+
config DRM_DEBUG_SELFTEST
tristate "kselftests for DRM"
depends on DRM
diff --git a/drivers/gpu/drm/Makefile b/drivers/gpu/drm/Makefile
index c2ef5f9fce54..e93b7902994a 100644
--- a/drivers/gpu/drm/Makefile
+++ b/drivers/gpu/drm/Makefile
@@ -3,6 +3,8 @@
# Makefile for the drm device driver. This driver provides support for the
# Direct Rendering Infrastructure (DRI) in XFree86 4.1.0 and higher.

+CFLAGS-$(CONFIG_DRM_USE_DYNAMIC_DEBUG) += -DDYNAMIC_DEBUG_MODULE
+
drm-y := drm_aperture.o drm_auth.o drm_cache.o \
drm_file.o drm_gem.o drm_ioctl.o \
drm_drv.o \
diff --git a/drivers/gpu/drm/drm_print.c b/drivers/gpu/drm/drm_print.c
index e77b49c7725b..5192533794a2 100644
--- a/drivers/gpu/drm/drm_print.c
+++ b/drivers/gpu/drm/drm_print.c
@@ -53,7 +53,7 @@ MODULE_PARM_DESC(debug, "Enable debug output, where each bit enables a debug cat
"\t\tBit 7 (0x80) will enable LEASE messages (leasing code)\n"
"\t\tBit 8 (0x100) will enable DP messages (displayport code)");

-#if !defined(CONFIG_DYNAMIC_DEBUG_CORE)
+#if !defined(CONFIG_DRM_USE_DYNAMIC_DEBUG)
module_param_named(debug, __drm_debug, ulong, 0600);
#else
static struct ddebug_classes_bitmap_param drm_debug_bitmap = {
diff --git a/include/drm/drm_print.h b/include/drm/drm_print.h
index 383feb0d34fe..5c39bacac2b3 100644
--- a/include/drm/drm_print.h
+++ b/include/drm/drm_print.h
@@ -388,8 +388,14 @@ void __drm_dev_dbg(const struct device *dev, enum drm_debug_category category,
} \
})

+#if !defined(CONFIG_DRM_USE_DYNAMIC_DEBUG)
#define drm_dev_dbg(dev, cat, fmt, ...) \
__drm_dev_dbg(dev, cat, fmt, ##__VA_ARGS__)
+#else
+#define drm_dev_dbg(dev, cat, fmt, ...) \
+ _dynamic_func_call_no_desc(fmt, __drm_dev_dbg, \
+ dev, cat, fmt, ##__VA_ARGS__)
+#endif

/**
* DRM_DEV_DEBUG() - Debug output for generic drm code
@@ -496,7 +502,13 @@ void ___drm_dbg(enum drm_debug_category category, const char *format, ...);
__printf(1, 2)
void __drm_err(const char *format, ...);

+#if !defined(CONFIG_DRM_USE_DYNAMIC_DEBUG)
#define __drm_dbg(fmt, ...) ___drm_dbg(fmt, ##__VA_ARGS__)
+#else
+#define __drm_dbg(cat, fmt, ...) \
+ _dynamic_func_call_no_desc(fmt, ___drm_dbg, \
+ cat, fmt, ##__VA_ARGS__)
+#endif

/* Macros to make printk easier */

--
2.35.3


2022-05-17 08:49:24

by Jim Cromie

[permalink] [raw]
Subject: [PATCH v2 06/27] dyndbg: add dynamic_debug_(un)register_classes

Add dynamic_debug_register_classes() to API, allowing user modules
(builtin and loadable) to register class_names for the .class_id's
they are using. Knowing classes is 1st step to validating with them.
Add dynamic_debug_unregister_classes() also.

Add struct ddebug_known_classes_map: maps known class_name strings to
.class_id[0..N], where N<31. .base allows sharing of that range.

A wrapper macro: DYNAMIC_DEBUG_CLASSES(_var, _modmatch, _base,
classes) defines and initializes that struct var, _maybe_unused is
added so the decl doesn't draw warnings when dyndbg is not enabled; a
small list of classnames is tolerable wasted space.

_var: user passes this into dynamic_debug_register_classes(var).

_base: usually 0, it allows splitting 31 classes into subranges, so
that multiple sysfs-nodes can share the module's class-id space.

classes: list of strings with classnames, mapped to class-id=idx(+_base)

mod_name: KBUILD_MODNAME, available for builtins, loadables
mod: ref to loadable module. allows ==, distinguishing loadables.

When modules register known classnames, they opt-in to permit dyndbg
to allow "class <name>" queries to manipulate their class'd pr_debugs
(if any), default class_id pr_debugs are still controllable as before.

dynamic_debug_register_classes(&map) finds the module's ddebug_table
record, and attaches the map to it. This makes it available to
ddebug_change(), which will use it to validate class'd commands.

Sharing class-names across multiple modules is how those modules
coordinate; all drm* and drivers would respond to:

#> echo class DRM_UT_CORE +p > /proc/dynamic_debug/control

Therefore no class-name uniqueness check is useful.

TODO: Eventually we need a list of registered classes, not just the
zero-or-one implemented here. This will support multiple sysfs-nodes,
one each for print-to-syslog, print-to-tracefs, or subranges using
_base.

Signed-off-by: Jim Cromie <[email protected]>
---
. fix register_classes() for !CONFIG_MODULES
. add maybe-unused to var decl in DYNAMIC_DEBUG_CLASSES
. kdoc for DYNAMIC_DEBUG_CLASSES
. add dynamic_debug_unregister_classes
---
include/linux/dynamic_debug.h | 36 ++++++++++++++++++++++++
lib/dynamic_debug.c | 53 +++++++++++++++++++++++++++++++++++
2 files changed, 89 insertions(+)

diff --git a/include/linux/dynamic_debug.h b/include/linux/dynamic_debug.h
index 39550fefcf0f..328722ba2d8e 100644
--- a/include/linux/dynamic_debug.h
+++ b/include/linux/dynamic_debug.h
@@ -56,6 +56,34 @@ struct _ddebug {
#endif
} __attribute__((aligned(8)));

+struct ddebug_known_classes_map {
+ struct list_head link;
+ struct module *mod;
+ const char *mod_name; /* needed for builtins */
+ const int base; /* index of 1st .class_id, allows split/shared space */
+ const int length;
+ const char *classes[]; /* index maps .class_id */
+};
+
+#define NUM_TYPE_ARGS(eltype, ...) \
+ (sizeof((eltype[]) {__VA_ARGS__}) / sizeof(eltype))
+/**
+ * DYNAMIC_DEBUG_CLASSES - declare classnames known by a module
+ * @_var: passed to dynamic_debug_register_classes(_var)
+ * @_base: offset of 1st class-name. splits .class_id space
+ * @classes: class-names known/used by of .class_ids[_base.._base+length]
+ *
+ * @classes specifies names for the classids used by a module; dyndbg
+ * accepts "class <name>" commands if <name> is known and registered.
+ */
+#define DYNAMIC_DEBUG_CLASSES(_var, _base, ...) \
+ static __maybe_unused struct ddebug_known_classes_map _var = { \
+ .mod = THIS_MODULE, \
+ .mod_name = KBUILD_MODNAME, \
+ .base = _base, \
+ .length = NUM_TYPE_ARGS(char*, __VA_ARGS__), \
+ .classes = { __VA_ARGS__ } \
+ }


#if defined(CONFIG_DYNAMIC_DEBUG_CORE)
@@ -206,6 +234,9 @@ void __dynamic_ibdev_dbg(struct _ddebug *descriptor,
KERN_DEBUG, prefix_str, prefix_type, \
rowsize, groupsize, buf, len, ascii)

+int dynamic_debug_register_classes(struct ddebug_known_classes_map *map);
+void dynamic_debug_unregister_classes(struct ddebug_known_classes_map *map);
+
#else /* !CONFIG_DYNAMIC_DEBUG_CORE */

#include <linux/string.h>
@@ -247,6 +278,11 @@ static inline int ddebug_dyndbg_module_param_cb(char *param, char *val,
} while (0)


+static inline int dynamic_debug_register_classes(const struct ddebug_known_classes_map *map)
+{ return 0; }
+static inline void dynamic_debug_unregister_classes(struct ddebug_known_classes_map *map)
+{}
+
#endif /* !CONFIG_DYNAMIC_DEBUG_CORE */

#endif
diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
index cdc0b03b1148..8f600c13048a 100644
--- a/lib/dynamic_debug.c
+++ b/lib/dynamic_debug.c
@@ -45,6 +45,8 @@ extern struct _ddebug __stop___dyndbg[];
struct ddebug_table {
struct list_head link;
const char *mod_name;
+ /* a module can have multiple class-sets eventually, but not yet */
+ struct ddebug_known_classes_map const *map;
unsigned int num_ddebugs;
struct _ddebug *ddebugs;
};
@@ -916,6 +918,57 @@ static const struct proc_ops proc_fops = {
.proc_write = ddebug_proc_write
};

+/**
+ * dynamic_debug_register_classes - register a module's known classes
+ * @map: &struct ddebug_known_classes_map
+ *
+ * modules using non-default pr_debug.class_id's should call this to
+ * inform dyndbg which classes they use (0..N), and what their
+ * classnames are. They are then usable in ```echo $cmd >control```
+ */
+int dynamic_debug_register_classes(struct ddebug_known_classes_map *map)
+{
+ struct ddebug_table *dt;
+ int rc = -ENOENT;
+
+ mutex_lock(&ddebug_lock);
+#ifdef CONFIG_MODULES
+ if (map->mod) {
+ /* loadable module */
+ list_for_each_entry(dt, &ddebug_tables, link) {
+ if (dt->mod_name == map->mod->name) {
+ rc = 0;
+ dt->map = map;
+ break;
+ }
+ }
+ }
+#endif
+ if (!map->mod) {
+ /* builtin module */
+ list_for_each_entry(dt, &ddebug_tables, link) {
+ if (!strcmp(dt->mod_name, map->mod_name)) {
+ rc = 0;
+ dt->map = map;
+ break;
+ }
+ }
+ }
+ mutex_unlock(&ddebug_lock);
+ if (rc)
+ pr_warn("register_classes: module %s not found\n", map->mod_name);
+ else
+ vpr_info("register_classes: %s\n", map->mod_name);
+
+ return rc;
+}
+EXPORT_SYMBOL(dynamic_debug_register_classes);
+
+void dynamic_debug_unregister_classes(struct ddebug_known_classes_map *map)
+{
+ vpr_info("unregister_classes: %s\n", map->mod_name);
+}
+
/*
* Allocate a new ddebug_table for the given module
* and add it to the global list.
--
2.35.3


2022-05-17 11:16:14

by Jim Cromie

[permalink] [raw]
Subject: [PATCH v2 11/27] dyndbg: support symbolic class-names in bitmap

Extend the sysfs-node bitmap support to accept class-names
registered by the module, allowing:

#> echo DRM_UT_CORE,-DRM_UT_ATOMIC,+DRM_UT_KMS \
> /sys/module/drm/parameters/debug

Do this in param_set_dyndbg_class_strings(), which is called from
param_set_dyndbg_classes() when the input string isn't a integer.

Signed-off-by: Jim Cromie <[email protected]>

---
. continue/skip on unknown class, so following symbols are processed.
. better loadable module handling, no more KP_MOD_NAME
. add do_callback_changes
---
lib/dynamic_debug.c | 63 ++++++++++++++++++++++++++++++++++++++++++---
1 file changed, 59 insertions(+), 4 deletions(-)

diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
index 42dce2e76014..8e1b9159e881 100644
--- a/lib/dynamic_debug.c
+++ b/lib/dynamic_debug.c
@@ -618,6 +618,61 @@ static int do_callback_changes(const struct ddebug_classes_bitmap_param *dcp,
return matches;
}

+/* support for [+-] symbolic-name boolean list */
+static int param_set_dyndbg_class_strings(const char *instr, const struct kernel_param *kp)
+{
+ const struct ddebug_classes_bitmap_param *dcp = kp->arg;
+ unsigned long inbits;
+ int idx_rc, totct = 0;
+ bool wanted;
+ char *cls, *p;
+
+ if (!dcp || !dcp->map) {
+ pr_err("set_dyndbg_classes: no bits=>queries map\n");
+ return -EINVAL;
+ }
+
+ cls = kstrdup(instr, GFP_KERNEL);
+ p = strchr(cls, '\n');
+ if (p)
+ *p = '\0';
+
+ inbits = *dcp->bits;
+ vpr_info("set_dyndbg_class_strings: %s on 0x%lx\n", cls, inbits);
+
+ for (; cls; cls = p) {
+ p = strchr(cls, ',');
+ if (p)
+ *p++ = '\0';
+
+ if (*cls == '-') {
+ wanted = false;
+ cls++;
+ } else {
+ wanted = true;
+ if (*cls == '+')
+ cls++;
+ }
+ idx_rc = match_string(dcp->map->classes, dcp->map->length, cls);
+ if (idx_rc < 0) {
+ pr_err("%s not found for module: %s\n", cls, dcp->map->mod_name);
+ continue;
+ }
+ if (test_bit(idx_rc, &inbits) == wanted) {
+ v3pr_info("no change on %s\n", cls);
+ continue;
+ }
+
+ vpr_info("set_dyndbg_classes: bit %d: %s\n", idx_rc, dcp->map->classes[idx_rc]);
+ inbits ^= BIT(idx_rc);
+ totct += do_callback_changes(dcp, idx_rc, &inbits);
+ }
+ kfree(cls);
+ *dcp->bits = inbits;
+ vpr_info("total matches: %d\n", totct);
+ return 0;
+}
+
/**
* param_set_dyndbg_classes - bits => categories >control setter
* @instr: string echo>d to sysfs
@@ -639,10 +694,9 @@ int param_set_dyndbg_classes(const char *instr, const struct kernel_param *kp)
return -EINVAL;
}
rc = kstrtoul(instr, 0, &inbits);
- if (rc) {
- pr_err("set_dyndbg_classes: expecting bits/integer\n");
- return -EINVAL;
- }
+ if (rc)
+ return param_set_dyndbg_class_strings(instr, kp);
+
vpr_info("set_dyndbg_classes: new 0x%lx current 0x%lx\n", inbits, *dcp->bits);

for (i = 0; i < dcp->map->length; i++) {
@@ -650,6 +704,7 @@ int param_set_dyndbg_classes(const char *instr, const struct kernel_param *kp)
if (test_bit(i, &inbits) == test_bit(i, dcp->bits))
continue;

+ vpr_info("set_dyndbg_classes: bit %d: %s\n", i, dcp->map->classes[i]);
totct += do_callback_changes(dcp, i, &inbits);
}
*dcp->bits = inbits;
--
2.35.3


2022-05-17 17:21:47

by Jim Cromie

[permalink] [raw]
Subject: [PATCH v2 15/27] drm: POC drm on dyndbg - map class-names to drm_debug_category's

Invoke DYNAMIC_DEBUG_CLASSES from drm_drv.h. This declares a
maybe-unused struct ddebug_known_classes_map var, initialized with:

. var: passed to dynamic_debug_register_classes()
. class-names: "DRM_UT_CORE", "DRM_UT_DRIVER", "DRM_UT_KMS", etc.
These names map to .class_id's by their index, ie: 0-30.

Then in 4 test-case drm-drivers (drm, i915, amdgpu, nouveau); call
dynamic_debug_register_classes(var). i915 also gets an adaptor func,
and calls it 1st in the array of initialization helpers, since early
logging might be valuable for diagnosing setup problems.

Since these modules all use the same class-names, they all will
respond together to class FOO changes:

#> echo class DRM_UT_KMS +p > /proc/dynamic_debug/control

NOTES:

DRM uses enum drm_debug_category across modules and common core, so
our class-names => index map must apply across them too, hence
drm_drv.h invokes the macro once for everyone.

DRM's enum drm_debug_category values need to sync with the index of
their respective class-names here. Then .class_id == category, and
dyndbg's class FOO mechanisms will work. Once enum drm_debug_category
is naturalized (value inits dropped, yielding 0..N), then this
condition holds true:

assert(!strcmp(classes[DRM_UT_KMS],"DRM_UT_KMS"));

Though DRM needs consistent categories across all modules, thats not
generally needed; modules X and Y could define FOO differently (ie
different corresponding .class_id) and things would work.

No callsites are actually selected here, since none are class'd yet.

bash-5.1# dmesg | grep register_class
[ 7.095579] dyndbg: register_classes: drm
[ 7.557109] dyndbg: register_classes: i915
[ 8.096818] dyndbg: register_classes: amdgpu

Signed-off-by: Jim Cromie <[email protected]>
---
drivers/gpu/drm/amd/amdgpu/amdgpu_drv.c | 3 +++
drivers/gpu/drm/drm_drv.c | 2 ++
drivers/gpu/drm/i915/i915_module.c | 11 +++++++++++
drivers/gpu/drm/nouveau/nouveau_drm.c | 4 ++++
include/drm/drm_drv.h | 14 ++++++++++++++
include/drm/drm_print.h | 4 ++++
6 files changed, 38 insertions(+)

diff --git a/drivers/gpu/drm/amd/amdgpu/amdgpu_drv.c b/drivers/gpu/drm/amd/amdgpu/amdgpu_drv.c
index 7fd0277b2805..addb991b4663 100644
--- a/drivers/gpu/drm/amd/amdgpu/amdgpu_drv.c
+++ b/drivers/gpu/drm/amd/amdgpu/amdgpu_drv.c
@@ -2765,6 +2765,8 @@ static int __init amdgpu_init(void)
if (r)
goto error_fence;

+ dynamic_debug_register_classes(&drm_debug_classes);
+
DRM_INFO("amdgpu kernel modesetting enabled.\n");
amdgpu_register_atpx_handler();
amdgpu_acpi_detect();
@@ -2787,6 +2789,7 @@ static void __exit amdgpu_exit(void)
amdgpu_amdkfd_fini();
pci_unregister_driver(&amdgpu_kms_pci_driver);
amdgpu_unregister_atpx_handler();
+ dynamic_debug_unregister_classes(&drm_debug_classes);
amdgpu_sync_fini();
amdgpu_fence_slab_fini();
mmu_notifier_synchronize();
diff --git a/drivers/gpu/drm/drm_drv.c b/drivers/gpu/drm/drm_drv.c
index 8214a0b1ab7f..16683fb169aa 100644
--- a/drivers/gpu/drm/drm_drv.c
+++ b/drivers/gpu/drm/drm_drv.c
@@ -1045,6 +1045,8 @@ static int __init drm_core_init(void)
{
int ret;

+ dynamic_debug_register_classes(&drm_debug_classes);
+
drm_connector_ida_init();
idr_init(&drm_minors_idr);
drm_memcpy_init_early();
diff --git a/drivers/gpu/drm/i915/i915_module.c b/drivers/gpu/drm/i915/i915_module.c
index 65acd7bf75d0..31f00f973866 100644
--- a/drivers/gpu/drm/i915/i915_module.c
+++ b/drivers/gpu/drm/i915/i915_module.c
@@ -44,10 +44,21 @@ static int i915_check_nomodeset(void)
return 0;
}

+static int i915_ddebug_classes_register(void)
+{
+ return dynamic_debug_register_classes(&drm_debug_classes);
+}
+static void i915_ddebug_classes_unregister(void)
+{
+ dynamic_debug_unregister_classes(&drm_debug_classes);
+}
+
static const struct {
int (*init)(void);
void (*exit)(void);
} init_funcs[] = {
+ { .init = i915_ddebug_classes_register,
+ .exit = i915_ddebug_classes_unregister },
{ .init = i915_check_nomodeset },
{ .init = i915_active_module_init,
.exit = i915_active_module_exit },
diff --git a/drivers/gpu/drm/nouveau/nouveau_drm.c b/drivers/gpu/drm/nouveau/nouveau_drm.c
index 561309d447e0..9a780b6d4796 100644
--- a/drivers/gpu/drm/nouveau/nouveau_drm.c
+++ b/drivers/gpu/drm/nouveau/nouveau_drm.c
@@ -1355,6 +1355,8 @@ nouveau_drm_init(void)
driver_pci = driver_stub;
driver_platform = driver_stub;

+ dynamic_debug_register_classes(&drm_debug_classes);
+
nouveau_display_options();

if (nouveau_modeset == -1) {
@@ -1391,6 +1393,8 @@ nouveau_drm_exit(void)
nouveau_backlight_dtor();
nouveau_unregister_dsm_handler();

+ dynamic_debug_unregister_classes(&drm_debug_classes);
+
#ifdef CONFIG_NOUVEAU_PLATFORM_DRIVER
platform_driver_unregister(&nouveau_platform_driver);
#endif
diff --git a/include/drm/drm_drv.h b/include/drm/drm_drv.h
index f6159acb8856..c2ffe12161b8 100644
--- a/include/drm/drm_drv.h
+++ b/include/drm/drm_drv.h
@@ -29,6 +29,7 @@

#include <linux/list.h>
#include <linux/irqreturn.h>
+#include <linux/dynamic_debug.h>

#include <drm/drm_device.h>

@@ -43,6 +44,19 @@ struct drm_mode_create_dumb;
struct drm_printer;
struct sg_table;

+/* these must comport with enum drm_debug_category values */
+DYNAMIC_DEBUG_CLASSES(drm_debug_classes, "*", 0,
+ "DRM_UT_CORE",
+ "DRM_UT_DRIVER",
+ "DRM_UT_KMS",
+ "DRM_UT_PRIME",
+ "DRM_UT_ATOMIC",
+ "DRM_UT_VBL",
+ "DRM_UT_STATE",
+ "DRM_UT_LEASE",
+ "DRM_UT_DP",
+ "DRM_UT_DRMRES");
+
/**
* enum drm_driver_feature - feature flags
*
diff --git a/include/drm/drm_print.h b/include/drm/drm_print.h
index 22fabdeed297..5b7eedb0f477 100644
--- a/include/drm/drm_print.h
+++ b/include/drm/drm_print.h
@@ -274,6 +274,10 @@ static inline struct drm_printer drm_err_printer(const char *prefix)
* # echo 0xf > /sys/module/drm/parameters/debug
*
*/
+/*
+ * These must be kept in sync with the class-names given in drm_drv.h
+ * DYNAMIC_DEBUG_CLASSES
+ */
enum drm_debug_category {
/**
* @DRM_UT_CORE: Used in the generic drm code: drm_ioctl.c, drm_mm.c,
--
2.35.3


2022-05-17 18:57:11

by Jim Cromie

[permalink] [raw]
Subject: [PATCH v2 13/27] dyndbg: add __pr_debug_cls(class, fmt, ...)

For selftest purposes, add __pr_debug_cls(class, fmt, ...)

I didn't think we'd need to define this, since DRM effectively has it
already. But test_dynamic_debug needs it in order to demonstrate all
the moving parts.

Note the __ prefix; its not intended for general use, and doesn't
include any builtin-constant checks that could pertain. I'd prefer to
see a use-case where copying the drm.debug model isn't better.

Signed-off-by: Jim Cromie <[email protected]>
---
include/linux/dynamic_debug.h | 7 +++++++
1 file changed, 7 insertions(+)

diff --git a/include/linux/dynamic_debug.h b/include/linux/dynamic_debug.h
index e9e6d0f503f3..abf43e28d8d3 100644
--- a/include/linux/dynamic_debug.h
+++ b/include/linux/dynamic_debug.h
@@ -216,6 +216,10 @@ void __dynamic_ibdev_dbg(struct _ddebug *descriptor,
_DPRINTK_CLASS_DFLT, \
fmt, func, ##__VA_ARGS__)

+#define dynamic_pr_debug_cls(cls, fmt, ...) \
+ _dynamic_func_call_cls(cls, fmt, __dynamic_pr_debug, \
+ pr_fmt(fmt), ##__VA_ARGS__)
+
#define dynamic_pr_debug(fmt, ...) \
_dynamic_func_call(fmt, __dynamic_pr_debug, \
pr_fmt(fmt), ##__VA_ARGS__)
@@ -246,6 +250,9 @@ struct kernel_param;
int param_set_dyndbg_classes(const char *instr, const struct kernel_param *kp);
int param_get_dyndbg_classes(char *buffer, const struct kernel_param *kp);

+#define __pr_debug_cls(cls, fmt, ...) \
+ dynamic_pr_debug_cls(cls, fmt, ##__VA_ARGS__)
+
#else /* !CONFIG_DYNAMIC_DEBUG_CORE */

#include <linux/string.h>
--
2.35.3


2022-05-26 20:44:57

by Daniel Vetter

[permalink] [raw]
Subject: Re: [RFC PATCH v2 00/27] DRM.debug on DYNAMIC_DEBUG, add trace events

On Mon, May 16, 2022 at 04:56:13PM -0600, Jim Cromie wrote:
> DRM.debug API is 23 macros, issuing 10 exclusive categories of debug
> messages. By rough count, they are used 5140 times in the kernel.
> These all call drm_dbg or drm_devdbg, which call drm_debug_enabled(),
> which checks bits in global __drm_debug. Some of these are page-flips
> and vblanks, and get called often.
>
> DYNAMIC_DEBUG (with CONFIG_JUMP_LABEL) is built to avoid this kind of
> work, with NOOPd jump/callsites.
>
> This patchset is RFC because:
> - it touches 2.5 subsystems: dyndbg, drm, tracefs (new events)
> - dyndbg class support is built for drm, needs it for validation
> - new api, used by drm
> - big memory impact, with 5100 new pr-debug callsites.
> - drm class bikeshedding opportunities
> - others, names etc.

Thanks a lot for keeping on pushing this!

>
> DYNAMIC_DEBUG:
>
> Adapt to directly represent 32 exclusive classes / categories.
> All existing users get _CLASS_DFLT:31, reserving 0-30 for opt-in.
>
> dynamic_debug_register_classes(): Tells dyndbg that caller/client is
> using .class_id's 0..N, and wants them exposed and manipulatable with
> names: DRM_UT_KMS etc.
>
> Client invokes DYNAMIC_DEBUG_CLASSES to define the name->id map,
> then registers it during its initialization.
>
> Then, when a dyndbg command-query has "class FOO":
>
> echo class DRM_UT_KMS +p > /proc/dynamic_debug/control
>
> ddebug_change() will 1st ddebug_validate_classname() for each module,
> using its registered class-maps; only modules which know DRM_UT_KMS
> will get those callsite adjustments. This "protects" each module's
> class-id space, unlike "class 4" query syntax.
>
> Add bitmap support for:
> echo 0x02 > /sys/module/drm/parameters/debug
>
> Add symbolic bitmap, because we have the class-names:
> echo +DRM_UT_KMS,+DRM_UT_ATOMIC > /sys/module/drm/parameters/debug
>
> Add test_dynamic_debug, to prove out the API.
>
> which is (used 3x to prove class-id ranges):
> - DYNAMIC_DEBUG_CLASSES(var, ... [3 class-name-literals each])
> - dynamic_debug_register_classes(var)
> - dynamic_debug_unregister_classes(var)
> also (6x):
> +module_param_cb(<node-name>, &param_ops_dyndbg_classes, /[pt][123]_bitmap/, 0600);
>
> Bits 0,1,2 of each of the 6 bitmaps control the 3 named classes in
> each of 3 groups, toggling their p,T bits respectively.
>
> RFC:
>
> dynamic_debug_register_classes() cannot act early enough to be in
> effect at module-load. So this will not work as you'd reasonably
> expect:
>
> modprobe test_dynamic_debug dyndbg='+pfm; class FOO +pfmlt'
>
> The 1st query:+pfm will be enabled during load, but in the 2nd query,
> "class FOO" will be unknown at load time. Early class enablement
> would be nice. DYNAMIC_DEBUG_CLASSES is a static initializer, which
> is certainly early enough, but Im missing a trick, suggestions?

So maybe I'm just totally overloading this work here so feel free to
ignore or postpone, but: Could we do the dynamic_debug_register_classes()
automatically at module load as a new special section? And then throw in a
bit of kbuild so that in a given subsystem every driver gets the same
class names by default and everything would just work, without having to
sprinkle calls to dynamic_debug_register_classes() all over the place?
That kbuild magic could then also insert all the boilerplate to make the
module options work, or maybe you could push that all into the module
loader and it would add these special options on its own (yay for more
consistency across subsystems)?

Also I think with that the early class stuff should be possible to fix,
since you can make sure that the classes are all there (in the module
loader code) before anything else gets done. A bit a special case but oh
well.

For the entire class approach, did you spot another subsystem that could
benefit from this and maybe make a more solid case that this is something
good?

> Wildcarding on classname is possible, maybe useful:
>
> echo +DRM_UT_\* > /sys/module/drm/parameters/debug
>
> If contemplated in earnest, it should consider the difference between
> "DRM_*" and "*_KMS", wrt observing across class hierarchies, as well
> as decide whether that echo means 1st match, or all matching names.
>
> __pr_debug_cls(cls, fmt,...) is just for testing, drm doesnt need it.
>
>
> DRM adaptation:
>
> Basically, these patches add another layer of macro indirection, which
> by CONFIG_DRM_USE_DYNAMIC_DEBUG=y, wraps drm_*dbg() in dyndbg's callsite
> Factory macro, and adds the new descriptor arg to the funcs.
>
> With these patches, drm.debugs appear as controllable *pr-dbg* callsites:
>
> [ 11.804352] dyndbg: register_classes: drm
> [ 11.920715] dyndbg: 234 debug prints in module drm_kms_helper
> [ 11.932135] dyndbg: 2 debug prints in module ttm
> [ 11.936119] dyndbg: 8 debug prints in module video
> [ 12.537543] dyndbg: 1756 debug prints in module i915
> [ 12.555045] dyndbg: register_classes: i915
> [ 12.666727] AMD-Vi: AMD IOMMUv2 functionality not available on this ..
> [ 13.735310] dyndbg: 3859 debug prints in module amdgpu
>
> amdgpu's large count includes:
> 582 direct uses/mentions of pr_debug
> 43 defns of DC_LOG_*, which use either pr_debug or DRM_DEBUG_*
> ~1000 uses of DC_LOG_*
> 1116 uses of dml_print in drivers/gpu/drm/amd
> 15 drm_dbg_\\w+ drivers/gpu/drm/amd
> 273 DRM_DEBUG_\\w+ drivers/gpu/drm/amd
>
> i915 has:
> 1072 drm_dbg_\\w+ drivers/gpu/drm/i915/ | wc -l
> 200 DRM_DEBUG_\\w+ drivers/gpu/drm/i915/
> 46 pr_debug drivers/gpu/drm/i915/
> 144 gvt_dbg_\\w+ drivers/gpu/drm/i915/gvt, using pr_debug
>
> This impacts the data footprint, so everything new/drm is dependent on
> DRM_USE_DYNAMIC_DEBUG=y.
>
> RFC for DRM:
>
> - decoration flags "fmlt" do not work on drm_*dbg().
> (drm_*dbg() dont use pr_debug, they *become* one flavor of them)
> this could (should?) be added, and maybe tailored for drm.
> some of the device prefixes are very long, a "d" flag could optionalize them.

I'm lost what the fmlt decoration flags are?

> - api use needs review wrt drm life-cycle.
> enum drm_debug_category and DYNAMIC_DEBUG_CLASSES could be together?

Hm if they're tied to module lifetime we should be good? Not sure what
could go wrong here.

> - class-names could stand review, perhaps extension
> "drm:core:" etc have appeared (maybe just from me)
> or a "plan" to look at it later

Yeah it's been a bit sprawling. I'm kinda hoping that by firmly
establishing dyndbg as the drm debug approach we can cut down for the need
for ad-hoc flags a bit.

> - i915 & amdgpu have pr_debugs (DC_LOG_*, gvt_dbg_*) that have
> class-ish prefixes that are separate from, but similar to DRM_UT_*,
> and could stand review and possible unification with reformed or
> extended drm categories.

Yeah drm is not entirely consistent with how exactly driver debug printing
should be done. Another reason why I'm hoping that the kitchen sync with
everything approach you're doing here could help unify things.

> - the change to enum drm_debug_category from bitmask values to 0..31
> means that we foreclose this possiblility:
>
> drm_dbg(DRM_UT_CORE|DRM_UT_KMS, "wierd double-cat experiment");

Yeah no, that doesn't make much sense to me :-)

> - nouveau has very few drm.debug calls,
> has NV_DEBUG, VMM_DEBUG, nvkm_printk_, I havent looked deeply.

Yeah see above. There's a pile more drivers (more on the armsoc side of
things) which are quite big on the raw debug call approach.

Cheers, Daniel

>
> DYNDBG/DRM -> TRACEFS
>
> My 1st try was motivated by Sean Paul's patch - DRM.trace:
> https://patchwork.freedesktop.org/patch/445549/?series=78133&rev=5
>
> Those used trace_printk, so were not good for upstream.
>
> Vincent Whitchurch's code:
> https://lore.kernel.org/lkml/[email protected]/
>
> added similar features, by sending printk:console events from dyndbg.
> It met with a good reception from Steve Rostedt, so I re-started with
> that.
>
> The biggest addition (from UI viewpoint) is 4 new trace-events, 2 each
> from dyndbg (pr_debug, dev_dbg) and drm (drm_dbg, drm_dev_dbg); 2 have
> dev, other 2 avoid storing nulls. Im unsure that 4 distinctions is
> valuable, but it seemed most obvious to reflect them straight thru to
> tracefs.
>
> RFC: the event/message formats are a bit of a mash-up;
>
> in /sys/kernel/tracing:
> drm/drm_debug/format:print fmt: "%s", __get_str(msg)
> drm/drm_devdbg/format:print fmt: "cat:%d, %s %s", \
> REC->drm_debug_category, dev_name(REC->dev), __get_str(msg)
>
> The 1st prints just the mesg itself, 2nd prints category as int;
> it'd be better if DRM.class-name replaced (not just augmented) the
> event-name "drm_devdbg" in the trace, is that possible ?
>
> dyndbg/prdbg/format:
> print fmt: "%s.%s %s", REC->desc->modname, REC->desc->function, __get_str(msg)
> dyndbg/devdbg/format:
> print fmt: "%s.%s %s", REC->desc->modname, REC->desc->function, __get_str(msg)
>
> These add a prefix string similar to dyndbg's decorations, except they
> don't use dyndbg's "fmlt" decoration flags.
>
> There are also 3 vblank trace-events already,
> declared in: drivers/gpu/drm/drm_trace.h
> 15:TRACE_EVENT(drm_vblank_event,
> 35:TRACE_EVENT(drm_vblank_event_queued,
> 52:TRACE_EVENT(drm_vblank_event_delivered,
>
> STATUS
>
> kernel-test-robot tested this patchset (on 5.18-rc6).
> github:[jimc:blead] BUILD SUCCESS 6c59e52ac81dd81ac7da4522a5e15b7ac488d5b5
> May 15, 2022, 8:39 AM (1 day ago)
>
>
> Ive been testing, mostly on virtme, mostly with this:
> #!/bin/bash
>
> # test class FOO handling of dynamic-debug
>
> alias lmt='modprobe test_dynamic_debug dyndbg=+pmf'
> alias rmt='rmmod test_dynamic_debug'
> alias look='grep test_dynamic_debug /proc/dynamic_debug/control'
>
> lookfor() {
> grep $1 /proc/dynamic_debug/control
> }
>
> vx() {
> echo $* > /sys/module/dynamic_debug/parameters/verbose
> }
>
> # amdgpu has ~2200 pr-debugs (before drm-debug-on-dyndbg),
> # use them to prove modprobe <mod> dyndbg=+p works
>
> test_param_dyndbg() {
>
> modprobe amdgpu dyndbg=+pfm
> let count=$(grep =pmf /proc/dynamic_debug/control | grep amdgpu | wc -l)
>
> if [ $count -gt 200 ] ; then
> echo amdgpu has $count pr-dbgs
> return 0
> else
> echo failed $count
> return -1
> fi
> }
> out=$(test_param_dyndbg)
> echo out:$out $?
> [ $? -eq 0 ] || exit $?
>
> qry_cmd() {
> echo "QCMD: $* >control" >&2
> echo $* > /proc/dynamic_debug/control
> }
>
> # enable dyndbg tracing
> dynable() {
> grep -P \\d $SKT/events/dyndbg/{.,*}/enable
> echo 1 > $SKT/events/dyndbg/enable
> grep -P \\d $SKT/events/dyndbg/{.,*}/enable
> }
>
> # enable drm tracing
> drmable() {
> grep -P \\d $SKT/events/drm/{.,*}/enable
> echo 1 > $SKT/events/drm/enable
> grep -P \\d $SKT/events/drm/{.,*}/enable
> }
>
> function doit() {
> cat /sys/module/test_dynamic_debug/parameters/do_prints
> }
>
> # test class FOO behavior of test_dynamic_debug module
> ttest_module__() {
> flg=$1
> dmesg -C
> modprobe test_dynamic_debug dyndbg=+pfm
> doit
>
> for cls in FOO BAR BUZZ; do
> qry_cmd module test_dynamic_debug class $cls $flg
> doit
> done
> doit
>
> for cls in Foo Bar Buzz; do
> qry_cmd module test_dynamic_debug class $cls $flg
> doit
> done
> doit
>
> for cls in bing bong boom; do
> qry_cmd module test_dynamic_debug class $cls $flg
> doit
> done
> doit
>
> dmesg | grep class
> }
>
> ttest_module() {
>
> ttest_module__ +p
> ttest_module__ -p
>
> #ttest_module__ +T
> #ttest_module__ -T
> }
>
> #dynable
> #drmable
>
> ttest_module
> grep test_dyn /proc/dynamic_debug/control
>
>
> # use/test bitmaps
>
> set_tddm_() {
> val=$1;
> knob=$2;
> echo "TDDM: $val >$knob" >&2
> echo $val > /sys/module/test_dynamic_debug/parameters/$knob
> cat /sys/module/test_dynamic_debug/parameters/$knob
> }
>
> CLS_1="FOO -FOO +FOO -FOO BAR -BAR +BAR -BAR BUZZ -BUZZ +BUZZ -BUZZ"
> CLS_2=" Foo Bar Buzz -Foo -Bar -Buzz +Foo +Bar +Buzz -Foo -Bar -Buzz"
> CLS_3=" bing bong boom -bing -bong -boom +bing +bong +boom -bing -bong -boom"
>
> tddm_sysnode_classes__() {
> targ=$1
> shift
> cls=$*
> for bitsym in $cls;
> do
> set_tddm_ $bitsym $targ
> done
> }
>
> # work all 3 sysfs bitmaps
>
> for sysnode in c1_syslog_bits c2_syslog_bits c3_syslog_bits;
> do
> for val in 0 1 2 4 8 0;
> do
> tddm_sysnode_classes__ $sysnode $val
> done
> done
>
> tddm_sysnode_classes__ c1_syslog_bits $CLS_1
> tddm_sysnode_classes__ c2_syslog_bits $CLS_2
> tddm_sysnode_classes__ c3_syslog_bits $CLS_3
>
> echo "show unknown: c3-names on c1-knob" >&2
> tddm_sysnode_classes__ c1_trace_bits $CLS_3
>
> echo "flags look inverted" >&2
> tddm_sysnode_classes__ c1_syslog_bits $CLS_1
>
> CLS_1_=FOO,-FOO,+FOO,-FOO,BAR,-BAR,+BAR,-BAR,BUZZ,-BUZZ,+BUZZ,-BUZZ
> CLS_2_=Foo,Bar,Buzz,-Foo,-Bar,-Buzz,+Foo,+Bar,+Buzz,-Foo,-Bar,-Buzz
> # leading err doesnt wreck the rest
> CLS_3_=,bing,bong,boom,-bing,-bong,-boom,+bing,+bong,+boom,-bing,-bong,-boom
>
> tddm_sysnode_classes__ c1_syslog_bits $CLS_1_
> tddm_sysnode_classes__ c2_syslog_bits $CLS_2_
> tddm_sysnode_classes__ c3_syslog_bits $CLS_3_
>
>
> Cc: Sean Paul <[email protected]>
> Cc: Daniel Vetter <[email protected]>
> Cc: David Airlie <[email protected]>
> Cc: Jani Nikula <[email protected]>
> Cc: Joonas Lahtinen <[email protected]>
> Cc: Pekka Paalanen <[email protected]>
> Cc: Rob Clark <[email protected]>
> Cc: Steven Rostedt <[email protected]>
> Cc: Thomas Zimmermann <[email protected]>
> Cc: Ville Syrj?l? <[email protected]>
> Cc: Chris Wilson <[email protected]>
> Cc: Steven Rostedt <[email protected]>
>
> Jim Cromie (27):
> dyndbg: fix static_branch manipulation
> dyndbg: show both old and new in change-info
> dyndbg: fix module.dyndbg handling
> dyndbg: drop EXPORTed dynamic_debug_exec_queries
> dyndbg: add exclusive class_id to pr_debug callsites
> dyndbg: add dynamic_debug_(un)register_classes
> dyndbg: validate class FOO on module
> dyndbg: add drm.debug style bitmap support
> Doc/dyndbg: document new class class_name query support
> dyndbg: let query-modname override defaulting modname
> dyndbg: support symbolic class-names in bitmap
> dyndbg: change zero-or-one classes-map to maps list
> dyndbg: add __pr_debug_cls(class, fmt, ...)
> dyndbg: add test_dynamic_debug module
> drm: POC drm on dyndbg - map class-names to drm_debug_category's
> drm/print: POC drm on dyndbg - use bitmap
> drm_print: condense enum drm_debug_category
> drm_print: interpose drm_*dbg with forwarding macros
> drm_print: wrap drm_*_dbg in dyndbg descriptor factory macro
> drm_print: refine drm_debug_enabled for jump-label
> drm_print: prefer bare printk KERN_DEBUG on generic fn
> drm_print: add _ddebug desc to drm_*dbg prototypes
> dyndbg: add _DPRINTK_FLAGS_ENABLED
> dyndbg: add _DPRINTK_FLAGS_TRACE
> dyndbg: add write-events-to-tracefs code
> dyndbg: 4 new trace-events: pr_debug, dev_dbg, drm_{,dev}debug
> dyndbg/drm: POC add tracebits sysfs-knob
>
> .../admin-guide/dynamic-debug-howto.rst | 12 +
> MAINTAINERS | 1 +
> drivers/gpu/drm/Kconfig | 12 +
> drivers/gpu/drm/Makefile | 2 +
> drivers/gpu/drm/amd/amdgpu/amdgpu_drv.c | 3 +
> drivers/gpu/drm/drm_drv.c | 5 +
> drivers/gpu/drm/drm_print.c | 69 ++-
> drivers/gpu/drm/i915/i915_module.c | 11 +
> drivers/gpu/drm/nouveau/nouveau_drm.c | 4 +
> include/drm/drm_drv.h | 26 +
> include/drm/drm_print.h | 84 ++-
> include/linux/dynamic_debug.h | 136 ++++-
> include/trace/events/drm.h | 68 +++
> include/trace/events/dyndbg.h | 74 +++
> lib/Kconfig.debug | 11 +
> lib/Makefile | 1 +
> lib/dynamic_debug.c | 487 +++++++++++++++---
> lib/test_dynamic_debug.c | 172 +++++++
> 18 files changed, 1049 insertions(+), 129 deletions(-)
> create mode 100644 include/trace/events/drm.h
> create mode 100644 include/trace/events/dyndbg.h
> create mode 100644 lib/test_dynamic_debug.c
>
> --
> 2.35.1
>

--
Daniel Vetter
Software Engineer, Intel Corporation
http://blog.ffwll.ch

2022-06-08 16:24:07

by Daniel Vetter

[permalink] [raw]
Subject: Re: [RFC PATCH v2 00/27] DRM.debug on DYNAMIC_DEBUG, add trace events

On Mon, Jun 06, 2022 at 08:59:36AM -0600, [email protected] wrote:
> On Wed, May 25, 2022 at 9:02 AM Daniel Vetter <[email protected]> wrote:
>
> > On Mon, May 16, 2022 at 04:56:13PM -0600, Jim Cromie wrote:
> > > DRM.debug API is 23 macros, issuing 10 exclusive categories of debug
> > > messages. By rough count, they are used 5140 times in the kernel.
> > > These all call drm_dbg or drm_devdbg, which call drm_debug_enabled(),
> > > which checks bits in global __drm_debug. Some of these are page-flips
> > > and vblanks, and get called often.
> > >
> > > DYNAMIC_DEBUG (with CONFIG_JUMP_LABEL) is built to avoid this kind of
> > > work, with NOOPd jump/callsites.
> > >
> > > This patchset is RFC because:
> > > - it touches 2.5 subsystems: dyndbg, drm, tracefs (new events)
> > > - dyndbg class support is built for drm, needs it for validation
> > > - new api, used by drm
> > > - big memory impact, with 5100 new pr-debug callsites.
> > > - drm class bikeshedding opportunities
> > > - others, names etc.
> >
> > Thanks a lot for keeping on pushing this!
>
>
> > >
> > > DYNAMIC_DEBUG:
> > >
>
>
>
> > > RFC:
> > >
> > > dynamic_debug_register_classes() cannot act early enough to be in
> > > effect at module-load. So this will not work as you'd reasonably
> > > expect:
> > >
> > > modprobe test_dynamic_debug dyndbg='+pfm; class FOO +pfmlt'
> > >
> > > The 1st query:+pfm will be enabled during load, but in the 2nd query,
> > > "class FOO" will be unknown at load time. Early class enablement
> > > would be nice. DYNAMIC_DEBUG_CLASSES is a static initializer, which
> > > is certainly early enough, but Im missing a trick, suggestions?
> >
> > So maybe I'm just totally overloading this work here so feel free to
> > ignore or postpone, but: Could we do the dynamic_debug_register_classes()
> > automatically at module load as a new special section? And then throw in a
> > bit of kbuild so that in a given subsystem every driver gets the same
> > class names by default and everything would just work, without having to
> > sprinkle calls to dynamic_debug_register_classes() all over the place?
> >
>
> This is now done; Ive added __dyndbg_classes section.
> load_module() now grabs it from the .ko
> and ddebug_add_module() attaches it to the module's ddebug_table record.
> for builtins, dynamic_debug_init feeds the builtin class-maps to
> ddebug_add_module
>
> bash-5.1# modprobe test_dynamic_debug dyndbg="class FOO +p"
> [ 88.374722] dyndbg: class[0]: nm:test_dynamic_debug base:20 len:7 ty:1
> [ 88.375158] dyndbg: 0: EMERG
> [ 88.375345] dyndbg: 1: DANGER
> [ 88.375540] dyndbg: 2: ERROR
> [ 88.375726] dyndbg: 3: WARNING
> [ 88.375930] dyndbg: 4: NOTICE
> [ 88.376130] dyndbg: 5: INFO
> [ 88.376310] dyndbg: 6: DEBUG
> [ 88.376499] dyndbg: class[1]: nm:test_dynamic_debug base:12 len:3 ty:1
> [ 88.376903] dyndbg: 0: ONE
> [ 88.377079] dyndbg: 1: TWO
> [ 88.377253] dyndbg: 2: THREE
> [ 88.377441] dyndbg: class[2]: nm:test_dynamic_debug base:8 len:3 ty:0
> [ 88.377837] dyndbg: 0: bing
> [ 88.378022] dyndbg: 1: bong
> [ 88.378203] dyndbg: 2: boom
> [ 88.378387] dyndbg: class[3]: nm:test_dynamic_debug base:4 len:3 ty:0
> [ 88.378800] dyndbg: 0: Foo
> [ 88.378986] dyndbg: 1: Bar
> [ 88.379167] dyndbg: 2: Buzz
> [ 88.379348] dyndbg: class[4]: nm:test_dynamic_debug base:0 len:3 ty:0
> [ 88.379757] dyndbg: 0: FOO
> [ 88.379938] dyndbg: 1: BAR
> [ 88.380136] dyndbg: 2: BUZZ
> [ 88.380410] dyndbg: module:test_dynamic_debug attached 5 classes
> [ 88.380881] dyndbg: 24 debug prints in module test_dynamic_debug
> [ 88.381315] dyndbg: module: test_dynamic_debug dyndbg="class FOO +p"
> [ 88.381714] dyndbg: query 0: "class FOO +p" mod:test_dynamic_debug
> [ 88.382109] dyndbg: split into words: "class" "FOO" "+p"
> [ 88.382445] dyndbg: op='+'
> [ 88.382616] dyndbg: flags=0x1
> [ 88.382802] dyndbg: *flagsp=0x1 *maskp=0xffffffff
> [ 88.383101] dyndbg: parsed: func="" file="" module="test_dynamic_debug"
> format="" lineno=0-0 class=FOO
> [ 88.383740] dyndbg: applied: func="" file="" module="test_dynamic_debug"
> format="" lineno=0-0 class=FOO
> [ 88.384324] dyndbg: processed 1 queries, with 2 matches, 0 errs
> bash-5.1#
>
> so its working at module-load time.

Awesome!

> > For the entire class approach, did you spot another subsystem that could
> > benefit from this and maybe make a more solid case that this is something
> > good?
> >
>
> I had been working on the premise that ~4k drm*dbg callsites was a good
> case.

Oh I'm happy with just drm, but occasionally we've done stuff in drm that
the wider kernel community found a bit silly. So bit more acks/validation
from outside the dri-devel echo chamber would be great, whatever form it
is.

> verbosity-levels - with x<y logic instead of x==y is what's currently
> missing.
>
> the next revision adds something, which "kinda works".
> But I think I'll rip it out, and do this simpler approach instead:
>
> implement a verbose/levels param & callback, which takes
>
> echo 3 > /sys/module/foo/parameters/debug_verbosity
>
> and effectively does
>
> echo <<EOQRY > /proc/dynamic_debug/control
> module foo class V1 +p
> module foo class V2 +p
> module foo class V3 +p
> module foo class V4 -p
> module foo class V5 -p
> module foo class V6 -p
> module foo class V7 -p
> module foo class V8 -p
> EOQRY
>
> since only real +/-p changes incur kernel-patching costs,
> the remaining overheads are minimal.
>
>
> > RFC for DRM:
> >
> > - decoration flags "fmlt" do not work on drm_*dbg().
> > (drm_*dbg() dont use pr_debug, they *become* one flavor of them)
> > this could (should?) be added, and maybe tailored for drm.
> > some of the device prefixes are very long, a "d" flag could optionalize
> them.
>
> I'm lost what the fmlt decoration flags are?
>
>
> The flags are::
>
> p enables the pr_debug() callsite.
> f Include the function name in the printed message
> l Include line number in the printed message
> m Include module name in the printed message
> t Include thread ID in messages not generated from interrupt context
> _ No flags are set. (Or'd with others on input)
>
>
> the fmlt flags add a "decoration" prefix to enabled/printed log messages

Oh I was just confused and thought fmlt was some special format thing, and
not just the list of letters that wond work due to the implementation.

If you havent, maybe just spell the above list out (like you do here) in
the docs?

> > - api use needs review wrt drm life-cycle.
> > > enum drm_debug_category and DYNAMIC_DEBUG_CLASSES could be together?
> >
> > Hm if they're tied to module lifetime we should be good? Not sure what
> > could go wrong here.
> >
> >
> with the new __section, "life-cycle" doesnt really pertain.
> the new issue is how the class-maps are shared across the subsystem;
> the current class-maps list for each module will probably break;
> a list item cannot be on N different lists of different modules.
> Altering the list-items to ref the class-map (not contain it) should solve
> the problem.
>
>
>
>
> > > - class-names could stand review, perhaps extension
> > > "drm:core:" etc have appeared (maybe just from me)
> > > or a "plan" to look at it later
> >
> > Yeah it's been a bit sprawling. I'm kinda hoping that by firmly
> > establishing dyndbg as the drm debug approach we can cut down for the need
> > for ad-hoc flags a bit.
> >
> > yeah thats why I kept the DRM_UT_* names.
> OTOH - the symbolic names patch exposes the choices,
> which locks the names as API ??

Yeah that part is fine. It's more because the flags was the only thing we
ever had, any debug need was solved with them. With dyndbg we should have
a lot more and a lot more precise options for handling this.

So I'm not worried about the flags and their names per-se, more that we
had some pressure to add more flags for specific files and libraries.
Dyndbg should give us a much more powerful tool for these problems.

> > > - i915 & amdgpu have pr_debugs (DC_LOG_*, gvt_dbg_*) that have
> > > class-ish prefixes that are separate from, but similar to DRM_UT_*,
> > > and could stand review and possible unification with reformed or
> > > extended drm categories.
> >
> > Yeah drm is not entirely consistent with how exactly driver debug printing
> > should be done. Another reason why I'm hoping that the kitchen sync with
> > everything approach you're doing here could help unify things.
> >
>
>
> the decoration flags can help here; they loosely/precisely describe
> the elements of most/all the current debug format-prefix variations.
> So case by case, the ad-hoc variations should map onto these flags,
>
> The flags allow selectively dropping the prefix info from some of the log
> entries,
> after you've seen the module name and function a dozen times,
> it's helpful to reduce screen clutter.
>
> It might make sense to add a new flag for device,
> so that dev_dbg() flavors can shorten-or-skip the longer device strings,
> maybe some drm specific flavors.
>
>
>
> >
> > > - the change to enum drm_debug_category from bitmask values to 0..31
> > > means that we foreclose this possiblility:
> > >
> > > drm_dbg(DRM_UT_CORE|DRM_UT_KMS, "wierd double-cat experiment");
> >
> > Yeah no, that doesn't make much sense to me :-)
> >
> > no chuckles for the schrodinger's cat joke ?
> (maybe "yeah no" is the artful superpositional reply, I just caught :)
>
>
> > > - nouveau has very few drm.debug calls,
> > > has NV_DEBUG, VMM_DEBUG, nvkm_printk_, I havent looked deeply.
> >
> >
> nouveau has like levels, man ..
> test_dynamic_debug implements its priority-style names as a POC
>
> patch 18 converts nvkm_debug/trace to use dev_dbg instead of dev_info
> it probably could adapt to use drm_devdbg
>
>
>
>
> > Yeah see above. There's a pile more drivers (more on the armsoc side of
> > things) which are quite big on the raw debug call approach.
> >
> >
> LOW, MID, HI has been proposed at least once wrt dyndbg.
> that probably fits well with current disjoint classes.
> level/verbose classes should be practical too, as described above.
>
> NB: The symbolic names should also work
>
> echo +MID > /sys/module/foobar/parameters/debug_verbosity
>
> though theres some ambiguity with
>
> echo -V3 > /sys/module/foobar/parameters/debug_verbosity
>
> that should turn off V4,5,6,
> but what about V1,2 ?
> it could leave them alone (whatever their previous settings are)
>
> anyway, lkp-robot and igt-trybot should be grinding on the latest patchset
> soon,
> I'll send it after I fix whatever breaks.

Awesome, like I said I'm a bit drowned in everything, but I'm really happy
you're pushing this!
-Daniel

>
>
>
> > Cheers, Daniel
> >
>
> thanks,
> Jim

--
Daniel Vetter
Software Engineer, Intel Corporation
http://blog.ffwll.ch

2022-06-29 20:38:28

by Steven Rostedt

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


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 <[email protected]> wrote:


> diff --git a/include/trace/events/drm.h b/include/trace/events/drm.h
> new file mode 100644
> index 000000000000..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 <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)
> + __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 */
> +