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 indivdually) to trace to aid in debugging. The debug
logs output to trace can be enabled with T flag. Additionally trace
destination can be provided to the T flag after ":". The trace destination
field is used to determine where debug logs will be written. Setting trace
destination value to 0 (default) enables output to prdbg and devdbg trace
events. Setting trace destination value to a value in range of [1..255]
enables output to trace instance identified by trace destination value.
For example when trace destination value is 2 then debug logs will
be written to <debugfs>/tracing/instances/dyndbg_inst_2 instance.

Usage examples:

localhost ~ # echo "module thunderbolt =pT:7" > 
				<debugfs>/dynamic_debug/control

This will enable output of debug logs to trace instance 
<debugfs>/tracing/instances/dyndbg_inst_7 and debug logs will
be written to the syslog also because p flag is set.

localhost ~ # echo "module thunderbolt =pT:7,l" > 
                                <debugfs>/dynamic_debug/control

When trace destination is followed by another flag then trace
destination has to be followed by ",".

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

When trace destination is not provided explicitly then its value
defaults to 0. In this case debug logs will be written to the prdbg
and devdbg trace events.

localhost ~ # echo "module thunderbolt =T:25" > 
                                <debugfs>/dynamic_debug/control

This will enable output of debug logs to trace instance
<debugfs>/tracing/instances/dyndbg_inst_25 with debug logs output
to syslog disabled.

Given trace instance will not be initialized until debug logs are
requested to be written to it and afer init it will persist until
reboot.

Please note that output of debug logs to syslog (p flag) and trace
(T flag) can be independently enabled/disabled for each callsite.



Jim I took the liberty and based my work on your patches you pointed me
to https://github.com/jimc/linux/tree/dd-kitchen-sink. I picked up
the commits relevant to trace from the dd-kitchen-sink branch.
The only changes I introduced in your commits were related to checkpatch
complains. There are two errors still left:

1)
ERROR: need consistent spacing around '*' (ctx:WxV)
140: FILE: lib/dynamic_debug.c:1070:
+				  va_list *args)

Which seems to be a false positive to me.

2)
ERROR: Macros with complex values should be enclosed in parentheses
62: FILE: include/trace/stages/stage3_trace_output.h:12:
+#define TP_printk_no_nl(fmt, args...) fmt, args

I have not figured out how to fix it.

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

Jim Cromie (7):
  dyndbg: add _DPRINTK_FLAGS_ENABLED
  dyndbg: add _DPRINTK_FLAGS_TRACE
  dyndbg: add write-events-to-tracefs code
  dyndbg: add 2 trace-events: pr_debug, dev_dbg
  tracefs: add TP_printk_no_nl - RFC
  trace: use TP_printk_no_nl in dyndbg:prdbg,devdbg
  dyndbg: repack struct _ddebug

Łukasz Bartosik (5):
  dyndbg: move flags field to a new structure
  dyndbg: add trace destination field to _ddebug
  dyndbg: add processing of T(race) flag argument
  dyndbg: write debug logs to trace instance
  dyndbg: add trace support for hexdump

 .../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    |   3 +
 include/trace/stages/stage7_class_define.h    |   3 +
 lib/Kconfig.debug                             |   1 +
 lib/dynamic_debug.c                           | 414 +++++++++++++++---
 8 files changed, 465 insertions(+), 73 deletions(-)
 create mode 100644 include/trace/events/dyndbg.h

-- 
2.42.0.869.gea05f2083d-goog

Hi Łukasz,

can I haz a git remote url ?
no webmail antics that way.

On Fri, Nov 3, 2023 at 7:10 AM Ł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 indivdually) to trace to aid in debugging. The debug
> logs output to trace can be enabled with T flag. Additionally trace
> destination can be provided to the T flag after ":". The trace destination
> field is used to determine where debug logs will be written. Setting trace
> destination value to 0 (default) enables output to prdbg and devdbg trace

isnt +p independent of dest var ?  its just "on" to syslog.

