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

[Steven Rostedt]

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.

> 
> > Would adding automatic module parameters be an issue? That is, you can add
> > in the insmod command line a parameter that will enable tracepoints. We
> > could have a way to even see them from the modinfo. I think I had that
> > working once, and it wasn't really that hard to do.  
> 
> Yeah, that's what you seemed to have working at the beginning of this thread:
> 
> https://lore.kernel.org/lkml/1299622684.20306.77.camel@xxxxxxxxxxxxxxxxxxx/

Yeah, and I should brush that off and resubmit ;-)

-- Steve