2022-08-05 22:27:37

by Jim Cromie

[permalink] [raw]
Subject: [PATCH v5 00/33] DYNDBG: opt-in class'd debug for modules, use in drm.

Hi Jason, Greg, DRM-folk,

heres V5. Diffs vs V4:

1st 9 have Jason's Ack
10 is new: simple var cleanup
11 new struct, to contain future addins. touches kernel/module/

dyndbg-param callbacks moved to last (of dyndbg patches)
they're where the uncertainty is,
and the bulk of the API addition (class keyword is small)

patches between the move are the guts of the "class foo" feature.
exposure of feature is only via >control, until sysfs parts added

DRM chunk:
included here to see how patchwork's merge & test proceeds.
categories -> classes re-work is unchanged - feels pretty solid.
nouveau & LEVEL made some progress, still WIP.

I left out tracefs bits for now.

UNCERTAINTIES / RFC:

1st is my "sharing" technique, across DRM's multi modules. Its
literally duplicated decls, by each participating module, each adding
static data in its own special section. I didn't try at all to shrink
or unify this any further. There might be a perfect place to add a
single decl, but that quest will require a pony.

Sharing by class-names lacks the compiler support that varnames get;
"incomplete" enables will probably happen if one of the declarations
miss-spells one of the classnames.

That said, see the how-to below: stringifying va-args in the macro
would allow direct use of the enum-consts, and cc will insist that
those consts are defined, eliminating part of the un-support.

I could split the _BITS,_NUM handling out from _NAMES (ie split
drm.debug style patch); theres no user-demand for the _NAMES feature
ATM, and theres probably some legit API-bikeshedding to do.

PATCHSET DESCRIPTION

This patchset adds 'typed' "class FOO" support to dynamic-debug, where
'typed' means either DISJOINT_BITS, like drm_dbg(DRM_UT_CORE,..), or
LEVEL_NUM (like nouveau debug-levels). Use it in DRM modules: core,
helpers, and in drivers i915, amdgpu, nouveau.

If a module is using class'd prdbgs (pr_debug_class, dev_dbg_class, or
adapted drm_dbg_<category>) or similar in its code, it can "opt in" to
allow dyndbg to manipulate those class'd prdebugs, by declaring in a
c-file:

DECLARE_DYNDBG_CLASSMAP(drm_debug_classes,
DD_CLASS_TYPE_DISJOINT_BITS, 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");
// how-to stringify __va_args inside the macro ?

By doing this, a module tells dyndbg that it:

- is using class-ids [0..N] in prdbg callsites
( 0..N == DRM_UT_CORE..DRM_UT_DRMRES )
- wants to refer to them by class-names [0..N]
- is mapping those names to those class-ids
- expects users to enable them via >control or >parameter/knob

Then, a user can enable the prdbgs by their class:

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

And with another 3-line bitmap param decl/init, wrapping the
drm_debug_classes var in a module-param-cb:

:#> echo 0x1 > /sys/module/drm/parameters/debug

and optionally using classnames:

:#> echo +DRM_UT_CORE,-DRM_UT_KMS \
> /sys/module/drm/parameters/debug_cats

DYNAMIC_DEBUG gets:

struct _ddebug gets a new .class_id:5 field, big enough to represent
drm_debug_category (after squeezing). It defaults to 31 for all
existing prdbgs. class_id also supports verbose uses.

classmaps (as declared by macro above) are in their own linker
section, are loaded by kernel/module, and handled by add_module,
which attaches classmaps to their module's ddebug table.

ddebug_change() handles a class FOO query by validating that FOO is
known by each module in the loop. The query is skipped unless the
module knows FOO, so no changes are possible w/o a good classname.

Without class FOO in a query/command, only ids=31 can be changed by
that query. This protects all class'd prdbgs from changes by legacy
class-less user queries.

With this support, the module opt-in approach means that:

- modules declare classnames they like, meaningful names: DRM_UT_*
these are numbered [0..N]
- modules call pr_debug_class(N, "fmt..",...)
or drm_dbg(CAT, "fmt..",...) - same form.
- class-id space, while limited:0-30, is private to each module
- "class FOO" is only way to select a class'd prdbg
- unrelated modules use 0..N separately, for different purposes.
- modules "share" classnames by separate decls (uses of macro)
all drm modules reuse the above declaration.
then they respond together to a >control

4 CLASS_TYPES are defined; they split behavior on 2 factors:

1. independent bits vs related:(X<Y) bits [0-N]
2. input form: number/hex vs CSV-list: [+-]CLASS_NAMES

DD_CLASS_TYPE_DISJOINT_BITS independent bits, 0x1f input is clearest
DD_CLASS_TYPE_LEVEL_NUM (x<y), input is level, not bitvec

DD_CLASS_TYPE_DISJOINT_NAMES csv-list of independent +-CLASS_NAMEs
DD_CLASS_TYPE_LEVEL_NAMES csv-list of related +-CLASS_NAMEs, only 1 term needed

Splitting up behavior this way is safe, and flexible:

- no bitmap-vs-level > sysknob ambiguity
as was case when both were accepted on same knob
- narrower interfaces
uint is uint
- can defer DISJOINT_NAMES handling, but keep the enums.
it has no users ...
- can later add 2 more ENUMS allowing both inputs
in separate LEVEL_NUM & DISJOINT_BITS choices
then authors choice if they want to accept mixed input
- can enumerate "wierd" relations if needed
DISJOINT_BITS|LEVEL_NUM should cover everything I can forsee
but theres room for DD_CLASS_TYPE_STOCHASTIC (over the garage)

DISJOINT & LEVEL cover the space; 1st is independent, 2nd is related.
The relation could differ from (x<y), but atm I can't think of another
that makes any sensible distinction from (x<y).

Quick review of debug logging:

DRM is biggest use-case: 23 macros, issuing 10 exclusive categories of
messages, from ~5100 callsites, across core (drm, _*helpers), and 3+
drivers (Im working amdgpu, i915, more recently nouveau). These mostly
flow to drm_debug_enabled(category) for a print/no decision.

nouveau has minimum direct use of the DRM.debug macros, but does use
pr_debug (in VMM iirc), and drm_debug_enabled() in ~50 places via
macros, and another ~50 iirc due to NOUVEAU_DEBUG_MMU=y

What nouveau has most of is log-levels: there are ~800 uses of them;
nvkm_(fatal|error|warn|info|debug|trace|spam), they all flow thru
nvkm_printk_. Even excluding some levels as "always-on" and not
appropriate for dyndbg's extra resources and complexity, theres ~450
callsites.

A reported smattering of raw/adhoc debug code. all but unknown to me.

Like any debug logging, they're mostly off, and should have close to
0-off-cost. This is what dyndbg (with/on jump-label) was made for.

Bottom line: in order to unify more potential (drm,etc) use-cases,
dyndbg needs to support both debug classification schemes:
RELATED/LEVEL_NUM and INDEPENDENT/DISJOINT_BITS.

This is rev3. rev2 is here:
https://lore.kernel.org/lkml/[email protected]/

summary of diffs:

- rebased on 5.19-rc6 to pick up kernel/module changes
- tracfs bits now use __vstring, __vstr_assign, from S.Rostedt

- 4 class-map-types - as outlined above
now supports LEVEL_NUM semantics, WIP nouveau integration.
v2 became the DISJOINT_BITS use case
Lots of API-ish surface area here *RFC*

- class-maps now in section("__dyndbg_classes")
class FOO queries are available at earlyboot / module-load
drop (un)?register_classes()

- test-dynamic-debug module
tests the 4 CLASS-TYPES
good place to bikeshed / paintshop the API

- nouveau - start poking - WIP
NV_PRINT -> dev_dbg (creates 632 prdbgs, but not class'd)
LEVEL_NUM classes declared to see how they "fit", unused yet.

Summary:

- plenty of new stuff here.
- plenty of new API surface area.
- exposes CLASSNAMES to user, via control, >symbolic-sysknob

More on LEVEL_NUM:

dyndbg's class scheme is names-based, so even for LEVEL_NUM with
numeric input, there must be a "V0" name; a name with which to turn
off "V1". And don't do 'pr_dbg_class(0,..)'.

LEVEL_NUM is an overlay on DISJOINT_BITS; the callback reads the input as a
level, and computes and applies the bitmap to enforce it. Yes it
wastes "V0" bit. That might matter if an author wanted many separate
verbose-knobs with a few levels each, but that seems fairly unlikely.

More importantly, it means that relative verbosity is not enforced at
the >control input; IOW this is allowed:

:#> echo class V1 -p > /proc/dynamic_debug/control
:#> echo class V3 +p > /proc/dynamic_debug/control

2nd line doesn't undo 1st, as it would if changed via sysfs-knob:

:#> echo 3 > /sys/module/drm/parameters/debug

ISTM this is fine, the "relative" meaning is added at the interface,
where it presents to a user. Doing otherwise means surgery to
ddebug_change, which seems unnecessary given an option.

CLASS NAMESPACE and DRM

The class namespace is flat and wide, so "V1" is a poor choice, other
than for demonstration (as in test_dynamic_debug module). If every
module had a "V1", turning them all on would issue lots of unrelated
noise.

Instead, class DRM_UT_CORE has a name with a specific sub-system wide
(ie multi-module) meaning, and can (and should) be responded to by all
cooperating modules.

For DRM, this means 4-5 duplicate uses of DEFINE_DYNDBG_CLASSMAP, from
multiple drivers' "*_{drm,dev,main}.c" files; all of them agreeing on
the classnames, map-type and base. Though repetitive, and a bit
fiddly when multiple classes share the module's id-space, it is
simple, and consistent with the "static struct foo = {INIT_expr}"
pattern used in the macro. Im open to simpler ways, initializing an
extern sounded like a maze w/o cheese.

For core, drm_print.c has an additional task; it defines and
initializes the bitmap sysknob that converts bits to a query:

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);

then the callback converts bit-toggles on input into something like:

:#> echo class DRM_UT_KMS +p > control

which enables all drm_dbg_kms() callsites in all modules that declared
that classname as known.

NB: classmaps and classes_bitmap_params are different structs. this
allows the former to be shared by 2 of latter, each toggling 'p' & 'T'
flags, to control output to syslog or tracelog independently.

NBB: while "V1" isnt a good classname, "EMERG" and and other
KERN-LEVEL names have a legacy. That said, dyndbg shouldnt be
involved in EMERG actions.

NOUVEAU and multiple LEVEL_NUM knobs ?

One thing nouveau has that I havent yet grokked is 2|3 independent
verbose levels, in {,cli,sub}->debug (see subdev.h). But Ive coded
them as 2 more macro invocations; using bases 10, 15 to avoid/respect
the 0-9 mapping of DRM.debug categories to those class-ids.

With this, the drm subsystem uses 20/31 of its class-id range, perhaps
63 is better, despite the cumbersome 0x-64bit interface. Note that
the sysfs-knobs do not expose the base/offset (its an inward-facing
.class_id offset); each sysfs-knob gets its own 0..N bitmap, the base
maps it to the 0..30 subrange allocated (manually, via the base arg to
macro) for this class-map.

anyway, heres how `modprobe nouveau` goes with dynamic_debug.verbose=3

[86512.693954] dyndbg: class[0]: module:nouveau base:15 len:5 ty:1
[86512.693958] dyndbg: 15: 0 NV_SUBDEV_DBG_OFF # aka V0
[86512.693959] dyndbg: 16: 1 NV_SUBDEV_DBG_INFO
[86512.693960] dyndbg: 17: 2 NV_SUBDEV_DBG_DEBUG
[86512.693960] dyndbg: 18: 3 NV_SUBDEV_DBG_TRACE
[86512.693960] dyndbg: 19: 4 NV_SUBDEV_DBG_SPAM
[86512.693961] dyndbg: class[1]: module:nouveau base:10 len:5 ty:1
[86512.693961] dyndbg: 10: 0 NV_CLI_DBG_OFF
[86512.693962] dyndbg: 11: 1 NV_CLI_DBG_INFO
[86512.693962] dyndbg: 12: 2 NV_CLI_DBG_DEBUG
[86512.693963] dyndbg: 13: 3 NV_CLI_DBG_TRACE
[86512.693963] dyndbg: 14: 4 NV_CLI_DBG_SPAM
[86512.693963] dyndbg: class[2]: module:nouveau base:0 len:10 ty:0
[86512.693964] dyndbg: 0: 0 DRM_UT_CORE
[86512.693964] dyndbg: 1: 1 DRM_UT_DRIVER
[86512.693965] dyndbg: 2: 2 DRM_UT_KMS
[86512.693965] dyndbg: 3: 3 DRM_UT_PRIME
[86512.693965] dyndbg: 4: 4 DRM_UT_ATOMIC
[86512.693966] dyndbg: 5: 5 DRM_UT_VBL
[86512.693966] dyndbg: 6: 6 DRM_UT_STATE
[86512.693966] dyndbg: 7: 7 DRM_UT_LEASE
[86512.693967] dyndbg: 8: 8 DRM_UT_DP
[86512.693967] dyndbg: 9: 9 DRM_UT_DRMRES
[86512.693968] dyndbg: module:nouveau attached 3 classes
[86512.693968] dyndbg: 632 debug prints in module nouveau

They are not yet wired by class; the nv-printks are using dev_dbg for
now, so they can be enabled with standard selections (module, func,
etc).

DYNDBG API

I added __pr_debug_cls to make things testable, I wanted to keep it
private/un-api, because drm already has drm_dbg_<cat>(cat, fmt..), and
that seemed a pretty good model to follow: enums with strong names for
class_id constants, and same names for classes.

ie: __pr_debug_cls(DRM_UT_KMS, "Whats the Matter with KMS: %s\n", reason);

But now nouveau probably wants/needs it, perhaps others too.

pr_dbg_cls / dev_dbg_cls ? class or debug spelled out ?

MORE TESTING with DRM & TRACEFS

Most dev & testing has been on virtme, with test-dynamic-debug module
doing an api-validation-demonstration. The test module proves
multiple sysknobs, but cannot prove real multi-module sharing of the
class-name space. The DRM.debug adaptation must (and does) do that.

Now Im running on real gpu/drm hw; on both an amdgpu desktop, and this
amdgpu+nouveau laptop. Its stable enough to type on, browse, build
more kernels, etc.

:#> uname -r
5.18.0-f2-00038-g61d300083196
:#> wc /proc/dynamic_debug/control
11554 95556 1442827 /proc/dynamic_debug/control
:#> lsmod | grep drm
drm_buddy 20480 1 i915
drm_ttm_helper 16384 2 amdgpu,nouveau
ttm 86016 4 amdgpu,drm_ttm_helper,i915,nouveau
drm_dp_helper 184320 3 amdgpu,i915,nouveau
drm_kms_helper 208896 6 drm_dp_helper,amdgpu,i915,nouveau
drm 655360 16 gpu_sched,drm_dp_helper,drm_kms_helper,drm_buddy,amdgpu,drm_ttm_helper,i915,ttm,nouveau
cec 49152 2 drm_dp_helper,i915

I've never turned on DRM.debug in frustration (or curiousity until
recently); I dunno what normal traffic looks like. So I wrote a
script to toggle each category: on/off for 1 sec, so I could 'more'
thru the output to see the partitioned streams.

