lib/dynamic_debug.c | 52 ++++++++++++++++++++++++++++----------------- 1 file changed, 32 insertions(+), 20 deletions(-)
hi Lukas,
Sorry for the delay, I probably should have split this up.
(also cc'g gregkh)
Ive been banging on your v2 patchset:
https://lore.kernel.org/lkml/20231130234048.157509-1-lb@semihalf.com/
Things are looking pretty good, a few issues follow. And some patches.
trivial:
dyndbg: export _print_hex_dump # squash wo comment
dyndbg: tweak pr_info format s/trace dest/trace_dest/ # greppability squash
dyndbg: disambiguate quoting in a debug msg
dyndbg: fix old BUG_ON in >control parser
Then:
dyndbg: change +T:name_terminator to dot
dyndbg: treat comma as a token separator
1st allows 2nd, 2nd allows simpler arg-passing, boot-args, etc:
echo module,test_dynamic_debug,class,L2,+p > /proc/dynamic_debug/control
modprobe test_dynamic_debug dyndbg=class,L2,+mfl
Given theres no legacy wrt comma, swapping it now with dot seems
better semantically than "dot as token/list separator".
Aside: /proc/dynamic_debug/control is always there (if configd), even
when <debugfs> isn't mounted. Its more universal, and copy-pastable.
dyndbg: __skip_spaces - and comma
dyndbg: split multi-query strings with %
% allows escape-free multi-cmd dyndbg args:
modprobe test_dynamic_debug \
dyndbg=open,selftest%class,D2_CORE,+T:selftest.mf
dyndbg: reduce verbose/debug clutter
dyndbg: move lock,unlock into ddebug_change, drop goto - revisit
Ive just pushed it, I will bump my version here.
To github.com:jimc/linux.git
+ 20d113eb6f9a...66fa2e4cb989 lukas-v2.1 -> lukas-v2.1 (forced update)
SELFTEST
Ive taken the liberty to write an ad-hoc test script (inline below),
to exersize the parser with legacy command input, and with the new
stuff mentioned above: comma-separated-tokens, %-separated-multi-cmds,
while counting changes to builtin,etc modules, to validate against
expectations.
The change-count tests achieve some closed-loop testing, but checking
syslog for messages written always seemed too hard/unreliable. Your
private trace-instances work promises a solution, by giving an
observable closed system to build upon.
I made some attempts to write messages to the trace-buf, but ran out
of clues*tuits. And I encountered a couple more definite problems:
1- modprobe/rmmod lifecycle probs
Ive coded some blue-sky and not-so-proper "modprobe,+T:it,-T:it,rmmod"
life-cycle scenarios, which can wedge a previously created instance.
Once wedged, I cannot recover. See the test_private_trace{,_2,_3}
functions, and the error_log_ref() following each.
This brittleness begs a question; should we have auto-open (mapping
new names to available 1-63 trc-ids) ? And non-close ? If it just did
the right thing, particularly on rmmod, it would prevent "misuse".
I don't think auto-open obsoletes the open (& esp) close commands, but
Id like to see scripted test scenarios using close in combo with the
right /sys/kernel/tracing/* manipulations, to prove its not all just a
fever dream.
Your expertise in opening, writing to, manipulating & destroying
private (and the global) tracebufs, distilled into new shell funcs,
would be enormously helpful towards demonstrating the private-buffer
use case and its value.
2- some new flags parse error:
[ 1273.074535] dyndbg: 32 debug prints in module test_dynamic_debug
[ 1273.075365] dyndbg: module: test_dynamic_debug dyndbg="class,D2_CORE,+T:foo%class,D2_KMS,+T:foo"
[ 1273.076307] dyndbg: query 0: <class,D2_CORE,+T:foo> on module: <test_dynamic_debug>
[ 1273.077068] dyndbg: split into words: "class" "D2_CORE" "+T:foo"
[ 1273.077673] dyndbg: unknown flag 'c'
[ 1273.078033] dyndbg: flags parse failed on 2: +T:foo
[ 1273.078519] dyndbg: query 1: <class,D2_KMS,+T:foo> on module: <test_dynamic_debug>
[ 1273.079266] dyndbg: split into words: "class" "D2_KMS" "+T:foo"
[ 1273.079872] dyndbg: unknown flag '�'
[ 1273.080228] dyndbg: flags parse failed on 2: +T:foo
[ 1273.080716] dyndbg: processed 2 queries, with 0 matches, 2 errs
: 0 matches on =Tl
I have a suspicion this relates to moving the parse_flags call in
ddebug_query, but I havent dug in.
I also have some reservations about the default dest; 1st that it is a
global state var, as noted at bottom of control:
[root@v6 lx]# ddgrep \\btrace\\b # a better/narrower search-term ?
...
Default trace destination: foo # add a '#:' prefix to these lines ?
Opened trace instances: # all values should be on this line
Then theres the "preset" value, ie each site's dest_id (sorry I forgot
your fieldname). I presume the default would override such a "preset"
(otherwise it would have no effect).
Is the default set on last open ? or on next use of +T:<foo> ?
In the no-default world, a user/tester would decide how many
trace-instances are needed, and map sets of callsites to them.
# configure drm-debug streams for this test scenario
cat<<EOF >/proc/dynamic_debug/control
open drm_core
open drm_mix
open driver_1 # we can separate by modname but not drvr-number
open driver_2
class DRM_UT_CORE -T:drm_core # set dest_id, disabled state
class DRM_UT_CORE +mf # traces dont do prefixing (should it?)
# mix KMS & ATOMIC into 1 stream
class DRM_UT_KMS -T:drm_mix
class DRM_UT_ATOMIC -T:drm_mix
EOF
Then perhaps to turn on/off when needed: (legacy analogue version)
echo 0x15 > /sys/module/drm/parameters/debug_trace
With those trace-dest presets honored, the configured drm_core &
drm_mix streams persist. If a later enablement applies the
then-current default trace-dest, it would spoil this scheme.
Could you elaborate a scenario or 2 where the default behavior does
something specific, and that its the right thing ? I dont understand
it yet.
OTOH
One limitation of the above: the drm.debug_trace (posited above) would
turn on all Ts in all those class'd callsites across the whole
subsystem, irrespective of their preconfigured destination. That was
always inherent in drm.debug, but its less than perfect.
It sort-of defeats the point of doing +T only on the useful callsites.
And global event buf is also enabled, it might be flood-prone.
echo 1 > /sys/kernel/tracing/events/dyndbg/enable
It would help if we could filter on trace-instance names:
(this sounds familiar :-)
ddcmd module '*' trace_dest drm_mix +T
In reality, the dest-id is not even dependent on tracing per-se, it is
a user classification system (in contrast to class <subsys-names>).
It just happens to be tied by +T:name syntax to tracefs.
No promise about +p:_alt_log_.mflt having meaning, or working.
anyway, Ive gone on long enough. heres that/those scripts
cat dd-tools.rc
#!/bin/bash
function ddcmd () {
echo $* > /proc/dynamic_debug/control
}
function ddcat () {
cat $1 > /proc/dynamic_debug/control
}
function vx () {
echo $1 > /sys/module/dynamic_debug/parameters/verbose
}
function ddgrep () {
grep $1 /proc/dynamic_debug/control
}
function doprints () {
cat /sys/module/test_dynamic_debug/parameters/do_prints
}
cat dd-selftest.rc
#!/bin/bash
# dd-selftest.rc: shell-fns & test-script for dynamic-debug
# mostly run as:
# vng --force-9p -v -e ./dd-selftest.rc
. dd-tools.rc
# vx 3
function check_matches {
let ct=$(ddgrep $1 | wc -l )
echo ": $ct matches on $1 "
[ "$2" == "-v" ] && ddgrep $1
}
function check_instance {
# 1. trace instance name 2. -v for verbose
if [ -e /sys/kernel/tracing/instances/$1 ]; then
if [ "$2" == "-v" ] ; then
echo "ls -l /sys/kernel/tracing/instances/$1: "
ls -l /sys/kernel/tracing/instances/$1
fi
else
echo "no instance: $1"
fi
}
function tmark {
echo $* > /sys/kernel/tracing/trace_marker
}
function read_trace_instance {
# get traces opened, default
tail -n9 /proc/dynamic_debug/control | grep -P \\w+ | grep -vP ^drivers/
}
function error_log_ref {
# to show what I got
: echo "# error-log-ref: $1"
: echo cat \$2
}
function ifrmmod {
lsmod | grep $1 || echo $1 not there
lsmod | grep $1 && rmmod $1
}
echo LOADING TEST FUNCS
echo SHLVL: $SHLVL
function basic_tests {
echo \# BASIC_TESTS
ddcmd =_ "# zero everything (except class'd sites)"
check_matches =p 0
# there are several main's :-/
ddcmd module main file */module/main.c +p
check_matches =p 14
ddcmd =_
check_matches =p 0
ddcmd module mptcp =_
ddcmd module mptcp +pmf
check_matches =pmf 120
ddcmd =_
# multi-cmd newline separated with embedded comments
cat <<"EOF" > /proc/dynamic_debug/control
module main +mf # multi-query
module main file init/main.c +ml # newline separated
module kvm +fl # comment prefixed
module kvm_intel +flt #
EOF
# the intersection of all those main's is hard to track/count
# esp when mixed with overlapping greps
check_matches =mf 27
check_matches =ml 0
check_matches =mfl 6
check_matches =fl 29
check_matches =flt 16
ddcmd =_
}
basic_tests; # run
function comma_terminator_tests {
echo \# COMMA_TERMINATOR_TESTS
# try combos of space & comma
ddcmd module,mptcp,=_
ddcmd module,mptcp,+mf
ddcmd " module, mptcp, +mfl"
check_matches =pmf 120
ddcmd module , mptcp,-p
check_matches =mf 120
check_matches =p 0
ddcmd ,module ,, mptcp, -p
ddcmd ",module ,, mptcp, -p"
ddcmd =_
}
comma_terminator_tests; # run
function private_trace_test {
echo \# PRIVATE_TRACE_TEST - proper lifo cycle - open, enable:named disable:named close
ddcmd open usb_stream
check_instance usb_stream
ddcmd module usbcore +T:usb_stream.mf
check_matches =T:usb_stream.mf 161
ddcmd module usbcore -T:usb_stream.mf
check_matches =T:usb_stream.mf 0
read_trace_instance
ddcmd close usb_stream
read_trace_instance
ddcmd =_
}
private_trace_test; # run
function test_percent_splitting {
echo \# TEST_PERCENT_SPLITTING - multi-command splitting on %
ddcmd =_
modprobe test_dynamic_debug dyndbg=class,D2_CORE,+pf%class,D2_KMS,+pt%class,D2_ATOMIC,+pm
check_matches =pf -v
check_matches =pt -v
check_matches =pm -v
ddcmd class,D2_CORE,+mf%class,D2_KMS,+lt%class,D2_ATOMIC,+ml "# add some prefixes"
check_matches =pmf -v
check_matches =plt -v
check_matches =pml -v
doprints
ifrmmod test_dynamic_debug
}
test_percent_splitting; # run
function test_actual_trace {
echo \# test_actual_trace
ddcmd =_
ifrmmod test_dynamic_debug
echo 1 >/sys/kernel/tracing/tracing_on
echo 1 >/sys/kernel/tracing/events/dyndbg/enable
modprobe test_dynamic_debug dyndbg=class,D2_CORE,+T
check_matches =T -v
tmark here comes the WARN
doprints
cat /sys/kernel/tracing/trace
}
test_actual_trace; # run, hits 1313: WARN_ON_ONCE(!arr)
error_log_ref test_actual_trace <<"EO_LOG"
[ 6.587595] dyndbg: read 3 bytes from userspace
[ 6.588174] dyndbg: query 0: <=_> on module: <*>
[ 6.588842] dyndbg: processed 1 queries, with 3236 matches, 0 errs
[ 6.726160] dyndbg: class[0]: module:test_dynamic_debug base:22 len:8 ty:3
[ 6.727052] dyndbg: class[1]: module:test_dynamic_debug base:14 len:8 ty:1
[ 6.728158] dyndbg: class[2]: module:test_dynamic_debug base:10 len:3 ty:2
[ 6.729112] dyndbg: class[3]: module:test_dynamic_debug base:0 len:10 ty:0
[ 6.729969] dyndbg: module:test_dynamic_debug attached 4 classes
[ 6.730729] dyndbg: 32 debug prints in module test_dynamic_debug
[ 6.731494] dyndbg: module: test_dynamic_debug dyndbg="class,D2_CORE,+T"
[ 6.732350] dyndbg: query 0: <class,D2_CORE,+T> on module: <test_dynamic_debug>
[ 6.733291] dyndbg: processed 1 queries, with 1 matches, 0 errs
[ 6.734224] ------------[ cut here ]------------
[ 6.734811] WARNING: CPU: 1 PID: 472 at lib/dynamic_debug.c:1309 ddebug_printk+0xde/0xf0
[ 6.735814] Modules linked in: test_dynamic_debug(E+) intel_rapl_msr(E) crc32_pclmul(E) intel_rapl_common(E) ghash_clmulni_intel(E) crct10dif_pclmul(E) crc32c_intel(E) joydev(E) serio_raw(E) pcspkr(E) i2c_piix4(E) [last unloaded: test_dynamic_debug(E)]
[ 6.738594] CPU: 1 PID: 472 Comm: modprobe Tainted: G W E 6.6.0-tf2-virtme-00026-g20d113eb6f9a-dirty #220
[ 6.740008] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.16.3-0-ga6ed6b701f0a-prebuilt.qemu.org 04/01/2014
[ 6.741669] RIP: 0010:ddebug_printk+0xde/0xf0
[ 6.742220] Code: 48 8d 44 24 28 48 89 44 24 20 e8 ed 71 9c ff 48 83 c4 58 5b 41 5c 5d c3 48 8d 56 02 48 8d 4c 24 10 31 f6 e8 84 f9 ff ff eb b5 <0f> 0b eb a0 66 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 00 41 57 48 89
[ 6.745072] RSP: 0018:ffffb38140453bd0 EFLAGS: 00010246
[ 6.745914] RAX: 0000000000000000 RBX: ffffffffc03b97e0 RCX: ffffb38140453c50
[ 6.747002] RDX: ffffb38140453be0 RSI: ffffffffb26f8150 RDI: 0000000000000000
[ 6.747883] RBP: ffffb38140453c38 R08: 0000000000000020 R09: ffffffffb3370ce4
[ 6.748753] R10: 0000000000000001 R11: 0000000000010000 R12: ffffffffb26f8150
[ 6.749586] R13: ffff9b68029bc440 R14: ffff9b6805640800 R15: ffff9b6805c9d640
[ 6.750497] FS: 00007f7cdc453740(0000) GS:ffff9b683ec80000(0000) knlGS:0000000000000000
[ 6.751537] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 6.752310] CR2: 000055ce7a609ae0 CR3: 000000000575a000 CR4: 0000000000750ee0
[ 6.753238] PKRU: 55555554
[ 6.753604] Call Trace:
[ 6.753910] <TASK>
[ 6.754240] ? ddebug_printk+0xde/0xf0
[ 6.754772] ? __warn+0x7d/0x130
[ 6.755197] ? ddebug_printk+0xde/0xf0
[ 6.755669] ? report_bug+0x189/0x1c0
[ 6.756176] ? handle_bug+0x38/0x70
[ 6.756642] ? exc_invalid_op+0x13/0x60
[ 6.757112] ? asm_exc_invalid_op+0x16/0x20
[ 6.757635] ? ddebug_printk+0xde/0xf0
[ 6.758123] ? 0xffffffffc03c0000
[ 6.758533] __dynamic_pr_debug+0x133/0x170
[ 6.759066] ? 0xffffffffc03c0000
[ 6.759438] do_cats+0x127/0x180 [test_dynamic_debug]
[ 6.760063] test_dynamic_debug_init+0x7/0x1000 [test_dynamic_debug]
[ 6.760890] do_one_initcall+0x43/0x2f0
[ 6.761399] ? kmalloc_trace+0x26/0x90
[ 6.761904] do_init_module+0x9d/0x290
[ 6.762377] init_module_from_file+0x77/0xd0
[ 6.762877] idempotent_init_module+0xf9/0x270
[ 6.763439] __x64_sys_finit_module+0x5a/0xb0
[ 6.764040] do_syscall_64+0x35/0x80
[ 6.764474] entry_SYSCALL_64_after_hwframe+0x46/0xb0
[ 6.765089] RIP: 0033:0x7f7cdc56b5ad
[ 6.765522] Code: ff c3 66 2e 0f 1f 84 00 00 00 00 00 90 f3 0f 1e fa 48 89 f8 48 89 f7 48 89 d6 48 89 ca 4d 89 c2 4d 89 c8 4c 8b 4c 24 08 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d 53 48 0c 00 f7 d8 64 89 01 48
[ 6.767763] RSP: 002b:00007fff198e28d8 EFLAGS: 00000246 ORIG_RAX: 0000000000000139
[ 6.768781] RAX: ffffffffffffffda RBX: 000055ce7bb53980 RCX: 00007f7cdc56b5ad
[ 6.769611] RDX: 0000000000000000 RSI: 000055ce7bb72930 RDI: 0000000000000006
[ 6.770598] RBP: 00007fff198e2990 R08: 0000000000000000 R09: 0000000000000002
[ 6.771447] R10: 0000000000000006 R11: 0000000000000246 R12: 000055ce7bb72930
[ 6.772328] R13: 0000000000040000 R14: 000055ce7bb53bc0 R15: 000055ce7bb72930
[ 6.773252] </TASK>
[ 6.773532] ---[ end trace 0000000000000000 ]---
: 2 matches on =T
drivers/cpufreq/intel_pstate.c:1912 [intel_pstate]core_get_max_pstate =_ "max_pstate=TAC %x\n"
lib/test_dynamic_debug.c:109 [test_dynamic_debug]do_cats =T:(null) "D2_CORE msg\n" class:D2_CORE
did do_prints
# tracer: nop
#
# entries-in-buffer/entries-written: 0/0 #P:4
EO_LOG
# that 2nd =T match has :(null) in the control-line. I didnt chase it.
function test_early_close () {
ddcmd open usb_stream
ddcmd module usbcore +T:usb_stream.mf
check_matches =T:usb_stream.mf 161
echo ":not-running # ddcmd module usbcore -T:usb_stream.mf"
ddcmd close usb_stream
}
# test_early_close - works, unused, refactored below.
function self_start {
echo \# open, modprobe +T:it
ddcmd open selftest
check_instance selftest
modprobe test_dynamic_debug dyndbg=+T:selftest.mf
check_matches =T:selftest.mf -v
}
function self_end_normal {
echo \# disable -T:it, rmmod, close
ddcmd module test_dynamic_debug -T:selftest # leave mf
check_matches =mf -v
ifrmmod test_dynamic_debug
ddcmd close selftest
}
function self_end_disable_anon {
echo \# disable, close, rmmod
ddcmd module test_dynamic_debug -T
check_matches =mf -v
ddcmd close selftest
ifrmmod test_dynamic_debug
}
function self_end_disable_anon_mf {
echo \# disable, close, rmmod
ddcmd module test_dynamic_debug -Tf
check_matches =m -v
ddcmd close selftest
ifrmmod test_dynamic_debug
}
function self_end_nodisable {
echo \# SKIPPING: ddcmd module test_dynamic_debug -T:selftest
rmmod test_dynamic_debug
echo FAIL_COMING on close
ddcmd close selftest
}
function self_test_ {
echo "# SELFTEST $1"
self_start
self_end_$1
}
function cycle_tests_normal {
echo \# CYCLE_TESTS_NORMAL
self_test_ normal # ok
self_test_ disable_anon # ok
ddgrep selftest
self_test_ normal # ok
self_test_ disable_anon_mf #
ddgrep selftest
}
cycle_tests_normal; # run
function cycle_tests_problem {
self_test_ nodisable # write error: Device or resource busy
ddgrep selftest # still used, defaulted - prob
self_test_ normal # open error, write error persists
ddgrep selftest # still used, defaulted
ddcmd close selftest # too late ??
}
# cycle_tests_problem;
function test_private_trace {
echo "# TEST_PRIVATE_TRACE"
ddcmd =_
ifrmmod test_dynamic_debug
echo 1 >/sys/kernel/tracing/tracing_on
echo 1 >/sys/kernel/tracing/events/dyndbg/enable
ddcmd open foo
modprobe test_dynamic_debug
ddcmd class,D2_CORE,+T:foo,%class,D2_KMS,+T:foo
check_matches =Tl -v
check_matches =Tmf -v
echo 1 >/sys/kernel/tracing/tracing_on
echo 1 >/sys/kernel/tracing/events/dyndbg/enable
tmark test_private_trace about to do_prints
doprints
cat /sys/kernel/tracing/trace
ddcmd class,D2_CORE,-T:foo
ddcmd close foo
ddcmd close bar
ifrmmod test_dynamic_debug
}
test_private_trace; # run
error_log_ref test_private_trace <<EOF
# test_private_trace
[ 7.803744] dyndbg: read 3 bytes from userspace
[ 7.804329] dyndbg: query 0: <=_> on module: <*>
[ 7.804844] dyndbg: processed 1 queries, with 3236 matches, 0 errs
rmmod: ERROR: Module test_dynamic_debug is not currently loaded
[ 7.838191] dyndbg: read 9 bytes from userspace
[ 7.838858] dyndbg: query 0: <open foo> on module: <*>
[ 7.872066] dyndbg: processed 1 queries, with 0 matches, 0 errs
[ 7.991723] dyndbg: class[0]: module:test_dynamic_debug base:22 len:8 ty:3
[ 7.992488] dyndbg: class[1]: module:test_dynamic_debug base:14 len:8 ty:1
[ 7.993178] dyndbg: class[2]: module:test_dynamic_debug base:10 len:3 ty:2
[ 7.993873] dyndbg: class[3]: module:test_dynamic_debug base:0 len:10 ty:0
[ 7.994560] dyndbg: module:test_dynamic_debug attached 4 classes
[ 7.995174] dyndbg: 32 debug prints in module test_dynamic_debug
[ 7.998426] dyndbg: read 42 bytes from userspace
[ 7.999169] dyndbg: query 0: <class,D2_CORE,+T:foo,> on module: <*>
[ 8.000126] dyndbg: query 1: <class,D2_KMS,+T:foo> on module: <*>
[ 8.000956] dyndbg: processed 2 queries, with 2 matches, 0 errs
: 0 matches on =Tl
: 0 matches on =Tmf
did do_prints
# tracer: nop
#
# entries-in-buffer/entries-written: 2/2 #P:4
#
# _-----=> irqs-off/BH-disabled
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| / _-=> migrate-disable
# |||| / delay
# TASK-PID CPU# ||||| TIMESTAMP FUNCTION
# | | | ||||| | |
dd-selftest.rc-375 [003] ..... 6.876234: tracing_mark_write: here comes the WARN
dd-selftest.rc-375 [003] ..... 8.168406: tracing_mark_write: should be ready
[ 8.093538] dyndbg: read 21 bytes from userspace
[ 8.094156] dyndbg: query 0: <class,D2_CORE,-T:foo> on module: <*>
[ 8.094924] dyndbg: processed 1 queries, with 1 matches, 0 errs
[ 8.095560] dyndbg: read 10 bytes from userspace
[ 8.096038] dyndbg: query 0: <close foo> on module: <*>
[ 8.096565] dyndbg: trace instance is being used name=foo, use_cnt=1
[ 8.097198] dyndbg: processed 1 queries, with 0 matches, 1 errs
dd-tools.rc: line 4: echo: write error: Device or resource busy
[ 8.097850] dyndbg: read 10 bytes from userspace
[ 8.098356] dyndbg: query 0: <close bar> on module: <*>
[ 8.098887] dyndbg: processed 1 queries, with 0 matches, 1 errs
dd-tools.rc: line 4: echo: write error: No such file or directory
EOF
function test_private_trace_2 {
echo "# TEST_PRIVATE_TRACE_2"
ddcmd =_
rmmod test_dynamic_debug
echo 1 >/sys/kernel/tracing/tracing_on
echo 1 >/sys/kernel/tracing/events/dyndbg/enable
ddcmd open foo \; open bar # 2nd fails
modprobe test_dynamic_debug
ddcmd class,D2_CORE,+T:foo
ddcmd class,D2_KMS,+T:foo
ddcmd class D2_CORE +T:foo \; class D2_KMS +T:foo
echo \# this breaks ??
ddcmd "class,D2_CORE,+T:foo;,class,D2_KMS,+T:foo"
# ddcmd class,D2_CORE,+T:foo\;class,D2_KMS,+T:foo
check_matches =Tl -v
check_matches =Tmf -v
echo 1 >/sys/kernel/tracing/tracing_on
echo 1 >/sys/kernel/tracing/events/dyndbg/enable
tmark test_private_trace_2 about to do_prints
doprints
cat /sys/kernel/tracing/trace
#rmmod test_dynamic_debug
}
test_private_trace_2; # run
# a real parse error in this log, with same input as worked above.
# the unkown flag 'c' error conflicts with what the following error
# says is the flags token
error_log_ref test_private_trace_2 <<EOF
[ 8.107982] d# test_private_trace_2
yndbg: read 3 bytes from userspace
[ 8.108490] dyndbg: query 0: <=_> on module: <*>
[ 8.108997] dyndbg: processed 1 queries, with 3241 matches, 0 errs
[ 8.139645] dyndbg: removed module "test_dynamic_debug"
[ 8.152344] dyndbg: read 20 bytes from userspace
[ 8.152952] dyndbg: query 0: <open foo > on module: <*>
[ 8.153610] dyndbg: instance is already opened name:foo
[ 8.153610]
[ 8.153612] dyndbg: query 1: <open bar> on module: <*>
[ 8.185399] dyndbg: processed 2 queries, with 0 matches, 1 errs
dd-tools.rc: line 4: echo: write error: File exists
[ 8.300750] dyndbg: class[0]: module:test_dynamic_debug base:22 len:8 ty:3
[ 8.301509] dyndbg: class[1]: module:test_dynamic_debug base:14 len:8 ty:1
[ 8.302189] dyndbg: class[2]: module:test_dynamic_debug base:10 len:3 ty:2
[ 8.302876] dyndbg: class[3]: module:test_dynamic_debug base:0 len:10 ty:0
[ 8.303550] dyndbg: module:test_dynamic_debug attached 4 classes
[ 8.304147] dyndbg: 32 debug prints in module test_dynamic_debug
[ 8.307165] dyndbg: read 21 bytes from userspace
[ 8.307754] dyndbg: query 0: <class,D2_CORE,+T:foo> on module: <*>
[ 8.308914] dyndbg: processed 1 queries, with 1 matches, 0 errs
[ 8.310076] dyndbg: read 20 bytes from userspace
[ 8.310916] dyndbg: query 0: <class,D2_KMS,+T:foo> on module: <*>
[ 8.311915] dyndbg: processed 1 queries, with 1 matches, 0 errs
[ 8.312764] dyndbg: read 43 bytes from userspace
[ 8.313597] dyndbg: query 0: <class D2_CORE +T:foo > on module: <*>
[ 8.314697] dyndbg: query 1: <class D2_KMS +T:foo> on module: <*>
[ 8.315687] dyndbg: processed 2 queries, with 2 matches, 0 errs
# this breaks ??
[ 8.320048] dyndbg: read 41 bytes from userspace
[ 8.320904] dyndbg: query 0: <class,D2_CORE,+T:foo> on module: <*>
[ 8.321925] dyndbg: unknown flag 'c'
[ 8.322525] dyndbg: flags parse failed on 2: +T:foo
[ 8.323348] dyndbg: query 1: <class,D2_KMS,+T:foo> on module: <*>
[ 8.324428] dyndbg: processed 2 queries, with 1 matches, 1 errs
dd-tools.rc: line 4: echo: write error: Invalid argument
[ 8.325536] dyndbg: read 41 bytes from userspace
[ 8.326305] dyndbg: query 0: <class,D2_CORE,+T:foo> on module: <*>
[ 8.327415] dyndbg: unknown flag 'c'
[ 8.328138] dyndbg: flags parse failed on 2: +T:foo
[ 8.328993] dyndbg: query 1: <class,D2_KMS,+T:foo> on module: <*>
[ 8.330035] dyndbg: processed 2 queries, with 1 matches, 1 errs
dd-tools.rc: line 4: echo: write error: Invalid argument
: 0 matches on =Tl
: 0 matches on =Tmf
did do_prints
# tracer: nop
#
# entries-in-buffer/entries-written: 3/3 #P:4
#
# _-----=> irqs-off/BH-disabled
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| / _-=> migrate-disable
# |||| / delay
# TASK-PID CPU# ||||| TIMESTAMP FUNCTION
# | | | ||||| | |
dd-selftest.rc-375 [001] ..... 6.934983: tracing_mark_write: here comes the WARN
dd-selftest.rc-375 [003] ..... 8.208645: tracing_mark_write: test_private_trace about to do_prints
dd-selftest.rc-375 [003] ..... 8.539307: tracing_mark_write: test_private_trace_2 about to do_prints
EOF
function test_private_trace_3 {
echo "# TEST_PRIVATE_TRACE_3"
ddcmd =_
rmmod test_dynamic_debug
echo 1 >/sys/kernel/tracing/tracing_on
echo 1 >/sys/kernel/tracing/events/dyndbg/enable
ddcmd open foo # gets already open err
modprobe test_dynamic_debug dyndbg=class,D2_CORE,+T:foo%class,D2_KMS,+T:foo
# triggers:
# dyndbg: query 0: <class,D2_CORE,+T:foo> on module: <*>
# dyndbg: unknown flag 'c'
# dyndbg: flags parse failed
check_matches =Tl -v
check_matches =Tmf -v
echo 1 >/sys/kernel/tracing/tracing_on
echo 1 >/sys/kernel/tracing/events/dyndbg/enable
tmark should be ready
doprints
cat /sys/kernel/tracing/trace
#rmmod test_dynamic_debug
}
test_private_trace_3;
echo -n "# done on: "
date
Jim Cromie (11):
dyndbg: export _print_hex_dump
dyndbg: tweak pr_info format s/trace dest/trace_dest/
dyndbg: disambiguate quoting in a debug msg
dyndbg: fix old BUG_ON in >control parser
dyndbg: change +T:name_terminator to dot
dyndbg: treat comma as a token separator
dyndbg: __skip_spaces
dyndbg: split multi-query strings with %
dyndbg: reduce verbose/debug clutter
dyndbg: move lock,unlock into ddebug_change, drop goto
dyndbg: id the bad word in parse-flags err msg
lib/dynamic_debug.c | 52 ++++++++++++++++++++++++++++-----------------
1 file changed, 32 insertions(+), 20 deletions(-)
--
2.43.0
pt., 8 gru 2023 o 01:15 Jim Cromie <jim.cromie@gmail.com> napisał(a):
>
> hi Lukas,
>
> Sorry for the delay, I probably should have split this up.
> (also cc'g gregkh)
>
> Ive been banging on your v2 patchset:
> https://lore.kernel.org/lkml/20231130234048.157509-1-lb@semihalf.com/
>
Jim, thank you for your thorough testing and review.
> Things are looking pretty good, a few issues follow. And some patches.
>
;)
> trivial:
>
> dyndbg: export _print_hex_dump # squash wo comment
> dyndbg: tweak pr_info format s/trace dest/trace_dest/ # greppability squash
> dyndbg: disambiguate quoting in a debug msg
> dyndbg: fix old BUG_ON in >control parser
>
> Then:
>
> dyndbg: change +T:name_terminator to dot
> dyndbg: treat comma as a token separator
>
> 1st allows 2nd, 2nd allows simpler arg-passing, boot-args, etc:
>
> echo module,test_dynamic_debug,class,L2,+p > /proc/dynamic_debug/control
> modprobe test_dynamic_debug dyndbg=class,L2,+mfl
>
> Given theres no legacy wrt comma, swapping it now with dot seems
> better semantically than "dot as token/list separator".
>
> Aside: /proc/dynamic_debug/control is always there (if configd), even
> when <debugfs> isn't mounted. Its more universal, and copy-pastable.
>
> dyndbg: __skip_spaces - and comma
> dyndbg: split multi-query strings with %
>
> % allows escape-free multi-cmd dyndbg args:
>
> modprobe test_dynamic_debug \
> dyndbg=open,selftest%class,D2_CORE,+T:selftest.mf
>
> dyndbg: reduce verbose/debug clutter
> dyndbg: move lock,unlock into ddebug_change, drop goto - revisit
>
> Ive just pushed it, I will bump my version here.
> To github.com:jimc/linux.git
> + 20d113eb6f9a...66fa2e4cb989 lukas-v2.1 -> lukas-v2.1 (forced update)
>
> SELFTEST
>
> Ive taken the liberty to write an ad-hoc test script (inline below),
> to exersize the parser with legacy command input, and with the new
> stuff mentioned above: comma-separated-tokens, %-separated-multi-cmds,
> while counting changes to builtin,etc modules, to validate against
> expectations.
>
> The change-count tests achieve some closed-loop testing, but checking
> syslog for messages written always seemed too hard/unreliable. Your
> private trace-instances work promises a solution, by giving an
> observable closed system to build upon.
>
> I made some attempts to write messages to the trace-buf, but ran out
> of clues*tuits. And I encountered a couple more definite problems:
>
Let me dig through test scripts you created and issues you run into.
> 1- modprobe/rmmod lifecycle probs
>
> Ive coded some blue-sky and not-so-proper "modprobe,+T:it,-T:it,rmmod"
> life-cycle scenarios, which can wedge a previously created instance.
> Once wedged, I cannot recover. See the test_private_trace{,_2,_3}
> functions, and the error_log_ref() following each.
>
> This brittleness begs a question; should we have auto-open (mapping
> new names to available 1-63 trc-ids) ? And non-close ? If it just did
> the right thing, particularly on rmmod, it would prevent "misuse".
>
> I don't think auto-open obsoletes the open (& esp) close commands, but
> Id like to see scripted test scenarios using close in combo with the
> right /sys/kernel/tracing/* manipulations, to prove its not all just a
> fever dream.
>
> Your expertise in opening, writing to, manipulating & destroying
> private (and the global) tracebufs, distilled into new shell funcs,
> would be enormously helpful towards demonstrating the private-buffer
> use case and its value.
>
> 2- some new flags parse error:
>
> [ 1273.074535] dyndbg: 32 debug prints in module test_dynamic_debug
> [ 1273.075365] dyndbg: module: test_dynamic_debug dyndbg="class,D2_CORE,+T:foo%class,D2_KMS,+T:foo"
> [ 1273.076307] dyndbg: query 0: <class,D2_CORE,+T:foo> on module: <test_dynamic_debug>
> [ 1273.077068] dyndbg: split into words: "class" "D2_CORE" "+T:foo"
> [ 1273.077673] dyndbg: unknown flag 'c'
> [ 1273.078033] dyndbg: flags parse failed on 2: +T:foo
> [ 1273.078519] dyndbg: query 1: <class,D2_KMS,+T:foo> on module: <test_dynamic_debug>
> [ 1273.079266] dyndbg: split into words: "class" "D2_KMS" "+T:foo"
> [ 1273.079872] dyndbg: unknown flag '�'
> [ 1273.080228] dyndbg: flags parse failed on 2: +T:foo
> [ 1273.080716] dyndbg: processed 2 queries, with 0 matches, 2 errs
> : 0 matches on =Tl
>
> I have a suspicion this relates to moving the parse_flags call in
> ddebug_query, but I havent dug in.
>
>
> I also have some reservations about the default dest; 1st that it is a
> global state var, as noted at bottom of control:
>
> [root@v6 lx]# ddgrep \\btrace\\b # a better/narrower search-term ?
> ...
> Default trace destination: foo # add a '#:' prefix to these lines ?
> Opened trace instances: # all values should be on this line
>
> Then theres the "preset" value, ie each site's dest_id (sorry I forgot
> your fieldname). I presume the default would override such a "preset"
> (otherwise it would have no effect).
>
> Is the default set on last open ? or on next use of +T:<foo> ?
>
> In the no-default world, a user/tester would decide how many
> trace-instances are needed, and map sets of callsites to them.
>
> # configure drm-debug streams for this test scenario
> cat<<EOF >/proc/dynamic_debug/control
> open drm_core
> open drm_mix
> open driver_1 # we can separate by modname but not drvr-number
> open driver_2
> class DRM_UT_CORE -T:drm_core # set dest_id, disabled state
> class DRM_UT_CORE +mf # traces dont do prefixing (should it?)
> # mix KMS & ATOMIC into 1 stream
> class DRM_UT_KMS -T:drm_mix
> class DRM_UT_ATOMIC -T:drm_mix
> EOF
>
> Then perhaps to turn on/off when needed: (legacy analogue version)
>
> echo 0x15 > /sys/module/drm/parameters/debug_trace
>
> With those trace-dest presets honored, the configured drm_core &
> drm_mix streams persist. If a later enablement applies the
> then-current default trace-dest, it would spoil this scheme.
>
> Could you elaborate a scenario or 2 where the default behavior does
> something specific, and that its the right thing ? I dont understand
> it yet.
>
> OTOH
>
> One limitation of the above: the drm.debug_trace (posited above) would
> turn on all Ts in all those class'd callsites across the whole
> subsystem, irrespective of their preconfigured destination. That was
> always inherent in drm.debug, but its less than perfect.
>
> It sort-of defeats the point of doing +T only on the useful callsites.
>
> And global event buf is also enabled, it might be flood-prone.
>
> echo 1 > /sys/kernel/tracing/events/dyndbg/enable
>
> It would help if we could filter on trace-instance names:
> (this sounds familiar :-)
>
> ddcmd module '*' trace_dest drm_mix +T
>
>
> In reality, the dest-id is not even dependent on tracing per-se, it is
> a user classification system (in contrast to class <subsys-names>).
> It just happens to be tied by +T:name syntax to tracefs.
>
> No promise about +p:_alt_log_.mflt having meaning, or working.
>
>
>
> anyway, Ive gone on long enough. heres that/those scripts
>
> cat dd-tools.rc
> #!/bin/bash
>
> function ddcmd () {
> echo $* > /proc/dynamic_debug/control
> }
> function ddcat () {
> cat $1 > /proc/dynamic_debug/control
> }
> function vx () {
> echo $1 > /sys/module/dynamic_debug/parameters/verbose
> }
> function ddgrep () {
> grep $1 /proc/dynamic_debug/control
> }
> function doprints () {
> cat /sys/module/test_dynamic_debug/parameters/do_prints
> }
>
> cat dd-selftest.rc
> #!/bin/bash
> # dd-selftest.rc: shell-fns & test-script for dynamic-debug
> # mostly run as:
> # vng --force-9p -v -e ./dd-selftest.rc
>
> . dd-tools.rc
> # vx 3
>
> function check_matches {
> let ct=$(ddgrep $1 | wc -l )
> echo ": $ct matches on $1 "
> [ "$2" == "-v" ] && ddgrep $1
> }
> function check_instance {
> # 1. trace instance name 2. -v for verbose
> if [ -e /sys/kernel/tracing/instances/$1 ]; then
> if [ "$2" == "-v" ] ; then
> echo "ls -l /sys/kernel/tracing/instances/$1: "
> ls -l /sys/kernel/tracing/instances/$1
> fi
> else
> echo "no instance: $1"
> fi
> }
> function tmark {
> echo $* > /sys/kernel/tracing/trace_marker
> }
> function read_trace_instance {
> # get traces opened, default
> tail -n9 /proc/dynamic_debug/control | grep -P \\w+ | grep -vP ^drivers/
> }
> function error_log_ref {
> # to show what I got
> : echo "# error-log-ref: $1"
> : echo cat \$2
> }
> function ifrmmod {
> lsmod | grep $1 || echo $1 not there
> lsmod | grep $1 && rmmod $1
> }
>
> echo LOADING TEST FUNCS
> echo SHLVL: $SHLVL
>
> function basic_tests {
> echo \# BASIC_TESTS
>
> ddcmd =_ "# zero everything (except class'd sites)"
> check_matches =p 0
>
> # there are several main's :-/
> ddcmd module main file */module/main.c +p
> check_matches =p 14
> ddcmd =_
> check_matches =p 0
>
> ddcmd module mptcp =_
> ddcmd module mptcp +pmf
> check_matches =pmf 120
> ddcmd =_
>
> # multi-cmd newline separated with embedded comments
> cat <<"EOF" > /proc/dynamic_debug/control
> module main +mf # multi-query
> module main file init/main.c +ml # newline separated
> module kvm +fl # comment prefixed
> module kvm_intel +flt #
> EOF
> # the intersection of all those main's is hard to track/count
> # esp when mixed with overlapping greps
> check_matches =mf 27
> check_matches =ml 0
> check_matches =mfl 6
> check_matches =fl 29
> check_matches =flt 16
> ddcmd =_
> }
> basic_tests; # run
>
> function comma_terminator_tests {
> echo \# COMMA_TERMINATOR_TESTS
>
> # try combos of space & comma
> ddcmd module,mptcp,=_
> ddcmd module,mptcp,+mf
> ddcmd " module, mptcp, +mfl"
> check_matches =pmf 120
> ddcmd module , mptcp,-p
> check_matches =mf 120
> check_matches =p 0
> ddcmd ,module ,, mptcp, -p
> ddcmd ",module ,, mptcp, -p"
> ddcmd =_
> }
> comma_terminator_tests; # run
>
> function private_trace_test {
> echo \# PRIVATE_TRACE_TEST - proper lifo cycle - open, enable:named disable:named close
>
> ddcmd open usb_stream
> check_instance usb_stream
> ddcmd module usbcore +T:usb_stream.mf
> check_matches =T:usb_stream.mf 161
> ddcmd module usbcore -T:usb_stream.mf
> check_matches =T:usb_stream.mf 0
> read_trace_instance
> ddcmd close usb_stream
> read_trace_instance
> ddcmd =_
> }
> private_trace_test; # run
>
> function test_percent_splitting {
> echo \# TEST_PERCENT_SPLITTING - multi-command splitting on %
> ddcmd =_
> modprobe test_dynamic_debug dyndbg=class,D2_CORE,+pf%class,D2_KMS,+pt%class,D2_ATOMIC,+pm
> check_matches =pf -v
> check_matches =pt -v
> check_matches =pm -v
> ddcmd class,D2_CORE,+mf%class,D2_KMS,+lt%class,D2_ATOMIC,+ml "# add some prefixes"
> check_matches =pmf -v
> check_matches =plt -v
> check_matches =pml -v
> doprints
> ifrmmod test_dynamic_debug
> }
> test_percent_splitting; # run
>
> function test_actual_trace {
> echo \# test_actual_trace
> ddcmd =_
> ifrmmod test_dynamic_debug
> echo 1 >/sys/kernel/tracing/tracing_on
> echo 1 >/sys/kernel/tracing/events/dyndbg/enable
>
> modprobe test_dynamic_debug dyndbg=class,D2_CORE,+T
> check_matches =T -v
> tmark here comes the WARN
> doprints
> cat /sys/kernel/tracing/trace
> }
> test_actual_trace; # run, hits 1313: WARN_ON_ONCE(!arr)
>
> error_log_ref test_actual_trace <<"EO_LOG"
> [ 6.587595] dyndbg: read 3 bytes from userspace
> [ 6.588174] dyndbg: query 0: <=_> on module: <*>
> [ 6.588842] dyndbg: processed 1 queries, with 3236 matches, 0 errs
> [ 6.726160] dyndbg: class[0]: module:test_dynamic_debug base:22 len:8 ty:3
> [ 6.727052] dyndbg: class[1]: module:test_dynamic_debug base:14 len:8 ty:1
> [ 6.728158] dyndbg: class[2]: module:test_dynamic_debug base:10 len:3 ty:2
> [ 6.729112] dyndbg: class[3]: module:test_dynamic_debug base:0 len:10 ty:0
> [ 6.729969] dyndbg: module:test_dynamic_debug attached 4 classes
> [ 6.730729] dyndbg: 32 debug prints in module test_dynamic_debug
> [ 6.731494] dyndbg: module: test_dynamic_debug dyndbg="class,D2_CORE,+T"
> [ 6.732350] dyndbg: query 0: <class,D2_CORE,+T> on module: <test_dynamic_debug>
> [ 6.733291] dyndbg: processed 1 queries, with 1 matches, 0 errs
> [ 6.734224] ------------[ cut here ]------------
> [ 6.734811] WARNING: CPU: 1 PID: 472 at lib/dynamic_debug.c:1309 ddebug_printk+0xde/0xf0
> [ 6.735814] Modules linked in: test_dynamic_debug(E+) intel_rapl_msr(E) crc32_pclmul(E) intel_rapl_common(E) ghash_clmulni_intel(E) crct10dif_pclmul(E) crc32c_intel(E) joydev(E) serio_raw(E) pcspkr(E) i2c_piix4(E) [last unloaded: test_dynamic_debug(E)]
> [ 6.738594] CPU: 1 PID: 472 Comm: modprobe Tainted: G W E 6.6.0-tf2-virtme-00026-g20d113eb6f9a-dirty #220
> [ 6.740008] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.16.3-0-ga6ed6b701f0a-prebuilt.qemu.org 04/01/2014
> [ 6.741669] RIP: 0010:ddebug_printk+0xde/0xf0
> [ 6.742220] Code: 48 8d 44 24 28 48 89 44 24 20 e8 ed 71 9c ff 48 83 c4 58 5b 41 5c 5d c3 48 8d 56 02 48 8d 4c 24 10 31 f6 e8 84 f9 ff ff eb b5 <0f> 0b eb a0 66 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 00 41 57 48 89
> [ 6.745072] RSP: 0018:ffffb38140453bd0 EFLAGS: 00010246
> [ 6.745914] RAX: 0000000000000000 RBX: ffffffffc03b97e0 RCX: ffffb38140453c50
> [ 6.747002] RDX: ffffb38140453be0 RSI: ffffffffb26f8150 RDI: 0000000000000000
> [ 6.747883] RBP: ffffb38140453c38 R08: 0000000000000020 R09: ffffffffb3370ce4
> [ 6.748753] R10: 0000000000000001 R11: 0000000000010000 R12: ffffffffb26f8150
> [ 6.749586] R13: ffff9b68029bc440 R14: ffff9b6805640800 R15: ffff9b6805c9d640
> [ 6.750497] FS: 00007f7cdc453740(0000) GS:ffff9b683ec80000(0000) knlGS:0000000000000000
> [ 6.751537] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> [ 6.752310] CR2: 000055ce7a609ae0 CR3: 000000000575a000 CR4: 0000000000750ee0
> [ 6.753238] PKRU: 55555554
> [ 6.753604] Call Trace:
> [ 6.753910] <TASK>
> [ 6.754240] ? ddebug_printk+0xde/0xf0
> [ 6.754772] ? __warn+0x7d/0x130
> [ 6.755197] ? ddebug_printk+0xde/0xf0
> [ 6.755669] ? report_bug+0x189/0x1c0
> [ 6.756176] ? handle_bug+0x38/0x70
> [ 6.756642] ? exc_invalid_op+0x13/0x60
> [ 6.757112] ? asm_exc_invalid_op+0x16/0x20
> [ 6.757635] ? ddebug_printk+0xde/0xf0
> [ 6.758123] ? 0xffffffffc03c0000
> [ 6.758533] __dynamic_pr_debug+0x133/0x170
> [ 6.759066] ? 0xffffffffc03c0000
> [ 6.759438] do_cats+0x127/0x180 [test_dynamic_debug]
> [ 6.760063] test_dynamic_debug_init+0x7/0x1000 [test_dynamic_debug]
> [ 6.760890] do_one_initcall+0x43/0x2f0
> [ 6.761399] ? kmalloc_trace+0x26/0x90
> [ 6.761904] do_init_module+0x9d/0x290
> [ 6.762377] init_module_from_file+0x77/0xd0
> [ 6.762877] idempotent_init_module+0xf9/0x270
> [ 6.763439] __x64_sys_finit_module+0x5a/0xb0
> [ 6.764040] do_syscall_64+0x35/0x80
> [ 6.764474] entry_SYSCALL_64_after_hwframe+0x46/0xb0
> [ 6.765089] RIP: 0033:0x7f7cdc56b5ad
> [ 6.765522] Code: ff c3 66 2e 0f 1f 84 00 00 00 00 00 90 f3 0f 1e fa 48 89 f8 48 89 f7 48 89 d6 48 89 ca 4d 89 c2 4d 89 c8 4c 8b 4c 24 08 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d 53 48 0c 00 f7 d8 64 89 01 48
> [ 6.767763] RSP: 002b:00007fff198e28d8 EFLAGS: 00000246 ORIG_RAX: 0000000000000139
> [ 6.768781] RAX: ffffffffffffffda RBX: 000055ce7bb53980 RCX: 00007f7cdc56b5ad
> [ 6.769611] RDX: 0000000000000000 RSI: 000055ce7bb72930 RDI: 0000000000000006
> [ 6.770598] RBP: 00007fff198e2990 R08: 0000000000000000 R09: 0000000000000002
> [ 6.771447] R10: 0000000000000006 R11: 0000000000000246 R12: 000055ce7bb72930
> [ 6.772328] R13: 0000000000040000 R14: 000055ce7bb53bc0 R15: 000055ce7bb72930
> [ 6.773252] </TASK>
> [ 6.773532] ---[ end trace 0000000000000000 ]---
> : 2 matches on =T
> drivers/cpufreq/intel_pstate.c:1912 [intel_pstate]core_get_max_pstate =_ "max_pstate=TAC %x\n"
> lib/test_dynamic_debug.c:109 [test_dynamic_debug]do_cats =T:(null) "D2_CORE msg\n" class:D2_CORE
> did do_prints
> # tracer: nop
> #
> # entries-in-buffer/entries-written: 0/0 #P:4
> EO_LOG
>
> # that 2nd =T match has :(null) in the control-line. I didnt chase it.
>
> function test_early_close () {
> ddcmd open usb_stream
> ddcmd module usbcore +T:usb_stream.mf
> check_matches =T:usb_stream.mf 161
> echo ":not-running # ddcmd module usbcore -T:usb_stream.mf"
> ddcmd close usb_stream
> }
> # test_early_close - works, unused, refactored below.
> function self_start {
> echo \# open, modprobe +T:it
> ddcmd open selftest
> check_instance selftest
> modprobe test_dynamic_debug dyndbg=+T:selftest.mf
> check_matches =T:selftest.mf -v
> }
> function self_end_normal {
> echo \# disable -T:it, rmmod, close
> ddcmd module test_dynamic_debug -T:selftest # leave mf
> check_matches =mf -v
> ifrmmod test_dynamic_debug
> ddcmd close selftest
> }
> function self_end_disable_anon {
> echo \# disable, close, rmmod
> ddcmd module test_dynamic_debug -T
> check_matches =mf -v
> ddcmd close selftest
> ifrmmod test_dynamic_debug
> }
> function self_end_disable_anon_mf {
> echo \# disable, close, rmmod
> ddcmd module test_dynamic_debug -Tf
> check_matches =m -v
> ddcmd close selftest
> ifrmmod test_dynamic_debug
> }
> function self_end_nodisable {
> echo \# SKIPPING: ddcmd module test_dynamic_debug -T:selftest
> rmmod test_dynamic_debug
> echo FAIL_COMING on close
> ddcmd close selftest
> }
> function self_test_ {
> echo "# SELFTEST $1"
> self_start
> self_end_$1
> }
>
> function cycle_tests_normal {
> echo \# CYCLE_TESTS_NORMAL
>
> self_test_ normal # ok
> self_test_ disable_anon # ok
> ddgrep selftest
>
> self_test_ normal # ok
> self_test_ disable_anon_mf #
> ddgrep selftest
> }
> cycle_tests_normal; # run
>
> function cycle_tests_problem {
> self_test_ nodisable # write error: Device or resource busy
> ddgrep selftest # still used, defaulted - prob
>
> self_test_ normal # open error, write error persists
> ddgrep selftest # still used, defaulted
>
> ddcmd close selftest # too late ??
> }
> # cycle_tests_problem;
>
>
> function test_private_trace {
> echo "# TEST_PRIVATE_TRACE"
> ddcmd =_
>
> ifrmmod test_dynamic_debug
> echo 1 >/sys/kernel/tracing/tracing_on
> echo 1 >/sys/kernel/tracing/events/dyndbg/enable
>
> ddcmd open foo
> modprobe test_dynamic_debug
> ddcmd class,D2_CORE,+T:foo,%class,D2_KMS,+T:foo
>
> check_matches =Tl -v
> check_matches =Tmf -v
> echo 1 >/sys/kernel/tracing/tracing_on
> echo 1 >/sys/kernel/tracing/events/dyndbg/enable
> tmark test_private_trace about to do_prints
> doprints
> cat /sys/kernel/tracing/trace
>
> ddcmd class,D2_CORE,-T:foo
> ddcmd close foo
> ddcmd close bar
> ifrmmod test_dynamic_debug
> }
> test_private_trace; # run
>
> error_log_ref test_private_trace <<EOF
> # test_private_trace
> [ 7.803744] dyndbg: read 3 bytes from userspace
> [ 7.804329] dyndbg: query 0: <=_> on module: <*>
> [ 7.804844] dyndbg: processed 1 queries, with 3236 matches, 0 errs
> rmmod: ERROR: Module test_dynamic_debug is not currently loaded
> [ 7.838191] dyndbg: read 9 bytes from userspace
> [ 7.838858] dyndbg: query 0: <open foo> on module: <*>
> [ 7.872066] dyndbg: processed 1 queries, with 0 matches, 0 errs
> [ 7.991723] dyndbg: class[0]: module:test_dynamic_debug base:22 len:8 ty:3
> [ 7.992488] dyndbg: class[1]: module:test_dynamic_debug base:14 len:8 ty:1
> [ 7.993178] dyndbg: class[2]: module:test_dynamic_debug base:10 len:3 ty:2
> [ 7.993873] dyndbg: class[3]: module:test_dynamic_debug base:0 len:10 ty:0
> [ 7.994560] dyndbg: module:test_dynamic_debug attached 4 classes
> [ 7.995174] dyndbg: 32 debug prints in module test_dynamic_debug
> [ 7.998426] dyndbg: read 42 bytes from userspace
> [ 7.999169] dyndbg: query 0: <class,D2_CORE,+T:foo,> on module: <*>
> [ 8.000126] dyndbg: query 1: <class,D2_KMS,+T:foo> on module: <*>
> [ 8.000956] dyndbg: processed 2 queries, with 2 matches, 0 errs
> : 0 matches on =Tl
> : 0 matches on =Tmf
> did do_prints
> # tracer: nop
> #
> # entries-in-buffer/entries-written: 2/2 #P:4
> #
> # _-----=> irqs-off/BH-disabled
> # / _----=> need-resched
> # | / _---=> hardirq/softirq
> # || / _--=> preempt-depth
> # ||| / _-=> migrate-disable
> # |||| / delay
> # TASK-PID CPU# ||||| TIMESTAMP FUNCTION
> # | | | ||||| | |
> dd-selftest.rc-375 [003] ..... 6.876234: tracing_mark_write: here comes the WARN
> dd-selftest.rc-375 [003] ..... 8.168406: tracing_mark_write: should be ready
> [ 8.093538] dyndbg: read 21 bytes from userspace
> [ 8.094156] dyndbg: query 0: <class,D2_CORE,-T:foo> on module: <*>
> [ 8.094924] dyndbg: processed 1 queries, with 1 matches, 0 errs
> [ 8.095560] dyndbg: read 10 bytes from userspace
> [ 8.096038] dyndbg: query 0: <close foo> on module: <*>
> [ 8.096565] dyndbg: trace instance is being used name=foo, use_cnt=1
> [ 8.097198] dyndbg: processed 1 queries, with 0 matches, 1 errs
> dd-tools.rc: line 4: echo: write error: Device or resource busy
> [ 8.097850] dyndbg: read 10 bytes from userspace
> [ 8.098356] dyndbg: query 0: <close bar> on module: <*>
> [ 8.098887] dyndbg: processed 1 queries, with 0 matches, 1 errs
> dd-tools.rc: line 4: echo: write error: No such file or directory
> EOF
>
> function test_private_trace_2 {
> echo "# TEST_PRIVATE_TRACE_2"
>
> ddcmd =_
> rmmod test_dynamic_debug
> echo 1 >/sys/kernel/tracing/tracing_on
> echo 1 >/sys/kernel/tracing/events/dyndbg/enable
>
> ddcmd open foo \; open bar # 2nd fails
> modprobe test_dynamic_debug
> ddcmd class,D2_CORE,+T:foo
> ddcmd class,D2_KMS,+T:foo
> ddcmd class D2_CORE +T:foo \; class D2_KMS +T:foo
>
> echo \# this breaks ??
> ddcmd "class,D2_CORE,+T:foo;,class,D2_KMS,+T:foo"
> # ddcmd class,D2_CORE,+T:foo\;class,D2_KMS,+T:foo
>
> check_matches =Tl -v
> check_matches =Tmf -v
> echo 1 >/sys/kernel/tracing/tracing_on
> echo 1 >/sys/kernel/tracing/events/dyndbg/enable
> tmark test_private_trace_2 about to do_prints
> doprints
> cat /sys/kernel/tracing/trace
> #rmmod test_dynamic_debug
> }
> test_private_trace_2; # run
>
> # a real parse error in this log, with same input as worked above.
> # the unkown flag 'c' error conflicts with what the following error
> # says is the flags token
>
> error_log_ref test_private_trace_2 <<EOF
> [ 8.107982] d# test_private_trace_2
> yndbg: read 3 bytes from userspace
> [ 8.108490] dyndbg: query 0: <=_> on module: <*>
> [ 8.108997] dyndbg: processed 1 queries, with 3241 matches, 0 errs
> [ 8.139645] dyndbg: removed module "test_dynamic_debug"
> [ 8.152344] dyndbg: read 20 bytes from userspace
> [ 8.152952] dyndbg: query 0: <open foo > on module: <*>
> [ 8.153610] dyndbg: instance is already opened name:foo
> [ 8.153610]
> [ 8.153612] dyndbg: query 1: <open bar> on module: <*>
> [ 8.185399] dyndbg: processed 2 queries, with 0 matches, 1 errs
> dd-tools.rc: line 4: echo: write error: File exists
> [ 8.300750] dyndbg: class[0]: module:test_dynamic_debug base:22 len:8 ty:3
> [ 8.301509] dyndbg: class[1]: module:test_dynamic_debug base:14 len:8 ty:1
> [ 8.302189] dyndbg: class[2]: module:test_dynamic_debug base:10 len:3 ty:2
> [ 8.302876] dyndbg: class[3]: module:test_dynamic_debug base:0 len:10 ty:0
> [ 8.303550] dyndbg: module:test_dynamic_debug attached 4 classes
> [ 8.304147] dyndbg: 32 debug prints in module test_dynamic_debug
> [ 8.307165] dyndbg: read 21 bytes from userspace
> [ 8.307754] dyndbg: query 0: <class,D2_CORE,+T:foo> on module: <*>
> [ 8.308914] dyndbg: processed 1 queries, with 1 matches, 0 errs
> [ 8.310076] dyndbg: read 20 bytes from userspace
> [ 8.310916] dyndbg: query 0: <class,D2_KMS,+T:foo> on module: <*>
> [ 8.311915] dyndbg: processed 1 queries, with 1 matches, 0 errs
> [ 8.312764] dyndbg: read 43 bytes from userspace
> [ 8.313597] dyndbg: query 0: <class D2_CORE +T:foo > on module: <*>
> [ 8.314697] dyndbg: query 1: <class D2_KMS +T:foo> on module: <*>
> [ 8.315687] dyndbg: processed 2 queries, with 2 matches, 0 errs
> # this breaks ??
> [ 8.320048] dyndbg: read 41 bytes from userspace
> [ 8.320904] dyndbg: query 0: <class,D2_CORE,+T:foo> on module: <*>
> [ 8.321925] dyndbg: unknown flag 'c'
> [ 8.322525] dyndbg: flags parse failed on 2: +T:foo
> [ 8.323348] dyndbg: query 1: <class,D2_KMS,+T:foo> on module: <*>
> [ 8.324428] dyndbg: processed 2 queries, with 1 matches, 1 errs
> dd-tools.rc: line 4: echo: write error: Invalid argument
> [ 8.325536] dyndbg: read 41 bytes from userspace
> [ 8.326305] dyndbg: query 0: <class,D2_CORE,+T:foo> on module: <*>
> [ 8.327415] dyndbg: unknown flag 'c'
> [ 8.328138] dyndbg: flags parse failed on 2: +T:foo
> [ 8.328993] dyndbg: query 1: <class,D2_KMS,+T:foo> on module: <*>
> [ 8.330035] dyndbg: processed 2 queries, with 1 matches, 1 errs
> dd-tools.rc: line 4: echo: write error: Invalid argument
> : 0 matches on =Tl
> : 0 matches on =Tmf
> did do_prints
> # tracer: nop
> #
> # entries-in-buffer/entries-written: 3/3 #P:4
> #
> # _-----=> irqs-off/BH-disabled
> # / _----=> need-resched
> # | / _---=> hardirq/softirq
> # || / _--=> preempt-depth
> # ||| / _-=> migrate-disable
> # |||| / delay
> # TASK-PID CPU# ||||| TIMESTAMP FUNCTION
> # | | | ||||| | |
> dd-selftest.rc-375 [001] ..... 6.934983: tracing_mark_write: here comes the WARN
> dd-selftest.rc-375 [003] ..... 8.208645: tracing_mark_write: test_private_trace about to do_prints
> dd-selftest.rc-375 [003] ..... 8.539307: tracing_mark_write: test_private_trace_2 about to do_prints
> EOF
>
> function test_private_trace_3 {
> echo "# TEST_PRIVATE_TRACE_3"
>
> ddcmd =_
> rmmod test_dynamic_debug
> echo 1 >/sys/kernel/tracing/tracing_on
> echo 1 >/sys/kernel/tracing/events/dyndbg/enable
>
> ddcmd open foo # gets already open err
> modprobe test_dynamic_debug dyndbg=class,D2_CORE,+T:foo%class,D2_KMS,+T:foo
> # triggers:
> # dyndbg: query 0: <class,D2_CORE,+T:foo> on module: <*>
> # dyndbg: unknown flag 'c'
> # dyndbg: flags parse failed
>
> check_matches =Tl -v
> check_matches =Tmf -v
> echo 1 >/sys/kernel/tracing/tracing_on
> echo 1 >/sys/kernel/tracing/events/dyndbg/enable
> tmark should be ready
> doprints
> cat /sys/kernel/tracing/trace
> #rmmod test_dynamic_debug
> }
> test_private_trace_3;
>
> echo -n "# done on: "
> date
>
>
> Jim Cromie (11):
> dyndbg: export _print_hex_dump
> dyndbg: tweak pr_info format s/trace dest/trace_dest/
> dyndbg: disambiguate quoting in a debug msg
> dyndbg: fix old BUG_ON in >control parser
> dyndbg: change +T:name_terminator to dot
> dyndbg: treat comma as a token separator
> dyndbg: __skip_spaces
> dyndbg: split multi-query strings with %
> dyndbg: reduce verbose/debug clutter
> dyndbg: move lock,unlock into ddebug_change, drop goto
> dyndbg: id the bad word in parse-flags err msg
>
> lib/dynamic_debug.c | 52 ++++++++++++++++++++++++++++-----------------
> 1 file changed, 32 insertions(+), 20 deletions(-)
>
> --
> 2.43.0
>
sob., 9 gru 2023 o 01:31 Łukasz Bartosik <lb@semihalf.com> napisał(a):
>
> pt., 8 gru 2023 o 01:15 Jim Cromie <jim.cromie@gmail.com> napisał(a):
> >
> > hi Lukas,
> >
> > Sorry for the delay, I probably should have split this up.
> > (also cc'g gregkh)
> >
> > Ive been banging on your v2 patchset:
> > https://lore.kernel.org/lkml/20231130234048.157509-1-lb@semihalf.com/
> >
>
> Jim, thank you for your thorough testing and review.
>
> > Things are looking pretty good, a few issues follow. And some patches.
> >
>
> ;)
>
> > trivial:
> >
> > dyndbg: export _print_hex_dump # squash wo comment
> > dyndbg: tweak pr_info format s/trace dest/trace_dest/ # greppability squash
> > dyndbg: disambiguate quoting in a debug msg
> > dyndbg: fix old BUG_ON in >control parser
> >
> > Then:
> >
> > dyndbg: change +T:name_terminator to dot
> > dyndbg: treat comma as a token separator
> >
> > 1st allows 2nd, 2nd allows simpler arg-passing, boot-args, etc:
> >
> > echo module,test_dynamic_debug,class,L2,+p > /proc/dynamic_debug/control
> > modprobe test_dynamic_debug dyndbg=class,L2,+mfl
> >
> > Given theres no legacy wrt comma, swapping it now with dot seems
> > better semantically than "dot as token/list separator".
> >
> > Aside: /proc/dynamic_debug/control is always there (if configd), even
> > when <debugfs> isn't mounted. Its more universal, and copy-pastable.
> >
> > dyndbg: __skip_spaces - and comma
> > dyndbg: split multi-query strings with %
> >
> > % allows escape-free multi-cmd dyndbg args:
> >
> > modprobe test_dynamic_debug \
> > dyndbg=open,selftest%class,D2_CORE,+T:selftest.mf
> >
> > dyndbg: reduce verbose/debug clutter
> > dyndbg: move lock,unlock into ddebug_change, drop goto - revisit
> >
> > Ive just pushed it, I will bump my version here.
> > To github.com:jimc/linux.git
> > + 20d113eb6f9a...66fa2e4cb989 lukas-v2.1 -> lukas-v2.1 (forced update)
> >
hi Jim,
I will squash the following commits to their appropriate peers:
- dyndbg: export _print_hex_dump
- dyndbg: tweak pr_info format s/trace dest/trace_dest/
- dyndbg: change +T:name_terminator to dot
I will also drop completely "dyndbg: move lock,unlock into
ddebug_change, drop goto" and leave the remaining commits as is.
> > SELFTEST
> >
> > Ive taken the liberty to write an ad-hoc test script (inline below),
> > to exersize the parser with legacy command input, and with the new
> > stuff mentioned above: comma-separated-tokens, %-separated-multi-cmds,
> > while counting changes to builtin,etc modules, to validate against
> > expectations.
> >
> > The change-count tests achieve some closed-loop testing, but checking
> > syslog for messages written always seemed too hard/unreliable. Your
> > private trace-instances work promises a solution, by giving an
> > observable closed system to build upon.
> >
> > I made some attempts to write messages to the trace-buf, but ran out
> > of clues*tuits. And I encountered a couple more definite problems:
> >
>
> Let me dig through test scripts you created and issues you run into.
>
>
> > 1- modprobe/rmmod lifecycle probs
> >
> > Ive coded some blue-sky and not-so-proper "modprobe,+T:it,-T:it,rmmod"
> > life-cycle scenarios, which can wedge a previously created instance.
> > Once wedged, I cannot recover. See the test_private_trace{,_2,_3}
> > functions, and the error_log_ref() following each.
> >
The tests are very useful. I root caused the failures. Please see below.
> > This brittleness begs a question; should we have auto-open (mapping
> > new names to available 1-63 trc-ids) ? And non-close ? If it just did
> > the right thing, particularly on rmmod, it would prevent "misuse".
> >
I would rather not have auto-open. For me personal argument against it is
that I usually make a lot of typos and with auto-open if I don't
verify what I wrote
I won't know whether logs will be written to the "right" instance or a
newly created instance
with typo name. In case of open/close commands error pops up when I
try to write logs
to a trace instance which was not opened.
> > I don't think auto-open obsoletes the open (& esp) close commands, but
> > Id like to see scripted test scenarios using close in combo with the
> > right /sys/kernel/tracing/* manipulations, to prove its not all just a
> > fever dream.
> >
Would you please elaborate what you mean by close in combo with right
/sys/kernel/tracing/* manipulations ?
> > Your expertise in opening, writing to, manipulating & destroying
> > private (and the global) tracebufs, distilled into new shell funcs,
> > would be enormously helpful towards demonstrating the private-buffer
> > use case and its value.
> >
I will work on adding new tests for trace.
> > 2- some new flags parse error:
> >
> > [ 1273.074535] dyndbg: 32 debug prints in module test_dynamic_debug
> > [ 1273.075365] dyndbg: module: test_dynamic_debug dyndbg="class,D2_CORE,+T:foo%class,D2_KMS,+T:foo"
> > [ 1273.076307] dyndbg: query 0: <class,D2_CORE,+T:foo> on module: <test_dynamic_debug>
> > [ 1273.077068] dyndbg: split into words: "class" "D2_CORE" "+T:foo"
> > [ 1273.077673] dyndbg: unknown flag 'c'
> > [ 1273.078033] dyndbg: flags parse failed on 2: +T:foo
> > [ 1273.078519] dyndbg: query 1: <class,D2_KMS,+T:foo> on module: <test_dynamic_debug>
> > [ 1273.079266] dyndbg: split into words: "class" "D2_KMS" "+T:foo"
> > [ 1273.079872] dyndbg: unknown flag '�'
> > [ 1273.080228] dyndbg: flags parse failed on 2: +T:foo
> > [ 1273.080716] dyndbg: processed 2 queries, with 0 matches, 2 errs
> > : 0 matches on =Tl
> >
> > I have a suspicion this relates to moving the parse_flags call in
> > ddebug_query, but I havent dug in.
> >
> >
> > I also have some reservations about the default dest; 1st that it is a
> > global state var, as noted at bottom of control:
> >
> > [root@v6 lx]# ddgrep \\btrace\\b # a better/narrower search-term ?
> > ...
> > Default trace destination: foo # add a '#:' prefix to these lines ?
Do you mean
#: Default trace destination:
#: Opened trace instances:
or
Default trace destination: #:foo
Opened trace instances: #:foo, #:bar
> > Opened trace instances: # all values should be on this line
> >
I will put all opened trace instance names on the same line
> > Then theres the "preset" value, ie each site's dest_id (sorry I forgot
> > your fieldname). I presume the default would override such a "preset"
> > (otherwise it would have no effect).
> >
> > Is the default set on last open ? or on next use of +T:<foo> ?
> >
Default trace destination is set on [+-]T:<foo>
> > In the no-default world, a user/tester would decide how many
> > trace-instances are needed, and map sets of callsites to them.
> >
> > # configure drm-debug streams for this test scenario
> > cat<<EOF >/proc/dynamic_debug/control
> > open drm_core
> > open drm_mix
> > open driver_1 # we can separate by modname but not drvr-number
> > open driver_2
> > class DRM_UT_CORE -T:drm_core # set dest_id, disabled state
This sets default trace destination to drm_core
> > class DRM_UT_CORE +mf # traces dont do prefixing (should it?)
In this case logs will be neither written to syslog nor trace because
both pT flags are not set.
I verified that both output to trace instance and trace events honors
mf flags (prefixing) when they are set for a given callsite.
> > # mix KMS & ATOMIC into 1 stream
> > class DRM_UT_KMS -T:drm_mix
> > class DRM_UT_ATOMIC -T:drm_mix
> > EOF
> >
> > Then perhaps to turn on/off when needed: (legacy analogue version)
> >
> > echo 0x15 > /sys/module/drm/parameters/debug_trace
> >
> > With those trace-dest presets honored, the configured drm_core &
> > drm_mix streams persist. If a later enablement applies the
> > then-current default trace-dest, it would spoil this scheme.
> >
> > Could you elaborate a scenario or 2 where the default behavior does
> > something specific, and that its the right thing ? I dont understand
> > it yet.
> >
I'm a bit lost here. Help me out please. What do you mean by default behavior ?
> > OTOH
> >
> > One limitation of the above: the drm.debug_trace (posited above) would
> > turn on all Ts in all those class'd callsites across the whole
> > subsystem, irrespective of their preconfigured destination. That was
> > always inherent in drm.debug, but its less than perfect.
> >
> > It sort-of defeats the point of doing +T only on the useful callsites.
> >
> > And global event buf is also enabled, it might be flood-prone.
> >
> > echo 1 > /sys/kernel/tracing/events/dyndbg/enable
> >
> > It would help if we could filter on trace-instance names:
> > (this sounds familiar :-)
> >
> > ddcmd module '*' trace_dest drm_mix +T
> >
> >
> > In reality, the dest-id is not even dependent on tracing per-se, it is
> > a user classification system (in contrast to class <subsys-names>).
> > It just happens to be tied by +T:name syntax to tracefs.
> >
> > No promise about +p:_alt_log_.mflt having meaning, or working.
> >
> >
> >
> > anyway, Ive gone on long enough. heres that/those scripts
> >
> > cat dd-tools.rc
> > #!/bin/bash
> >
> > function ddcmd () {
> > echo $* > /proc/dynamic_debug/control
> > }
> > function ddcat () {
> > cat $1 > /proc/dynamic_debug/control
> > }
> > function vx () {
> > echo $1 > /sys/module/dynamic_debug/parameters/verbose
> > }
> > function ddgrep () {
> > grep $1 /proc/dynamic_debug/control
> > }
> > function doprints () {
> > cat /sys/module/test_dynamic_debug/parameters/do_prints
> > }
> >
> > cat dd-selftest.rc
> > #!/bin/bash
> > # dd-selftest.rc: shell-fns & test-script for dynamic-debug
> > # mostly run as:
> > # vng --force-9p -v -e ./dd-selftest.rc
> >
> > . dd-tools.rc
> > # vx 3
> >
> > function check_matches {
> > let ct=$(ddgrep $1 | wc -l )
> > echo ": $ct matches on $1 "
> > [ "$2" == "-v" ] && ddgrep $1
> > }
> > function check_instance {
> > # 1. trace instance name 2. -v for verbose
> > if [ -e /sys/kernel/tracing/instances/$1 ]; then
> > if [ "$2" == "-v" ] ; then
> > echo "ls -l /sys/kernel/tracing/instances/$1: "
> > ls -l /sys/kernel/tracing/instances/$1
> > fi
> > else
> > echo "no instance: $1"
> > fi
> > }
> > function tmark {
> > echo $* > /sys/kernel/tracing/trace_marker
> > }
> > function read_trace_instance {
> > # get traces opened, default
> > tail -n9 /proc/dynamic_debug/control | grep -P \\w+ | grep -vP ^drivers/
> > }
> > function error_log_ref {
> > # to show what I got
> > : echo "# error-log-ref: $1"
> > : echo cat \$2
> > }
> > function ifrmmod {
> > lsmod | grep $1 || echo $1 not there
> > lsmod | grep $1 && rmmod $1
> > }
> >
> > echo LOADING TEST FUNCS
> > echo SHLVL: $SHLVL
> >
> > function basic_tests {
> > echo \# BASIC_TESTS
> >
> > ddcmd =_ "# zero everything (except class'd sites)"
> > check_matches =p 0
> >
> > # there are several main's :-/
> > ddcmd module main file */module/main.c +p
> > check_matches =p 14
> > ddcmd =_
> > check_matches =p 0
> >
> > ddcmd module mptcp =_
> > ddcmd module mptcp +pmf
> > check_matches =pmf 120
> > ddcmd =_
> >
> > # multi-cmd newline separated with embedded comments
> > cat <<"EOF" > /proc/dynamic_debug/control
> > module main +mf # multi-query
> > module main file init/main.c +ml # newline separated
> > module kvm +fl # comment prefixed
> > module kvm_intel +flt #
> > EOF
> > # the intersection of all those main's is hard to track/count
> > # esp when mixed with overlapping greps
> > check_matches =mf 27
> > check_matches =ml 0
> > check_matches =mfl 6
> > check_matches =fl 29
> > check_matches =flt 16
> > ddcmd =_
> > }
> > basic_tests; # run
> >
> > function comma_terminator_tests {
> > echo \# COMMA_TERMINATOR_TESTS
> >
> > # try combos of space & comma
> > ddcmd module,mptcp,=_
> > ddcmd module,mptcp,+mf
> > ddcmd " module, mptcp, +mfl"
> > check_matches =pmf 120
> > ddcmd module , mptcp,-p
> > check_matches =mf 120
> > check_matches =p 0
> > ddcmd ,module ,, mptcp, -p
> > ddcmd ",module ,, mptcp, -p"
> > ddcmd =_
> > }
> > comma_terminator_tests; # run
> >
> > function private_trace_test {
> > echo \# PRIVATE_TRACE_TEST - proper lifo cycle - open, enable:named disable:named close
> >
> > ddcmd open usb_stream
> > check_instance usb_stream
> > ddcmd module usbcore +T:usb_stream.mf
> > check_matches =T:usb_stream.mf 161
> > ddcmd module usbcore -T:usb_stream.mf
> > check_matches =T:usb_stream.mf 0
> > read_trace_instance
> > ddcmd close usb_stream
> > read_trace_instance
> > ddcmd =_
> > }
> > private_trace_test; # run
> >
> > function test_percent_splitting {
> > echo \# TEST_PERCENT_SPLITTING - multi-command splitting on %
> > ddcmd =_
> > modprobe test_dynamic_debug dyndbg=class,D2_CORE,+pf%class,D2_KMS,+pt%class,D2_ATOMIC,+pm
> > check_matches =pf -v
> > check_matches =pt -v
> > check_matches =pm -v
> > ddcmd class,D2_CORE,+mf%class,D2_KMS,+lt%class,D2_ATOMIC,+ml "# add some prefixes"
> > check_matches =pmf -v
> > check_matches =plt -v
> > check_matches =pml -v
> > doprints
> > ifrmmod test_dynamic_debug
> > }
> > test_percent_splitting; # run
> >
> > function test_actual_trace {
> > echo \# test_actual_trace
> > ddcmd =_
> > ifrmmod test_dynamic_debug
> > echo 1 >/sys/kernel/tracing/tracing_on
> > echo 1 >/sys/kernel/tracing/events/dyndbg/enable
> >
> > modprobe test_dynamic_debug dyndbg=class,D2_CORE,+T
> > check_matches =T -v
> > tmark here comes the WARN
> > doprints
> > cat /sys/kernel/tracing/trace
> > }
> > test_actual_trace; # run, hits 1313: WARN_ON_ONCE(!arr)
> >
> > error_log_ref test_actual_trace <<"EO_LOG"
> > [ 6.587595] dyndbg: read 3 bytes from userspace
> > [ 6.588174] dyndbg: query 0: <=_> on module: <*>
> > [ 6.588842] dyndbg: processed 1 queries, with 3236 matches, 0 errs
> > [ 6.726160] dyndbg: class[0]: module:test_dynamic_debug base:22 len:8 ty:3
> > [ 6.727052] dyndbg: class[1]: module:test_dynamic_debug base:14 len:8 ty:1
> > [ 6.728158] dyndbg: class[2]: module:test_dynamic_debug base:10 len:3 ty:2
> > [ 6.729112] dyndbg: class[3]: module:test_dynamic_debug base:0 len:10 ty:0
> > [ 6.729969] dyndbg: module:test_dynamic_debug attached 4 classes
> > [ 6.730729] dyndbg: 32 debug prints in module test_dynamic_debug
> > [ 6.731494] dyndbg: module: test_dynamic_debug dyndbg="class,D2_CORE,+T"
> > [ 6.732350] dyndbg: query 0: <class,D2_CORE,+T> on module: <test_dynamic_debug>
> > [ 6.733291] dyndbg: processed 1 queries, with 1 matches, 0 errs
> > [ 6.734224] ------------[ cut here ]------------
> > [ 6.734811] WARNING: CPU: 1 PID: 472 at lib/dynamic_debug.c:1309 ddebug_printk+0xde/0xf0
> > [ 6.735814] Modules linked in: test_dynamic_debug(E+) intel_rapl_msr(E) crc32_pclmul(E) intel_rapl_common(E) ghash_clmulni_intel(E) crct10dif_pclmul(E) crc32c_intel(E) joydev(E) serio_raw(E) pcspkr(E) i2c_piix4(E) [last unloaded: test_dynamic_debug(E)]
> > [ 6.738594] CPU: 1 PID: 472 Comm: modprobe Tainted: G W E 6.6.0-tf2-virtme-00026-g20d113eb6f9a-dirty #220
> > [ 6.740008] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.16.3-0-ga6ed6b701f0a-prebuilt.qemu.org 04/01/2014
> > [ 6.741669] RIP: 0010:ddebug_printk+0xde/0xf0
> > [ 6.742220] Code: 48 8d 44 24 28 48 89 44 24 20 e8 ed 71 9c ff 48 83 c4 58 5b 41 5c 5d c3 48 8d 56 02 48 8d 4c 24 10 31 f6 e8 84 f9 ff ff eb b5 <0f> 0b eb a0 66 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 00 41 57 48 89
> > [ 6.745072] RSP: 0018:ffffb38140453bd0 EFLAGS: 00010246
> > [ 6.745914] RAX: 0000000000000000 RBX: ffffffffc03b97e0 RCX: ffffb38140453c50
> > [ 6.747002] RDX: ffffb38140453be0 RSI: ffffffffb26f8150 RDI: 0000000000000000
> > [ 6.747883] RBP: ffffb38140453c38 R08: 0000000000000020 R09: ffffffffb3370ce4
> > [ 6.748753] R10: 0000000000000001 R11: 0000000000010000 R12: ffffffffb26f8150
> > [ 6.749586] R13: ffff9b68029bc440 R14: ffff9b6805640800 R15: ffff9b6805c9d640
> > [ 6.750497] FS: 00007f7cdc453740(0000) GS:ffff9b683ec80000(0000) knlGS:0000000000000000
> > [ 6.751537] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> > [ 6.752310] CR2: 000055ce7a609ae0 CR3: 000000000575a000 CR4: 0000000000750ee0
> > [ 6.753238] PKRU: 55555554
> > [ 6.753604] Call Trace:
> > [ 6.753910] <TASK>
> > [ 6.754240] ? ddebug_printk+0xde/0xf0
> > [ 6.754772] ? __warn+0x7d/0x130
> > [ 6.755197] ? ddebug_printk+0xde/0xf0
> > [ 6.755669] ? report_bug+0x189/0x1c0
> > [ 6.756176] ? handle_bug+0x38/0x70
> > [ 6.756642] ? exc_invalid_op+0x13/0x60
> > [ 6.757112] ? asm_exc_invalid_op+0x16/0x20
> > [ 6.757635] ? ddebug_printk+0xde/0xf0
> > [ 6.758123] ? 0xffffffffc03c0000
> > [ 6.758533] __dynamic_pr_debug+0x133/0x170
> > [ 6.759066] ? 0xffffffffc03c0000
> > [ 6.759438] do_cats+0x127/0x180 [test_dynamic_debug]
> > [ 6.760063] test_dynamic_debug_init+0x7/0x1000 [test_dynamic_debug]
> > [ 6.760890] do_one_initcall+0x43/0x2f0
> > [ 6.761399] ? kmalloc_trace+0x26/0x90
> > [ 6.761904] do_init_module+0x9d/0x290
> > [ 6.762377] init_module_from_file+0x77/0xd0
> > [ 6.762877] idempotent_init_module+0xf9/0x270
> > [ 6.763439] __x64_sys_finit_module+0x5a/0xb0
> > [ 6.764040] do_syscall_64+0x35/0x80
> > [ 6.764474] entry_SYSCALL_64_after_hwframe+0x46/0xb0
> > [ 6.765089] RIP: 0033:0x7f7cdc56b5ad
> > [ 6.765522] Code: ff c3 66 2e 0f 1f 84 00 00 00 00 00 90 f3 0f 1e fa 48 89 f8 48 89 f7 48 89 d6 48 89 ca 4d 89 c2 4d 89 c8 4c 8b 4c 24 08 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d 53 48 0c 00 f7 d8 64 89 01 48
> > [ 6.767763] RSP: 002b:00007fff198e28d8 EFLAGS: 00000246 ORIG_RAX: 0000000000000139
> > [ 6.768781] RAX: ffffffffffffffda RBX: 000055ce7bb53980 RCX: 00007f7cdc56b5ad
> > [ 6.769611] RDX: 0000000000000000 RSI: 000055ce7bb72930 RDI: 0000000000000006
> > [ 6.770598] RBP: 00007fff198e2990 R08: 0000000000000000 R09: 0000000000000002
> > [ 6.771447] R10: 0000000000000006 R11: 0000000000000246 R12: 000055ce7bb72930
> > [ 6.772328] R13: 0000000000040000 R14: 000055ce7bb53bc0 R15: 000055ce7bb72930
> > [ 6.773252] </TASK>
> > [ 6.773532] ---[ end trace 0000000000000000 ]---
> > : 2 matches on =T
> > drivers/cpufreq/intel_pstate.c:1912 [intel_pstate]core_get_max_pstate =_ "max_pstate=TAC %x\n"
> > lib/test_dynamic_debug.c:109 [test_dynamic_debug]do_cats =T:(null) "D2_CORE msg\n" class:D2_CORE
> > did do_prints
> > # tracer: nop
> > #
> > # entries-in-buffer/entries-written: 0/0 #P:4
> > EO_LOG
> >
I reproduced this warning and found root cause. This was caused by an
error in how default trace destination
is set. I will fix it in the next patchset.
> > # that 2nd =T match has :(null) in the control-line. I didnt chase it.
> >
The root cause of the T:(null) is the same as above (error in how
default trace destination is set).
> > function test_early_close () {
> > ddcmd open usb_stream
> > ddcmd module usbcore +T:usb_stream.mf
> > check_matches =T:usb_stream.mf 161
> > echo ":not-running # ddcmd module usbcore -T:usb_stream.mf"
> > ddcmd close usb_stream
> > }
> > # test_early_close - works, unused, refactored below.
> > function self_start {
> > echo \# open, modprobe +T:it
> > ddcmd open selftest
> > check_instance selftest
> > modprobe test_dynamic_debug dyndbg=+T:selftest.mf
> > check_matches =T:selftest.mf -v
> > }
> > function self_end_normal {
> > echo \# disable -T:it, rmmod, close
> > ddcmd module test_dynamic_debug -T:selftest # leave mf
> > check_matches =mf -v
> > ifrmmod test_dynamic_debug
> > ddcmd close selftest
> > }
> > function self_end_disable_anon {
> > echo \# disable, close, rmmod
> > ddcmd module test_dynamic_debug -T
> > check_matches =mf -v
> > ddcmd close selftest
> > ifrmmod test_dynamic_debug
> > }
> > function self_end_disable_anon_mf {
> > echo \# disable, close, rmmod
> > ddcmd module test_dynamic_debug -Tf
> > check_matches =m -v
> > ddcmd close selftest
> > ifrmmod test_dynamic_debug
> > }
> > function self_end_nodisable {
> > echo \# SKIPPING: ddcmd module test_dynamic_debug -T:selftest
> > rmmod test_dynamic_debug
> > echo FAIL_COMING on close
> > ddcmd close selftest
> > }
> > function self_test_ {
> > echo "# SELFTEST $1"
> > self_start
> > self_end_$1
> > }
> >
> > function cycle_tests_normal {
> > echo \# CYCLE_TESTS_NORMAL
> >
> > self_test_ normal # ok
> > self_test_ disable_anon # ok
> > ddgrep selftest
> >
> > self_test_ normal # ok
> > self_test_ disable_anon_mf #
> > ddgrep selftest
> > }
> > cycle_tests_normal; # run
> >
> > function cycle_tests_problem {
> > self_test_ nodisable # write error: Device or resource busy
> > ddgrep selftest # still used, defaulted - prob
> >
> > self_test_ normal # open error, write error persists
> > ddgrep selftest # still used, defaulted
> >
> > ddcmd close selftest # too late ??
> > }
> > # cycle_tests_problem;
> >
> >
> > function test_private_trace {
> > echo "# TEST_PRIVATE_TRACE"
> > ddcmd =_
> >
> > ifrmmod test_dynamic_debug
> > echo 1 >/sys/kernel/tracing/tracing_on
> > echo 1 >/sys/kernel/tracing/events/dyndbg/enable
> >
> > ddcmd open foo
> > modprobe test_dynamic_debug
> > ddcmd class,D2_CORE,+T:foo,%class,D2_KMS,+T:foo
> >
> > check_matches =Tl -v
> > check_matches =Tmf -v
> > echo 1 >/sys/kernel/tracing/tracing_on
> > echo 1 >/sys/kernel/tracing/events/dyndbg/enable
> > tmark test_private_trace about to do_prints
> > doprints
> > cat /sys/kernel/tracing/trace
> >
> > ddcmd class,D2_CORE,-T:foo
> > ddcmd close foo
> > ddcmd close bar
> > ifrmmod test_dynamic_debug
> > }
> > test_private_trace; # run
> >
> > error_log_ref test_private_trace <<EOF
> > # test_private_trace
> > [ 7.803744] dyndbg: read 3 bytes from userspace
> > [ 7.804329] dyndbg: query 0: <=_> on module: <*>
> > [ 7.804844] dyndbg: processed 1 queries, with 3236 matches, 0 errs
> > rmmod: ERROR: Module test_dynamic_debug is not currently loaded
> > [ 7.838191] dyndbg: read 9 bytes from userspace
> > [ 7.838858] dyndbg: query 0: <open foo> on module: <*>
> > [ 7.872066] dyndbg: processed 1 queries, with 0 matches, 0 errs
> > [ 7.991723] dyndbg: class[0]: module:test_dynamic_debug base:22 len:8 ty:3
> > [ 7.992488] dyndbg: class[1]: module:test_dynamic_debug base:14 len:8 ty:1
> > [ 7.993178] dyndbg: class[2]: module:test_dynamic_debug base:10 len:3 ty:2
> > [ 7.993873] dyndbg: class[3]: module:test_dynamic_debug base:0 len:10 ty:0
> > [ 7.994560] dyndbg: module:test_dynamic_debug attached 4 classes
> > [ 7.995174] dyndbg: 32 debug prints in module test_dynamic_debug
> > [ 7.998426] dyndbg: read 42 bytes from userspace
> > [ 7.999169] dyndbg: query 0: <class,D2_CORE,+T:foo,> on module: <*>
> > [ 8.000126] dyndbg: query 1: <class,D2_KMS,+T:foo> on module: <*>
> > [ 8.000956] dyndbg: processed 2 queries, with 2 matches, 0 errs
> > : 0 matches on =Tl
> > : 0 matches on =Tmf
> > did do_prints
> > # tracer: nop
> > #
> > # entries-in-buffer/entries-written: 2/2 #P:4
> > #
> > # _-----=> irqs-off/BH-disabled
> > # / _----=> need-resched
> > # | / _---=> hardirq/softirq
> > # || / _--=> preempt-depth
> > # ||| / _-=> migrate-disable
> > # |||| / delay
> > # TASK-PID CPU# ||||| TIMESTAMP FUNCTION
> > # | | | ||||| | |
> > dd-selftest.rc-375 [003] ..... 6.876234: tracing_mark_write: here comes the WARN
> > dd-selftest.rc-375 [003] ..... 8.168406: tracing_mark_write: should be ready
> > [ 8.093538] dyndbg: read 21 bytes from userspace
> > [ 8.094156] dyndbg: query 0: <class,D2_CORE,-T:foo> on module: <*>
> > [ 8.094924] dyndbg: processed 1 queries, with 1 matches, 0 errs
> > [ 8.095560] dyndbg: read 10 bytes from userspace
> > [ 8.096038] dyndbg: query 0: <close foo> on module: <*>
> > [ 8.096565] dyndbg: trace instance is being used name=foo, use_cnt=1
> > [ 8.097198] dyndbg: processed 1 queries, with 0 matches, 1 errs
> > dd-tools.rc: line 4: echo: write error: Device or resource busy
> > [ 8.097850] dyndbg: read 10 bytes from userspace
> > [ 8.098356] dyndbg: query 0: <close bar> on module: <*>
> > [ 8.098887] dyndbg: processed 1 queries, with 0 matches, 1 errs
> > dd-tools.rc: line 4: echo: write error: No such file or directory
> > EOF
> >
Here the root cause is that foo trace instance is still being used
when close command is issued, i.e.
ddcmd class,D2_CORE,+T:foo,%class,D2_KMS,+T:foo # foo use count is now 2
...
ddcmd class,D2_CORE,-T:foo
ddcmd close foo # it fails because foo instance is still being used by
D2_KMS callsite(s), use count is 1
It can be fixed for example by issuing
ddcmd class,D2_KMS,-T:foo
before close command
But I also realized that use count of trace instances is not
decremented when callsite using
it is removed as a part of module removal, I will fix it in the next patchset
> > function test_private_trace_2 {
> > echo "# TEST_PRIVATE_TRACE_2"
> >
> > ddcmd =_
> > rmmod test_dynamic_debug
> > echo 1 >/sys/kernel/tracing/tracing_on
> > echo 1 >/sys/kernel/tracing/events/dyndbg/enable
> >
> > ddcmd open foo \; open bar # 2nd fails
> > modprobe test_dynamic_debug
> > ddcmd class,D2_CORE,+T:foo
> > ddcmd class,D2_KMS,+T:foo
> > ddcmd class D2_CORE +T:foo \; class D2_KMS +T:foo
> >
> > echo \# this breaks ??
> > ddcmd "class,D2_CORE,+T:foo;,class,D2_KMS,+T:foo"
> > # ddcmd class,D2_CORE,+T:foo\;class,D2_KMS,+T:foo
> >
> > check_matches =Tl -v
> > check_matches =Tmf -v
> > echo 1 >/sys/kernel/tracing/tracing_on
> > echo 1 >/sys/kernel/tracing/events/dyndbg/enable
> > tmark test_private_trace_2 about to do_prints
> > doprints
> > cat /sys/kernel/tracing/trace
> > #rmmod test_dynamic_debug
> > }
> > test_private_trace_2; # run
> >
> > # a real parse error in this log, with same input as worked above.
> > # the unkown flag 'c' error conflicts with what the following error
> > # says is the flags token
> >
> > error_log_ref test_private_trace_2 <<EOF
> > [ 8.107982] d# test_private_trace_2
> > yndbg: read 3 bytes from userspace
> > [ 8.108490] dyndbg: query 0: <=_> on module: <*>
> > [ 8.108997] dyndbg: processed 1 queries, with 3241 matches, 0 errs
> > [ 8.139645] dyndbg: removed module "test_dynamic_debug"
> > [ 8.152344] dyndbg: read 20 bytes from userspace
> > [ 8.152952] dyndbg: query 0: <open foo > on module: <*>
> > [ 8.153610] dyndbg: instance is already opened name:foo
> > [ 8.153610]
> > [ 8.153612] dyndbg: query 1: <open bar> on module: <*>
> > [ 8.185399] dyndbg: processed 2 queries, with 0 matches, 1 errs
> > dd-tools.rc: line 4: echo: write error: File exists
> > [ 8.300750] dyndbg: class[0]: module:test_dynamic_debug base:22 len:8 ty:3
> > [ 8.301509] dyndbg: class[1]: module:test_dynamic_debug base:14 len:8 ty:1
> > [ 8.302189] dyndbg: class[2]: module:test_dynamic_debug base:10 len:3 ty:2
> > [ 8.302876] dyndbg: class[3]: module:test_dynamic_debug base:0 len:10 ty:0
> > [ 8.303550] dyndbg: module:test_dynamic_debug attached 4 classes
> > [ 8.304147] dyndbg: 32 debug prints in module test_dynamic_debug
> > [ 8.307165] dyndbg: read 21 bytes from userspace
> > [ 8.307754] dyndbg: query 0: <class,D2_CORE,+T:foo> on module: <*>
> > [ 8.308914] dyndbg: processed 1 queries, with 1 matches, 0 errs
> > [ 8.310076] dyndbg: read 20 bytes from userspace
> > [ 8.310916] dyndbg: query 0: <class,D2_KMS,+T:foo> on module: <*>
> > [ 8.311915] dyndbg: processed 1 queries, with 1 matches, 0 errs
> > [ 8.312764] dyndbg: read 43 bytes from userspace
> > [ 8.313597] dyndbg: query 0: <class D2_CORE +T:foo > on module: <*>
> > [ 8.314697] dyndbg: query 1: <class D2_KMS +T:foo> on module: <*>
> > [ 8.315687] dyndbg: processed 2 queries, with 2 matches, 0 errs
> > # this breaks ??
> > [ 8.320048] dyndbg: read 41 bytes from userspace
> > [ 8.320904] dyndbg: query 0: <class,D2_CORE,+T:foo> on module: <*>
> > [ 8.321925] dyndbg: unknown flag 'c'
> > [ 8.322525] dyndbg: flags parse failed on 2: +T:foo
> > [ 8.323348] dyndbg: query 1: <class,D2_KMS,+T:foo> on module: <*>
> > [ 8.324428] dyndbg: processed 2 queries, with 1 matches, 1 errs
> > dd-tools.rc: line 4: echo: write error: Invalid argument
> > [ 8.325536] dyndbg: read 41 bytes from userspace
> > [ 8.326305] dyndbg: query 0: <class,D2_CORE,+T:foo> on module: <*>
> > [ 8.327415] dyndbg: unknown flag 'c'
> > [ 8.328138] dyndbg: flags parse failed on 2: +T:foo
> > [ 8.328993] dyndbg: query 1: <class,D2_KMS,+T:foo> on module: <*>
> > [ 8.330035] dyndbg: processed 2 queries, with 1 matches, 1 errs
> > dd-tools.rc: line 4: echo: write error: Invalid argument
> > : 0 matches on =Tl
> > : 0 matches on =Tmf
> > did do_prints
> > # tracer: nop
> > #
> > # entries-in-buffer/entries-written: 3/3 #P:4
> > #
> > # _-----=> irqs-off/BH-disabled
> > # / _----=> need-resched
> > # | / _---=> hardirq/softirq
> > # || / _--=> preempt-depth
> > # ||| / _-=> migrate-disable
> > # |||| / delay
> > # TASK-PID CPU# ||||| TIMESTAMP FUNCTION
> > # | | | ||||| | |
> > dd-selftest.rc-375 [001] ..... 6.934983: tracing_mark_write: here comes the WARN
> > dd-selftest.rc-375 [003] ..... 8.208645: tracing_mark_write: test_private_trace about to do_prints
> > dd-selftest.rc-375 [003] ..... 8.539307: tracing_mark_write: test_private_trace_2 about to do_prints
> > EOF
> >
The root cause is parsing error in read_T_args. I will fix it in the
next patchset.
> > function test_private_trace_3 {
> > echo "# TEST_PRIVATE_TRACE_3"
> >
> > ddcmd =_
> > rmmod test_dynamic_debug
> > echo 1 >/sys/kernel/tracing/tracing_on
> > echo 1 >/sys/kernel/tracing/events/dyndbg/enable
> >
> > ddcmd open foo # gets already open err
> > modprobe test_dynamic_debug dyndbg=class,D2_CORE,+T:foo%class,D2_KMS,+T:foo
> > # triggers:
> > # dyndbg: query 0: <class,D2_CORE,+T:foo> on module: <*>
> > # dyndbg: unknown flag 'c'
> > # dyndbg: flags parse failed
> >
This is again parsing error in read_T_args. I will fix it in the next patchset.
> > check_matches =Tl -v
> > check_matches =Tmf -v
> > echo 1 >/sys/kernel/tracing/tracing_on
> > echo 1 >/sys/kernel/tracing/events/dyndbg/enable
> > tmark should be ready
> > doprints
> > cat /sys/kernel/tracing/trace
> > #rmmod test_dynamic_debug
> > }
> > test_private_trace_3;
> >
> > echo -n "# done on: "
> > date
> >
Thank you for creating the scripts and thorough testing.
I plan to add more trace related tests and hopefully I will send new
patchset version next week.
Thanks,
Lukasz
> >
> > Jim Cromie (11):
> > dyndbg: export _print_hex_dump
> > dyndbg: tweak pr_info format s/trace dest/trace_dest/
> > dyndbg: disambiguate quoting in a debug msg
> > dyndbg: fix old BUG_ON in >control parser
> > dyndbg: change +T:name_terminator to dot
> > dyndbg: treat comma as a token separator
> > dyndbg: __skip_spaces
> > dyndbg: split multi-query strings with %
> > dyndbg: reduce verbose/debug clutter
> > dyndbg: move lock,unlock into ddebug_change, drop goto
> > dyndbg: id the bad word in parse-flags err msg
> >
> > lib/dynamic_debug.c | 52 ++++++++++++++++++++++++++++-----------------
> > 1 file changed, 32 insertions(+), 20 deletions(-)
> >
> > --
> > 2.43.0
> >
On Thu, Dec 14, 2023 at 8:20 AM Łukasz Bartosik <lb@semihalf.com> wrote:
>
> sob., 9 gru 2023 o 01:31 Łukasz Bartosik <lb@semihalf.com> napisał(a):
> >
> > pt., 8 gru 2023 o 01:15 Jim Cromie <jim.cromie@gmail.com> napisał(a):
> > >
> > > hi Lukas,
> > >
> > > Sorry for the delay, I probably should have split this up.
> > > (also cc'g gregkh)
> > >
> > > Ive been banging on your v2 patchset:
> > > https://lore.kernel.org/lkml/20231130234048.157509-1-lb@semihalf.com/
> > >
> >
> > Jim, thank you for your thorough testing and review.
> >
> > > Things are looking pretty good, a few issues follow. And some patches.
> > >
> >
> > ;)
> >
> > > trivial:
> > >
> > > dyndbg: export _print_hex_dump # squash wo comment
> > > dyndbg: tweak pr_info format s/trace dest/trace_dest/ # greppability squash
> > > dyndbg: disambiguate quoting in a debug msg
> > > dyndbg: fix old BUG_ON in >control parser
> > >
> > > Then:
> > >
> > > dyndbg: change +T:name_terminator to dot
> > > dyndbg: treat comma as a token separator
> > >
> > > 1st allows 2nd, 2nd allows simpler arg-passing, boot-args, etc:
> > >
> > > echo module,test_dynamic_debug,class,L2,+p > /proc/dynamic_debug/control
> > > modprobe test_dynamic_debug dyndbg=class,L2,+mfl
> > >
> > > Given theres no legacy wrt comma, swapping it now with dot seems
> > > better semantically than "dot as token/list separator".
> > >
> > > Aside: /proc/dynamic_debug/control is always there (if configd), even
> > > when <debugfs> isn't mounted. Its more universal, and copy-pastable.
> > >
> > > dyndbg: __skip_spaces - and comma
> > > dyndbg: split multi-query strings with %
> > >
> > > % allows escape-free multi-cmd dyndbg args:
> > >
> > > modprobe test_dynamic_debug \
> > > dyndbg=open,selftest%class,D2_CORE,+T:selftest.mf
> > >
> > > dyndbg: reduce verbose/debug clutter
> > > dyndbg: move lock,unlock into ddebug_change, drop goto - revisit
> > >
> > > Ive just pushed it, I will bump my version here.
> > > To github.com:jimc/linux.git
> > > + 20d113eb6f9a...66fa2e4cb989 lukas-v2.1 -> lukas-v2.1 (forced update)
> > >
>
> hi Jim,
>
> I will squash the following commits to their appropriate peers:
> - dyndbg: export _print_hex_dump
> - dyndbg: tweak pr_info format s/trace dest/trace_dest/
> - dyndbg: change +T:name_terminator to dot
>
> I will also drop completely "dyndbg: move lock,unlock into
> ddebug_change, drop goto" and leave the remaining commits as is.
cool. and yes, late ack.
I got distracted by move of flags-handler to the bottom of the fn.
Pls add note about moving the lock to protect open/close too.
>
> > > SELFTEST
> > >
> > > Ive taken the liberty to write an ad-hoc test script (inline below),
> > > to exersize the parser with legacy command input, and with the new
> > > stuff mentioned above: comma-separated-tokens, %-separated-multi-cmds,
> > > while counting changes to builtin,etc modules, to validate against
> > > expectations.
> > >
> > > The change-count tests achieve some closed-loop testing, but checking
> > > syslog for messages written always seemed too hard/unreliable. Your
> > > private trace-instances work promises a solution, by giving an
> > > observable closed system to build upon.
> > >
> > > I made some attempts to write messages to the trace-buf, but ran out
> > > of clues*tuits. And I encountered a couple more definite problems:
> > >
> >
> > Let me dig through test scripts you created and issues you run into.
> >
> >
> > > 1- modprobe/rmmod lifecycle probs
> > >
> > > Ive coded some blue-sky and not-so-proper "modprobe,+T:it,-T:it,rmmod"
> > > life-cycle scenarios, which can wedge a previously created instance.
> > > Once wedged, I cannot recover. See the test_private_trace{,_2,_3}
> > > functions, and the error_log_ref() following each.
> > >
>
> The tests are very useful. I root caused the failures. Please see below.
>
> > > This brittleness begs a question; should we have auto-open (mapping
> > > new names to available 1-63 trc-ids) ? And non-close ? If it just did
> > > the right thing, particularly on rmmod, it would prevent "misuse".
> > >
>
> I would rather not have auto-open. For me personal argument against it is
> that I usually make a lot of typos and with auto-open if I don't
> verify what I wrote
> I won't know whether logs will be written to the "right" instance or a
> newly created instance
> with typo name. In case of open/close commands error pops up when I
> try to write logs
> to a trace instance which was not opened.
yes. that is a value. auto-open was 1/2 baked speculation
>
> > > I don't think auto-open obsoletes the open (& esp) close commands, but
> > > Id like to see scripted test scenarios using close in combo with the
> > > right /sys/kernel/tracing/* manipulations, to prove its not all just a
> > > fever dream.
> > >
>
> Would you please elaborate what you mean by close in combo with right
> /sys/kernel/tracing/* manipulations ?
>
you detected the furious flapping, didnt you :-)
lemme start with the global-events trace-buf, for analogy/comparison.
to use it one must do both:
echo 1 > /sys/kernel/tracing/events/dyndbg/enable
echo $some_selection +T > /proc/dynamic_debug/control
using +T:private_buffer no longer requires the enable (im guessing)
but are there any other/corresponding setup actions / manipulations ?
if nothing else is needed, when does the instance open ?
after test-dynamic-debug-doprints on +T:private callsites ?
is it detectable from a script ?
probably: if [ -e /sys/kernel/tracing/instances/foo ]
if the instance is already open, I presume it is not cleared ?
any other play-nice-with-other-users stuff ?
conversely, to write a closed-loop test-script,
should the script just delete the instance/$name
after verifying its contents from the last doprints ?
> > > Your expertise in opening, writing to, manipulating & destroying
> > > private (and the global) tracebufs, distilled into new shell funcs,
> > > would be enormously helpful towards demonstrating the private-buffer
> > > use case and its value.
> > >
>
> I will work on adding new tests for trace.
nice!
>
> > > 2- some new flags parse error:
> > >
> > > [ 1273.074535] dyndbg: 32 debug prints in module test_dynamic_debug
> > > [ 1273.075365] dyndbg: module: test_dynamic_debug dyndbg="class,D2_CORE,+T:foo%class,D2_KMS,+T:foo"
> > > [ 1273.076307] dyndbg: query 0: <class,D2_CORE,+T:foo> on module: <test_dynamic_debug>
> > > [ 1273.077068] dyndbg: split into words: "class" "D2_CORE" "+T:foo"
> > > [ 1273.077673] dyndbg: unknown flag 'c'
> > > [ 1273.078033] dyndbg: flags parse failed on 2: +T:foo
> > > [ 1273.078519] dyndbg: query 1: <class,D2_KMS,+T:foo> on module: <test_dynamic_debug>
> > > [ 1273.079266] dyndbg: split into words: "class" "D2_KMS" "+T:foo"
> > > [ 1273.079872] dyndbg: unknown flag '�'
> > > [ 1273.080228] dyndbg: flags parse failed on 2: +T:foo
> > > [ 1273.080716] dyndbg: processed 2 queries, with 0 matches, 2 errs
> > > : 0 matches on =Tl
> > >
> > > I have a suspicion this relates to moving the parse_flags call in
> > > ddebug_query, but I havent dug in.
> > >
> > >
> > > I also have some reservations about the default dest; 1st that it is a
> > > global state var, as noted at bottom of control:
> > >
> > > [root@v6 lx]# ddgrep \\btrace\\b # a better/narrower search-term ?
> > > ...
> > > Default trace destination: foo # add a '#:' prefix to these lines ?
>
> Do you mean
This. it hides the info behind a # so any parser expecting just
callsites is safe.
and the following colon marks it as info for the clever ones.
> #: Default trace destination:
> #: Opened trace instances: foo bar buz
But I would lalso ike the labels optimized for a tight grep, that wont
hit anything else,
and mostly thats easy to use. "trace_dest" almost does it, is a
pretty good mark on the bikeshed.
> > > Opened trace instances: # all values should be on this line
> > >
>
> I will put all opened trace instance names on the same line
>
> > > Then theres the "preset" value, ie each site's dest_id (sorry I forgot
> > > your fieldname). I presume the default would override such a "preset"
> > > (otherwise it would have no effect).
> > >
> > > Is the default set on last open ? or on next use of +T:<foo> ?
> > >
>
> Default trace destination is set on [+-]T:<foo>
unless foo hasnt been opened, Im guessing
does it matter if the last destination used resulted in a match ?
>
> > > In the no-default world, a user/tester would decide how many
> > > trace-instances are needed, and map sets of callsites to them.
> > >
> > > # configure drm-debug streams for this test scenario
> > > cat<<EOF >/proc/dynamic_debug/control
> > > open drm_core
> > > open drm_mix
> > > open driver_1 # we can separate by modname but not drvr-number
> > > open driver_2
> > > class DRM_UT_CORE -T:drm_core # set dest_id, disabled state
>
> This sets default trace destination to drm_core
>
> > > class DRM_UT_CORE +mf # traces dont do prefixing (should it?)
>
> In this case logs will be neither written to syslog nor trace because
> both pT flags are not set.
I think my example fails to illuminate the corner I seek.
> I verified that both output to trace instance and trace events honors
> mf flags (prefixing) when they are set for a given callsite.
Ok. that is good to know. that sounds reducible to a test-fn.
>
> > > # mix KMS & ATOMIC into 1 stream
> > > class DRM_UT_KMS -T:drm_mix
> > > class DRM_UT_ATOMIC -T:drm_mix
> > > EOF
> > >
> > > Then perhaps to turn on/off when needed: (legacy analogue version)
> > >
> > > echo 0x15 > /sys/module/drm/parameters/debug_trace
> > >
> > > With those trace-dest presets honored, the configured drm_core &
> > > drm_mix streams persist. If a later enablement applies the
> > > then-current default trace-dest, it would spoil this scheme.
> > >
so each callsite has a dest, which is set individually when the
callsite is selected
and -T:name'd in the EOF block.
I would *not* want enablements of those callsites to alter the dest
just because
the default-dest were altered in the interim.
I think it would break the way drm.debug is supported, by only
touching the T bit.
> > > Could you elaborate a scenario or 2 where the default behavior does
> > > something specific, and that its the right thing ? I dont understand
> > > it yet.
> > >
>
> I'm a bit lost here. Help me out please. What do you mean by default behavior ?
default behavior is what happens when +T (wo a dest) is done,
after a default dest has been set. w/o a default-dest, it would be just :0
So having a default dest means implying the :default_dest_name.
whatever it is set to,
on whatever callsites are selected, unless the ddcmd gives a name, ie
+T:this_buf
As of last writing, I dont see how the extra implication helps.
It feels like hidden state.
I can squint at it and see a local / loop var, fwiw.
>
> > > OTOH
> > >
> > > One limitation of the above: the drm.debug_trace (posited above) would
> > > turn on all Ts in all those class'd callsites across the whole
> > > subsystem, irrespective of their preconfigured destination. That was
> > > always inherent in drm.debug, but its less than perfect.
> > >
> > > It sort-of defeats the point of doing +T only on the useful callsites.
> > >
> > > And global event buf is also enabled, it might be flood-prone.
> > >
> > > echo 1 > /sys/kernel/tracing/events/dyndbg/enable
> > >
> > > It would help if we could filter on trace-instance names:
> > > (this sounds familiar :-)
> > >
> > > ddcmd module '*' trace_dest drm_mix +T
> > >
I think we need to implement this new keyword selector,
I think it addresses the flooding possible above,
when using both private traces and the global-trace.
but we dont need it yet.
> > > In reality, the dest-id is not even dependent on tracing per-se, it is
> > > a user classification system (in contrast to class <subsys-names>).
> > > It just happens to be tied by +T:name syntax to tracefs.
> > >
> > > No promise about +p:_alt_log_.mflt having meaning, or working.
or not complaining, pr_notice ?
> > >
> > >
I look forward to v3
Jim
sob., 16 gru 2023 o 04:09 <jim.cromie@gmail.com> napisał(a):
>
> On Thu, Dec 14, 2023 at 8:20 AM Łukasz Bartosik <lb@semihalf.com> wrote:
> >
> > sob., 9 gru 2023 o 01:31 Łukasz Bartosik <lb@semihalf.com> napisał(a):
> > >
> > > pt., 8 gru 2023 o 01:15 Jim Cromie <jim.cromie@gmail.com> napisał(a):
> > > >
> > > > hi Lukas,
> > > >
> > > > Sorry for the delay, I probably should have split this up.
> > > > (also cc'g gregkh)
> > > >
> > > > Ive been banging on your v2 patchset:
> > > > https://lore.kernel.org/lkml/20231130234048.157509-1-lb@semihalf.com/
> > > >
> > >
> > > Jim, thank you for your thorough testing and review.
> > >
> > > > Things are looking pretty good, a few issues follow. And some patches.
> > > >
> > >
> > > ;)
> > >
> > > > trivial:
> > > >
> > > > dyndbg: export _print_hex_dump # squash wo comment
> > > > dyndbg: tweak pr_info format s/trace dest/trace_dest/ # greppability squash
> > > > dyndbg: disambiguate quoting in a debug msg
> > > > dyndbg: fix old BUG_ON in >control parser
> > > >
> > > > Then:
> > > >
> > > > dyndbg: change +T:name_terminator to dot
> > > > dyndbg: treat comma as a token separator
> > > >
> > > > 1st allows 2nd, 2nd allows simpler arg-passing, boot-args, etc:
> > > >
> > > > echo module,test_dynamic_debug,class,L2,+p > /proc/dynamic_debug/control
> > > > modprobe test_dynamic_debug dyndbg=class,L2,+mfl
> > > >
> > > > Given theres no legacy wrt comma, swapping it now with dot seems
> > > > better semantically than "dot as token/list separator".
> > > >
> > > > Aside: /proc/dynamic_debug/control is always there (if configd), even
> > > > when <debugfs> isn't mounted. Its more universal, and copy-pastable.
> > > >
> > > > dyndbg: __skip_spaces - and comma
> > > > dyndbg: split multi-query strings with %
> > > >
> > > > % allows escape-free multi-cmd dyndbg args:
> > > >
> > > > modprobe test_dynamic_debug \
> > > > dyndbg=open,selftest%class,D2_CORE,+T:selftest.mf
> > > >
> > > > dyndbg: reduce verbose/debug clutter
> > > > dyndbg: move lock,unlock into ddebug_change, drop goto - revisit
> > > >
> > > > Ive just pushed it, I will bump my version here.
> > > > To github.com:jimc/linux.git
> > > > + 20d113eb6f9a...66fa2e4cb989 lukas-v2.1 -> lukas-v2.1 (forced update)
> > > >
> >
> > hi Jim,
> >
> > I will squash the following commits to their appropriate peers:
> > - dyndbg: export _print_hex_dump
> > - dyndbg: tweak pr_info format s/trace dest/trace_dest/
> > - dyndbg: change +T:name_terminator to dot
> >
> > I will also drop completely "dyndbg: move lock,unlock into
> > ddebug_change, drop goto" and leave the remaining commits as is.
>
> cool. and yes, late ack.
> I got distracted by move of flags-handler to the bottom of the fn.
> Pls add note about moving the lock to protect open/close too.
>
> >
> > > > SELFTEST
> > > >
> > > > Ive taken the liberty to write an ad-hoc test script (inline below),
> > > > to exersize the parser with legacy command input, and with the new
> > > > stuff mentioned above: comma-separated-tokens, %-separated-multi-cmds,
> > > > while counting changes to builtin,etc modules, to validate against
> > > > expectations.
> > > >
> > > > The change-count tests achieve some closed-loop testing, but checking
> > > > syslog for messages written always seemed too hard/unreliable. Your
> > > > private trace-instances work promises a solution, by giving an
> > > > observable closed system to build upon.
> > > >
> > > > I made some attempts to write messages to the trace-buf, but ran out
> > > > of clues*tuits. And I encountered a couple more definite problems:
> > > >
> > >
> > > Let me dig through test scripts you created and issues you run into.
> > >
> > >
> > > > 1- modprobe/rmmod lifecycle probs
> > > >
> > > > Ive coded some blue-sky and not-so-proper "modprobe,+T:it,-T:it,rmmod"
> > > > life-cycle scenarios, which can wedge a previously created instance.
> > > > Once wedged, I cannot recover. See the test_private_trace{,_2,_3}
> > > > functions, and the error_log_ref() following each.
> > > >
> >
> > The tests are very useful. I root caused the failures. Please see below.
> >
> > > > This brittleness begs a question; should we have auto-open (mapping
> > > > new names to available 1-63 trc-ids) ? And non-close ? If it just did
> > > > the right thing, particularly on rmmod, it would prevent "misuse".
> > > >
> >
> > I would rather not have auto-open. For me personal argument against it is
> > that I usually make a lot of typos and with auto-open if I don't
> > verify what I wrote
> > I won't know whether logs will be written to the "right" instance or a
> > newly created instance
> > with typo name. In case of open/close commands error pops up when I
> > try to write logs
> > to a trace instance which was not opened.
>
> yes. that is a value. auto-open was 1/2 baked speculation
>
> >
> > > > I don't think auto-open obsoletes the open (& esp) close commands, but
> > > > Id like to see scripted test scenarios using close in combo with the
> > > > right /sys/kernel/tracing/* manipulations, to prove its not all just a
> > > > fever dream.
> > > >
> >
> > Would you please elaborate what you mean by close in combo with right
> > /sys/kernel/tracing/* manipulations ?
> >
>
> you detected the furious flapping, didnt you :-)
>
> lemme start with the global-events trace-buf, for analogy/comparison.
> to use it one must do both:
> echo 1 > /sys/kernel/tracing/events/dyndbg/enable
> echo $some_selection +T > /proc/dynamic_debug/control
>
Currently if default destination is not set then +T will fail because
it does not know
what destination to use. Would you like in this case to use
prdbg&dyndbg events as
a default destination instead of failing ?
> using +T:private_buffer no longer requires the enable (im guessing)
It does not require to be enabled
> but are there any other/corresponding setup actions / manipulations ?
>
We need to call trace_array_get_by_name, it will either create new
trace instance
or reuse existing one if it already exists. In both cases it also
increases reference count of the requested trace instance.
This is done as a part of open command.
> if nothing else is needed, when does the instance open ?
The open command calls trace_array_get_by_name
> after test-dynamic-debug-doprints on +T:private callsites ?
> is it detectable from a script ?
> probably: if [ -e /sys/kernel/tracing/instances/foo ]
>
> if the instance is already open, I presume it is not cleared ?
>
Contents of instance will be preserved
> any other play-nice-with-other-users stuff ?
>
I will take this into account when creating new tests.
> conversely, to write a closed-loop test-script,
> should the script just delete the instance/$name
> after verifying its contents from the last doprints ?
>
Yes, it makes sense for the test script to delete trace instance at
the end of a test scenario.
It will simulate the user action of deleting the instance.
>
>
> > > > Your expertise in opening, writing to, manipulating & destroying
> > > > private (and the global) tracebufs, distilled into new shell funcs,
> > > > would be enormously helpful towards demonstrating the private-buffer
> > > > use case and its value.
> > > >
> >
> > I will work on adding new tests for trace.
>
> nice!
>
> >
> > > > 2- some new flags parse error:
> > > >
> > > > [ 1273.074535] dyndbg: 32 debug prints in module test_dynamic_debug
> > > > [ 1273.075365] dyndbg: module: test_dynamic_debug dyndbg="class,D2_CORE,+T:foo%class,D2_KMS,+T:foo"
> > > > [ 1273.076307] dyndbg: query 0: <class,D2_CORE,+T:foo> on module: <test_dynamic_debug>
> > > > [ 1273.077068] dyndbg: split into words: "class" "D2_CORE" "+T:foo"
> > > > [ 1273.077673] dyndbg: unknown flag 'c'
> > > > [ 1273.078033] dyndbg: flags parse failed on 2: +T:foo
> > > > [ 1273.078519] dyndbg: query 1: <class,D2_KMS,+T:foo> on module: <test_dynamic_debug>
> > > > [ 1273.079266] dyndbg: split into words: "class" "D2_KMS" "+T:foo"
> > > > [ 1273.079872] dyndbg: unknown flag '�'
> > > > [ 1273.080228] dyndbg: flags parse failed on 2: +T:foo
> > > > [ 1273.080716] dyndbg: processed 2 queries, with 0 matches, 2 errs
> > > > : 0 matches on =Tl
> > > >
> > > > I have a suspicion this relates to moving the parse_flags call in
> > > > ddebug_query, but I havent dug in.
> > > >
> > > >
> > > > I also have some reservations about the default dest; 1st that it is a
> > > > global state var, as noted at bottom of control:
> > > >
> > > > [root@v6 lx]# ddgrep \\btrace\\b # a better/narrower search-term ?
> > > > ...
> > > > Default trace destination: foo # add a '#:' prefix to these lines ?
> >
> > Do you mean
>
> This. it hides the info behind a # so any parser expecting just
> callsites is safe.
> and the following colon marks it as info for the clever ones.
>
> > #: Default trace destination:
> > #: Opened trace instances: foo bar buz
>
Ack
> But I would lalso ike the labels optimized for a tight grep, that wont
> hit anything else,
> and mostly thats easy to use. "trace_dest" almost does it, is a
> pretty good mark on the bikeshed.
>
> > > > Opened trace instances: # all values should be on this line
> > > >
> >
> > I will put all opened trace instance names on the same line
> >
> > > > Then theres the "preset" value, ie each site's dest_id (sorry I forgot
> > > > your fieldname). I presume the default would override such a "preset"
> > > > (otherwise it would have no effect).
> > > >
> > > > Is the default set on last open ? or on next use of +T:<foo> ?
> > > >
> >
> > Default trace destination is set on [+-]T:<foo>
>
> unless foo hasnt been opened, Im guessing
yes foo has to be opened otherwise the command will fail
> does it matter if the last destination used resulted in a match ?
>
yes it does, if there was no match then such destination will not be
used for setting default destination
> >
> > > > In the no-default world, a user/tester would decide how many
> > > > trace-instances are needed, and map sets of callsites to them.
> > > >
> > > > # configure drm-debug streams for this test scenario
> > > > cat<<EOF >/proc/dynamic_debug/control
> > > > open drm_core
> > > > open drm_mix
> > > > open driver_1 # we can separate by modname but not drvr-number
> > > > open driver_2
> > > > class DRM_UT_CORE -T:drm_core # set dest_id, disabled state
> >
> > This sets default trace destination to drm_core
> >
> > > > class DRM_UT_CORE +mf # traces dont do prefixing (should it?)
> >
> > In this case logs will be neither written to syslog nor trace because
> > both pT flags are not set.
>
> I think my example fails to illuminate the corner I seek.
>
What corner case did you try to emphasize here ?
> > I verified that both output to trace instance and trace events honors
> > mf flags (prefixing) when they are set for a given callsite.
>
> Ok. that is good to know. that sounds reducible to a test-fn.
>
> >
> > > > # mix KMS & ATOMIC into 1 stream
> > > > class DRM_UT_KMS -T:drm_mix
> > > > class DRM_UT_ATOMIC -T:drm_mix
> > > > EOF
> > > >
> > > > Then perhaps to turn on/off when needed: (legacy analogue version)
> > > >
> > > > echo 0x15 > /sys/module/drm/parameters/debug_trace
> > > >
> > > > With those trace-dest presets honored, the configured drm_core &
> > > > drm_mix streams persist. If a later enablement applies the
> > > > then-current default trace-dest, it would spoil this scheme.
> > > >
>
> so each callsite has a dest, which is set individually when the
> callsite is selected
> and -T:name'd in the EOF block.
>
> I would *not* want enablements of those callsites to alter the dest
> just because
> the default-dest were altered in the interim.
>
> I think it would break the way drm.debug is supported, by only
> touching the T bit.
>
If I understood you correctly -T: <trace_name> should preset only
destination for a given callsite(s) and
not a global default destination ?
>
> > > > Could you elaborate a scenario or 2 where the default behavior does
> > > > something specific, and that its the right thing ? I dont understand
> > > > it yet.
> > > >
> >
> > I'm a bit lost here. Help me out please. What do you mean by default behavior ?
>
> default behavior is what happens when +T (wo a dest) is done,
> after a default dest has been set. w/o a default-dest, it would be just :0
>
> So having a default dest means implying the :default_dest_name.
> whatever it is set to,
> on whatever callsites are selected, unless the ddcmd gives a name, ie
> +T:this_buf
>
> As of last writing, I dont see how the extra implication helps.
> It feels like hidden state.
>
Yes it can be misleading.
> I can squint at it and see a local / loop var, fwiw.
>
Maybe let's get rid of default global destination and when +T will be
provided without a name
then it will always default to trace events (:0). Apart from that we
would have presetting destination with -T:<trace_name> but only for a
given callsite(s)
Thanks,
Lukasz
> > > > OTOH
> > > >
> > > > One limitation of the above: the drm.debug_trace (posited above) would
> > > > turn on all Ts in all those class'd callsites across the whole
> > > > subsystem, irrespective of their preconfigured destination. That was
> > > > always inherent in drm.debug, but its less than perfect.
> > > >
> > > > It sort-of defeats the point of doing +T only on the useful callsites.
> > > >
> > > > And global event buf is also enabled, it might be flood-prone.
> > > >
> > > > echo 1 > /sys/kernel/tracing/events/dyndbg/enable
> > > >
> > > > It would help if we could filter on trace-instance names:
> > > > (this sounds familiar :-)
> > > >
> > > > ddcmd module '*' trace_dest drm_mix +T
> > > >
>
> I think we need to implement this new keyword selector,
> I think it addresses the flooding possible above,
> when using both private traces and the global-trace.
>
> but we dont need it yet.
>
> > > > In reality, the dest-id is not even dependent on tracing per-se, it is
> > > > a user classification system (in contrast to class <subsys-names>).
> > > > It just happens to be tied by +T:name syntax to tracefs.
> > > >
> > > > No promise about +p:_alt_log_.mflt having meaning, or working.
>
> or not complaining, pr_notice ?
>
>
> > > >
> > > >
>
> I look forward to v3
> Jim
© 2016 - 2025 Red Hat, Inc.