Add support for writing debug logs to trace events and trace instances.
The rationale behing this feature is to be able to redirect debug logs
(per each callsite individually) to trace to aid in debugging. The debug
logs output to trace can be enabled with T flag. Additionally the T flag
accepts trace destination which can be provided to the T flag after ":".
The trace destination field is used to determine where debug logs will be
written. 

In order to redirect callsite debug log to a trace instance it has to be
initialized first with a newly introduced "open" command. For example,
"usb" trace instance in <debugfs>/tracing/instances/ can be initialized
by issuing the command:

localhost ~ # echo "open usb" >
                                <debugfs>/dynamic_debug/control

If the trace instance <debugfs>/tracing/instances/usb already exists
then it will be reused otherwise new usbcore instance will be created.
Maximum 63 trace instances can be "opened". The trace instance name can
include any of ^\w+ and underscore characters. There is also a special
name "0" reserved for writing debug logs to trace prdbg and devdbg events.
The reserved name "0" does not require to be "opened" before use.

To enable writing usbcore module debug logs to the "usb" trace instance
opened above a user can issue the command:

localhost ~ # echo "module usbcore =pT:usb" >
                                <debugfs>/dynamic_debug/control

Please note that output of debug logs to syslog (p flag) and trace (T flag)
can be independently enabled/disabled for each callsite. Therefore the
above command will enable writing of debug logs not only to the trace
instance "usb" but also to syslog.

When trace destination is followed by another flag the next flag has to
be preeceded with ".", for example

localhost ~ # echo "module usbcore =pT:usb.l" > 
                                <debugfs>/dynamic_debug/control

To simplify processing trace destination can be omitted when default
trace destination is set, for example the command

localhost ~ # echo "module usbcore =pTl" >   
                                <debugfs>/dynamic_debug/control

will use default trace destination. If default trace destination is not
set the above command will fail. The default trace destination is set
when a command with any of the flags [-+=] and explicitly provided trace
destination matches at least one callsite, for example the command

localhost ~ # echo "module usbcore -T:usb" >   
                                <debugfs>/dynamic_debug/control

will disable trace for all usbcore module callsites (if any was enabled)
and will set "usb" instance as default trace destination. To enable writing
thunderbolt module debug logs to the "usb" trace instance as well a user
can issue the command:
  
localhost ~ # echo "module thunderbolt =T" >    
                                <debugfs>/dynamic_debug/control

Since default trace destination was previously set therefore "usb" instance
name does not have to be explicitly provided.

When no callsite writes debug logs to a trace instance then it can be
released (its reference counter decrased) with the "close" command. 
Closing a trace instance make it unavailable for dynamic debug and also
allows a user to delete such a trace instance at convenient time later
with rmdir command. For example when "usb" instance is not used anymore
a user can issue the command:

localhost ~ # echo "close usb" >
                                <debugfs>/dynamic_debug/control 
and then to delete it with:

localhost ~ # rmdir <debugfs>/tracing/instances/

To enable writing usbcore module debug logs to trace dyndbg:prdbg and
dyndbg:devdbg events user can issue the command:

localhost ~ # echo "module usbcore =T:0" >
                                <debugfs>/dynamic_debug/control
 
Then dyndbg trace events can be for example captured with the command:

localhost ~ # trace-cmd start -e dyndbg 

And displayed with the command:

localhost ~ # trace-cmd show



Jim, I made a few changes to the test script dd-selftest.rc you created
and I also added new test scenarios. You can find the entire patchset
with the test script changes on top here
https://chromium.googlesource.com/chromiumos/third_party/kernel/+log/refs/sandbox/ukaszb/dyndbg_trace_v3
I wonder where would be the proper place to store the test script
(upstream, your github.com:jimc/linux.git)
Do you have a suggestion for that ?

TODOs:
- update dynamic debug documentation,
- finalize discussion related to default trace destination
(whether we want it at all, if yes then conclude on the details)

Changes:
V3 -> V2
- squash "dyndbg: export _print_hex_dump" with "dyndbg: add support for hex_dump output to trace",
- squash "dyndbg: tweak pr_info format s/trace dest/trace_dest/"  with "dyndbg: add processing of T(race) flag argument",
- squash "dyndbg: change +T:name_terminator to dot" with "dyndbg: add processing of T(race) flag argument",
- fix setting default trace destination,
- decrease use count when callsite is being disabled as a part of module removal,
- fix parsing of T flag argument,
- update __get_str_strip_nl macro per Steve's comment,
- drop commit "dyndbg: move lock,unlock into ddebug_change, drop goto" and add comment explaining why ddebug_parse_flags
and ddebug_change have to be run in critical section,
- add "depends on TRACING" for "DYNAMIC_DEBUG",
- update DYNAMIC_DEBUG_BRANCH macro which is used when CONFIG_JUMP_LABEL is not set,
- change structure name ddebug_trace_inst to dd_private_tracebuf,
- change structure name ddebug_trace to dd_tracebuf_tbl_info,
- rename is_ddebug_cmd to is_dd_trace_cmd,
- rename validate_tr_name to dd_good_trace_name,
- rename handle_tr_opend_cmd to handle_trace_opend_cmd and handle_tr_close_cmd to handle_trace_close_cmd,
- refactor ddebug_parse_cmd,
- add pr_err when trace_array_get_by_name or trace_array_init_printk fails in trace_array_init_printk,
- add static prefix to show_T_args,
- rename TRACE_DST_MAX to TRACE_DST_LAST and change its value to 64, reserve index 0 for trace events in dd_tracebuf_tbl_info (index 0 will be wasted),
- add "#: " prefix to "Default trace destination" and "Opened trace instances" and print all opened trace instances on the same line,

V2->V1
Major rework after receiving feedback in
https://lore.kernel.org/all/20231103131011.1316396-1-lb@semihalf.com/

This includes among other things:
- addittion of open/close commands,
- use names instead of numbers for trace destinations,
- change prdbg and devdbg trace events to strip newline
on the slow path (read side),
- change prdbg and devdbg trace events to stores actual values
instead of pointers because if a pointer becomes invalid then
the TP_printk call will cause a crash,
- add support for default trace destination. 

V1 
Major rework after receiving feedback in 
https://lore.kernel.org/all/20230915154856.1896062-1-lb@semihalf.com/

Jim Cromie (14):
  dyndbg: add _DPRINTK_FLAGS_ENABLED
  dyndbg: add _DPRINTK_FLAGS_TRACE
  dyndbg: add write events to tracefs code
  dyndbg: add 2 trace-events: prdbg, devdbg
  tracefs: add __get_str_strip_nl - RFC
  dyndbg: use __get_str_strip_nl in prdbg and devdbg
  dyndbg: repack _ddebug structure
  dyndbg: disambiguate quoting in a debug msg
  dyndbg: fix old BUG_ON in >control parser
  dyndbg: treat comma as a token separator
  dyndbg: add skip_spaces_and_coma()
  dyndbg: split multi-query strings with %
  dyndbg: reduce verbose/debug clutter
  dyndbg: id the bad word in parse-flags err msg

Łukasz Bartosik (8):
  dyndbg: move flags field to a new structure
  dyndbg: add trace destination field to _ddebug
  dyndbg: add open and close commands for trace
  dyndbg: don't close trace instance when in use
  dyndbg: add processing of T(race) flag argument
  dyndbg: add support for default trace destination
  dyndbg: write debug logs to trace instance
  dyndbg: add support for hex_dump output to trace

 .../admin-guide/dynamic-debug-howto.rst       |   5 +-
 MAINTAINERS                                   |   1 +
 include/linux/dynamic_debug.h                 |  57 +-
 include/trace/events/dyndbg.h                 |  54 ++
 include/trace/stages/stage3_trace_output.h    |  13 +
 lib/Kconfig.debug                             |   2 +
 lib/dynamic_debug.c                           | 736 ++++++++++++++++--
 7 files changed, 775 insertions(+), 93 deletions(-)
 create mode 100644 include/trace/events/dyndbg.h

-- 
2.43.0.472.g3155946c3a-goog

re-adding gregkh, who fell off the cc's again.
he is one of our upstreams.

On Fri, Dec 22, 2023 at 6:51 PM Łukasz Bartosik <lb@semihalf.com> wrote:
>
> Add support for writing debug logs to trace events and trace instances.
> The rationale behing this feature is to be able to redirect debug logs
> (per each callsite individually) to trace to aid in debugging. The debug
> logs output to trace can be enabled with T flag. Additionally the T flag
> accepts trace destination which can be provided to the T flag after ":".
> The trace destination field is used to determine where debug logs will be
> written.
>
> In order to redirect callsite debug log to a trace instance it has to be
> initialized first with a newly introduced "open" command. For example,
> "usb" trace instance in <debugfs>/tracing/instances/ can be initialized
> by issuing the command:
>
> localhost ~ # echo "open usb" >
>                                 <debugfs>/dynamic_debug/control
>
> If the trace instance <debugfs>/tracing/instances/usb already exists
> then it will be reused otherwise new usbcore instance will be created.
> Maximum 63 trace instances can be "opened". The trace instance name can
> include any of ^\w+ and underscore characters. There is also a special
> name "0" reserved for writing debug logs to trace prdbg and devdbg events.
> The reserved name "0" does not require to be "opened" before use.

theres implication here that p only works when :0.
Is that intended ?
it seems wrong, or at least unnecessary.

In fact, theres no specific reason to exclude +p:trcbuf.mf,
esp if we keep default-trace-buf
since +pTfml  could have that meaning implicitly.
We can call it allowed and "unimplemented until proven useful" on +p

+p completely independent of +T is a simplicity,
lets keep that until proven useful otherwise.

>
> To enable writing usbcore module debug logs to the "usb" trace instance
> opened above a user can issue the command:
>
> localhost ~ # echo "module usbcore =pT:usb" >
>                                 <debugfs>/dynamic_debug/control
>
> Please note that output of debug logs to syslog (p flag) and trace (T flag)
> can be independently enabled/disabled for each callsite. Therefore the
> above command will enable writing of debug logs not only to the trace
> instance "usb" but also to syslog.
>
> When trace destination is followed by another flag the next flag has to
> be preeceded with ".", for example
>
> localhost ~ # echo "module usbcore =pT:usb.l" >
>                                 <debugfs>/dynamic_debug/control
>
> To simplify processing trace destination can be omitted when default
> trace destination is set, for example the command
>
> localhost ~ # echo "module usbcore =pTl" >
>                                 <debugfs>/dynamic_debug/control
>
> will use default trace destination. If default trace destination is not
> set the above command will fail. The default trace destination is set
> when a command with any of the flags [-+=] and explicitly provided trace
> destination matches at least one callsite, for example the command
>
> localhost ~ # echo "module usbcore -T:usb" >
>                                 <debugfs>/dynamic_debug/control
>
> will disable trace for all usbcore module callsites (if any was enabled)
> and will set "usb" instance as default trace destination. To enable writing
> thunderbolt module debug logs to the "usb" trace instance as well a user
> can issue the command:
>
> localhost ~ # echo "module thunderbolt =T" >
>                                 <debugfs>/dynamic_debug/control
>
> Since default trace destination was previously set therefore "usb" instance
> name does not have to be explicitly provided.
>
> When no callsite writes debug logs to a trace instance then it can be
> released (its reference counter decrased) with the "close" command.
decreased