Different runs (of '10' sec of active tracing) produce between 330-3500
lines of logging, depending upon mousing/screen activity. Heres a bit
of a many-window-select run: `wc trace` gives "size" of the category's stream.

:#> trc_classes
12 /sys/kernel/tracing/trace
doing class DRM_UT_CORE +/- T 1394 13941 141614 /sys/kernel/tracing/trace
doing class DRM_UT_DRIVER +/- T 1396 13959 141816 /sys/kernel/tracing/trace
doing class DRM_UT_KMS +/- T 1482 14521 148246 /sys/kernel/tracing/trace
doing class DRM_UT_PRIME +/- T 1484 14539 148446 /sys/kernel/tracing/trace
doing class DRM_UT_ATOMIC +/- T 2984 31658 396064 /sys/kernel/tracing/trace
doing class DRM_UT_VBL +/- T 3411 37321 449848 /sys/kernel/tracing/trace
doing class DRM_UT_STATE +/- T 3413 37339 450048 /sys/kernel/tracing/trace
doing class DRM_UT_LEASE +/- T 3415 37357 450248 /sys/kernel/tracing/trace
doing class DRM_UT_DP +/- T 3417 37375 450442 /sys/kernel/tracing/trace
doing class DRM_UT_DRMRES +/- T 3419 37393 450644 /sys/kernel/tracing/trace

and some mid-run output from a quiet run, with less repetition.

bash-96790 [006] ..... 410237.432255: tracing_mark_write: doing class DRM_UT_DRIVER +T
bash-96790 [006] ..... 410238.610319: tracing_mark_write: doing class DRM_UT_DRIVER -T
bash-96790 [006] ..... 410239.776285: tracing_mark_write: doing class DRM_UT_KMS +T
gnome-shell-2101 [003] ..... 410239.923029: drm_debug: [FB:98]
kworker/u32:10-367584 [010] ..... 410239.924627: drm_debug: Allow idle optimizations (MALL): 0
kworker/u32:0-364714 [008] ..... 410239.935126: drm_debug: Allow idle optimizations (MALL): 1
gnome-shell-2101 [003] ..... 410240.527186: drm_debug: [FB:100]
kworker/u32:0-364714 [008] ..... 410240.528686: drm_debug: Allow idle optimizations (MALL): 0
kworker/u32:10-367584 [010] ..... 410240.539378: drm_debug: Allow idle optimizations (MALL): 1
bash-96790 [006] ..... 410240.957921: tracing_mark_write: doing class DRM_UT_KMS -T
bash-96790 [006] ..... 410242.199120: tracing_mark_write: doing class DRM_UT_PRIME +T
bash-96790 [006] ..... 410243.301988: tracing_mark_write: doing class DRM_UT_PRIME -T
bash-96790 [006] ..... 410244.416400: tracing_mark_write: doing class DRM_UT_ATOMIC +T
gnome-shell-2101 [003] ..... 410244.653372: drm_devdbg: cat:4, (0xffff8f26c173de00:0000:06:00.0)[UNSAFE-MEMORY] Allocated atomic state 000000001f1e6cb6
gnome-shell-2101 [003] ..... 410244.653381: drm_devdbg: cat:4, (0xffff8f26c173de00:0000:06:00.0)[UNSAFE-MEMORY] Added [PLANE:55:plane-3] 00000000785ae904 state to 000000001f1e6cb6
gnome-shell-2101 [003] ..... 410244.653384: drm_devdbg: cat:4, (0xffff8f26c173de00:0000:06:00.0)[UNSAFE-MEMORY] Added [CRTC:67:crtc-0] 00000000b06ca618 state to 000000001f1e6cb6
gnome-shell-2101 [003] ..... 410244.653389: drm_devdbg: cat:4, (0xffff8f26c173de00:0000:06:00.0)[UNSAFE-MEMORY] Set [FB:98] for [PLANE:55:plane-3] state 00000000785ae904
gnome-shell-2101 [003] ..... 410244.653392: drm_devdbg: cat:4, (0xffff8f26c173de00:0000:06:00.0)[UNSAFE-MEMORY] checking 000000001f1e6cb6
gnome-shell-2101 [003] ..... 410244.653407: drm_devdbg: cat:4, (0xffff8f26c173de00:0000:06:00.0)[UNSAFE-MEMORY] committing 000000001f1e6cb6 nonblocking
kworker/u32:0-364714 [010] ..... 410244.653729: drm_debug: amdgpu_crtc id:0 crtc_state_flags: enable:1, active:1, planes_changed:1, mode_changed:0,active_changed:0,connectors_changed:0
kworker/u32:0-364714 [010] ..... 410244.654642: drm_debug: plane: id=3 dcc_en=0