> events. Setting trace destination value to a value in range of [1..255]
> enables output to trace instance identified by trace destination value.
> For example when trace destination value is 2 then debug logs will
> be written to <debugfs>/tracing/instances/dyndbg_inst_2 instance.
>
> Usage examples:
>
> localhost ~ # echo "module thunderbolt =pT:7" >
>                                 <debugfs>/dynamic_debug/control
>
> This will enable output of debug logs to trace instance
> <debugfs>/tracing/instances/dyndbg_inst_7 and debug logs will
> be written to the syslog also because p flag is set.
>
> localhost ~ # echo "module thunderbolt =pT:7,l" >
>                                 <debugfs>/dynamic_debug/control
>
> When trace destination is followed by another flag then trace
> destination has to be followed by ",".
>
> localhost ~ # echo "module thunderbolt =pTl" >
>                                 <debugfs>/dynamic_debug/control
>
> When trace destination is not provided explicitly then its value
> defaults to 0. In this case debug logs will be written to the prdbg
> and devdbg trace events.
>
> localhost ~ # echo "module thunderbolt =T:25" >
>                                 <debugfs>/dynamic_debug/control
>
> This will enable output of debug logs to trace instance
> <debugfs>/tracing/instances/dyndbg_inst_25 with debug logs output
> to syslog disabled.
>
> Given trace instance will not be initialized until debug logs are
> requested to be written to it and afer init it will persist until
> reboot.
>

that (delayed init) might be a problem,
user side will have to look for the appearance of traces ?

Also, I have some reservations about exposing numeric destinations -
the user(space) must then decide/coordinate what dest-number
is used for which instance/purpose.

It would be fine for 1 customer, but might be a little tedious for many,
who now have to coordinate.  A bit like a shared/party line in the early
days of rural telephone.

As I recall, an early early version of classmaps used numeric classes,
(taken straight from drm_debug_category).
As Jason noted (more diplomatically than I assimilated)
it was kind of arbitrary and obscure/obtuse/unhelpful numbering.

It is why I added classnames, with the bonus that
the name->num mapping was also a validation step
against known CLASSMAP_DEFINE-itions
(if you knew DRM drivers knew "DRM_KMS_CORE",
 you knew what you were asking for)

Your earlier version had a dest keyword which maybe fits better with this point.
that said, it was in a selector position, so it doesnt work grammatically.

So, what do you think about a new command:

echo <<EoCMDBlk
open kms-stream
class DRM_UT_CORE +T  # global
class DRM_UT_KMS +T:kms-stream
EoCMDBlk \
> /proc/dynamic/debug

this allows tracking names, assigning ids, erroring when all used,
and validating names > control
without exposing the numbers.

the open/close changes are (would be) persistent

the thing it doesnt allow is pre-selecting the destination,
then arming it later with a +T

so it doesnt (wouldnt) play super-nice with
echo 0x1F > /sys/module/drm/parameters/debug_trace

that said, we can preset the dst:

echo <<EoCMDBlk
open drm-kms-stream
open drm-core-stream
class DRM_UT_CORE -T:drm-core-stream
class DRM_UT_KMS -T:drm-kms-stream
EoCMDBlk \
> /proc/dynamic/debug

then enable whatever is preset selectively:

echo $I_forgot_the_bit > /sys/module/drm/parameters/debug_trace
OR
echo class DRM_UT_KMS +T > /proc/dynamic/debug







> Please note that output of debug logs to syslog (p flag) and trace
> (T flag) can be independently enabled/disabled for each callsite.
>

so its the specific wording I previously grumbled about, I think.

>
>
> Jim I took the liberty and based my work on your patches you pointed me
> to https://github.com/jimc/linux/tree/dd-kitchen-sink. I picked up
> the commits relevant to trace from the dd-kitchen-sink branch.
> The only changes I introduced in your commits were related to checkpatch
> complains. There are two errors still left:

Bah - macros !
I'll look at your diffs in git :-)

>
> 1)
> ERROR: need consistent spacing around '*' (ctx:WxV)
> 140: FILE: lib/dynamic_debug.c:1070:
> +                                 va_list *args)
>
> Which seems to be a false positive to me.
>
> 2)
> ERROR: Macros with complex values should be enclosed in parentheses
> 62: FILE: include/trace/stages/stage3_trace_output.h:12:
> +#define TP_printk_no_nl(fmt, args...) fmt, args
>
> I have not figured out how to fix it.

those 2  no_nl   patches were pretty exploratory,
IIRC, Steve was inclined to add the \n  when not already in the format.
It would be variation-proof