> Closing a trace instance make it unavailable for dynamic debug and also
makes
> allows a user to delete such a trace instance at convenient time later
> with rmdir command. For example when "usb" instance is not used anymore
> a user can issue the command:
>
> localhost ~ # echo "close usb" >
>                                 <debugfs>/dynamic_debug/control
> and then to delete it with:
>
> localhost ~ # rmdir <debugfs>/tracing/instances/
>
> To enable writing usbcore module debug logs to trace dyndbg:prdbg and
> dyndbg:devdbg events user can issue the command:
>
> localhost ~ # echo "module usbcore =T:0" >
>                                 <debugfs>/dynamic_debug/control
>
> Then dyndbg trace events can be for example captured with the command:
>
> localhost ~ # trace-cmd start -e dyndbg
>
> And displayed with the command:
>
> localhost ~ # trace-cmd show
>

is there a recipe to show private traces ? prolly worth a mention here.


>
>
> Jim, I made a few changes to the test script dd-selftest.rc you created
> and I also added new test scenarios. You can find the entire patchset
> with the test script changes on top here
> https://chromium.googlesource.com/chromiumos/third_party/kernel/+log/refs/sandbox/ukaszb/dyndbg_trace_v3
> I wonder where would be the proper place to store the test script
> (upstream, your github.com:jimc/linux.git)
> Do you have a suggestion for that ?
>

I got it (your HEAD), renamed and put it in:
tools/testing/selftests/dynamic_debug/
and copied & modified Makefile and config from ../users/
I added your SOB, that seems proper.

nice additions.  and I like the colors.  maybe they belong in lib.mk,
but thats 4 later.

and tweaked the modules / DUTs to *hopefully* get stable callsite counts
from the tests on them, in virtually any usable config.
DUTs: file init/main, module mm_init, and module test_dynamic_debug (a
config constraint)
The ref-counts are taken from a default virtme-ng -k config on my x86-64 box

I now pass tests up to:

[root@v6 wk-proof]# ./tools/testing/selftests/dynamic_debug/dyndbg_selftest.sh
...
# TEST_PRIVATE_TRACE_6
[ 1009.296557] dyndbg: read 3 bytes from userspace
[ 1009.296876] dyndbg: query 0: <=_> on module: <*>
[ 1009.297171] dyndbg: processed 1 queries, with 1559 matches, 0 errs
[ 1009.311621] dyndbg: read 39 bytes from userspace
[ 1009.312032] dyndbg: query 0: <open
A_bit_lengthy_trace_instance_name> on module: <*>
[ 1009.312569] dyndbg: instance is already opened
name:A_bit_lengthy_trace_instance_name
[ 1009.313063] dyndbg: processed 1 queries, with 0 matches, 1 errs
: ./tools/testing/selftests/dynamic_debug/dyndbg_selftest.sh:454
ddcmd() expected to exit with code 0
Error: 'File exists'

it seems invocation dependent
I suspect 2 possibilities:
1-  invoking as shell-script, repeatedly vs vng -e script-name
(one-shot per boot)
2- virtme-ng's minimal-default config has no CONFIG_USB.
   this changes post-conditions of the script, affecting preconditions
of the next run.

2 means that we should replace usbcore with some other always *builtin* module.

I chose module params, on the idea that its builtin, but also invoked later,
when modules are modprobed with params, so its callsites can be enabled &
then invoked via do_prints, to test for writes to the private trace-buf.

I've pushed it to lukas-v3.0 at jimc.github.com/linux

Would you look at err on _6, above,
and figure out if its insufficiently robust to test preconditions, or
something else ?
and also:
rename test_private_trace_N() to better names
- and/or comments to intent & pattern of use
more tweaks invited in its commit-msg

since cycle_test_problem() is not actually a problem, whats a better name ?
_not_best_practices ?

I think the final test script enhancement needed is (maybe separately):
private-buffer-expected-write-verification after do_prints,
and around modprobe test_dynamic_debug dyndbg=$multicmd
subject to 2 below.

> TODOs:
> - update dynamic debug documentation,
> - finalize discussion related to default trace destination
> (whether we want it at all, if yes then conclude on the details)
>

good list. before docs;

wrt default-trace, at least in some details, it seems extra rules to know.
for example, if the default were set on successful open,
rather than successful rule application (iirc), then it would read a lot
like "with" or "using" blocks, esp with <<EOX form

with that new form, it might be pretty expressive:

echo <<YMMV > /proc/dynamic_debug/control
  open sesame # ie with
    module magic_carpet function forward +Tfml
    module magic_lamp function rub_vigorously +Tfmt
  open voicetrace
    module voice2ai function text2cmdprompt +T
    module undo function oh_crap +T
YMMV

I think set-default-on-good-rule-applied is flawed:
it relies on the most complex expression in the grammar to be correct
and without spelling errors, where module unknown is
OK grammatically, but nonsense.
set-default-on-open is simpler to explain and test separately.

We should probably consider modifying the continue-looping behavior
of ddebug_exec_queries, depending upon the return-code.
open, close errors could reasonably warrant different treatment,
like terminating the mult-cmd loop prematurely on open/close errs.
Esp if we keep the set-default-on-good-rule-applied
What do you think ?

I'm inclined to reword a commit-msg or 2, drop RFC, obsolete comments etc.

I can do that in a lukas-v3.1, or as in-thread responses,
do you have a preference ?
some inline below..

> Changes:
> V3 -> V2
> - squash "dyndbg: export _print_hex_dump" with "dyndbg: add support for hex_dump output to trace",
> - squash "dyndbg: tweak pr_info format s/trace dest/trace_dest/"  with "dyndbg: add processing of T(race) flag argument",
> - squash "dyndbg: change +T:name_terminator to dot" with "dyndbg: add processing of T(race) flag argument",
> - fix setting default trace destination,
> - decrease use count when callsite is being disabled as a part of module removal,
> - fix parsing of T flag argument,
> - update __get_str_strip_nl macro per Steve's comment,
> - drop commit "dyndbg: move lock,unlock into ddebug_change, drop goto" and add comment explaining why ddebug_parse_flags
> and ddebug_change have to be run in critical section,
> - add "depends on TRACING" for "DYNAMIC_DEBUG",
> - update DYNAMIC_DEBUG_BRANCH macro which is used when CONFIG_JUMP_LABEL is not set,
> - change structure name ddebug_trace_inst to dd_private_tracebuf,
> - change structure name ddebug_trace to dd_tracebuf_tbl_info,
> - rename is_ddebug_cmd to is_dd_trace_cmd,
> - rename validate_tr_name to dd_good_trace_name,
> - rename handle_tr_opend_cmd to handle_trace_opend_cmd and handle_tr_close_cmd to handle_trace_close_cmd,
> - refactor ddebug_parse_cmd,
> - add pr_err when trace_array_get_by_name or trace_array_init_printk fails in trace_array_init_printk,
> - add static prefix to show_T_args,
> - rename TRACE_DST_MAX to TRACE_DST_LAST and change its value to 64, reserve index 0 for trace events in dd_tracebuf_tbl_info (index 0 will be wasted),
> - add "#: " prefix to "Default trace destination" and "Opened trace instances" and print all opened trace instances on the same line,
>
> V2->V1
> Major rework after receiving feedback in
> https://lore.kernel.org/all/20231103131011.1316396-1-lb@semihalf.com/
>
> This includes among other things:
> - addittion of open/close commands,
> - use names instead of numbers for trace destinations,
> - change prdbg and devdbg trace events to strip newline
> on the slow path (read side),
> - change prdbg and devdbg trace events to stores actual values
> instead of pointers because if a pointer becomes invalid then
> the TP_printk call will cause a crash,
> - add support for default trace destination.
>
> V1
> Major rework after receiving feedback in
> https://lore.kernel.org/all/20230915154856.1896062-1-lb@semihalf.com/
>
> Jim Cromie (14):
>   dyndbg: add _DPRINTK_FLAGS_ENABLED
>   dyndbg: add _DPRINTK_FLAGS_TRACE
>   dyndbg: add write events to tracefs code
>   dyndbg: add 2 trace-events: prdbg, devdbg
>   tracefs: add __get_str_strip_nl - RFC
>   dyndbg: use __get_str_strip_nl in prdbg and devdbg
>   dyndbg: repack _ddebug structure
>   dyndbg: disambiguate quoting in a debug msg
>   dyndbg: fix old BUG_ON in >control parser
>   dyndbg: treat comma as a token separator
>   dyndbg: add skip_spaces_and_coma()

probly just squash this with prev, its not separately tested,
and not worth isolating a test for it.
s/coma/comma/ otherwise.

>   dyndbg: split multi-query strings with %
>   dyndbg: reduce verbose/debug clutter
>   dyndbg: id the bad word in parse-flags err msg
>
> Łukasz Bartosik (8):
>   dyndbg: move flags field to a new structure
>   dyndbg: add trace destination field to _ddebug
>   dyndbg: add open and close commands for trace
>   dyndbg: don't close trace instance when in use
>   dyndbg: add processing of T(race) flag argument

tweak subject   s/T(race)/+T:prv_trcbuf_name./   - might as well use
legal flag syntax.


>   dyndbg: add support for default trace destination
>   dyndbg: write debug logs to trace instance
>   dyndbg: add support for hex_dump output to trace
>
>  .../admin-guide/dynamic-debug-howto.rst       |   5 +-
>  MAINTAINERS                                   |   1 +
>  include/linux/dynamic_debug.h                 |  57 +-
>  include/trace/events/dyndbg.h                 |  54 ++
>  include/trace/stages/stage3_trace_output.h    |  13 +
>  lib/Kconfig.debug                             |   2 +
>  lib/dynamic_debug.c                           | 736 ++++++++++++++++--
>  7 files changed, 775 insertions(+), 93 deletions(-)
>  create mode 100644 include/trace/events/dyndbg.h
>
> --
> 2.43.0.472.g3155946c3a-goog
>

śr., 27 gru 2023 o 05:23 <jim.cromie@gmail.com> napisał(a):
>
> re-adding gregkh, who fell off the cc's again.
> he is one of our upstreams.
>

hi Jim,

It's good to hear from you.

Thanks. I missed to add Greg.