a few things to note in the trace output:

. the event-name: drm_(debug|devdbg) is not very informative

. drm_devdbg fmt has cat:%d, it could be the classname, but that should
replace event-name, not supplement it. this pertains to drm_debug too.

. drm_devdbg has lots of (dev-info), that could be optional on a new flag(s)


If anyone wants to repeat the above with the patchset, the .rc file follows:

events_3() {
local a=$1
local b=$2
local c=$3
echo $a > /sys/kernel/tracing/events/dyndbg/enable
# avoid drm_vblank*, its noisy
echo $b > /sys/kernel/tracing/events/drm/drm_debug/enable
echo $c > /sys/kernel/tracing/events/drm/drm_devdbg/enable
}

flags_class() {
local flgs=$1;
local cls=$2;
echo class $cls $flgs > /proc/dynamic_debug/control
}

# turn on each DRM_UT_* for 1 second each.
# kinda shows relative traffic of each category
# separated into blocks to get flavor of each

drm_classes() {
local flgs=$1
[ -z $flgs ] && flgs="p"

#echo > /sys/kernel/tracing/trace
#wc /sys/kernel/tracing/trace

for cls in 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;
do
echo -n doing class $cls " "

echo doing class $cls +$flgs
sleep .1
flags_class +$flgs $cls
sleep 1

echo doing class $cls -$flgs
sleep .1
flags_class -$flgs $cls
sleep 1

#wc /sys/kernel/tracing/trace
done
}

# like above but with T flag, and markers, trace/enable
trc_classes() {
local flgs=$1
[ -z $flgs ] && flgs="T"

echo > /sys/kernel/tracing/trace
wc -l /sys/kernel/tracing/trace

events_3 1 1 1
for cls in 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;
do
echo -n doing class $cls +/- $flgs " "

echo doing class $cls +$flgs > /sys/kernel/tracing/trace_marker
sleep .1
flags_class +$flgs $cls
sleep 1

echo doing class $cls -$flgs > /sys/kernel/tracing/trace_marker
sleep .1
flags_class -$flgs $cls
sleep 1

wc /sys/kernel/tracing/trace

done
events_3 0 0 0
}


Jim Cromie (33):

1st, a group of "cleanups"

dyndbg: fix static_branch manipulation
dyndbg: fix module.dyndbg handling
dyndbg: show both old and new in change-info
dyndbg: reverse module walk in cat control
dyndbg: reverse module.callsite walk in cat control
dyndbg: use ESCAPE_SPACE for cat control
dyndbg: let query-modname override actual module name
dyndbg: add test_dynamic_debug module
dyndbg: drop EXPORTed dynamic_debug_exec_queries
dyndbg: cleanup local vars in ddebug_init
dyndbg: create and use struct _ddebug_info

class FOO support

dyndbg: add class_id to pr_debug callsites
dyndbg: add __pr_debug_cls for testing
dyndbg: add DECLARE_DYNDBG_CLASSMAP macro
kernel/module: add __dyndbg_classes section
dyndbg: add ddebug_attach_module_classes
dyndbg: validate class FOO by checking with module
doc-dyndbg: describe "class CLASS_NAME" query support
doc-dyndbg: edit dynamic-debug-howto for brevity, audience

add dyndbg-class-param support

dyndbg: add drm.debug style (drm/parameters/debug) bitmap support
dyndbg: test DECLARE_DYNDBG_CLASSMAP, sysfs nodes

drm.debug adaptation

drm_print: condense enum drm_debug_category
drm: POC drm on dyndbg - use in core, 2 helpers, 3 drivers.
drm_print: interpose drm_*dbg with forwarding macros
drm_print: wrap drm_*_dbg in dyndbg descriptor factory macro
drm-print.h: include dyndbg header
drm-print: add drm_dbg_driver to improve namespace symmetry
drm_print: refine drm_debug_enabled for jump-label
drm_print: prefer bare printk KERN_DEBUG on generic fn
drm_print: add _ddebug descriptor to drm_*dbg prototypes

nouveau-LEVEL_NUM integration: WIP/exploratory.

nouveau: change nvkm_debug/trace to use dev_dbg POC
nouveau: adapt NV_DEBUG, NV_ATOMIC to use DRM.debug
nouveau: WIP add 2 LEVEL_NUM classmaps for CLI, SUBDEV

.../admin-guide/dynamic-debug-howto.rst | 246 +++++-----
MAINTAINERS | 2 +
drivers/gpu/drm/Kconfig | 12 +
drivers/gpu/drm/Makefile | 2 +
drivers/gpu/drm/amd/amdgpu/amdgpu_drv.c | 14 +
drivers/gpu/drm/display/drm_dp_helper.c | 13 +
drivers/gpu/drm/drm_crtc_helper.c | 13 +
drivers/gpu/drm/drm_print.c | 48 +-
drivers/gpu/drm/i915/i915_params.c | 12 +
.../gpu/drm/nouveau/include/nvkm/core/debug.h | 16 +
.../drm/nouveau/include/nvkm/core/subdev.h | 17 +-
drivers/gpu/drm/nouveau/nouveau_drm.c | 20 +
drivers/gpu/drm/nouveau/nouveau_drv.h | 16 +-
drivers/gpu/drm/nouveau/nvkm/core/subdev.c | 23 +
include/asm-generic/vmlinux.lds.h | 3 +
include/drm/drm_print.h | 85 +++-
include/linux/dynamic_debug.h | 176 +++++--
kernel/module/internal.h | 4 +-
kernel/module/main.c | 20 +-
lib/Kconfig.debug | 10 +
lib/Makefile | 1 +
lib/dynamic_debug.c | 450 +++++++++++++++---
lib/test_dynamic_debug.c | 165 +++++++
23 files changed, 1099 insertions(+), 269 deletions(-)
create mode 100644 lib/test_dynamic_debug.c

--
2.37.1


2022-08-05 22:27:48

by Jim Cromie

[permalink] [raw]
Subject: [PATCH v5 15/33] kernel/module: add __dyndbg_classes section

Add __dyndbg_classes section, using __dyndbg as a model. Use it:

vmlinux.lds.h:

KEEP the new section, which also silences orphan section warning on
loadable modules. Add (__start_/__stop_)__dyndbg_classes linker
symbols for the c externs (below).

kernel/module/main.c:
- fill new fields in find_module_sections(), using section_objs()
- extend callchain prototypes
to pass classes, length
load_module(): pass new info to dynamic_debug_setup()
dynamic_debug_setup(): new params, pass through to ddebug_add_module()

dynamic_debug.c:
- add externs to the linker symbols.

ddebug_add_module():
- It currently builds a debug_table, and *will* find and attach classes.

dynamic_debug_init():
- add class fields to the _ddebug_info cursor var: di.

Signed-off-by: Jim Cromie <[email protected]>
---
include/asm-generic/vmlinux.lds.h | 3 +++
include/linux/dynamic_debug.h | 2 ++
kernel/module/main.c | 2 ++
lib/dynamic_debug.c | 7 +++++++
4 files changed, 14 insertions(+)

diff --git a/include/asm-generic/vmlinux.lds.h b/include/asm-generic/vmlinux.lds.h
index 7515a465ec03..9b8bd5504ad9 100644
--- a/include/asm-generic/vmlinux.lds.h
+++ b/include/asm-generic/vmlinux.lds.h
@@ -345,6 +345,9 @@
*(__tracepoints) \
/* implement dynamic printk debug */ \
. = ALIGN(8); \
+ __start___dyndbg_classes = .; \
+ KEEP(*(__dyndbg_classes)) \
+ __stop___dyndbg_classes = .; \
__start___dyndbg = .; \
KEEP(*(__dyndbg)) \
__stop___dyndbg = .; \
diff --git a/include/linux/dynamic_debug.h b/include/linux/dynamic_debug.h
index 71cdc8612257..46ed10682e87 100644
--- a/include/linux/dynamic_debug.h
+++ b/include/linux/dynamic_debug.h
@@ -115,7 +115,9 @@ struct ddebug_class_map {
/* encapsulate linker provided built-in (or module) dyndbg data */
struct _ddebug_info {
struct _ddebug *descs;
+ struct ddebug_class_map *classes;
unsigned int num_descs;
+ unsigned int num_classes;
};

#if defined(CONFIG_DYNAMIC_DEBUG_CORE)
diff --git a/kernel/module/main.c b/kernel/module/main.c
index cfe10356793d..f68f331c867d 100644
--- a/kernel/module/main.c
+++ b/kernel/module/main.c
@@ -2095,6 +2095,8 @@ static int find_module_sections(struct module *mod, struct load_info *info)

info->dyndbg.descs = section_objs(info, "__dyndbg",
sizeof(*info->dyndbg.descs), &info->dyndbg.num_descs);
+ info->dyndbg.classes = section_objs(info, "__dyndbg_classes",
+ sizeof(*info->dyndbg.classes), &info->dyndbg.num_classes);

return 0;
}
diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
index 457ce936191a..0d6cb6b258bd 100644
--- a/lib/dynamic_debug.c
+++ b/lib/dynamic_debug.c
@@ -41,6 +41,8 @@

extern struct _ddebug __start___dyndbg[];
extern struct _ddebug __stop___dyndbg[];
+extern struct ddebug_class_map __start___dyndbg_classes[];
+extern struct ddebug_class_map __stop___dyndbg_classes[];