>
> Changes:
> V1) Major rework after receiving feedback in
> https://lore.kernel.org/all/20230915154856.1896062-1-lb@semihalf.com/
>
> Jim Cromie (7):
>   dyndbg: add _DPRINTK_FLAGS_ENABLED
>   dyndbg: add _DPRINTK_FLAGS_TRACE
>   dyndbg: add write-events-to-tracefs code
>   dyndbg: add 2 trace-events: pr_debug, dev_dbg
>   tracefs: add TP_printk_no_nl - RFC
>   trace: use TP_printk_no_nl in dyndbg:prdbg,devdbg
>   dyndbg: repack struct _ddebug
>
> Łukasz Bartosik (5):
>   dyndbg: move flags field to a new structure
>   dyndbg: add trace destination field to _ddebug
>   dyndbg: add processing of T(race) flag argument
>   dyndbg: write debug logs to trace instance
>   dyndbg: add trace support for hexdump
>
>  .../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    |   3 +
>  include/trace/stages/stage7_class_define.h    |   3 +
>  lib/Kconfig.debug                             |   1 +
>  lib/dynamic_debug.c                           | 414 +++++++++++++++---
>  8 files changed, 465 insertions(+), 73 deletions(-)
>  create mode 100644 include/trace/events/dyndbg.h
>
> --
> 2.42.0.869.gea05f2083d-goog
>

sob., 4 lis 2023 o 02:25 <jim.cromie@gmail.com> napisał(a):
>
> Hi Łukasz,
>
> can I haz a git remote url ?
> no webmail antics that way.
>

Here you are https://chromium.googlesource.com/chromiumos/third_party/kernel/+log/refs/sandbox/ukaszb/dyndbg_trace_v1

> On Fri, Nov 3, 2023 at 7:10 AM Ł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 indivdually) to trace to aid in debugging. The debug
> > logs output to trace can be enabled with T flag. Additionally trace
> > destination can be provided to the T flag after ":". The trace destination
> > field is used to determine where debug logs will be written. Setting trace
> > destination value to 0 (default) enables output to prdbg and devdbg trace
>
> isnt +p independent of dest var ?  its just "on" to syslog.
>

Yes +p would be independent from +T so that a given callsite debug log
could be written both to syslog and trace.

> > events. Setting trace destination value to a value in range of [1..255]
> > enables output to trace instance identified by trace destination value.
> > For example when trace destination value is 2 then debug logs will
> > be written to <debugfs>/tracing/instances/dyndbg_inst_2 instance.
> >
> > Usage examples:
> >
> > localhost ~ # echo "module thunderbolt =pT:7" >
> >                                 <debugfs>/dynamic_debug/control
> >
> > This will enable output of debug logs to trace instance
> > <debugfs>/tracing/instances/dyndbg_inst_7 and debug logs will
> > be written to the syslog also because p flag is set.
> >
> > localhost ~ # echo "module thunderbolt =pT:7,l" >
> >                                 <debugfs>/dynamic_debug/control
> >
> > When trace destination is followed by another flag then trace
> > destination has to be followed by ",".
> >
> > localhost ~ # echo "module thunderbolt =pTl" >
> >                                 <debugfs>/dynamic_debug/control
> >
> > When trace destination is not provided explicitly then its value
> > defaults to 0. In this case debug logs will be written to the prdbg
> > and devdbg trace events.
> >
> > localhost ~ # echo "module thunderbolt =T:25" >
> >                                 <debugfs>/dynamic_debug/control
> >
> > This will enable output of debug logs to trace instance
> > <debugfs>/tracing/instances/dyndbg_inst_25 with debug logs output
> > to syslog disabled.
> >
> > Given trace instance will not be initialized until debug logs are
> > requested to be written to it and afer init it will persist until
> > reboot.
> >
>
> that (delayed init) might be a problem,
> user side will have to look for the appearance of traces ?
>

With open/close commands you proposed this will become obsolete.

> Also, I have some reservations about exposing numeric destinations -
> the user(space) must then decide/coordinate what dest-number
> is used for which instance/purpose.
>
> It would be fine for 1 customer, but might be a little tedious for many,
> who now have to coordinate.  A bit like a shared/party line in the early
> days of rural telephone.
>

Nice comparison :). But it was pretty "socializing" as everyone could
hear a conversation which took place on such a line.