> On Fri, Dec 22, 2023 at 6:51 PM Łukasz Bartosik <lb@semihalf.com> wrote:
> >
> > Add support for writing debug logs to trace events and trace instances.
> > The rationale behing this feature is to be able to redirect debug logs
> > (per each callsite individually) to trace to aid in debugging. The debug
> > logs output to trace can be enabled with T flag. Additionally the T flag
> > accepts trace destination which can be provided to the T flag after ":".
> > The trace destination field is used to determine where debug logs will be
> > written.
> >
> > In order to redirect callsite debug log to a trace instance it has to be
> > initialized first with a newly introduced "open" command. For example,
> > "usb" trace instance in <debugfs>/tracing/instances/ can be initialized
> > by issuing the command:
> >
> > localhost ~ # echo "open usb" >
> >                                 <debugfs>/dynamic_debug/control
> >
> > If the trace instance <debugfs>/tracing/instances/usb already exists
> > then it will be reused otherwise new usbcore instance will be created.
> > Maximum 63 trace instances can be "opened". The trace instance name can
> > include any of ^\w+ and underscore characters. There is also a special
> > name "0" reserved for writing debug logs to trace prdbg and devdbg events.
> > The reserved name "0" does not require to be "opened" before use.
>
> theres implication here that p only works when :0.
> Is that intended ?
> it seems wrong, or at least unnecessary.
>

I don't see clearly the implication that p only works when :0.
Which statement implies this to you ? Please keep in mind that English
is not my native.

> In fact, theres no specific reason to exclude +p:trcbuf.mf,
> esp if we keep default-trace-buf
> since +pTfml  could have that meaning implicitly.
> We can call it allowed and "unimplemented until proven useful" on +p
>
> +p completely independent of +T is a simplicity,
> lets keep that until proven useful otherwise.
>
> >
> > To enable writing usbcore module debug logs to the "usb" trace instance
> > opened above a user can issue the command:
> >
> > localhost ~ # echo "module usbcore =pT:usb" >
> >                                 <debugfs>/dynamic_debug/control
> >
> > Please note that output of debug logs to syslog (p flag) and trace (T flag)
> > can be independently enabled/disabled for each callsite. Therefore the
> > above command will enable writing of debug logs not only to the trace
> > instance "usb" but also to syslog.
> >
> > When trace destination is followed by another flag the next flag has to
> > be preeceded with ".", for example
> >
> > localhost ~ # echo "module usbcore =pT:usb.l" >
> >                                 <debugfs>/dynamic_debug/control
> >
> > To simplify processing trace destination can be omitted when default
> > trace destination is set, for example the command
> >
> > localhost ~ # echo "module usbcore =pTl" >
> >                                 <debugfs>/dynamic_debug/control
> >
> > will use default trace destination. If default trace destination is not
> > set the above command will fail. The default trace destination is set
> > when a command with any of the flags [-+=] and explicitly provided trace
> > destination matches at least one callsite, for example the command
> >
> > localhost ~ # echo "module usbcore -T:usb" >
> >                                 <debugfs>/dynamic_debug/control
> >
> > will disable trace for all usbcore module callsites (if any was enabled)
> > and will set "usb" instance as default trace destination. To enable writing
> > thunderbolt module debug logs to the "usb" trace instance as well a user
> > can issue the command:
> >
> > localhost ~ # echo "module thunderbolt =T" >
> >                                 <debugfs>/dynamic_debug/control
> >
> > Since default trace destination was previously set therefore "usb" instance
> > name does not have to be explicitly provided.
> >
> > When no callsite writes debug logs to a trace instance then it can be
> > released (its reference counter decrased) with the "close" command.
> decreased
>

Ack

> > Closing a trace instance make it unavailable for dynamic debug and also
> makes

Ack

> > allows a user to delete such a trace instance at convenient time later
> > with rmdir command. For example when "usb" instance is not used anymore
> > a user can issue the command:
> >
> > localhost ~ # echo "close usb" >
> >                                 <debugfs>/dynamic_debug/control
> > and then to delete it with:
> >
> > localhost ~ # rmdir <debugfs>/tracing/instances/
> >
> > To enable writing usbcore module debug logs to trace dyndbg:prdbg and
> > dyndbg:devdbg events user can issue the command:
> >
> > localhost ~ # echo "module usbcore =T:0" >
> >                                 <debugfs>/dynamic_debug/control
> >
> > Then dyndbg trace events can be for example captured with the command:
> >
> > localhost ~ # trace-cmd start -e dyndbg
> >
> > And displayed with the command:
> >
> > localhost ~ # trace-cmd show
> >
>
> is there a recipe to show private traces ? prolly worth a mention here.
>

Trace-cmd stat shows among other things open trace instances. I will add it.

>
> >
> >
> > Jim, I made a few changes to the test script dd-selftest.rc you created
> > and I also added new test scenarios. You can find the entire patchset
> > with the test script changes on top here
> > https://chromium.googlesource.com/chromiumos/third_party/kernel/+log/refs/sandbox/ukaszb/dyndbg_trace_v3
> > I wonder where would be the proper place to store the test script
> > (upstream, your github.com:jimc/linux.git)
> > Do you have a suggestion for that ?
> >
>
> I got it (your HEAD), renamed and put it in:
> tools/testing/selftests/dynamic_debug/
> and copied & modified Makefile and config from ../users/
> I added your SOB, that seems proper.
>

Great, thanks ;)

> nice additions.  and I like the colors.  maybe they belong in lib.mk,
> but thats 4 later.
>
> and tweaked the modules / DUTs to *hopefully* get stable callsite counts
> from the tests on them, in virtually any usable config.
> DUTs: file init/main, module mm_init, and module test_dynamic_debug (a
> config constraint)
> The ref-counts are taken from a default virtme-ng -k config on my x86-64 box
>
> I now pass tests up to:
>
> [root@v6 wk-proof]# ./tools/testing/selftests/dynamic_debug/dyndbg_selftest.sh
> ...
> # TEST_PRIVATE_TRACE_6
> [ 1009.296557] dyndbg: read 3 bytes from userspace
> [ 1009.296876] dyndbg: query 0: <=_> on module: <*>
> [ 1009.297171] dyndbg: processed 1 queries, with 1559 matches, 0 errs
> [ 1009.311621] dyndbg: read 39 bytes from userspace
> [ 1009.312032] dyndbg: query 0: <open
> A_bit_lengthy_trace_instance_name> on module: <*>
> [ 1009.312569] dyndbg: instance is already opened
> name:A_bit_lengthy_trace_instance_name
> [ 1009.313063] dyndbg: processed 1 queries, with 0 matches, 1 errs
> : ./tools/testing/selftests/dynamic_debug/dyndbg_selftest.sh:454
> ddcmd() expected to exit with code 0
> Error: 'File exists'
>
> it seems invocation dependent
> I suspect 2 possibilities:
> 1-  invoking as shell-script, repeatedly vs vng -e script-name
> (one-shot per boot)
> 2- virtme-ng's minimal-default config has no CONFIG_USB.
>    this changes post-conditions of the script, affecting preconditions
> of the next run.
>

I guess you must have enabled CONFIG_USB in your setup otherwise
dyndbg_selftest.sh should fail earlier in TEST_PRIVATE_TRACE_5 ?

> 2 means that we should replace usbcore with some other always *builtin* module.
>

Sounds good. Do you have a module candidate ?

I'm also concerned that we might need to validate dyndbg_selftest.sh
against specific kernel version because
I took the dyndbg_selftest.sh from lukas-v3.0 branch and I had to do
the following changes to make it work on kernel v6.6:

--- a/tools/testing/selftests/dynamic_debug/dyndbg_selftest.sh
+++ b/tools/testing/selftests/dynamic_debug/dyndbg_selftest.sh
@@ -166,12 +166,12 @@ EOF
 function comma_terminator_tests {
     echo -e "${GREEN}# COMMA_TERMINATOR_TESTS ${NC}"
     # try combos of space & comma
-    check_match_ct mm_init 5
+    check_match_ct mm_init 4
     ddcmd module,mm_init,=_            # commas as spaces
     ddcmd module,mm_init,+mpf          # turn on non-classed
-    check_match_ct =pmf 5
+    check_match_ct =pmf 4
     ddcmd ,module ,, ,  mm_init, -p    # extra commas & spaces
-    check_match_ct =mf 5
+    check_match_ct =mf 4
     ddcmd =_
 }
 function test_percent_splitting {
@@ -350,7 +350,7 @@ function test_private_trace_3 {
     ddcmd class D2_CORE +T:foo \; class D2_KMS +T:foo
     ddcmd "class,D2_CORE,+T:foo;,class,D2_KMS,+T:foo"
     ddcmd class,D2_CORE,+T:foo\;class,D2_KMS,+T:foo
-    check_match_ct =T 2 -v
+    check_match_ct =T 3 -v
     check_match_ct =Tl 0
     check_match_ct =Tmf 0
     echo 1 >/sys/kernel/tracing/tracing_on
@@ -379,7 +379,7 @@ function test_private_trace_4 {
     modprobe test_dynamic_debug dyndbg=class,D2_CORE,+T:foo%class,D2_KMS,+T:foo
     check_match_ct =Tl 0
     check_match_ct =Tmf 0
-    check_match_ct =T 2
+    check_match_ct =T 3
     echo 1 >/sys/kernel/tracing/tracing_on

What kernel version did you use for the testing ?

> I chose module params, on the idea that its builtin, but also invoked later,
> when modules are modprobed with params, so its callsites can be enabled &
> then invoked via do_prints, to test for writes to the private trace-buf.
>
> I've pushed it to lukas-v3.0 at jimc.github.com/linux
>
> Would you look at err on _6, above,
> and figure out if its insufficiently robust to test preconditions, or
> something else ?

The following change fixes failure in TEST_PRIVATE_TRACE_6:
@@ -455,7 +455,7 @@ function test_private_trace_6 {
     ddcmd open $name
     is_trace_instance_opened $name
     check_trace_instance_dir $name 1
-    ddcmd "module module =T:$name.l" -v
+    ddcmd "module usbcore =T:$name.l"
     check_match_ct =T:A_bit_lengthy_trace....l 164

When dyndbg_selftest.sh completes with success which is announced by the line
# Done on: Thu Dec 28 23:04:17 CET 2023
then it leaves dynamic debug and trace in a state where next
dyndbg_selftest.sh run should also complete with success.
But when any of the tests fails manual intervention or reboot is
required at the moment.
Do you think we should have a cleanup function and call it whenever
dyndbg_selftest.sh fails in order
to prepare dynamic debug and trace for the next run of dyndbg_selftest.sh ?

> and also:
> rename test_private_trace_N() to better names
> - and/or comments to intent & pattern of use
> more tweaks invited in its commit-msg
>

I will rename the functions and add description of the tests.

> since cycle_test_problem() is not actually a problem, whats a better name ?
> _not_best_practices ?
>

Ack

> I think the final test script enhancement needed is (maybe separately):
> private-buffer-expected-write-verification after do_prints,
> and around modprobe test_dynamic_debug dyndbg=$multicmd
> subject to 2 below.
>

Ack

> > TODOs:
> > - update dynamic debug documentation,
> > - finalize discussion related to default trace destination
> > (whether we want it at all, if yes then conclude on the details)
> >
>
> good list. before docs;
>
> wrt default-trace, at least in some details, it seems extra rules to know.
> for example, if the default were set on successful open,
> rather than successful rule application (iirc), then it would read a lot
> like "with" or "using" blocks, esp with <<EOX form
>
> with that new form, it might be pretty expressive:
>
> echo <<YMMV > /proc/dynamic_debug/control
>   open sesame # ie with
>     module magic_carpet function forward +Tfml
>     module magic_lamp function rub_vigorously +Tfmt
>   open voicetrace
>     module voice2ai function text2cmdprompt +T
>     module undo function oh_crap +T
> YMMV
>
> I think set-default-on-good-rule-applied is flawed:
> it relies on the most complex expression in the grammar to be correct
> and without spelling errors, where module unknown is
> OK grammatically, but nonsense.

in case of "unknown" module default trace destination will not be
updated because
the code checks for nfound before updating  default destination:
if (nfound)
    update_tr_default_dst(modifiers);

> set-default-on-open is simpler to explain and test separately.
>

Actually I think we discussed set-default-on-open some time ago (in
the beginning).
But to sum up the default trace destination there were 3 directions
proposed/discussed:
- set-default-on-open,
- set-default-on-good-rule-applied,
- preset-default-per-each-callsite with -T:trace_dest_name,

All 3 pass information explicitly but IMHO
preset-default-per-each-callsite is most confusing as user would have
to remember what was preset for a given callsite when later passing a
T flag for the same callsite.

Then if it comes to set-default-on-open vs
set-default-on-good-rule-applied I don't have strong opinion but I
would
lean towards set-default-on-open because in this case it is pretty
straightforward, I mean last successful open sets default trace
destination.

If you also hesitate which one to choose maybe we should start with
very simple approach like that +T always defaults to trace events (:0)
?

> We should probably consider modifying the continue-looping behavior
> of ddebug_exec_queries, depending upon the return-code.
> open, close errors could reasonably warrant different treatment,
> like terminating the mult-cmd loop prematurely on open/close errs.
> Esp if we keep the set-default-on-good-rule-applied
> What do you think ?
>

Let's first conclude on default destination.

> I'm inclined to reword a commit-msg or 2, drop RFC, obsolete comments etc.
>
> I can do that in a lukas-v3.1, or as in-thread responses,
> do you have a preference ?

Please go ahead and make changes in the lukas-v3.1 branch. I find it
very convenient. I will just grab your changes from the branch.

> some inline below..
>
> > Changes:
> > V3 -> V2
> > - squash "dyndbg: export _print_hex_dump" with "dyndbg: add support for hex_dump output to trace",
> > - squash "dyndbg: tweak pr_info format s/trace dest/trace_dest/"  with "dyndbg: add processing of T(race) flag argument",
> > - squash "dyndbg: change +T:name_terminator to dot" with "dyndbg: add processing of T(race) flag argument",
> > - fix setting default trace destination,
> > - decrease use count when callsite is being disabled as a part of module removal,
> > - fix parsing of T flag argument,
> > - update __get_str_strip_nl macro per Steve's comment,
> > - drop commit "dyndbg: move lock,unlock into ddebug_change, drop goto" and add comment explaining why ddebug_parse_flags
> > and ddebug_change have to be run in critical section,
> > - add "depends on TRACING" for "DYNAMIC_DEBUG",
> > - update DYNAMIC_DEBUG_BRANCH macro which is used when CONFIG_JUMP_LABEL is not set,
> > - change structure name ddebug_trace_inst to dd_private_tracebuf,
> > - change structure name ddebug_trace to dd_tracebuf_tbl_info,
> > - rename is_ddebug_cmd to is_dd_trace_cmd,
> > - rename validate_tr_name to dd_good_trace_name,
> > - rename handle_tr_opend_cmd to handle_trace_opend_cmd and handle_tr_close_cmd to handle_trace_close_cmd,
> > - refactor ddebug_parse_cmd,
> > - add pr_err when trace_array_get_by_name or trace_array_init_printk fails in trace_array_init_printk,
> > - add static prefix to show_T_args,
> > - rename TRACE_DST_MAX to TRACE_DST_LAST and change its value to 64, reserve index 0 for trace events in dd_tracebuf_tbl_info (index 0 will be wasted),
> > - add "#: " prefix to "Default trace destination" and "Opened trace instances" and print all opened trace instances on the same line,
> >
> > V2->V1
> > Major rework after receiving feedback in
> > https://lore.kernel.org/all/20231103131011.1316396-1-lb@semihalf.com/
> >
> > This includes among other things:
> > - addittion of open/close commands,
> > - use names instead of numbers for trace destinations,
> > - change prdbg and devdbg trace events to strip newline
> > on the slow path (read side),
> > - change prdbg and devdbg trace events to stores actual values
> > instead of pointers because if a pointer becomes invalid then
> > the TP_printk call will cause a crash,
> > - add support for default trace destination.
> >
> > V1
> > Major rework after receiving feedback in
> > https://lore.kernel.org/all/20230915154856.1896062-1-lb@semihalf.com/
> >
> > Jim Cromie (14):
> >   dyndbg: add _DPRINTK_FLAGS_ENABLED
> >   dyndbg: add _DPRINTK_FLAGS_TRACE
> >   dyndbg: add write events to tracefs code
> >   dyndbg: add 2 trace-events: prdbg, devdbg
> >   tracefs: add __get_str_strip_nl - RFC
> >   dyndbg: use __get_str_strip_nl in prdbg and devdbg
> >   dyndbg: repack _ddebug structure
> >   dyndbg: disambiguate quoting in a debug msg
> >   dyndbg: fix old BUG_ON in >control parser
> >   dyndbg: treat comma as a token separator
> >   dyndbg: add skip_spaces_and_coma()
>
> probly just squash this with prev, its not separately tested,
> and not worth isolating a test for it.
> s/coma/comma/ otherwise.
>

I will squash it.

> >   dyndbg: split multi-query strings with %
> >   dyndbg: reduce verbose/debug clutter
> >   dyndbg: id the bad word in parse-flags err msg
> >
> > Łukasz Bartosik (8):
> >   dyndbg: move flags field to a new structure
> >   dyndbg: add trace destination field to _ddebug
> >   dyndbg: add open and close commands for trace
> >   dyndbg: don't close trace instance when in use
> >   dyndbg: add processing of T(race) flag argument
>
> tweak subject   s/T(race)/+T:prv_trcbuf_name./   - might as well use
> legal flag syntax.
>

Ack


>
> >   dyndbg: add support for default trace destination
> >   dyndbg: write debug logs to trace instance
> >   dyndbg: add support for hex_dump output to trace
> >
> >  .../admin-guide/dynamic-debug-howto.rst       |   5 +-
> >  MAINTAINERS                                   |   1 +
> >  include/linux/dynamic_debug.h                 |  57 +-
> >  include/trace/events/dyndbg.h                 |  54 ++
> >  include/trace/stages/stage3_trace_output.h    |  13 +
> >  lib/Kconfig.debug                             |   2 +
> >  lib/dynamic_debug.c                           | 736 ++++++++++++++++--
> >  7 files changed, 775 insertions(+), 93 deletions(-)
> >  create mode 100644 include/trace/events/dyndbg.h
> >
> > --
> > 2.43.0.472.g3155946c3a-goog
> >

ok, to catch up here,
Lukas & I have been nudging the test script forward,
some of this is settled..

On Thu, Dec 28, 2023 at 5:00 PM Łukasz Bartosik <lb@semihalf.com> wrote:
>
> śr., 27 gru 2023 o 05:23 <jim.cromie@gmail.com> napisał(a):
> >
> > re-adding gregkh, who fell off the cc's again.
> > he is one of our upstreams.
> >
>
> hi Jim,
>
> It's good to hear from you.
>
> Thanks. I missed to add Greg.
>
> > On Fri, Dec 22, 2023 at 6:51 PM Łukasz Bartosik <lb@semihalf.com> wrote:
> > >
> > > Add support for writing debug logs to trace events and trace instances.
> > > The rationale behing this feature is to be able to redirect debug logs
> > > (per each callsite individually) to trace to aid in debugging. The debug
> > > logs output to trace can be enabled with T flag. Additionally the T flag
> > > accepts trace destination which can be provided to the T flag after ":".
> > > The trace destination field is used to determine where debug logs will be
> > > written.
> > >
> > > In order to redirect callsite debug log to a trace instance it has to be
> > > initialized first with a newly introduced "open" command. For example,
> > > "usb" trace instance in <debugfs>/tracing/instances/ can be initialized
> > > by issuing the command:
> > >
> > > localhost ~ # echo "open usb" >
> > >                                 <debugfs>/dynamic_debug/control
> > >
> > > If the trace instance <debugfs>/tracing/instances/usb already exists
> > > then it will be reused otherwise new usbcore instance will be created.
> > > Maximum 63 trace instances can be "opened". The trace instance name can
> > > include any of ^\w+ and underscore characters. There is also a special
> > > name "0" reserved for writing debug logs to trace prdbg and devdbg events.
> > > The reserved name "0" does not require to be "opened" before use.
> >
> > theres implication here that p only works when :0.
> > Is that intended ?
> > it seems wrong, or at least unnecessary.
> >
>
> I don't see clearly the implication that p only works when :0.
> Which statement implies this to you ? Please keep in mind that English
> is not my native.

heh - Im not sure now - its mostly me probing for unseen inconsistencies.

> > In fact, theres no specific reason to exclude +p:trcbuf.mf,
> > esp if we keep default-trace-buf
> > since +pTfml  could have that meaning implicitly.
> > We can call it allowed and "unimplemented until proven useful" on +p
> >
> > +p completely independent of +T is a simplicity,
> > lets keep that until proven useful otherwise.
> >
> > >
> > > To enable writing usbcore module debug logs to the "usb" trace instance
> > > opened above a user can issue the command:
> > >
> > > localhost ~ # echo "module usbcore =pT:usb" >
> > >                                 <debugfs>/dynamic_debug/control
> > >
> > > Please note that output of debug logs to syslog (p flag) and trace (T flag)
> > > can be independently enabled/disabled for each callsite. Therefore the
> > > above command will enable writing of debug logs not only to the trace
> > > instance "usb" but also to syslog.
> > >
> > > When trace destination is followed by another flag the next flag has to
> > > be preeceded with ".", for example
> > >
> > > localhost ~ # echo "module usbcore =pT:usb.l" >
> > >                                 <debugfs>/dynamic_debug/control
> > >
> > > To simplify processing trace destination can be omitted when default
> > > trace destination is set, for example the command
> > >
> > > localhost ~ # echo "module usbcore =pTl" >
> > >                                 <debugfs>/dynamic_debug/control
> > >
> > > will use default trace destination. If default trace destination is not
> > > set the above command will fail. The default trace destination is set
> > > when a command with any of the flags [-+=] and explicitly provided trace
> > > destination matches at least one callsite, for example the command
> > >
> > > localhost ~ # echo "module usbcore -T:usb" >
> > >                                 <debugfs>/dynamic_debug/control
> > >
> > > will disable trace for all usbcore module callsites (if any was enabled)
> > > and will set "usb" instance as default trace destination. To enable writing
> > > thunderbolt module debug logs to the "usb" trace instance as well a user
> > > can issue the command:
> > >
> > > localhost ~ # echo "module thunderbolt =T" >
> > >                                 <debugfs>/dynamic_debug/control
> > >
> > > Since default trace destination was previously set therefore "usb" instance
> > > name does not have to be explicitly provided.
> > >
> > > When no callsite writes debug logs to a trace instance then it can be
> > > released (its reference counter decrased) with the "close" command.
> > decreased
> >
>
> Ack
>
> > > Closing a trace instance make it unavailable for dynamic debug and also
> > makes
>
> Ack
>
> > > allows a user to delete such a trace instance at convenient time later
> > > with rmdir command. For example when "usb" instance is not used anymore
> > > a user can issue the command:
> > >
> > > localhost ~ # echo "close usb" >
> > >                                 <debugfs>/dynamic_debug/control
> > > and then to delete it with:
> > >
> > > localhost ~ # rmdir <debugfs>/tracing/instances/
> > >
> > > To enable writing usbcore module debug logs to trace dyndbg:prdbg and
> > > dyndbg:devdbg events user can issue the command:
> > >
> > > localhost ~ # echo "module usbcore =T:0" >
> > >                                 <debugfs>/dynamic_debug/control
> > >
> > > Then dyndbg trace events can be for example captured with the command:
> > >
> > > localhost ~ # trace-cmd start -e dyndbg
> > >
> > > And displayed with the command:
> > >
> > > localhost ~ # trace-cmd show
> > >
> >
> > is there a recipe to show private traces ? prolly worth a mention here.
> >
>
> Trace-cmd stat shows among other things open trace instances. I will add it.
>
> >
> > >
> > >
> > > Jim, I made a few changes to the test script dd-selftest.rc you created
> > > and I also added new test scenarios. You can find the entire patchset
> > > with the test script changes on top here
> > > https://chromium.googlesource.com/chromiumos/third_party/kernel/+log/refs/sandbox/ukaszb/dyndbg_trace_v3
> > > I wonder where would be the proper place to store the test script
> > > (upstream, your github.com:jimc/linux.git)
> > > Do you have a suggestion for that ?
> > >
> >
> > I got it (your HEAD), renamed and put it in:
> > tools/testing/selftests/dynamic_debug/
> > and copied & modified Makefile and config from ../users/
> > I added your SOB, that seems proper.
> >
>
> Great, thanks ;)
>
> > nice additions.  and I like the colors.  maybe they belong in lib.mk,
> > but thats 4 later.
> >
> > and tweaked the modules / DUTs to *hopefully* get stable callsite counts
> > from the tests on them, in virtually any usable config.
> > DUTs: file init/main, module mm_init, and module test_dynamic_debug (a
> > config constraint)
> > The ref-counts are taken from a default virtme-ng -k config on my x86-64 box
> >
> > I now pass tests up to:
> >
> > [root@v6 wk-proof]# ./tools/testing/selftests/dynamic_debug/dyndbg_selftest.sh
> > ...
> > # TEST_PRIVATE_TRACE_6
> > [ 1009.296557] dyndbg: read 3 bytes from userspace
> > [ 1009.296876] dyndbg: query 0: <=_> on module: <*>
> > [ 1009.297171] dyndbg: processed 1 queries, with 1559 matches, 0 errs
> > [ 1009.311621] dyndbg: read 39 bytes from userspace
> > [ 1009.312032] dyndbg: query 0: <open
> > A_bit_lengthy_trace_instance_name> on module: <*>
> > [ 1009.312569] dyndbg: instance is already opened
> > name:A_bit_lengthy_trace_instance_name
> > [ 1009.313063] dyndbg: processed 1 queries, with 0 matches, 1 errs
> > : ./tools/testing/selftests/dynamic_debug/dyndbg_selftest.sh:454
> > ddcmd() expected to exit with code 0
> > Error: 'File exists'
> >
> > it seems invocation dependent
> > I suspect 2 possibilities:
> > 1-  invoking as shell-script, repeatedly vs vng -e script-name
> > (one-shot per boot)
> > 2- virtme-ng's minimal-default config has no CONFIG_USB.
> >    this changes post-conditions of the script, affecting preconditions
> > of the next run.
> >
>
> I guess you must have enabled CONFIG_USB in your setup otherwise
> dyndbg_selftest.sh should fail earlier in TEST_PRIVATE_TRACE_5 ?
>

Its usually on, but I have at least one config,
IIRC from default vng -vk, that left it off.

whats the shell syntax to check CONFIG_MODULES ?

ATM, basic-tests uses "module main" (maybe worth narrowing)
comma-terminator-tests uses "module params"
test-percent-splitting uses test_dynamic_debug to demo a useful case,
so it needs MODULES
so does the self-start-various-end tests

the private-trace tests appear to use a mix of
test_dynamic-debug, & module params,
maybe that can be materially improved, I dont know.

IIRC for builtins I think we're now using 'file kernel/
> > 2 means that we should replace usbcore with some other always *builtin* module.
> >
>
> Sounds good. Do you have a module candidate ?



>
> I'm also concerned that we might need to validate dyndbg_selftest.sh
> against specific kernel version because
> I took the dyndbg_selftest.sh from lukas-v3.0 branch and I had to do
> the following changes to make it work on kernel v6.6:
>

Yes, I hit this one too.
I decided to avoid using mm_init for this reason.
(without actually looking whether it was a config-based variance,
which I assumed, or a commit-based one)
I chose 'module params' instead,
despite the need to escape the brackets in the search:

    check_match_ct '\[params\]' 4

> --- a/tools/testing/selftests/dynamic_debug/dyndbg_selftest.sh
> +++ b/tools/testing/selftests/dynamic_debug/dyndbg_selftest.sh
> @@ -166,12 +166,12 @@ EOF
>  function comma_terminator_tests {
>      echo -e "${GREEN}# COMMA_TERMINATOR_TESTS ${NC}"
>      # try combos of space & comma
> -    check_match_ct mm_init 5
> +    check_match_ct mm_init 4
>      ddcmd module,mm_init,=_            # commas as spaces
>      ddcmd module,mm_init,+mpf          # turn on non-classed
> -    check_match_ct =pmf 5
> +    check_match_ct =pmf 4
>      ddcmd ,module ,, ,  mm_init, -p    # extra commas & spaces
> -    check_match_ct =mf 5
> +    check_match_ct =mf 4
>      ddcmd =_
>  }
>  function test_percent_splitting {
> @@ -350,7 +350,7 @@ function test_private_trace_3 {
>      ddcmd class D2_CORE +T:foo \; class D2_KMS +T:foo
>      ddcmd "class,D2_CORE,+T:foo;,class,D2_KMS,+T:foo"
>      ddcmd class,D2_CORE,+T:foo\;class,D2_KMS,+T:foo
> -    check_match_ct =T 2 -v
> +    check_match_ct =T 3 -v
>      check_match_ct =Tl 0
>      check_match_ct =Tmf 0
>      echo 1 >/sys/kernel/tracing/tracing_on
> @@ -379,7 +379,7 @@ function test_private_trace_4 {
>      modprobe test_dynamic_debug dyndbg=class,D2_CORE,+T:foo%class,D2_KMS,+T:foo
>      check_match_ct =Tl 0
>      check_match_ct =Tmf 0
> -    check_match_ct =T 2
> +    check_match_ct =T 3
>      echo 1 >/sys/kernel/tracing/tracing_on
>
> What kernel version did you use for the testing ?

turns out Im on top of -rc7
(I suppose I should pay closer attention :-)


> > I chose module params, on the idea that its builtin, but also invoked later,
> > when modules are modprobed with params, so its callsites can be enabled &
> > then invoked via do_prints, to test for writes to the private trace-buf.
> >
> > I've pushed it to lukas-v3.0 at jimc.github.com/linux
> >
> > Would you look at err on _6, above,
> > and figure out if its insufficiently robust to test preconditions, or
> > something else ?
>
> The following change fixes failure in TEST_PRIVATE_TRACE_6:
> @@ -455,7 +455,7 @@ function test_private_trace_6 {
>      ddcmd open $name
>      is_trace_instance_opened $name
>      check_trace_instance_dir $name 1
> -    ddcmd "module module =T:$name.l" -v
> +    ddcmd "module usbcore =T:$name.l"
>      check_match_ct =T:A_bit_lengthy_trace....l 164
>
> When dyndbg_selftest.sh completes with success which is announced by the line
> # Done on: Thu Dec 28 23:04:17 CET 2023
> then it leaves dynamic debug and trace in a state where next
> dyndbg_selftest.sh run should also complete with success.

yes .this works well for vng -e <script-path> runs

> But when any of the tests fails manual intervention or reboot is
> required at the moment.
> Do you think we should have a cleanup function and call it whenever
> dyndbg_selftest.sh fails in order
> to prepare dynamic debug and trace for the next run of dyndbg_selftest.sh ?
>

yes, I think so.
In part to prove that we can "un-wedge" whatever's wrong w/o a reboot.
and/or a rmmod, modprobe cycle.
self_end_* are doing various unwinds,
but a full-powered cleanup fn, with diagnostics and hints
would be a good addition, with demonstration value.



> > and also:
> > rename test_private_trace_N() to better names
> > - and/or comments to intent & pattern of use
> > more tweaks invited in its commit-msg
> >
>
> I will rename the functions and add description of the tests.
>
> > since cycle_test_problem() is not actually a problem, whats a better name ?
> > _not_best_practices ?
> >
>
> Ack
>
> > I think the final test script enhancement needed is (maybe separately):
> > private-buffer-expected-write-verification after do_prints,
> > and around modprobe test_dynamic_debug dyndbg=$multicmd
> > subject to 2 below.
> >
>
> Ack

we definitely have this in part, spread around the dozen or so functions

>
> > > TODOs:
> > > - update dynamic debug documentation,
> > > - finalize discussion related to default trace destination
> > > (whether we want it at all, if yes then conclude on the details)
> > >
> >
> > good list. before docs;
> >
> > wrt default-trace, at least in some details, it seems extra rules to know.
> > for example, if the default were set on successful open,
> > rather than successful rule application (iirc), then it would read a lot
> > like "with" or "using" blocks, esp with <<EOX form
> >
> > with that new form, it might be pretty expressive:
> >
> > echo <<YMMV > /proc/dynamic_debug/control
> >   open sesame # ie with
> >     module magic_carpet function forward +Tfml
> >     module magic_lamp function rub_vigorously +Tfmt
> >   open voicetrace
> >     module voice2ai function text2cmdprompt +T
> >     module undo function oh_crap +T
> > YMMV
> >

I was hoping this example was stupid enough to goad someone
into responding (with a better one).  Alas no.

How might DRM want to use this ?

one practical example is to segregate hi-rate drm_dbg events to a
separate buffer,
so theyre not cluttering your trace-cmd view until you want them.

But thats a little contrived, cuz vblank events are already trace-events
into the global buffer, they dont have drm_dbg's for this.


echo <<DRM_TRACE_BLK > /proc/dynamic_debug/control

   open vblank_stream      # segregate noisy/hi-vol stuff

     module amdgpu format *_vblank            +:vblank_stream   # one
way to select them
     module amdgpu format "[DML]:DML_"   +:vblank_strem   # pretty
much same set ?

   open drm_generic
       class DRM_CORE +:drm_generic.mf
       class DRM_DRIVER_ +:drm_generic.tmf

DRM_TRACE_BLK



> > I think set-default-on-good-rule-applied is flawed:
> > it relies on the most complex expression in the grammar to be correct
> > and without spelling errors, where module unknown is
> > OK grammatically, but nonsense.
>
> in case of "unknown" module default trace destination will not be
> updated because
> the code checks for nfound before updating  default destination:
> if (nfound)
>     update_tr_default_dst(modifiers);
>
> > set-default-on-open is simpler to explain and test separately.
> >
>
> Actually I think we discussed set-default-on-open some time ago (in
> the beginning).

we could have - I miss a lot :-}
anyway youve named our choices:

> But to sum up the default trace destination there were 3 directions
> proposed/discussed:
> - set-default-on-open,
> - set-default-on-good-rule-applied,

note in my DRM_TRC_BLK example above, I made a  subtle error.
DRM_DRIVER_ doesnt exist cuz of the trailing _.
non-matching keywords are silently skipped. (not just class)
the rule wont apply.
If Id misspelled it as DRM_DRIVERS it would be just as quiet.

So now the good/bad status creates an order-dependence;
if the rule is 1st in a set, good/bad chooses the new/old default-dest.
and this affects any following rule, unless that has an explicit dest.
This sounds complicated.

set-default-on-open  doesnt have these problems:
each rule gets the same setting

> - preset-default-per-each-callsite with -T:trace_dest_name,

this doesnt have a default-setting, it keeps what it had

>
> All 3 pass information explicitly but IMHO
> preset-default-per-each-callsite is most confusing as user would have
> to remember what was preset for a given callsite when later passing a
> T flag for the same callsite.
>

thats true, but for:
We could display the current destination in control, independent of the flags
(with the :0. default elided)

init/main.c:1117 [main]initcall_blacklist =pT:startup_trc.mf
"blacklisting initcall %s\n"
init/main.c:1156 [main]initcall_blacklisted =T:startup_trc.mf
"initcall %s blacklisted\n"
init/main.c:1351 [main]run_init_process =:startup_trc.mf "  with arguments:\n"

1st line writes to syslog and to private startup_trc, both with
"module:function:"  dynamic-prefix
2nd only to the private trace, with same prefix
3rd is not enabled, but has its dest preset to the private trace,
again with the prefix.

And the part I glossed over:
a new "trace_name" keyword would allow selection on the composed set
of sites with that preset.

   ddcmd  trace_name drm_generic +Ts     # enable the set which is
pointing at drm_generic




> Then if it comes to set-default-on-open vs
> set-default-on-good-rule-applied I don't have strong opinion but I
> would
> lean towards set-default-on-open because in this case it is pretty
> straightforward, I mean last successful open sets default trace
> destination.

of the 1st 2 options, I lean strongly to on-open.

To test the limits, what if we renamed "open" to "using" ?
using could:
a) force a dest update, from any previous state.
b) only upgrade from :0.  dont change :foo.

a is unnecessary, since +T:dest.  explicitly does that.
b is more subtle, but more useful.

>
> If you also hesitate which one to choose maybe we should start with
> very simple approach like that +T always defaults to trace events (:0)
> ?

that makes sense.
keep-presets-per-callsite does need keyword to be complete.

>
> > We should probably consider modifying the continue-looping behavior
> > of ddebug_exec_queries, depending upon the return-code.
> > open, close errors could reasonably warrant different treatment,
> > like terminating the mult-cmd loop prematurely on open/close errs.
> > Esp if we keep the set-default-on-good-rule-applied
> > What do you think ?

this is still open, and worth a review, but minor.

> Let's first conclude on default destination.
>
> > I'm inclined to reword a commit-msg or 2, drop RFC, obsolete comments etc.
> >
> > I can do that in a lukas-v3.1, or as in-thread responses,
> > do you have a preference ?
>
> Please go ahead and make changes in the lukas-v3.1 branch. I find it
> very convenient. I will just grab your changes from the branch.

excellent, it does feel pretty smooth.
is your repo also public, or did I just miss the clonable url?

I'll write some trace-thing for howto in the next few days,
(in particular, I'll stay out of dyndbg_selftest.sh, I think its your turn :-)

theres also s/coma/comma/ in the comma-separator patch.


thats all I got now,
Thanks!!
Jim

wt., 2 sty 2024 o 20:13 <jim.cromie@gmail.com> napisał(a):
>
> ok, to catch up here,
> Lukas & I have been nudging the test script forward,
> some of this is settled..
>
> On Thu, Dec 28, 2023 at 5:00 PM Łukasz Bartosik <lb@semihalf.com> wrote:
> >
> > śr., 27 gru 2023 o 05:23 <jim.cromie@gmail.com> napisał(a):
> > >
> > > re-adding gregkh, who fell off the cc's again.
> > > he is one of our upstreams.
> > >
> >
> > hi Jim,
> >
> > It's good to hear from you.
> >
> > Thanks. I missed to add Greg.
> >
> > > On Fri, Dec 22, 2023 at 6:51 PM Łukasz Bartosik <lb@semihalf.com> wrote:
> > > >
> > > > Add support for writing debug logs to trace events and trace instances.
> > > > The rationale behing this feature is to be able to redirect debug logs
> > > > (per each callsite individually) to trace to aid in debugging. The debug
> > > > logs output to trace can be enabled with T flag. Additionally the T flag
> > > > accepts trace destination which can be provided to the T flag after ":".
> > > > The trace destination field is used to determine where debug logs will be
> > > > written.
> > > >
> > > > In order to redirect callsite debug log to a trace instance it has to be
> > > > initialized first with a newly introduced "open" command. For example,
> > > > "usb" trace instance in <debugfs>/tracing/instances/ can be initialized
> > > > by issuing the command:
> > > >
> > > > localhost ~ # echo "open usb" >
> > > >                                 <debugfs>/dynamic_debug/control
> > > >
> > > > If the trace instance <debugfs>/tracing/instances/usb already exists
> > > > then it will be reused otherwise new usbcore instance will be created.
> > > > Maximum 63 trace instances can be "opened". The trace instance name can
> > > > include any of ^\w+ and underscore characters. There is also a special
> > > > name "0" reserved for writing debug logs to trace prdbg and devdbg events.
> > > > The reserved name "0" does not require to be "opened" before use.
> > >
> > > theres implication here that p only works when :0.
> > > Is that intended ?
> > > it seems wrong, or at least unnecessary.
> > >
> >
> > I don't see clearly the implication that p only works when :0.
> > Which statement implies this to you ? Please keep in mind that English
> > is not my native.
>
> heh - Im not sure now - its mostly me probing for unseen inconsistencies.
>
> > > In fact, theres no specific reason to exclude +p:trcbuf.mf,
> > > esp if we keep default-trace-buf
> > > since +pTfml  could have that meaning implicitly.
> > > We can call it allowed and "unimplemented until proven useful" on +p
> > >
> > > +p completely independent of +T is a simplicity,
> > > lets keep that until proven useful otherwise.
> > >
> > > >
> > > > To enable writing usbcore module debug logs to the "usb" trace instance
> > > > opened above a user can issue the command:
> > > >
> > > > localhost ~ # echo "module usbcore =pT:usb" >
> > > >                                 <debugfs>/dynamic_debug/control
> > > >
> > > > Please note that output of debug logs to syslog (p flag) and trace (T flag)
> > > > can be independently enabled/disabled for each callsite. Therefore the
> > > > above command will enable writing of debug logs not only to the trace
> > > > instance "usb" but also to syslog.
> > > >
> > > > When trace destination is followed by another flag the next flag has to
> > > > be preeceded with ".", for example
> > > >
> > > > localhost ~ # echo "module usbcore =pT:usb.l" >
> > > >                                 <debugfs>/dynamic_debug/control
> > > >
> > > > To simplify processing trace destination can be omitted when default
> > > > trace destination is set, for example the command
> > > >
> > > > localhost ~ # echo "module usbcore =pTl" >
> > > >                                 <debugfs>/dynamic_debug/control
> > > >
> > > > will use default trace destination. If default trace destination is not
> > > > set the above command will fail. The default trace destination is set
> > > > when a command with any of the flags [-+=] and explicitly provided trace
> > > > destination matches at least one callsite, for example the command
> > > >
> > > > localhost ~ # echo "module usbcore -T:usb" >
> > > >                                 <debugfs>/dynamic_debug/control
> > > >
> > > > will disable trace for all usbcore module callsites (if any was enabled)
> > > > and will set "usb" instance as default trace destination. To enable writing
> > > > thunderbolt module debug logs to the "usb" trace instance as well a user
> > > > can issue the command:
> > > >
> > > > localhost ~ # echo "module thunderbolt =T" >
> > > >                                 <debugfs>/dynamic_debug/control
> > > >
> > > > Since default trace destination was previously set therefore "usb" instance
> > > > name does not have to be explicitly provided.
> > > >
> > > > When no callsite writes debug logs to a trace instance then it can be
> > > > released (its reference counter decrased) with the "close" command.
> > > decreased
> > >
> >
> > Ack
> >
> > > > Closing a trace instance make it unavailable for dynamic debug and also
> > > makes
> >
> > Ack
> >
> > > > allows a user to delete such a trace instance at convenient time later
> > > > with rmdir command. For example when "usb" instance is not used anymore
> > > > a user can issue the command:
> > > >
> > > > localhost ~ # echo "close usb" >
> > > >                                 <debugfs>/dynamic_debug/control
> > > > and then to delete it with:
> > > >
> > > > localhost ~ # rmdir <debugfs>/tracing/instances/
> > > >
> > > > To enable writing usbcore module debug logs to trace dyndbg:prdbg and
> > > > dyndbg:devdbg events user can issue the command:
> > > >
> > > > localhost ~ # echo "module usbcore =T:0" >
> > > >                                 <debugfs>/dynamic_debug/control
> > > >
> > > > Then dyndbg trace events can be for example captured with the command:
> > > >
> > > > localhost ~ # trace-cmd start -e dyndbg
> > > >
> > > > And displayed with the command:
> > > >
> > > > localhost ~ # trace-cmd show
> > > >
> > >
> > > is there a recipe to show private traces ? prolly worth a mention here.
> > >
> >
> > Trace-cmd stat shows among other things open trace instances. I will add it.
> >
> > >
> > > >
> > > >
> > > > Jim, I made a few changes to the test script dd-selftest.rc you created
> > > > and I also added new test scenarios. You can find the entire patchset
> > > > with the test script changes on top here
> > > > https://chromium.googlesource.com/chromiumos/third_party/kernel/+log/refs/sandbox/ukaszb/dyndbg_trace_v3
> > > > I wonder where would be the proper place to store the test script
> > > > (upstream, your github.com:jimc/linux.git)
> > > > Do you have a suggestion for that ?
> > > >
> > >
> > > I got it (your HEAD), renamed and put it in:
> > > tools/testing/selftests/dynamic_debug/
> > > and copied & modified Makefile and config from ../users/
> > > I added your SOB, that seems proper.
> > >
> >
> > Great, thanks ;)
> >
> > > nice additions.  and I like the colors.  maybe they belong in lib.mk,
> > > but thats 4 later.
> > >
> > > and tweaked the modules / DUTs to *hopefully* get stable callsite counts
> > > from the tests on them, in virtually any usable config.
> > > DUTs: file init/main, module mm_init, and module test_dynamic_debug (a
> > > config constraint)
> > > The ref-counts are taken from a default virtme-ng -k config on my x86-64 box
> > >
> > > I now pass tests up to:
> > >
> > > [root@v6 wk-proof]# ./tools/testing/selftests/dynamic_debug/dyndbg_selftest.sh
> > > ...
> > > # TEST_PRIVATE_TRACE_6
> > > [ 1009.296557] dyndbg: read 3 bytes from userspace
> > > [ 1009.296876] dyndbg: query 0: <=_> on module: <*>
> > > [ 1009.297171] dyndbg: processed 1 queries, with 1559 matches, 0 errs
> > > [ 1009.311621] dyndbg: read 39 bytes from userspace
> > > [ 1009.312032] dyndbg: query 0: <open
> > > A_bit_lengthy_trace_instance_name> on module: <*>
> > > [ 1009.312569] dyndbg: instance is already opened
> > > name:A_bit_lengthy_trace_instance_name
> > > [ 1009.313063] dyndbg: processed 1 queries, with 0 matches, 1 errs
> > > : ./tools/testing/selftests/dynamic_debug/dyndbg_selftest.sh:454
> > > ddcmd() expected to exit with code 0
> > > Error: 'File exists'
> > >
> > > it seems invocation dependent
> > > I suspect 2 possibilities:
> > > 1-  invoking as shell-script, repeatedly vs vng -e script-name
> > > (one-shot per boot)
> > > 2- virtme-ng's minimal-default config has no CONFIG_USB.
> > >    this changes post-conditions of the script, affecting preconditions
> > > of the next run.
> > >
> >
> > I guess you must have enabled CONFIG_USB in your setup otherwise
> > dyndbg_selftest.sh should fail earlier in TEST_PRIVATE_TRACE_5 ?
> >
>
> Its usually on, but I have at least one config,
> IIRC from default vng -vk, that left it off.
>
> whats the shell syntax to check CONFIG_MODULES ?
>

Please elaborate what would you like to check ?

> ATM, basic-tests uses "module main" (maybe worth narrowing)
> comma-terminator-tests uses "module params"
> test-percent-splitting uses test_dynamic_debug to demo a useful case,
> so it needs MODULES
> so does the self-start-various-end tests
>
> the private-trace tests appear to use a mix of
> test_dynamic-debug, & module params,
> maybe that can be materially improved, I dont know.
>
> IIRC for builtins I think we're now using 'file kernel/

We can narrow further check conditions when there are different
results on different kernel versions.

> > > 2 means that we should replace usbcore with some other always *builtin* module.
> > >
> >
> > Sounds good. Do you have a module candidate ?
>
>
>
> >
> > I'm also concerned that we might need to validate dyndbg_selftest.sh
> > against specific kernel version because
> > I took the dyndbg_selftest.sh from lukas-v3.0 branch and I had to do
> > the following changes to make it work on kernel v6.6:
> >
>
> Yes, I hit this one too.
> I decided to avoid using mm_init for this reason.
> (without actually looking whether it was a config-based variance,
> which I assumed, or a commit-based one)
> I chose 'module params' instead,
> despite the need to escape the brackets in the search:
>
>     check_match_ct '\[params\]' 4
>

When I took dyndbg_selftest from top of dd-classmaps2-on-lukas-v3.1
branch I had two check_match_ct errors but these were caused by too
loose check conditions.
After narrowing conditions all tests passed on top of v6.6 kernel.

> > --- a/tools/testing/selftests/dynamic_debug/dyndbg_selftest.sh
> > +++ b/tools/testing/selftests/dynamic_debug/dyndbg_selftest.sh
> > @@ -166,12 +166,12 @@ EOF
> >  function comma_terminator_tests {
> >      echo -e "${GREEN}# COMMA_TERMINATOR_TESTS ${NC}"
> >      # try combos of space & comma
> > -    check_match_ct mm_init 5
> > +    check_match_ct mm_init 4
> >      ddcmd module,mm_init,=_            # commas as spaces
> >      ddcmd module,mm_init,+mpf          # turn on non-classed
> > -    check_match_ct =pmf 5
> > +    check_match_ct =pmf 4
> >      ddcmd ,module ,, ,  mm_init, -p    # extra commas & spaces
> > -    check_match_ct =mf 5
> > +    check_match_ct =mf 4
> >      ddcmd =_
> >  }
> >  function test_percent_splitting {
> > @@ -350,7 +350,7 @@ function test_private_trace_3 {
> >      ddcmd class D2_CORE +T:foo \; class D2_KMS +T:foo
> >      ddcmd "class,D2_CORE,+T:foo;,class,D2_KMS,+T:foo"
> >      ddcmd class,D2_CORE,+T:foo\;class,D2_KMS,+T:foo
> > -    check_match_ct =T 2 -v
> > +    check_match_ct =T 3 -v
> >      check_match_ct =Tl 0
> >      check_match_ct =Tmf 0
> >      echo 1 >/sys/kernel/tracing/tracing_on
> > @@ -379,7 +379,7 @@ function test_private_trace_4 {
> >      modprobe test_dynamic_debug dyndbg=class,D2_CORE,+T:foo%class,D2_KMS,+T:foo
> >      check_match_ct =Tl 0
> >      check_match_ct =Tmf 0
> > -    check_match_ct =T 2
> > +    check_match_ct =T 3
> >      echo 1 >/sys/kernel/tracing/tracing_on
> >
> > What kernel version did you use for the testing ?
>
> turns out Im on top of -rc7
> (I suppose I should pay closer attention :-)
>
>
> > > I chose module params, on the idea that its builtin, but also invoked later,
> > > when modules are modprobed with params, so its callsites can be enabled &
> > > then invoked via do_prints, to test for writes to the private trace-buf.
> > >
> > > I've pushed it to lukas-v3.0 at jimc.github.com/linux
> > >
> > > Would you look at err on _6, above,
> > > and figure out if its insufficiently robust to test preconditions, or
> > > something else ?
> >
> > The following change fixes failure in TEST_PRIVATE_TRACE_6:
> > @@ -455,7 +455,7 @@ function test_private_trace_6 {
> >      ddcmd open $name
> >      is_trace_instance_opened $name
> >      check_trace_instance_dir $name 1
> > -    ddcmd "module module =T:$name.l" -v
> > +    ddcmd "module usbcore =T:$name.l"
> >      check_match_ct =T:A_bit_lengthy_trace....l 164
> >
> > When dyndbg_selftest.sh completes with success which is announced by the line
> > # Done on: Thu Dec 28 23:04:17 CET 2023
> > then it leaves dynamic debug and trace in a state where next
> > dyndbg_selftest.sh run should also complete with success.
>
> yes .this works well for vng -e <script-path> runs
>
> > But when any of the tests fails manual intervention or reboot is
> > required at the moment.
> > Do you think we should have a cleanup function and call it whenever
> > dyndbg_selftest.sh fails in order
> > to prepare dynamic debug and trace for the next run of dyndbg_selftest.sh ?
> >
>
> yes, I think so.
> In part to prove that we can "un-wedge" whatever's wrong w/o a reboot.
> and/or a rmmod, modprobe cycle.
> self_end_* are doing various unwinds,
> but a full-powered cleanup fn, with diagnostics and hints
> would be a good addition, with demonstration value.
>

I will create such a cleanup function.

>
>
> > > and also:
> > > rename test_private_trace_N() to better names
> > > - and/or comments to intent & pattern of use
> > > more tweaks invited in its commit-msg
> > >
> >
> > I will rename the functions and add description of the tests.
> >
> > > since cycle_test_problem() is not actually a problem, whats a better name ?
> > > _not_best_practices ?
> > >
> >
> > Ack
> >
> > > I think the final test script enhancement needed is (maybe separately):
> > > private-buffer-expected-write-verification after do_prints,
> > > and around modprobe test_dynamic_debug dyndbg=$multicmd
> > > subject to 2 below.
> > >
> >
> > Ack
>
> we definitely have this in part, spread around the dozen or so functions
>

I will create new test to match the criteria above.

> >
> > > > TODOs:
> > > > - update dynamic debug documentation,
> > > > - finalize discussion related to default trace destination
> > > > (whether we want it at all, if yes then conclude on the details)
> > > >
> > >
> > > good list. before docs;
> > >
> > > wrt default-trace, at least in some details, it seems extra rules to know.
> > > for example, if the default were set on successful open,
> > > rather than successful rule application (iirc), then it would read a lot
> > > like "with" or "using" blocks, esp with <<EOX form
> > >
> > > with that new form, it might be pretty expressive:
> > >
> > > echo <<YMMV > /proc/dynamic_debug/control
> > >   open sesame # ie with
> > >     module magic_carpet function forward +Tfml
> > >     module magic_lamp function rub_vigorously +Tfmt
> > >   open voicetrace
> > >     module voice2ai function text2cmdprompt +T
> > >     module undo function oh_crap +T
> > > YMMV
> > >
>
> I was hoping this example was stupid enough to goad someone
> into responding (with a better one).  Alas no.
>
> How might DRM want to use this ?
>
> one practical example is to segregate hi-rate drm_dbg events to a
> separate buffer,
> so theyre not cluttering your trace-cmd view until you want them.
>
> But thats a little contrived, cuz vblank events are already trace-events
> into the global buffer, they dont have drm_dbg's for this.
>
>
> echo <<DRM_TRACE_BLK > /proc/dynamic_debug/control
>
>    open vblank_stream      # segregate noisy/hi-vol stuff
>
>      module amdgpu format *_vblank            +:vblank_stream   # one
> way to select them
>      module amdgpu format "[DML]:DML_"   +:vblank_strem   # pretty
> much same set ?
>
>    open drm_generic
>        class DRM_CORE +:drm_generic.mf
>        class DRM_DRIVER_ +:drm_generic.tmf
>
> DRM_TRACE_BLK
>
>
>
> > > I think set-default-on-good-rule-applied is flawed:
> > > it relies on the most complex expression in the grammar to be correct
> > > and without spelling errors, where module unknown is
> > > OK grammatically, but nonsense.
> >
> > in case of "unknown" module default trace destination will not be
> > updated because
> > the code checks for nfound before updating  default destination:
> > if (nfound)
> >     update_tr_default_dst(modifiers);
> >
> > > set-default-on-open is simpler to explain and test separately.
> > >
> >
> > Actually I think we discussed set-default-on-open some time ago (in
> > the beginning).
>
> we could have - I miss a lot :-}
> anyway youve named our choices:
>
> > But to sum up the default trace destination there were 3 directions
> > proposed/discussed:
> > - set-default-on-open,
> > - set-default-on-good-rule-applied,
>
> note in my DRM_TRC_BLK example above, I made a  subtle error.
> DRM_DRIVER_ doesnt exist cuz of the trailing _.
> non-matching keywords are silently skipped. (not just class)
> the rule wont apply.
> If Id misspelled it as DRM_DRIVERS it would be just as quiet.
>
> So now the good/bad status creates an order-dependence;
> if the rule is 1st in a set, good/bad chooses the new/old default-dest.
> and this affects any following rule, unless that has an explicit dest.
> This sounds complicated.
>

I agree but I think the order-dependence issue also applies to open.
Let me explain below.

> set-default-on-open  doesnt have these problems:
> each rule gets the same setting
>

Let's assume the following multi line command:
echo "open usb" > /proc/dynamic_debug/control  # usb becomes default
trace destination
echo "module usbcore =T" > /proc/dynamic_debug/control # use usb as
trace destination
echo "open tbt" > /proc/dynamic_debug/control
echo "module thunderbolt =T" > /proc/dynamic_debug/control

Now the thunderbolt debug logs will be written to tbt trace (when
"open tbt" succeeds) or to usb trace (when "open tbt" fails)

> > - preset-default-per-each-callsite with -T:trace_dest_name,
>
> this doesnt have a default-setting, it keeps what it had
>
> >
> > All 3 pass information explicitly but IMHO
> > preset-default-per-each-callsite is most confusing as user would have
> > to remember what was preset for a given callsite when later passing a
> > T flag for the same callsite.
> >
>
> thats true, but for:
> We could display the current destination in control, independent of the flags
> (with the :0. default elided)
>
> init/main.c:1117 [main]initcall_blacklist =pT:startup_trc.mf
> "blacklisting initcall %s\n"
> init/main.c:1156 [main]initcall_blacklisted =T:startup_trc.mf
> "initcall %s blacklisted\n"
> init/main.c:1351 [main]run_init_process =:startup_trc.mf "  with arguments:\n"
>
> 1st line writes to syslog and to private startup_trc, both with
> "module:function:"  dynamic-prefix
> 2nd only to the private trace, with same prefix
> 3rd is not enabled, but has its dest preset to the private trace,
> again with the prefix.
>

Yes we can display preset trace destination even when T flag is not
set for a given callsite.
I just wonder how much this approach of presetting trace destination
per callsite would be helpful to users ?

> And the part I glossed over:
> a new "trace_name" keyword would allow selection on the composed set
> of sites with that preset.
>
>    ddcmd  trace_name drm_generic +Ts     # enable the set which is
> pointing at drm_generic
>

How in this case drm_generic would be created ? Or is it just a
string/regexp which is used to select callsites ?

>
>
> > Then if it comes to set-default-on-open vs
> > set-default-on-good-rule-applied I don't have strong opinion but I
> > would
> > lean towards set-default-on-open because in this case it is pretty
> > straightforward, I mean last successful open sets default trace
> > destination.
>
> of the 1st 2 options, I lean strongly to on-open.
>

I realized there is one IMHO major advantage of
set-default-on-good-rule-applied over set-default-on-open because
it allows to change default destination without any side effects (
-T:trace_name on callsite which does not have T flag set) while
set-default-on-open causes side effect to change default destination
as new trace instance is opened as a result.

> To test the limits, what if we renamed "open" to "using" ?
> using could:
> a) force a dest update, from any previous state.
> b) only upgrade from :0.  dont change :foo.
>
> a is unnecessary, since +T:dest.  explicitly does that.
> b is more subtle, but more useful.
>

Or instead of using all this magic to implicitly set trace default
destination with set-default-on-open or
set-default-on-good-rule-applied we could create "using" command
to explicitly set default trace destination ?

> >
> > If you also hesitate which one to choose maybe we should start with
> > very simple approach like that +T always defaults to trace events (:0)
> > ?
>
> that makes sense.
> keep-presets-per-callsite does need keyword to be complete.
>
> >
> > > We should probably consider modifying the continue-looping behavior
> > > of ddebug_exec_queries, depending upon the return-code.
> > > open, close errors could reasonably warrant different treatment,
> > > like terminating the mult-cmd loop prematurely on open/close errs.
> > > Esp if we keep the set-default-on-good-rule-applied
> > > What do you think ?
>
> this is still open, and worth a review, but minor.
>

It makes sense to me to end multi command loop on open or close error.

> > Let's first conclude on default destination.
> >
> > > I'm inclined to reword a commit-msg or 2, drop RFC, obsolete comments etc.
> > >
> > > I can do that in a lukas-v3.1, or as in-thread responses,
> > > do you have a preference ?
> >
> > Please go ahead and make changes in the lukas-v3.1 branch. I find it
> > very convenient. I will just grab your changes from the branch.
>
> excellent, it does feel pretty smooth.
> is your repo also public, or did I just miss the clonable url?
>

Please try this:
git clone https://chromium.googlesource.com/chromiumos/third_party/kernel

kernel$ git ls-remote origin "refs/sandbox/ukaszb/*"
bdd057746b50a2f1c54b45274c60a51e64040b1f refs/sandbox/ukaszb/dyndbg_trace_v1
d07d243aba25650fc791c8af0c95d3904c64e043 refs/sandbox/ukaszb/dyndbg_trace_v3

git fetch origin refs/sandbox/ukaszb/dyndbg_trace_v3

> I'll write some trace-thing for howto in the next few days,

Great.

> (in particular, I'll stay out of dyndbg_selftest.sh, I think its your turn :-)
>

Yeah, it's my turn to add more colors ;).

> theres also s/coma/comma/ in the comma-separator patch.
>

Thanks for reminding me.

Thanks,
Lukasz


>
> thats all I got now,
> Thanks!!
> Jim

> >
> > Jim, I made a few changes to the test script dd-selftest.rc you created
> > and I also added new test scenarios. You can find the entire patchset
> > with the test script changes on top here
> > https://chromium.googlesource.com/chromiumos/third_party/kernel/+log/refs/sandbox/ukaszb/dyndbg_trace_v3
> > I wonder where would be the proper place to store the test script
> > (upstream, your github.com:jimc/linux.git)
> > Do you have a suggestion for that ?
> >
>
> I got it (your HEAD), renamed and put it in:
> tools/testing/selftests/dynamic_debug/
> and copied & modified Makefile and config from ../users/
> I added your SOB, that seems proper.
>

meh.
my select-paste of your HEAD dropped all the whitespace.
how annoying.


> nice additions.  and I like the colors.  maybe they belong in lib.mk,
> but thats 4 later.
>
> and tweaked the modules / DUTs to *hopefully* get stable callsite counts
> from the tests on them, in virtually any usable config.
> DUTs: file init/main, module mm_init, and module test_dynamic_debug (a
> config constraint)
> The ref-counts are taken from a default virtme-ng -k config on my x86-64 box
>
> I now pass tests up to:
>
> [root@v6 wk-proof]# ./tools/testing/selftests/dynamic_debug/dyndbg_selftest.sh
> ...
> # TEST_PRIVATE_TRACE_6
> [ 1009.296557] dyndbg: read 3 bytes from userspace
> [ 1009.296876] dyndbg: query 0: <=_> on module: <*>
> [ 1009.297171] dyndbg: processed 1 queries, with 1559 matches, 0 errs
> [ 1009.311621] dyndbg: read 39 bytes from userspace
> [ 1009.312032] dyndbg: query 0: <open
> A_bit_lengthy_trace_instance_name> on module: <*>
> [ 1009.312569] dyndbg: instance is already opened
> name:A_bit_lengthy_trace_instance_name
> [ 1009.313063] dyndbg: processed 1 queries, with 0 matches, 1 errs
> : ./tools/testing/selftests/dynamic_debug/dyndbg_selftest.sh:454
> ddcmd() expected to exit with code 0
> Error: 'File exists'
>

_7 has some obsolete counts, after previous $modname changes

śr., 27 gru 2023 o 05:44 <jim.cromie@gmail.com> napisał(a):
>
> > >
> > > Jim, I made a few changes to the test script dd-selftest.rc you created
> > > and I also added new test scenarios. You can find the entire patchset
> > > with the test script changes on top here
> > > https://chromium.googlesource.com/chromiumos/third_party/kernel/+log/refs/sandbox/ukaszb/dyndbg_trace_v3
> > > I wonder where would be the proper place to store the test script
> > > (upstream, your github.com:jimc/linux.git)
> > > Do you have a suggestion for that ?
> > >
> >
> > I got it (your HEAD), renamed and put it in:
> > tools/testing/selftests/dynamic_debug/
> > and copied & modified Makefile and config from ../users/
> > I added your SOB, that seems proper.
> >
>
> meh.
> my select-paste of your HEAD dropped all the whitespace.
> how annoying.
>
>
> > nice additions.  and I like the colors.  maybe they belong in lib.mk,
> > but thats 4 later.
> >
> > and tweaked the modules / DUTs to *hopefully* get stable callsite counts
> > from the tests on them, in virtually any usable config.
> > DUTs: file init/main, module mm_init, and module test_dynamic_debug (a
> > config constraint)
> > The ref-counts are taken from a default virtme-ng -k config on my x86-64 box
> >
> > I now pass tests up to:
> >
> > [root@v6 wk-proof]# ./tools/testing/selftests/dynamic_debug/dyndbg_selftest.sh
> > ...
> > # TEST_PRIVATE_TRACE_6
> > [ 1009.296557] dyndbg: read 3 bytes from userspace
> > [ 1009.296876] dyndbg: query 0: <=_> on module: <*>
> > [ 1009.297171] dyndbg: processed 1 queries, with 1559 matches, 0 errs
> > [ 1009.311621] dyndbg: read 39 bytes from userspace
> > [ 1009.312032] dyndbg: query 0: <open
> > A_bit_lengthy_trace_instance_name> on module: <*>
> > [ 1009.312569] dyndbg: instance is already opened
> > name:A_bit_lengthy_trace_instance_name
> > [ 1009.313063] dyndbg: processed 1 queries, with 0 matches, 1 errs
> > : ./tools/testing/selftests/dynamic_debug/dyndbg_selftest.sh:454
> > ddcmd() expected to exit with code 0
> > Error: 'File exists'
> >
>
> _7 has some obsolete counts, after previous $modname changes

Which obsolete counts are you referring to ?

Thanks,
Lukasz