struct ddebug_table {
struct list_head link;
@@ -1079,7 +1081,9 @@ static int __init dynamic_debug_init(void)

struct _ddebug_info di = {
.descs = __start___dyndbg,
+ .classes = __start___dyndbg_classes,
.num_descs = __stop___dyndbg - __start___dyndbg,
+ .num_classes = __stop___dyndbg_classes - __start___dyndbg_classes,
};

if (&__start___dyndbg == &__stop___dyndbg) {
@@ -1122,6 +1126,9 @@ static int __init dynamic_debug_init(void)
i, mod_ct, (int)((mod_ct * sizeof(struct ddebug_table)) >> 10),
(int)((i * sizeof(struct _ddebug)) >> 10));

+ if (di.num_classes)
+ v2pr_info(" %d builtin ddebug class-maps\n", di.num_classes);
+
/* now that ddebug tables are loaded, process all boot args
* again to find and activate queries given in dyndbg params.
* While this has already been done for known boot params, it
--
2.37.1

2022-08-05 22:41:32

by Jim Cromie

[permalink] [raw]
Subject: [PATCH v5 28/33] 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. 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, 3 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 29a29949ad0b..cb203d63b286 100644
--- a/drivers/gpu/drm/drm_print.c
+++ b/drivers/gpu/drm/drm_print.c
@@ -285,7 +285,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);
@@ -308,7 +308,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 dfdd81c3287c..7631b5fb669e 100644
--- a/include/drm/drm_print.h
+++ b/include/drm/drm_print.h
@@ -321,11 +321,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.37.1

2022-08-05 22:43:37

by Jim Cromie

[permalink] [raw]
Subject: [PATCH v5 27/33] drm-print: add drm_dbg_driver to improve namespace symmetry

drm_print defines all of these:
drm_dbg_{core,kms,prime,atomic,vbl,lease,_dp,_drmres}

but not drm_dbg_driver itself, since it was the original drm_dbg.

To improve namespace symmetry, change the drm_dbg defn to
drm_dbg_driver, and redef grandfathered name to symmetric one.

This will help with nouveau, which uses its own stack of macros to
construct calls to dev_info, dev_dbg, etc, for which adaptation means
drm_dbg_##driver constructs.

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

diff --git a/include/drm/drm_print.h b/include/drm/drm_print.h
index f8bb3e7158c6..dfdd81c3287c 100644
--- a/include/drm/drm_print.h
+++ b/include/drm/drm_print.h
@@ -468,7 +468,7 @@ void __drm_dev_dbg(const struct device *dev, enum drm_debug_category category,

#define drm_dbg_core(drm, fmt, ...) \
drm_dev_dbg((drm) ? (drm)->dev : NULL, DRM_UT_CORE, fmt, ##__VA_ARGS__)
-#define drm_dbg(drm, fmt, ...) \
+#define drm_dbg_driver(drm, fmt, ...) \
drm_dev_dbg((drm) ? (drm)->dev : NULL, DRM_UT_DRIVER, fmt, ##__VA_ARGS__)
#define drm_dbg_kms(drm, fmt, ...) \
drm_dev_dbg((drm) ? (drm)->dev : NULL, DRM_UT_KMS, fmt, ##__VA_ARGS__)
@@ -487,6 +487,7 @@ void __drm_dev_dbg(const struct device *dev, enum drm_debug_category category,
#define drm_dbg_drmres(drm, fmt, ...) \
drm_dev_dbg((drm) ? (drm)->dev : NULL, DRM_UT_DRMRES, fmt, ##__VA_ARGS__)

+#define drm_dbg(drm, fmt, ...) drm_dbg_driver(drm, fmt, ##__VA_ARGS__)

/*
* printk based logging
--
2.37.1

2022-08-05 22:47:48

by Jim Cromie

[permalink] [raw]
Subject: [PATCH v5 20/33] dyndbg: add drm.debug style (drm/parameters/debug) bitmap support

Add kernel_param_ops and callbacks to use a class-map to validate and
apply input to a sysfs-node, which allows users to control classes
defined in that class-map. This supports uses like:

echo 0x3 > /sys/module/drm/parameters/debug

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. This might be unnecessary here.

get/set use an augmented kernel_param; the arg refs a new struct
ddebug_class_param, which contains:

A union of &ulong bits, level; which points to user module's ulong
storing the module's debug-state. By ref'g the client's bit-state
_var, code coordinates with existing code (like drm_debug_enabled)
which uses it, so existing works unchanged. Changing to a ulong
allows use of BIT() etc.

FLAGS: dyndbg.flags toggled by changes to bitmap. Usually just "p".

MAP: a pointer to struct ddebug_classes_map, which maps those
class-names to .class_ids 0..N that the module is using. This
class-map is declared & initialized by DECLARE_DYNDBG_CLASSMAP.

map-type: 4 enums DD_CLASS_TYPE_* select 2 input forms and 2 meanings.

numeric input:
DD_CLASS_TYPE_DISJOINT_BITS integer input, independent bits. ie: drm.debug
DD_CLASS_TYPE_LEVEL_NUM integer input, 0..N levels

classnames-list (comma separated) input:
DD_CLASS_TYPE_DISJOINT_NAMES each name affects a bit, others preserved
DD_CLASS_TYPE_LEVEL_NAMES names have level meanings, like kern_levels.h

_NAMES - comma-separated classnames (with optional +-)
_NUM - numeric input, 0-N expected
_BITS - numeric input, 0x1F bitmap form expected

_DISJOINT - bits are independent
_LEVEL - (x<y) on bit-pos.

_DISJOINT treats input like a bit-vector (ala drm.debug), and sets
each bit accordingly. LEVEL is layered on top of this.

_LEVEL treats input like a bit-pos:N, then sets bits(0..N)=1, and
bits(N+1..max)=0. This applies (bit<N) semantics on top of disjoint
bits.

USAGES:

A potentially typical _DISJOINT_NAMES use:

echo +DRM_UT_CORE,+DRM_UT_KMS,-DRM_UT_DRIVER,-DRM_UT_ATOMIC \
> /sys/module/drm/parameters/debug_catnames

A standard _LEVEL_NAMES use, with one class, that sets all in the
class-map according to (x<y):

: problem seen
echo +L7 > /sys/module/test_dynamic_debug/parameters/p_level_names
: problem solved
echo -L1 > /sys/module/test_dynamic_debug/parameters/p_level_names

Note this artifact:

: this is same as prev cmd (due to +/-)
echo L0 > /sys/module/test_dynamic_debug/parameters/p_level_names

: this is "even-more" off, but same wo __pr_debug_class(L0, "..").
echo -L0 > /sys/module/test_dynamic_debug/parameters/p_level_names

A stress-test/make-work usage (kid toggling a light switch):

echo +L7,L0,L7,L0,L7,L0,L7,L0,L7,L0,L7,L0,L7 \
> /sys/module/test_dynamic_debug/parameters/p_level_names

ddebug_apply_class_bitmap(): inside-fn, works on bitmaps, receives
new-bits, finds diffs vs client-bitvector holding "current" state,
and issues exec_query to commit the adjustment.

param_set_dyndbg_classes(): interface fn, sends _NAMES to
param_set_dyndbg_classnames() and returns, falls thru to handle _BITS,
_NUM internally, and calls ddebug_apply_class_bitmap(). Finishes by
updating state.

param_set_dyndbg_classnames(): handles classnames-list in loop, calls
ddebug_apply_class_bitmap for each, then updates state.

NOTES:

_LEVEL_ is overlay on _DISJOINT_; inputs are converted to a bitmask,
and is done by callbacks. IOW this is possible, and possibly confusing:

echo class V3 +p > control
echo class V1 -p > control

IMO thats ok, relative verbosity is an interface property.

_LEVEL_NUM maps still need class-names, even though the names are not
usable at the sysfs interface (unlike with _NAMES style). The names
are the only way to >control the classes.

- It must have a "V0" name,
something below "V1" to turn "V1" off.
__pr_debug_cls(V0,..) is printk, don't do that.

- "class names" is required at the >control interface.
- relative levels are not enforced at >control

_LEVEL_NAMES bear +/- signs, which alters the on-bit-pos by 1. IOW,
+L2 means L0,L1,L2, and -L2 means just L0,L1. This kinda spoils the
readback fidelity, since the L0 bit gets turned on by any use of any
L*, except "-L0".

All the interface uncertainty here pertains to the _NAMES features.
Nobody has actually asked for this, so its practical (if a little
tedious) to split it out.

Signed-off-by: Jim Cromie <[email protected]>
---
. drop kp->mod->name as unneeded (build-dependent) <lkp>
. param_set_dyndbg_classnames, not _class_strings
. DD_CLASS_TYPE_* name changes, per Jason
. callbacks:
extend comments on DD_CLASS_TYPE_* handling, flow notes
varname changes
. kdoc tweaks
. add stub macro: #define KP_NAME(kp) kp->name
later, add "$module." prefix when config doesn't do it
. s/struct ddebug_classes_bitmap_param/struct ddebug_class_param/
. fix levels state handling

v4 had trouble where level-type's state was fouled by conversion to
bitmap form given to apply-bitmap. fix by:

(simplify/clarify)
add old-bits, new-bits to sysfs-iface&support
use CLASSMAP_BITMASK more
in param_set_dyndbg_class{es,names}():
move state-saving inside switches, and tailor it to type.
this preserves lvl-state, vs -v4 which didnt.

I could "hack" in an offset, but the problem feels deeper.

The root-problem may be the ambiguity wrt 0x0 > knob; per a
input-is-assert-bitpos interpretation, it turns on bit 0.

Thus far, code has avoided this ambiguity, by recommending against
coding pr_dbg_cls(V0|L0, ""), which makes "+L0" & "-L0" equivalent,
and "0" silent.

That might be "too clever by 1/2"; accepting an int, so -1 means
all-bits-off as well as verbosity-off, might be the better way.
---
include/linux/dynamic_debug.h | 20 ++++
lib/dynamic_debug.c | 218 +++++++++++++++++++++++++++++++++-
2 files changed, 234 insertions(+), 4 deletions(-)

diff --git a/include/linux/dynamic_debug.h b/include/linux/dynamic_debug.h
index 46ed10682e87..956614a208a4 100644
--- a/include/linux/dynamic_debug.h
+++ b/include/linux/dynamic_debug.h
@@ -120,6 +120,14 @@ struct _ddebug_info {
unsigned int num_classes;
};

+struct ddebug_class_param {
+ union { unsigned long *bits;
+ unsigned long *lvl;
+ };
+ char flags[8];
+ const struct ddebug_class_map *map;
+};
+
#if defined(CONFIG_DYNAMIC_DEBUG_CORE)

int ddebug_add_module(struct _ddebug_info *dyndbg, const char *modname);
@@ -279,6 +287,10 @@ void __dynamic_ibdev_dbg(struct _ddebug *descriptor,
KERN_DEBUG, prefix_str, prefix_type, \
rowsize, groupsize, buf, len, ascii)

+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);
+
/* for test only, generally expect drm.debug style macro wrappers */
#define __pr_debug_cls(cls, fmt, ...) do { \
BUILD_BUG_ON_MSG(!__builtin_constant_p(cls), \
@@ -325,6 +337,14 @@ static inline int ddebug_dyndbg_module_param_cb(char *param, char *val,
rowsize, groupsize, buf, len, ascii); \
} while (0)

+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 eb410b412f0d..c41e22d850e0 100644
--- a/lib/dynamic_debug.c
+++ b/lib/dynamic_debug.c
@@ -596,6 +596,218 @@ static int ddebug_exec_queries(char *query, const char *modname)
return nfound;
}