> As I recall, an early early version of classmaps used numeric classes,
> (taken straight from drm_debug_category).
> As Jason noted (more diplomatically than I assimilated)
> it was kind of arbitrary and obscure/obtuse/unhelpful numbering.
>
> It is why I added classnames, with the bonus that
> the name->num mapping was also a validation step
> against known CLASSMAP_DEFINE-itions
> (if you knew DRM drivers knew "DRM_KMS_CORE",
>  you knew what you were asking for)
>
> Your earlier version had a dest keyword which maybe fits better with this point.
> that said, it was in a selector position, so it doesnt work grammatically.
>
> So, what do you think about a new command:
>
> echo <<EoCMDBlk
> open kms-stream
> class DRM_UT_CORE +T  # global
> class DRM_UT_KMS +T:kms-stream
> EoCMDBlk \
> > /proc/dynamic/debug
>
> this allows tracking names, assigning ids, erroring when all used,
> and validating names > control
> without exposing the numbers.
>
> the open/close changes are (would be) persistent
>
> the thing it doesnt allow is pre-selecting the destination,
> then arming it later with a +T
>
> so it doesnt (wouldnt) play super-nice with
> echo 0x1F > /sys/module/drm/parameters/debug_trace
>
> that said, we can preset the dst:
>
> echo <<EoCMDBlk
> open drm-kms-stream
> open drm-core-stream
> class DRM_UT_CORE -T:drm-core-stream
> class DRM_UT_KMS -T:drm-kms-stream
> EoCMDBlk \
> > /proc/dynamic/debug
>
> then enable whatever is preset selectively:
>
> echo $I_forgot_the_bit > /sys/module/drm/parameters/debug_trace
> OR
> echo class DRM_UT_KMS +T > /proc/dynamic/debug
>

I agree that numbers are not very meaningful, I asked question related to your
proposal in revisited comment.


>
>
>
>
>
>
> > Please note that output of debug logs to syslog (p flag) and trace
> > (T flag) can be independently enabled/disabled for each callsite.
> >
>
> so its the specific wording I previously grumbled about, I think.
>
> >
> >
> > Jim I took the liberty and based my work on your patches you pointed me
> > to https://github.com/jimc/linux/tree/dd-kitchen-sink. I picked up
> > the commits relevant to trace from the dd-kitchen-sink branch.
> > The only changes I introduced in your commits were related to checkpatch
> > complains. There are two errors still left:
>
> Bah - macros !
> I'll look at your diffs in git :-)
>
> >
> > 1)
> > ERROR: need consistent spacing around '*' (ctx:WxV)
> > 140: FILE: lib/dynamic_debug.c:1070:
> > +                                 va_list *args)
> >
> > Which seems to be a false positive to me.
> >
> > 2)
> > ERROR: Macros with complex values should be enclosed in parentheses
> > 62: FILE: include/trace/stages/stage3_trace_output.h:12:
> > +#define TP_printk_no_nl(fmt, args...) fmt, args
> >
> > I have not figured out how to fix it.
>
> those 2  no_nl   patches were pretty exploratory,
> IIRC, Steve was inclined to add the \n  when not already in the format.
> It would be variation-proof
>
>
> >
> > Changes:
> > V1) Major rework after receiving feedback in
> > https://lore.kernel.org/all/20230915154856.1896062-1-lb@semihalf.com/
> >
> > Jim Cromie (7):
> >   dyndbg: add _DPRINTK_FLAGS_ENABLED
> >   dyndbg: add _DPRINTK_FLAGS_TRACE
> >   dyndbg: add write-events-to-tracefs code
> >   dyndbg: add 2 trace-events: pr_debug, dev_dbg
> >   tracefs: add TP_printk_no_nl - RFC
> >   trace: use TP_printk_no_nl in dyndbg:prdbg,devdbg
> >   dyndbg: repack struct _ddebug
> >
> > Łukasz Bartosik (5):
> >   dyndbg: move flags field to a new structure
> >   dyndbg: add trace destination field to _ddebug
> >   dyndbg: add processing of T(race) flag argument
> >   dyndbg: write debug logs to trace instance
> >   dyndbg: add trace support for hexdump
> >
> >  .../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    |   3 +
> >  include/trace/stages/stage7_class_define.h    |   3 +
> >  lib/Kconfig.debug                             |   1 +
> >  lib/dynamic_debug.c                           | 414 +++++++++++++++---
> >  8 files changed, 465 insertions(+), 73 deletions(-)
> >  create mode 100644 include/trace/events/dyndbg.h
> >
> > --
> > 2.42.0.869.gea05f2083d-goog
> >