Re: [PATCH][RFC] tracing: Enable tracepoints via module parameters

[Dan Williams]

On Tue, Apr 20, 2021 at 1:33 PM Steven Rostedt <rostedt@xxxxxxxxxxx> wrote:
>
> On Tue, 20 Apr 2021 12:54:39 -0700
> Dan Williams <dan.j.williams@xxxxxxxxx> wrote:
>
> > On Tue, Apr 20, 2021 at 5:55 AM Steven Rostedt <rostedt@xxxxxxxxxxx> wrote:
> > > >
> > > > The dev_dbg() filter language is attractive, it's too bad
> > >
> > > Not sure what you mean by that. What filter language. Tracepoints do have a
> > > pretty good filtering too.
> >
> > I'm trying to replicate dev_dbg() usability with tracing. So, when
> > people say "don't use dev_dbg() for that" that tracing can reliably
> > replace everything that dev_dbg() was offering. What I think that
> > looks like is the ability to turn on function tracing by a function
> > name glob in addition to any tracepoints in those same functions all
> > from the kernel boot command line, or a module parameter.
>
> You can enable functions on the kernel command line in globs (and trace
> events as well). And if the kernel command line doesn't work properly (it's
> not as tested as the run time side is), it should be trivial to fix it.
>
>
> >
> > > > trace_printk() has such a high runtime cost as combining dynamic-debug
> > > > and tracing would seem to be a panacea.
> > >
> > > trace_printk() has a high runtime cost? Besides that it's not allowed on
> > > production code (see nasty banner), it is made to be extremely fast.
> > > Although, it does do sprintf() work.
> >
> > I was referring to the banner. dev_dbg() does not have that production
> > code restriction.
>
> You can have a tracepoint like trace_printk that doesn't give a banner.
> Basically, the reason trace_printk() has that restriction is because you
> can't filter it like you can trace events. It's similar to a printk(). If I
> had allowed trace_printk() in the kernel, it would be all over the place,
> and it would just add a bunch of noise to the trace output, because its
> either on or off. And if you have trace_printk() and so would all other
> systems, and then you would deal with trace_printk()s from everyone which
> could drown out the ones you want. Hence, I added that banner to keep that
> from happening. trace_printk() will even drown out events. (I hate it when
> I leave one in my debug kernel, and it adds a bunch of noise against what
> I'm trying to debug with events!).
>
> But you can add your own trace point, and even make it generic. That's what
> bpf did for their bpf_trace_printk. You could convert dev_dbg() into a
> tracepoint!
>
>
> static __printf(2, 3) int __dev_dbg(const struct device *dev, char *fmt, ...)
> {
>         static char buf[DEV_DEBUG_PRINTK_SIZE];
>         unsigned long flags;
>         va_list ap;
>         int ret;
>
>         raw_spin_lock_irqsave(&dev_dbg_printk_lock, flags);
>         va_start(ap, fmt);
>         ret = vsnprintf(buf, sizeof(buf), fmt, ap);
>         va_end(ap);
>         /* vsnprintf() will not append null for zero-length strings */
>         if (ret == 0)
>                 buf[0] = '\0';
>         trace_dev_dbg_printk(dev, buf);
>         raw_spin_unlock_irqrestore(&dev_dbg_printk_lock, flags);
>
>         return ret;
> }
>
> #define dev_dbg(dev, fmt, ...)                                  \
>         do {                                                    \
>                 if (trace_dev_dbg_printk_enabled())             \
>                         __dev_dbg(dev, fmt, ##__VA_ARGS__);     \
>         } while (0)
>
> Note, the "trace_dev_dbg_printk_enabled()" is a static branch, which means
> it is a nop when the dev_dbg_printk tracepoint is not enabled, and is a jmp
> to the __dev_dbg() logic when it is enabled. It's not a conditional branch.
>
> And have:
>
> TRACE_EVENT(dev_dbg_printk,
>
>         TP_PROTO(const struct device *dev, const char *dbg_str),
>
>         TP_ARGS(dev, dbg_str),
>
>         TP_STRUCT__entry(
>                 __field(const struct device *dev)
>                 __string(dev_name, dev_name(dev))
>                 __string(dbg_str, dbg_str)
>         ),
>
>         TP_fast_assign(
>                 __entry->dev = dev;
>                 __assign_str(dev_name, dev_name(dev))
>                 __assign_str(dbg_str, dbg_str);
>         ),
>
>         TP_printk("%p dev=%s %s", __entry->dev, __get_string(dev_name), __get_str(dbg_str))
> );
>
> And then you could even filter on the device name, or even parts of the
> string, as you can filter events, and even have them have glob matches.

Oooh, I might run with this, it's been on my backlog to go investigate
and you just threw out a solution. Imagine being able to to specify
't' instead of 'p' for a given debug print so that dev_dbg() users can
move from console to trace buffer, but also tracing users have access
to more tracepoints that happen to appear at useful dev_dbg()
locations.

Thanks, Steven!