Re: [re: PATCH v2 00/15 - 00/11] dyndbg: add support for writing debug logs to trace

[Łukasz Bartosik]

pt., 8 gru 2023 o 01:15 Jim Cromie <jim.cromie@xxxxxxxxx> 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@xxxxxxxxxxxx/
>

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
>