+/* apply a new bitmap to the sys-knob's current bit-state */
+static int ddebug_apply_class_bitmap(const struct ddebug_class_param *dcp,
+ unsigned long *new_bits, unsigned long *old_bits)
+{
+#define QUERY_SIZE 128
+ char query[QUERY_SIZE];
+ const struct ddebug_class_map *map = dcp->map;
+ int matches = 0;
+ int bi, ct;
+
+ v2pr_info("apply: 0x%lx to: 0x%lx\n", *new_bits, *old_bits);
+
+ for (bi = 0; bi < map->length; bi++) {
+ if (test_bit(bi, new_bits) == test_bit(bi, old_bits))
+ continue;
+
+ snprintf(query, QUERY_SIZE, "class %s %c%s", map->class_names[bi],
+ test_bit(bi, new_bits) ? '+' : '-', dcp->flags);
+
+ ct = ddebug_exec_queries(query, NULL);
+ matches += ct;
+
+ v2pr_info("bit_%d: %d matches on class: %s -> 0x%lx\n", bi,
+ ct, map->class_names[bi], *new_bits);
+ }
+ return matches;
+}
+
+/* stub to later conditionally add "$module." prefix where not already done */
+#define KP_NAME(kp) kp->name
+
+#define CLASSMAP_BITMASK(width) ((1UL << (width)) - 1)
+
+/* accept comma-separated-list of [+-] classnames */
+static int param_set_dyndbg_classnames(const char *instr, const struct kernel_param *kp)
+{
+ const struct ddebug_class_param *dcp = kp->arg;
+ const struct ddebug_class_map *map = dcp->map;
+ unsigned long curr_bits, old_bits;
+ char *cl_str, *p, *tmp;
+ int cls_id, totct = 0;
+ bool wanted;
+
+ cl_str = tmp = kstrdup(instr, GFP_KERNEL);
+ p = strchr(cl_str, '\n');
+ if (p)
+ *p = '\0';
+
+ /* start with previously set state-bits, then modify */
+ curr_bits = old_bits = *dcp->bits;
+ vpr_info("\"%s\" > %s:0x%lx\n", cl_str, KP_NAME(kp), curr_bits);
+
+ for (; cl_str; cl_str = p) {
+ p = strchr(cl_str, ',');
+ if (p)
+ *p++ = '\0';
+
+ if (*cl_str == '-') {
+ wanted = false;
+ cl_str++;
+ } else {
+ wanted = true;
+ if (*cl_str == '+')
+ cl_str++;
+ }
+ cls_id = match_string(map->class_names, map->length, cl_str);
+ if (cls_id < 0) {
+ pr_err("%s unknown to %s\n", cl_str, KP_NAME(kp));
+ continue;
+ }
+
+ /* have one or more valid class_ids of one *_NAMES type */
+ switch (map->map_type) {
+ case DD_CLASS_TYPE_DISJOINT_NAMES:
+ /* the +/- pertains to a single bit */
+ if (test_bit(cls_id, &curr_bits) == wanted) {
+ v3pr_info("no change on %s\n", cl_str);
+ continue;
+ }
+ curr_bits ^= BIT(cls_id);
+ totct += ddebug_apply_class_bitmap(dcp, &curr_bits, dcp->bits);
+ *dcp->bits = curr_bits;
+ v2pr_info("%s: changed bit %d:%s\n", KP_NAME(kp), cls_id,
+ map->class_names[cls_id]);
+ break;
+ case DD_CLASS_TYPE_LEVEL_NAMES:
+ /* cls_id = N in 0..max. wanted +/- determines N or N-1 */
+ old_bits = CLASSMAP_BITMASK(*dcp->lvl);
+ curr_bits = CLASSMAP_BITMASK(cls_id + (wanted ? 1 : 0 ));
+
+ totct += ddebug_apply_class_bitmap(dcp, &curr_bits, &old_bits);
+ *dcp->lvl = (cls_id + (wanted ? 1 : 0));
+ v2pr_info("%s: changed bit-%d: \"%s\" %lx->%lx\n", KP_NAME(kp), cls_id,
+ map->class_names[cls_id], old_bits, curr_bits);
+ break;
+ default:
+ pr_err("illegal map-type value %d\n", map->map_type);
+ }
+ }
+ kfree(tmp);
+ vpr_info("total matches: %d\n", totct);
+ return 0;
+}
+
+/**
+ * param_set_dyndbg_classes - class FOO >control
+ * @instr: string echo>d to sysfs, input depends on map_type
+ * @kp: kp->arg has state: bits/lvl, map, map_type
+ *
+ * Enable/disable prdbgs by their class, as given in the arguments to
+ * DECLARE_DYNDBG_CLASSMAP. For LEVEL map-types, enforce relative
+ * levels by bitpos.
+ *
+ * Returns: 0 or <0 if error.
+ */
+int param_set_dyndbg_classes(const char *instr, const struct kernel_param *kp)
+{
+ const struct ddebug_class_param *dcp = kp->arg;
+ const struct ddebug_class_map *map = dcp->map;
+ unsigned long inrep, new_bits, old_bits;
+ int rc, totct = 0;
+
+ switch (map->map_type) {
+
+ case DD_CLASS_TYPE_DISJOINT_NAMES:
+ case DD_CLASS_TYPE_LEVEL_NAMES:
+ /* handle [+-]classnames list separately, we are done here */
+ return param_set_dyndbg_classnames(instr, kp);
+
+ case DD_CLASS_TYPE_DISJOINT_BITS:
+ case DD_CLASS_TYPE_LEVEL_NUM:
+ /* numeric input, accept and fall-thru */
+ rc = kstrtoul(instr, 0, &inrep);
+ if (rc) {
+ pr_err("expecting numeric input: %s > %s\n", instr, KP_NAME(kp));
+ return -EINVAL;
+ }
+ break;
+ default:
+ pr_err("%s: bad map type: %d\n", KP_NAME(kp), map->map_type);
+ return -EINVAL;
+ }
+
+ /* only _BITS,_NUM (numeric) map-types get here */
+ switch (map->map_type) {
+ case DD_CLASS_TYPE_DISJOINT_BITS:
+ /* expect bits. mask and warn if too many */
+ if (inrep & ~CLASSMAP_BITMASK(map->length)) {
+ pr_warn("%s: input: 0x%lx exceeds mask: 0x%lx, masking\n",
+ KP_NAME(kp), inrep, CLASSMAP_BITMASK(map->length));
+ inrep &= CLASSMAP_BITMASK(map->length);
+ }
+ v2pr_info("bits:%lx > %s\n", inrep, KP_NAME(kp));
+ totct += ddebug_apply_class_bitmap(dcp, &inrep, dcp->bits);
+ *dcp->bits = inrep;
+ break;
+ case DD_CLASS_TYPE_LEVEL_NUM:
+ /* input is bitpos, of highest verbosity to be enabled */
+ if (inrep > map->length) {
+ pr_warn("%s: level:%ld exceeds max:%d, clamping\n",
+ KP_NAME(kp), inrep, map->length);
+ inrep = map->length;
+ }
+ old_bits = CLASSMAP_BITMASK(*dcp->lvl);
+ new_bits = CLASSMAP_BITMASK(inrep);
+ v2pr_info("lvl:%ld bits:0x%lx > %s\n", inrep, new_bits, KP_NAME(kp));
+ totct += ddebug_apply_class_bitmap(dcp, &new_bits, &old_bits);
+ *dcp->lvl = inrep;
+ break;
+ default:
+ pr_warn("%s: bad map type: %d\n", KP_NAME(kp), map->map_type);
+ }
+ vpr_info("%s: total matches: %d\n", KP_NAME(kp), 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 state, underlying prdbg state may have been
+ * altered by direct >control. Displays 0x for DISJOINT, 0-N for
+ * LEVEL Returns: #chars written or <0 on error
+ */
+int param_get_dyndbg_classes(char *buffer, const struct kernel_param *kp)
+{
+ const struct ddebug_class_param *dcp = kp->arg;
+ const struct ddebug_class_map *map = dcp->map;
+
+ switch (map->map_type) {
+
+ case DD_CLASS_TYPE_DISJOINT_NAMES:
+ case DD_CLASS_TYPE_DISJOINT_BITS:
+ return scnprintf(buffer, PAGE_SIZE, "0x%lx\n", *dcp->bits);
+
+ case DD_CLASS_TYPE_LEVEL_NAMES:
+ case DD_CLASS_TYPE_LEVEL_NUM:
+ return scnprintf(buffer, PAGE_SIZE, "%ld\n", *dcp->lvl);
+ default:
+ return -1;
+ }
+}
+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)
@@ -1037,13 +1249,11 @@ static int __ddebug_add_module(struct _ddebug_info *di, unsigned int base,
dt->ddebugs = di->descs;
dt->num_ddebugs = di->num_descs;

- INIT_LIST_HEAD(&dt->link);
-
INIT_LIST_HEAD(&dt->link);
INIT_LIST_HEAD(&dt->maps);

- if (classes && num_classes)
- ddebug_attach_module_classes(dt, classes, num_classes);
+ if (di->classes && di->num_classes)
+ ddebug_attach_module_classes(dt, di->classes, di->num_classes);

mutex_lock(&ddebug_lock);
list_add_tail(&dt->link, &ddebug_tables);
--
2.37.1

2022-08-05 22:58:37

by Jim Cromie

[permalink] [raw]
Subject: [PATCH v5 29/33] 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.
it is soft-wired on currently by #define DEBUG
could accidentally: #> echo -p > /proc/dynamic_debug/control

2- optional "decorations" by dyndbg are unhelpful/misleading here,
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 cb203d63b286..ec477c44a784 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>
@@ -185,7 +183,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.37.1

2022-08-09 16:36:10

by Daniel Vetter

[permalink] [raw]
Subject: Re: [PATCH v5 00/33] DYNDBG: opt-in class'd debug for modules, use in drm.

[Catching up on mails]

Did you see the feedback form Steven from tracing side of things? Does
this version have that taken into account already?

I think once we have that and acks from dyndbg maintainers then I think we
should just land this and polish from there? Maybe some acks from drm
drivrer folks (cros people where once interested), but otherwise I'm a bit
afraid this might be stuck in limbo too much for too long and we just need
to get going :-/
-Daniel


On Fri, Aug 05, 2022 at 03:53:22PM -0600, Jim Cromie wrote:
> Hi Jason, Greg, DRM-folk,
>
> heres V5. Diffs vs V4:
>
> 1st 9 have Jason's Ack
> 10 is new: simple var cleanup
> 11 new struct, to contain future addins. touches kernel/module/
>
> dyndbg-param callbacks moved to last (of dyndbg patches)
> they're where the uncertainty is,
> and the bulk of the API addition (class keyword is small)
>
> patches between the move are the guts of the "class foo" feature.
> exposure of feature is only via >control, until sysfs parts added
>
> DRM chunk:
> included here to see how patchwork's merge & test proceeds.
> categories -> classes re-work is unchanged - feels pretty solid.
> nouveau & LEVEL made some progress, still WIP.
>
> I left out tracefs bits for now.
>
> UNCERTAINTIES / RFC:
>
> 1st is my "sharing" technique, across DRM's multi modules. Its
> literally duplicated decls, by each participating module, each adding
> static data in its own special section. I didn't try at all to shrink
> or unify this any further. There might be a perfect place to add a
> single decl, but that quest will require a pony.
>
> Sharing by class-names lacks the compiler support that varnames get;
> "incomplete" enables will probably happen if one of the declarations
> miss-spells one of the classnames.
>
> That said, see the how-to below: stringifying va-args in the macro
> would allow direct use of the enum-consts, and cc will insist that
> those consts are defined, eliminating part of the un-support.
>
> I could split the _BITS,_NUM handling out from _NAMES (ie split
> drm.debug style patch); theres no user-demand for the _NAMES feature
> ATM, and theres probably some legit API-bikeshedding to do.
>
> PATCHSET DESCRIPTION
>
> This patchset adds 'typed' "class FOO" support to dynamic-debug, where
> 'typed' means either DISJOINT_BITS, like drm_dbg(DRM_UT_CORE,..), or
> LEVEL_NUM (like nouveau debug-levels). Use it in DRM modules: core,
> helpers, and in drivers i915, amdgpu, nouveau.
>
> If a module is using class'd prdbgs (pr_debug_class, dev_dbg_class, or
> adapted drm_dbg_<category>) or similar in its code, it can "opt in" to
> allow dyndbg to manipulate those class'd prdebugs, by declaring in a
> c-file:
>
> DECLARE_DYNDBG_CLASSMAP(drm_debug_classes,
> DD_CLASS_TYPE_DISJOINT_BITS, 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");
> // how-to stringify __va_args inside the macro ?
>
> By doing this, a module tells dyndbg that it:
>
> - is using class-ids [0..N] in prdbg callsites
> ( 0..N == DRM_UT_CORE..DRM_UT_DRMRES )
> - wants to refer to them by class-names [0..N]
> - is mapping those names to those class-ids
> - expects users to enable them via >control or >parameter/knob
>
> Then, a user can enable the prdbgs by their class:
>
> :#> echo class DRM_UT_KMS +p > /proc/dynamic_debug/control
>
> And with another 3-line bitmap param decl/init, wrapping the
> drm_debug_classes var in a module-param-cb:
>
> :#> echo 0x1 > /sys/module/drm/parameters/debug
>
> and optionally using classnames:
>
> :#> echo +DRM_UT_CORE,-DRM_UT_KMS \
> > /sys/module/drm/parameters/debug_cats
>
> DYNAMIC_DEBUG gets:
>
> struct _ddebug gets a new .class_id:5 field, big enough to represent
> drm_debug_category (after squeezing). It defaults to 31 for all
> existing prdbgs. class_id also supports verbose uses.
>
> classmaps (as declared by macro above) are in their own linker
> section, are loaded by kernel/module, and handled by add_module,
> which attaches classmaps to their module's ddebug table.
>
> ddebug_change() handles a class FOO query by validating that FOO is
> known by each module in the loop. The query is skipped unless the
> module knows FOO, so no changes are possible w/o a good classname.
>
> Without class FOO in a query/command, only ids=31 can be changed by
> that query. This protects all class'd prdbgs from changes by legacy
> class-less user queries.
>
> With this support, the module opt-in approach means that:
>
> - modules declare classnames they like, meaningful names: DRM_UT_*
> these are numbered [0..N]
> - modules call pr_debug_class(N, "fmt..",...)
> or drm_dbg(CAT, "fmt..",...) - same form.
> - class-id space, while limited:0-30, is private to each module
> - "class FOO" is only way to select a class'd prdbg
> - unrelated modules use 0..N separately, for different purposes.
> - modules "share" classnames by separate decls (uses of macro)
> all drm modules reuse the above declaration.
> then they respond together to a >control
>
> 4 CLASS_TYPES are defined; they split behavior on 2 factors:
>
> 1. independent bits vs related:(X<Y) bits [0-N]
> 2. input form: number/hex vs CSV-list: [+-]CLASS_NAMES
>
> DD_CLASS_TYPE_DISJOINT_BITS independent bits, 0x1f input is clearest
> DD_CLASS_TYPE_LEVEL_NUM (x<y), input is level, not bitvec
>
> DD_CLASS_TYPE_DISJOINT_NAMES csv-list of independent +-CLASS_NAMEs
> DD_CLASS_TYPE_LEVEL_NAMES csv-list of related +-CLASS_NAMEs, only 1 term needed
>
> Splitting up behavior this way is safe, and flexible:
>
> - no bitmap-vs-level > sysknob ambiguity
> as was case when both were accepted on same knob
> - narrower interfaces
> uint is uint
> - can defer DISJOINT_NAMES handling, but keep the enums.
> it has no users ...
> - can later add 2 more ENUMS allowing both inputs
> in separate LEVEL_NUM & DISJOINT_BITS choices
> then authors choice if they want to accept mixed input
> - can enumerate "wierd" relations if needed
> DISJOINT_BITS|LEVEL_NUM should cover everything I can forsee
> but theres room for DD_CLASS_TYPE_STOCHASTIC (over the garage)
>
> DISJOINT & LEVEL cover the space; 1st is independent, 2nd is related.
> The relation could differ from (x<y), but atm I can't think of another
> that makes any sensible distinction from (x<y).
>
> Quick review of debug logging:
>
> DRM is biggest use-case: 23 macros, issuing 10 exclusive categories of
> messages, from ~5100 callsites, across core (drm, _*helpers), and 3+
> drivers (Im working amdgpu, i915, more recently nouveau). These mostly
> flow to drm_debug_enabled(category) for a print/no decision.
>
> nouveau has minimum direct use of the DRM.debug macros, but does use
> pr_debug (in VMM iirc), and drm_debug_enabled() in ~50 places via
> macros, and another ~50 iirc due to NOUVEAU_DEBUG_MMU=y
>
> What nouveau has most of is log-levels: there are ~800 uses of them;
> nvkm_(fatal|error|warn|info|debug|trace|spam), they all flow thru
> nvkm_printk_. Even excluding some levels as "always-on" and not
> appropriate for dyndbg's extra resources and complexity, theres ~450
> callsites.
>
> A reported smattering of raw/adhoc debug code. all but unknown to me.
>
> Like any debug logging, they're mostly off, and should have close to
> 0-off-cost. This is what dyndbg (with/on jump-label) was made for.
>
> Bottom line: in order to unify more potential (drm,etc) use-cases,
> dyndbg needs to support both debug classification schemes:
> RELATED/LEVEL_NUM and INDEPENDENT/DISJOINT_BITS.
>
> This is rev3. rev2 is here:
> https://lore.kernel.org/lkml/[email protected]/
>
> summary of diffs:
>
> - rebased on 5.19-rc6 to pick up kernel/module changes
> - tracfs bits now use __vstring, __vstr_assign, from S.Rostedt
>
> - 4 class-map-types - as outlined above
> now supports LEVEL_NUM semantics, WIP nouveau integration.
> v2 became the DISJOINT_BITS use case
> Lots of API-ish surface area here *RFC*
>
> - class-maps now in section("__dyndbg_classes")
> class FOO queries are available at earlyboot / module-load
> drop (un)?register_classes()
>
> - test-dynamic-debug module
> tests the 4 CLASS-TYPES
> good place to bikeshed / paintshop the API
>
> - nouveau - start poking - WIP
> NV_PRINT -> dev_dbg (creates 632 prdbgs, but not class'd)
> LEVEL_NUM classes declared to see how they "fit", unused yet.
>
> Summary:
>
> - plenty of new stuff here.
> - plenty of new API surface area.
> - exposes CLASSNAMES to user, via control, >symbolic-sysknob
>
> More on LEVEL_NUM:
>
> dyndbg's class scheme is names-based, so even for LEVEL_NUM with
> numeric input, there must be a "V0" name; a name with which to turn
> off "V1". And don't do 'pr_dbg_class(0,..)'.
>
> LEVEL_NUM is an overlay on DISJOINT_BITS; the callback reads the input as a
> level, and computes and applies the bitmap to enforce it. Yes it
> wastes "V0" bit. That might matter if an author wanted many separate
> verbose-knobs with a few levels each, but that seems fairly unlikely.
>
> More importantly, it means that relative verbosity is not enforced at
> the >control input; IOW this is allowed:
>
> :#> echo class V1 -p > /proc/dynamic_debug/control
> :#> echo class V3 +p > /proc/dynamic_debug/control
>
> 2nd line doesn't undo 1st, as it would if changed via sysfs-knob:
>
> :#> echo 3 > /sys/module/drm/parameters/debug
>
> ISTM this is fine, the "relative" meaning is added at the interface,
> where it presents to a user. Doing otherwise means surgery to
> ddebug_change, which seems unnecessary given an option.
>
> CLASS NAMESPACE and DRM
>
> The class namespace is flat and wide, so "V1" is a poor choice, other
> than for demonstration (as in test_dynamic_debug module). If every
> module had a "V1", turning them all on would issue lots of unrelated
> noise.
>
> Instead, class DRM_UT_CORE has a name with a specific sub-system wide
> (ie multi-module) meaning, and can (and should) be responded to by all
> cooperating modules.
>
> For DRM, this means 4-5 duplicate uses of DEFINE_DYNDBG_CLASSMAP, from
> multiple drivers' "*_{drm,dev,main}.c" files; all of them agreeing on
> the classnames, map-type and base. Though repetitive, and a bit
> fiddly when multiple classes share the module's id-space, it is
> simple, and consistent with the "static struct foo = {INIT_expr}"
> pattern used in the macro. Im open to simpler ways, initializing an
> extern sounded like a maze w/o cheese.
>
> For core, drm_print.c has an additional task; it defines and
> initializes the bitmap sysknob that converts bits to a query:
>
> 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);
>
> then the callback converts bit-toggles on input into something like:
>
> :#> echo class DRM_UT_KMS +p > control
>
> which enables all drm_dbg_kms() callsites in all modules that declared
> that classname as known.
>
> NB: classmaps and classes_bitmap_params are different structs. this
> allows the former to be shared by 2 of latter, each toggling 'p' & 'T'
> flags, to control output to syslog or tracelog independently.
>
> NBB: while "V1" isnt a good classname, "EMERG" and and other
> KERN-LEVEL names have a legacy. That said, dyndbg shouldnt be
> involved in EMERG actions.
>
> NOUVEAU and multiple LEVEL_NUM knobs ?
>
> One thing nouveau has that I havent yet grokked is 2|3 independent
> verbose levels, in {,cli,sub}->debug (see subdev.h). But Ive coded
> them as 2 more macro invocations; using bases 10, 15 to avoid/respect
> the 0-9 mapping of DRM.debug categories to those class-ids.
>
> With this, the drm subsystem uses 20/31 of its class-id range, perhaps
> 63 is better, despite the cumbersome 0x-64bit interface. Note that
> the sysfs-knobs do not expose the base/offset (its an inward-facing
> .class_id offset); each sysfs-knob gets its own 0..N bitmap, the base
> maps it to the 0..30 subrange allocated (manually, via the base arg to
> macro) for this class-map.
>
> anyway, heres how `modprobe nouveau` goes with dynamic_debug.verbose=3
>
> [86512.693954] dyndbg: class[0]: module:nouveau base:15 len:5 ty:1
> [86512.693958] dyndbg: 15: 0 NV_SUBDEV_DBG_OFF # aka V0
> [86512.693959] dyndbg: 16: 1 NV_SUBDEV_DBG_INFO
> [86512.693960] dyndbg: 17: 2 NV_SUBDEV_DBG_DEBUG
> [86512.693960] dyndbg: 18: 3 NV_SUBDEV_DBG_TRACE
> [86512.693960] dyndbg: 19: 4 NV_SUBDEV_DBG_SPAM
> [86512.693961] dyndbg: class[1]: module:nouveau base:10 len:5 ty:1
> [86512.693961] dyndbg: 10: 0 NV_CLI_DBG_OFF
> [86512.693962] dyndbg: 11: 1 NV_CLI_DBG_INFO
> [86512.693962] dyndbg: 12: 2 NV_CLI_DBG_DEBUG
> [86512.693963] dyndbg: 13: 3 NV_CLI_DBG_TRACE
> [86512.693963] dyndbg: 14: 4 NV_CLI_DBG_SPAM
> [86512.693963] dyndbg: class[2]: module:nouveau base:0 len:10 ty:0
> [86512.693964] dyndbg: 0: 0 DRM_UT_CORE
> [86512.693964] dyndbg: 1: 1 DRM_UT_DRIVER
> [86512.693965] dyndbg: 2: 2 DRM_UT_KMS
> [86512.693965] dyndbg: 3: 3 DRM_UT_PRIME
> [86512.693965] dyndbg: 4: 4 DRM_UT_ATOMIC
> [86512.693966] dyndbg: 5: 5 DRM_UT_VBL
> [86512.693966] dyndbg: 6: 6 DRM_UT_STATE
> [86512.693966] dyndbg: 7: 7 DRM_UT_LEASE
> [86512.693967] dyndbg: 8: 8 DRM_UT_DP
> [86512.693967] dyndbg: 9: 9 DRM_UT_DRMRES
> [86512.693968] dyndbg: module:nouveau attached 3 classes
> [86512.693968] dyndbg: 632 debug prints in module nouveau
>
> They are not yet wired by class; the nv-printks are using dev_dbg for
> now, so they can be enabled with standard selections (module, func,
> etc).
>
> DYNDBG API
>
> I added __pr_debug_cls to make things testable, I wanted to keep it
> private/un-api, because drm already has drm_dbg_<cat>(cat, fmt..), and
> that seemed a pretty good model to follow: enums with strong names for
> class_id constants, and same names for classes.
>
> ie: __pr_debug_cls(DRM_UT_KMS, "Whats the Matter with KMS: %s\n", reason);
>
> But now nouveau probably wants/needs it, perhaps others too.
>
> pr_dbg_cls / dev_dbg_cls ? class or debug spelled out ?
>
> MORE TESTING with DRM & TRACEFS
>
> Most dev & testing has been on virtme, with test-dynamic-debug module
> doing an api-validation-demonstration. The test module proves
> multiple sysknobs, but cannot prove real multi-module sharing of the
> class-name space. The DRM.debug adaptation must (and does) do that.
>
> Now Im running on real gpu/drm hw; on both an amdgpu desktop, and this
> amdgpu+nouveau laptop. Its stable enough to type on, browse, build
> more kernels, etc.
>
> :#> uname -r
> 5.18.0-f2-00038-g61d300083196
> :#> wc /proc/dynamic_debug/control
> 11554 95556 1442827 /proc/dynamic_debug/control
> :#> lsmod | grep drm
> drm_buddy 20480 1 i915
> drm_ttm_helper 16384 2 amdgpu,nouveau
> ttm 86016 4 amdgpu,drm_ttm_helper,i915,nouveau
> drm_dp_helper 184320 3 amdgpu,i915,nouveau
> drm_kms_helper 208896 6 drm_dp_helper,amdgpu,i915,nouveau
> drm 655360 16 gpu_sched,drm_dp_helper,drm_kms_helper,drm_buddy,amdgpu,drm_ttm_helper,i915,ttm,nouveau
> cec 49152 2 drm_dp_helper,i915
>
> I've never turned on DRM.debug in frustration (or curiousity until
> recently); I dunno what normal traffic looks like. So I wrote a
> script to toggle each category: on/off for 1 sec, so I could 'more'
> thru the output to see the partitioned streams.
>
> Different runs (of '10' sec of active tracing) produce between 330-3500
> lines of logging, depending upon mousing/screen activity. Heres a bit
> of a many-window-select run: `wc trace` gives "size" of the category's stream.
>
> :#> trc_classes
> 12 /sys/kernel/tracing/trace
> doing class DRM_UT_CORE +/- T 1394 13941 141614 /sys/kernel/tracing/trace
> doing class DRM_UT_DRIVER +/- T 1396 13959 141816 /sys/kernel/tracing/trace
> doing class DRM_UT_KMS +/- T 1482 14521 148246 /sys/kernel/tracing/trace
> doing class DRM_UT_PRIME +/- T 1484 14539 148446 /sys/kernel/tracing/trace
> doing class DRM_UT_ATOMIC +/- T 2984 31658 396064 /sys/kernel/tracing/trace
> doing class DRM_UT_VBL +/- T 3411 37321 449848 /sys/kernel/tracing/trace
> doing class DRM_UT_STATE +/- T 3413 37339 450048 /sys/kernel/tracing/trace
> doing class DRM_UT_LEASE +/- T 3415 37357 450248 /sys/kernel/tracing/trace
> doing class DRM_UT_DP +/- T 3417 37375 450442 /sys/kernel/tracing/trace
> doing class DRM_UT_DRMRES +/- T 3419 37393 450644 /sys/kernel/tracing/trace
>
> and some mid-run output from a quiet run, with less repetition.
>
> bash-96790 [006] ..... 410237.432255: tracing_mark_write: doing class DRM_UT_DRIVER +T
> bash-96790 [006] ..... 410238.610319: tracing_mark_write: doing class DRM_UT_DRIVER -T
> bash-96790 [006] ..... 410239.776285: tracing_mark_write: doing class DRM_UT_KMS +T
> gnome-shell-2101 [003] ..... 410239.923029: drm_debug: [FB:98]
> kworker/u32:10-367584 [010] ..... 410239.924627: drm_debug: Allow idle optimizations (MALL): 0
> kworker/u32:0-364714 [008] ..... 410239.935126: drm_debug: Allow idle optimizations (MALL): 1
> gnome-shell-2101 [003] ..... 410240.527186: drm_debug: [FB:100]
> kworker/u32:0-364714 [008] ..... 410240.528686: drm_debug: Allow idle optimizations (MALL): 0
> kworker/u32:10-367584 [010] ..... 410240.539378: drm_debug: Allow idle optimizations (MALL): 1
> bash-96790 [006] ..... 410240.957921: tracing_mark_write: doing class DRM_UT_KMS -T
> bash-96790 [006] ..... 410242.199120: tracing_mark_write: doing class DRM_UT_PRIME +T
> bash-96790 [006] ..... 410243.301988: tracing_mark_write: doing class DRM_UT_PRIME -T
> bash-96790 [006] ..... 410244.416400: tracing_mark_write: doing class DRM_UT_ATOMIC +T
> gnome-shell-2101 [003] ..... 410244.653372: drm_devdbg: cat:4, (0xffff8f26c173de00:0000:06:00.0)[UNSAFE-MEMORY] Allocated atomic state 000000001f1e6cb6
> gnome-shell-2101 [003] ..... 410244.653381: drm_devdbg: cat:4, (0xffff8f26c173de00:0000:06:00.0)[UNSAFE-MEMORY] Added [PLANE:55:plane-3] 00000000785ae904 state to 000000001f1e6cb6
> gnome-shell-2101 [003] ..... 410244.653384: drm_devdbg: cat:4, (0xffff8f26c173de00:0000:06:00.0)[UNSAFE-MEMORY] Added [CRTC:67:crtc-0] 00000000b06ca618 state to 000000001f1e6cb6
> gnome-shell-2101 [003] ..... 410244.653389: drm_devdbg: cat:4, (0xffff8f26c173de00:0000:06:00.0)[UNSAFE-MEMORY] Set [FB:98] for [PLANE:55:plane-3] state 00000000785ae904
> gnome-shell-2101 [003] ..... 410244.653392: drm_devdbg: cat:4, (0xffff8f26c173de00:0000:06:00.0)[UNSAFE-MEMORY] checking 000000001f1e6cb6
> gnome-shell-2101 [003] ..... 410244.653407: drm_devdbg: cat:4, (0xffff8f26c173de00:0000:06:00.0)[UNSAFE-MEMORY] committing 000000001f1e6cb6 nonblocking
> kworker/u32:0-364714 [010] ..... 410244.653729: drm_debug: amdgpu_crtc id:0 crtc_state_flags: enable:1, active:1, planes_changed:1, mode_changed:0,active_changed:0,connectors_changed:0
> kworker/u32:0-364714 [010] ..... 410244.654642: drm_debug: plane: id=3 dcc_en=0
>
> a few things to note in the trace output:
>
> . the event-name: drm_(debug|devdbg) is not very informative
>
> . drm_devdbg fmt has cat:%d, it could be the classname, but that should
> replace event-name, not supplement it. this pertains to drm_debug too.
>
> . drm_devdbg has lots of (dev-info), that could be optional on a new flag(s)
>
>
> If anyone wants to repeat the above with the patchset, the .rc file follows:
>
> events_3() {
> local a=$1
> local b=$2
> local c=$3
> echo $a > /sys/kernel/tracing/events/dyndbg/enable
> # avoid drm_vblank*, its noisy
> echo $b > /sys/kernel/tracing/events/drm/drm_debug/enable
> echo $c > /sys/kernel/tracing/events/drm/drm_devdbg/enable
> }
>
> flags_class() {
> local flgs=$1;
> local cls=$2;
> echo class $cls $flgs > /proc/dynamic_debug/control
> }
>
> # turn on each DRM_UT_* for 1 second each.
> # kinda shows relative traffic of each category
> # separated into blocks to get flavor of each
>
> drm_classes() {
> local flgs=$1
> [ -z $flgs ] && flgs="p"
>
> #echo > /sys/kernel/tracing/trace
> #wc /sys/kernel/tracing/trace
>
> for cls in 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;
> do
> echo -n doing class $cls " "
>
> echo doing class $cls +$flgs
> sleep .1
> flags_class +$flgs $cls
> sleep 1
>
> echo doing class $cls -$flgs
> sleep .1
> flags_class -$flgs $cls
> sleep 1
>
> #wc /sys/kernel/tracing/trace
> done
> }
>
> # like above but with T flag, and markers, trace/enable
> trc_classes() {
> local flgs=$1
> [ -z $flgs ] && flgs="T"
>
> echo > /sys/kernel/tracing/trace
> wc -l /sys/kernel/tracing/trace
>
> events_3 1 1 1
> for cls in 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;
> do
> echo -n doing class $cls +/- $flgs " "
>
> echo doing class $cls +$flgs > /sys/kernel/tracing/trace_marker
> sleep .1
> flags_class +$flgs $cls
> sleep 1
>
> echo doing class $cls -$flgs > /sys/kernel/tracing/trace_marker
> sleep .1
> flags_class -$flgs $cls
> sleep 1
>
> wc /sys/kernel/tracing/trace
>
> done
> events_3 0 0 0
> }
>
>
> Jim Cromie (33):
>
> 1st, a group of "cleanups"
>
> dyndbg: fix static_branch manipulation
> dyndbg: fix module.dyndbg handling
> dyndbg: show both old and new in change-info
> dyndbg: reverse module walk in cat control
> dyndbg: reverse module.callsite walk in cat control
> dyndbg: use ESCAPE_SPACE for cat control
> dyndbg: let query-modname override actual module name
> dyndbg: add test_dynamic_debug module
> dyndbg: drop EXPORTed dynamic_debug_exec_queries
> dyndbg: cleanup local vars in ddebug_init
> dyndbg: create and use struct _ddebug_info
>
> class FOO support
>
> dyndbg: add class_id to pr_debug callsites
> dyndbg: add __pr_debug_cls for testing
> dyndbg: add DECLARE_DYNDBG_CLASSMAP macro
> kernel/module: add __dyndbg_classes section
> dyndbg: add ddebug_attach_module_classes
> dyndbg: validate class FOO by checking with module
> doc-dyndbg: describe "class CLASS_NAME" query support
> doc-dyndbg: edit dynamic-debug-howto for brevity, audience
>
> add dyndbg-class-param support
>
> dyndbg: add drm.debug style (drm/parameters/debug) bitmap support
> dyndbg: test DECLARE_DYNDBG_CLASSMAP, sysfs nodes
>
> drm.debug adaptation
>
> drm_print: condense enum drm_debug_category
> drm: POC drm on dyndbg - use in core, 2 helpers, 3 drivers.
> drm_print: interpose drm_*dbg with forwarding macros
> drm_print: wrap drm_*_dbg in dyndbg descriptor factory macro
> drm-print.h: include dyndbg header
> drm-print: add drm_dbg_driver to improve namespace symmetry
> drm_print: refine drm_debug_enabled for jump-label
> drm_print: prefer bare printk KERN_DEBUG on generic fn
> drm_print: add _ddebug descriptor to drm_*dbg prototypes
>
> nouveau-LEVEL_NUM integration: WIP/exploratory.
>
> nouveau: change nvkm_debug/trace to use dev_dbg POC
> nouveau: adapt NV_DEBUG, NV_ATOMIC to use DRM.debug
> nouveau: WIP add 2 LEVEL_NUM classmaps for CLI, SUBDEV
>
> .../admin-guide/dynamic-debug-howto.rst | 246 +++++-----
> MAINTAINERS | 2 +
> drivers/gpu/drm/Kconfig | 12 +
> drivers/gpu/drm/Makefile | 2 +
> drivers/gpu/drm/amd/amdgpu/amdgpu_drv.c | 14 +
> drivers/gpu/drm/display/drm_dp_helper.c | 13 +
> drivers/gpu/drm/drm_crtc_helper.c | 13 +
> drivers/gpu/drm/drm_print.c | 48 +-
> drivers/gpu/drm/i915/i915_params.c | 12 +
> .../gpu/drm/nouveau/include/nvkm/core/debug.h | 16 +
> .../drm/nouveau/include/nvkm/core/subdev.h | 17 +-
> drivers/gpu/drm/nouveau/nouveau_drm.c | 20 +
> drivers/gpu/drm/nouveau/nouveau_drv.h | 16 +-
> drivers/gpu/drm/nouveau/nvkm/core/subdev.c | 23 +
> include/asm-generic/vmlinux.lds.h | 3 +
> include/drm/drm_print.h | 85 +++-
> include/linux/dynamic_debug.h | 176 +++++--
> kernel/module/internal.h | 4 +-
> kernel/module/main.c | 20 +-
> lib/Kconfig.debug | 10 +
> lib/Makefile | 1 +
> lib/dynamic_debug.c | 450 +++++++++++++++---
> lib/test_dynamic_debug.c | 165 +++++++
> 23 files changed, 1099 insertions(+), 269 deletions(-)
> create mode 100644 lib/test_dynamic_debug.c
>
> --
> 2.37.1
>

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